[LITMUS^RT] Printing per task event information

[Björn Brandenburg]

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