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 } CTbh, 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 > [email protected] > http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
signature.asc
Description: Digital signature
_______________________________________________ lttng-dev mailing list [email protected] http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
