[LITMUS^RT] Printing per task event information

Wed Dec 20 19:52:03 CET 2017

Hi Björn,

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.

Best
Giovani

On Tue, Dec 19, 2017 at 7:00 PM, Björn Brandenburg <bbb at mpi-sws.org> wrote:

> Dear Giovani,
>
> > On 18. Dec 2017, at 19:32, Giovani Gracioli <giovanig at gmail.com> wrote:
> >
> > I would like to print per task event information, such as the timestamp
> a task release was performed, context switching, etc.
> >
> > 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:
> >
> > 11263053713217, 11263053716617, 3400
> > 11263055442821, 11263055444997, 2176
> >
> > Which task was executing?
>
> The PID of the currently scheduled task (albeit truncated to 16 bits) is
> recorded by Feather-Trace,
>
>         https://github.com/LITMUS-RT/litmus-rt/blob/
> 4acc377593580e7d04ad8b42b258e8c2b39030ee/include/litmus/trace.h#L21
>
> but this information is not printed by ft2csv.
>
>         https://github.com/LITMUS-RT/feather-trace-tools/blob/
> 0a9701c7be2ef0256bb434d01a9261d9b345bdc6/src/ft2csv.c#L242-L248
>
> So the information is available, but you’ll need to modify the tool to
> extract it.  Patches welcome. ;-)
>
> > The stdump tool produces an output like this:
> >
> > [   7221140] RELEASE        19373/10    on CPU  0 7221160.00ms
> > [   7221142] SWITCH_FROM    19373/7     on CPU  0
> > [   7221142] COMPLETION     19373/7     on CPU  0
> > [   7221142] SWITCH_TO      19375/3     on CPU  0
> > [   7221144] RELEASE        19366/39    on CPU  0 7221148.00ms
> > [   7221146] RELEASE        19385/76    on CPU  0 7221148.00ms
> > [   7221148] RELEASE        19385/77    on CPU  0 7221150.00ms
> >
> > However, what is the meaning of the first, third, and last columns?
>
> 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:
>
> First column: the time, rounded to milliseconds.
>
>         https://github.com/LITMUS-RT/feather-trace-tools/blob/
> 0a9701c7be2ef0256bb434d01a9261d9b345bdc6/src/stdump.c#L81
>
> Third column: PID/job-id
>
>         https://github.com/LITMUS-RT/feather-trace-tools/blob/
> 0a9701c7be2ef0256bb434d01a9261d9b345bdc6/src/util.c#L67-L70
>
> Last columns: event-specific information.
>
>         https://github.com/LITMUS-RT/feather-trace-tools/blob/
> 0a9701c7be2ef0256bb434d01a9261d9b345bdc6/src/util.c#L110-L126
>
>
> > Ideally, I would like to have something like this in the output,
> considering all CPUs (not having a separate log for each of them):
>
> First of all, unless you are debugging the tracing subsystem itself, you
> should *never* work on the individual per-CPU trace files.
>
> 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.
>
> 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.
>
> > task ID, CPU ID, event name or ID, timestamp
> >
> > Is there an easy way to provide such an output using one of the
> feather-trace tools?
>
> 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.)
>
>         https://github.com/LITMUS-RT/feather-trace-tools/tree/
> master/sched_trace
>
> First, load all the trace files using the SchedTrace class. The st-draw
> utility can serve as guide for how to use it.
>
>         https://github.com/LITMUS-RT/feather-trace-tools/blob/
> 0a9701c7be2ef0256bb434d01a9261d9b345bdc6/st-draw#L86-L91
>
> Second, you can then use SchedTrace::events_of_type_chrono() to iterate
> over all events of a given type in order of increasing timestamps.
>
>         https://github.com/LITMUS-RT/feather-trace-tools/blob/
> 0a9701c7be2ef0256bb434d01a9261d9b345bdc6/sched_trace/__init__.py#L84-L94
>
> 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.
>
> When iterating over the events, refer to the unpack() logic to understand
> the tuples describing the events.
>
>         https://github.com/LITMUS-RT/feather-trace-tools/blob/
> 0a9701c7be2ef0256bb434d01a9261d9b345bdc6/sched_trace/format.py#L115-L118
>
> 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.
>
> 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…
>
> Let us know if you have a questions or run into any problems.
>
> Cheers,
> Björn
>
>
> _______________________________________________
> litmus-dev mailing list
> litmus-dev at lists.litmus-rt.org
> https://lists.litmus-rt.org/listinfo/litmus-dev
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.litmus-rt.org/pipermail/litmus-dev/attachments/20171220/b36685ec/attachment.html>