<html><body><div style="font-family: times new roman, new york, times, serif; font-size: 12pt; color: #000000"><div><br></div><hr id="zwchr"><blockquote style="border-left:2px solid #1010FF;margin-left:5px;padding-left:5px;color:#000;font-weight:normal;font-style:normal;text-decoration:none;font-family:Helvetica,Arial,sans-serif;font-size:12pt;"><b>From: </b>"Mattias Johansson" <matjo75@gmail.com><br><b>To: </b>lttng-dev@lists.lttng.org<br><b>Sent: </b>Friday, January 23, 2015 4:29:57 AM<br><b>Subject: </b>[lttng-dev] Strange sequence of events<br><div><br></div><div dir="ltr">Hi lttng-people!<div><br></div><div>I have been using lttng to make a combined kernel and userspace trace and I can't make sense of a simple sequence of events. I am using a two core cpu, a custom distro (by yocto), linux kernel version is 3.12.15 with the PREEMPT RT patches, the lttng probe module lttng-probe-sched loaded.</div><div>This is my strange sequence:</div><div><div><br></div><div>[13:26:17.542825060] (+0.000003659) unit1 sched_switch: { cpu_id = 1 }, { pid = 2390 }, { prev_comm = "ThreadA", prev_tid = 2547, prev_prio = -19, prev_state = 1024, next_comm = "KernelThreadB", next_tid = 2410, next_prio = -51 }</div><div>[13:26:17.542831008] (+0.000005948) unit1 sched_migrate_task: { cpu_id = 0 }, { pid = 2408 }, { comm = "ThreadA", tid = 2547, prio = -19, orig_cpu = 1, dest_cpu = 0 }</div><div>[13:26:17.542837060] (+0.000003256) unit1 ust_event:my_ust_event: { cpu_id = 1 }, { vtid = 2547 }, { }</div></div><div><br></div><div>ThreadA makes the userspace trace event 'my_ust_event'.</div><div><br></div><div>What is strange to me is either the timestamp of 'my_ust_event' is "wrong" (it should have been a time before the sched_switch), or the cpu_id of the ust_event is "wrong" (it should be 0 since ThreadA has been migrated to cpu_id 0 at 13:26:17.542831008).</div><div><br></div><div>Or am I interpreting the sequence wrong?</div><div><br></div><div>Or could it be that the my_ust_event itself got interrupted and had already sampled the cpu_id, and after the migration completed the event, thus the trace is "correct"?</div></div></blockquote><div>This last guess is the most likely. UST ring buffer reserve code looks like:<br></div><div><br></div><div>lttng_event_reserve()</div><div>- read current CPU number (A)<br></div><div>- lib_ring_buffer_try_reserve()</div><div> do {<br></div><div> 1) lib_ring_buffer_clock_read() (B)<br></div><div> 2) cmpxchg() to reserve space in ring buffer (C)<br></div><div> } while cmpxchg fails<br></div><div><br></div><div>So if we are preempted and migrated between (A) and (B), we could<br></div><div>see the effect you are experiencing. The issue here is that userspace<br></div><div>does not have a way to atomically read cpu number, read time, and reserve<br></div><div>space in the ring buffer with respect to the scheduler (it cannot disable preemption).<br></div><div>We would need kernel-level support for this. I have a few ideas on how this<br></div><div>could be done, but it's only at the idea stage at the moment, and would require<br></div><div>extending the kernel. It's far from simple, because we cannot disable preemption<br></div><div>nor migration from user-space (it's on purpose, and a strict requirement from<br></div><div>the Linux scheduler developers).<br></div><div><br></div><div>Thoughts ?<br></div><div><br></div><div>Thanks,<br></div><div><br></div><div>Mathieu<br></div><div><br></div><div><br></div><blockquote style="border-left:2px solid #1010FF;margin-left:5px;padding-left:5px;color:#000;font-weight:normal;font-style:normal;text-decoration:none;font-family:Helvetica,Arial,sans-serif;font-size:12pt;"><div dir="ltr"><div><br></div><div>Thanks!</div><div>/Mattias</div><div><br></div></div><br>_______________________________________________<br>lttng-dev mailing list<br>lttng-dev@lists.lttng.org<br>http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev<br></blockquote><div><br><br></div><div><br></div><div>-- <br></div><div><span name="x"></span>Mathieu Desnoyers<br>EfficiOS Inc.<br>http://www.efficios.com<span name="x"></span><br></div></div></body></html>