[lttng-dev] trace time out of order

[David Goulet]

On 25 Jun (15:15:50), zhenyu.ren wrote:
> Hi,lttng-dev
> 
>    I traced my rpc application. On the server side ,a thread reads a request from the socket and push the workitem to a queue(pushWorkItem tracepoint after queuing),another thread will get the workitem from queue and process it(ProcessWorkItem tracepoint here). However, in the trace log,I saw the ProcessWorkItem before pushWorkItem.Is this a clock issue?
> 
> [14:38:07.619841156] (+0.000000693)  arpc_server:ProcessWorkItem: { cpu_id = 0 }, { vtid = 28581 }, { Item = 112046400 }                 A
> [14:38:07.619841558] (+0.000000402)  arpc_server:ProcessWorkItem: { cpu_id = 12 }, { vtid = 28583 }, { Item = 112049088 }                B
> [14:38:07.619844551] (+0.000002993)  arpc_server:ProcessWorkItem: { cpu_id = 9 }, { vtid = 28582 }, { Item = 72969600 }                   C
> [14:38:07.619845090] (+0.000000539)  arpc_server:pushWorkItem: { cpu_id = 3 }, { vtid = 28569 }, { Item = 112046400 }                      A
> [14:38:07.619846525] (+0.000001435)  sched_wakeup: { cpu_id = 12 }, { vtid = 28583 }, { comm = "", tid = 28581, prio = 120, success = 0, target_cpu = 0 }
> [14:38:07.619846872] (+0.000000347)  arpc_server:pushWorkItem: { cpu_id = 7 }, { vtid = 28563 }, { Item = 72968352 }
> [14:38:07.619849172] (+0.000002300)  arpc_server:ProcessWorkItem: { cpu_id = 19 }, { vtid = 28587 }, { Item = 72968352 }
> [14:38:07.619850525] (+0.000001353)  arpc_server:pushWorkItem: { cpu_id = 6 }, { vtid = 28564 }, { Item = 112049088 }                      B
> [14:38:07.619862696] (+0.000012171)  sched_switch: { cpu_id = 3 }, { vtid = 28569 }, { prev_comm = "pangu_chunkserv", prev_tid = 28569, prev_prio = 20, prev_state = 1, next_comm = "swapper", next_tid = 0, next_prio = 20 }
> [14:38:07.619864494] (+0.000001798)  sched_switch: { cpu_id = 6 }, { vtid = 28564 }, { prev_comm = "pangu_chunkserv", prev_tid = 28564, prev_prio = 20, prev_state = 1, next_comm = "pangu_chunkserv", next_tid = 28568, next_prio = 20 }
> [14:38:07.619867101] (+0.000002607)  arpc_server:pushWorkItem: { cpu_id = 6 }, { vtid = 28568 }, { Item = 72969600 }                       C

Tbh, I doubt that the timestamp collected by lttng is skewed. My guess
would be that your threading might actually be racy making the Process
Work Item run before the push. Could that be possible?

Also, can you reproduce that each time or it looks like a race?

Cheers!
David

> 
> 
> 
> ps: Hardware: 2 x Xeon E5-2430 0 2.20GHz(24HT) ， 96G mem 
>       urcu 0.8 lttng 2.3
> 
> Thanks
> zhenyu.ren
> 
> _______________________________________________
> lttng-dev mailing list
> lttng-dev at lists.lttng.org
> http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 603 bytes
Desc: Digital signature
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20140625/a7c6a85c/attachment-0001.sig>