<div dir="ltr">Hi Björn,<div><br></div><div>Thank you for you detailed answer. For sure it pointed me to the right direction. If I change something in the tools I will send a patch for sure.</div><div><br></div><div>Best</div><div>Giovani</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Dec 19, 2017 at 7:00 PM, Björn Brandenburg <span dir="ltr"><<a href="mailto:bbb@mpi-sws.org" target="_blank">bbb@mpi-sws.org</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Dear Giovani,<br>
<span class=""><br>
> On 18. Dec 2017, at 19:32, Giovani Gracioli <<a href="mailto:giovanig@gmail.com">giovanig@gmail.com</a>> wrote:<br>
><br>
> I would like to print per task event information, such as the timestamp a task release was performed, context switching, etc.<br>
><br>
> The ft2csv tool produces the start and end timestamps and the duration of events, but it does not include information about the task. For instance:<br>
><br>
> 11263053713217, 11263053716617, 3400<br>
> 11263055442821, 11263055444997, 2176<br>
><br>
> Which task was executing?<br>
<br>
</span>The PID of the currently scheduled task (albeit truncated to 16 bits) is recorded by Feather-Trace,<br>
<br>
<a href="https://github.com/LITMUS-RT/litmus-rt/blob/4acc377593580e7d04ad8b42b258e8c2b39030ee/include/litmus/trace.h#L21" rel="noreferrer" target="_blank">https://github.com/LITMUS-RT/<wbr>litmus-rt/blob/<wbr>4acc377593580e7d04ad8b42b258e8<wbr>c2b39030ee/include/litmus/<wbr>trace.h#L21</a><br>
<br>
but this information is not printed by ft2csv.<br>
<br>
<a href="https://github.com/LITMUS-RT/feather-trace-tools/blob/0a9701c7be2ef0256bb434d01a9261d9b345bdc6/src/ft2csv.c#L242-L248" rel="noreferrer" target="_blank">https://github.com/LITMUS-RT/<wbr>feather-trace-tools/blob/<wbr>0a9701c7be2ef0256bb434d01a9261<wbr>d9b345bdc6/src/ft2csv.c#L242-<wbr>L248</a><br>
<br>
So the information is available, but you’ll need to modify the tool to extract it. Patches welcome. ;-)<br>
<span class=""><br>
> The stdump tool produces an output like this:<br>
><br>
> [ 7221140] RELEASE 19373/10 on CPU 0 7221160.00ms<br>
> [ 7221142] SWITCH_FROM 19373/7 on CPU 0<br>
> [ 7221142] COMPLETION 19373/7 on CPU 0<br>
> [ 7221142] SWITCH_TO 19375/3 on CPU 0<br>
> [ 7221144] RELEASE 19366/39 on CPU 0 7221148.00ms<br>
> [ 7221146] RELEASE 19385/76 on CPU 0 7221148.00ms<br>
> [ 7221148] RELEASE 19385/77 on CPU 0 7221150.00ms<br>
><br>
> However, what is the meaning of the first, third, and last columns?<br>
<br>
</span>The stdump tool really is a debugging aid, not so much a real tracing tool… I wouldn’t use it to extract useful information. Anyway:<br>
<br>
First column: the time, rounded to milliseconds.<br>
<br>
<a href="https://github.com/LITMUS-RT/feather-trace-tools/blob/0a9701c7be2ef0256bb434d01a9261d9b345bdc6/src/stdump.c#L81" rel="noreferrer" target="_blank">https://github.com/LITMUS-RT/<wbr>feather-trace-tools/blob/<wbr>0a9701c7be2ef0256bb434d01a9261<wbr>d9b345bdc6/src/stdump.c#L81</a><br>
<br>
Third column: PID/job-id<br>
<br>
<a href="https://github.com/LITMUS-RT/feather-trace-tools/blob/0a9701c7be2ef0256bb434d01a9261d9b345bdc6/src/util.c#L67-L70" rel="noreferrer" target="_blank">https://github.com/LITMUS-RT/<wbr>feather-trace-tools/blob/<wbr>0a9701c7be2ef0256bb434d01a9261<wbr>d9b345bdc6/src/util.c#L67-L70</a><br>
<br>
Last columns: event-specific information.<br>
<br>
<a href="https://github.com/LITMUS-RT/feather-trace-tools/blob/0a9701c7be2ef0256bb434d01a9261d9b345bdc6/src/util.c#L110-L126" rel="noreferrer" target="_blank">https://github.com/LITMUS-RT/<wbr>feather-trace-tools/blob/<wbr>0a9701c7be2ef0256bb434d01a9261<wbr>d9b345bdc6/src/util.c#L110-<wbr>L126</a><br>
<span class=""><br>
<br>
> Ideally, I would like to have something like this in the output, considering all CPUs (not having a separate log for each of them):<br>
<br>
</span>First of all, unless you are debugging the tracing subsystem itself, you should *never* work on the individual per-CPU trace files.<br>
<br>
Instead, just pass *all* the per-CPU files as command line arguments when invoking st-dump or st-draw, and they will do the merge of the timelines for you. Internally, all events are inserted into a min-heap, and then they are processed in order or increasing timestamps.<br>
<br>
In particular, when looking at a global scheduler like GSN-EDF, it doesn’t even make sense to look at individual cores, and even under partitioned schedulers like PSN-EDF, P-FP, or P-RES, there is no guarantee that all events relevant to a given core will be in the core’s trace file. For example, wake-up events are recorded on the core where the wake-up occurs, not on the core to which the woken-up task has been assigned. So always process all per-CPU files together to make sure that you are not missing any relevant events.<br>
<span class=""><br>
> task ID, CPU ID, event name or ID, timestamp<br>
><br>
> Is there an easy way to provide such an output using one of the feather-trace tools?<br>
<br>
</span>Yes and no. There is no ready-made tool that will give you this, but it’s fairly easy to come up with one. Have a look at the Python interface to sched_trace data. (Alternatively, you could hack st-dump to give you that output, too, but I think the Python interface is nicer to work with.)<br>
<br>
<a href="https://github.com/LITMUS-RT/feather-trace-tools/tree/master/sched_trace" rel="noreferrer" target="_blank">https://github.com/LITMUS-RT/<wbr>feather-trace-tools/tree/<wbr>master/sched_trace</a><br>
<br>
First, load all the trace files using the SchedTrace class. The st-draw utility can serve as guide for how to use it.<br>
<br>
<a href="https://github.com/LITMUS-RT/feather-trace-tools/blob/0a9701c7be2ef0256bb434d01a9261d9b345bdc6/st-draw#L86-L91" rel="noreferrer" target="_blank">https://github.com/LITMUS-RT/<wbr>feather-trace-tools/blob/<wbr>0a9701c7be2ef0256bb434d01a9261<wbr>d9b345bdc6/st-draw#L86-L91</a><br>
<br>
Second, you can then use SchedTrace::events_of_type_<wbr>chrono() to iterate over all events of a given type in order of increasing timestamps.<br>
<br>
<a href="https://github.com/LITMUS-RT/feather-trace-tools/blob/0a9701c7be2ef0256bb434d01a9261d9b345bdc6/sched_trace/__init__.py#L84-L94" rel="noreferrer" target="_blank">https://github.com/LITMUS-RT/<wbr>feather-trace-tools/blob/<wbr>0a9701c7be2ef0256bb434d01a9261<wbr>d9b345bdc6/sched_trace/__init_<wbr>_.py#L84-L94</a><br>
<br>
Alternatively, if you are interested in all events, you can add a method like events_of_type_chrono() that internally does not call events_of_type() to filter unwanted events.<br>
<br>
When iterating over the events, refer to the unpack() logic to understand the tuples describing the events.<br>
<br>
<a href="https://github.com/LITMUS-RT/feather-trace-tools/blob/0a9701c7be2ef0256bb434d01a9261d9b345bdc6/sched_trace/format.py#L115-L118" rel="noreferrer" target="_blank">https://github.com/LITMUS-RT/<wbr>feather-trace-tools/blob/<wbr>0a9701c7be2ef0256bb434d01a9261<wbr>d9b345bdc6/sched_trace/format.<wbr>py#L115-L118</a><br>
<br>
The reason why we are using basic tuples (rather than some nice class abstraction) is that object creating is really quite slow in Python, so with millions of events in a file, it’s much faster to iterate using raw tuples.<br>
<br>
I hope this points you in the right direction. Again, patches extending the Python interface and adding a tool to produce the desired CSV-friendly output would be very welcome…<br>
<br>
Let us know if you have a questions or run into any problems.<br>
<br>
Cheers,<br>
Björn<br>
<br>
<br>
______________________________<wbr>_________________<br>
litmus-dev mailing list<br>
<a href="mailto:litmus-dev@lists.litmus-rt.org">litmus-dev@lists.litmus-rt.org</a><br>
<a href="https://lists.litmus-rt.org/listinfo/litmus-dev" rel="noreferrer" target="_blank">https://lists.litmus-rt.org/<wbr>listinfo/litmus-dev</a><br>
</blockquote></div><br></div>