[lttng-dev] faulty context for sched_stat_ tracepoints?

[Luetkebohle Ingo (CR/AEA2)]

Hi Mathieu,


thank you for the explanation!


This would suggest that the problem only occurs for scheduler events, because only then we have this situation that the currently scheduled task is not the one that the tracepoint relates that. Am I interpreting that correctly?


If yes, this would certainly ease my concerns, because for most tracepoints, I get the expected behavior. I can also get the information that I want right now by looking at comm instead.


However, for future development of LTTng: Isn't the intuitive context that of the *tracepoint*? In other words, isn't it wrong to always use the currently scheduled task?


cheers,


Dr. Ingo Lütkebohle
Software Design and Analysis -- Robotics (CR/AEA2)

Tel. +49(711)811-12248
Fax +49(711)811-0
Mobil +49-1525-8813417
Ingo.Luetkebohle at de.bosch.com<mailto:Ingo.Luetkebohle at de.bosch.com>
________________________________
Von: Mathieu Desnoyers <mathieu.desnoyers at efficios.com>
Gesendet: Donnerstag, 26. November 2015 16:21
An: Luetkebohle Ingo (CR/AEA2)
Cc: lttng-dev
Betreff: Re: [lttng-dev] faulty context for sched_stat_ tracepoints?

---- On Nov 26, 2015, at 7:34 AM, Luetkebohle Ingo (CR/AEA2) <Ingo.Luetkebohle at de.bosch.com> wrote:
Hi,

I noticed that the "procname" and "tid" *context* variables can differ from the "comm" and "tid" variables of the sched_stat_-tracepoints (e.g., for sched_stat_runtime).

For example, see the following two outputs:
[15:49:33.674072890] (+0.000029771) rng2070 sched_stat_sleep: { cpu_id = 4 }, { pid = 26974, procname = "amcl", tid = 26975 }, { comm = "lttng-sessiond", tid = 798, delay = 194122524 }
[15:49:33.722894563] (+0.000004851) rng2070 sched_stat_sleep: { cpu_id = 0 }, { pid = 0, procname = "swapper/0", tid = 0 }, { comm = "amcl", tid = 27078, delay = 10043658 }

In both cases, procname differs from comm.  I've looked at the kernel source code, and the "comm" variable is taken from task_struct.filename. Barring renames, this would be the correct one, so I'm assuming that the context is sometimes incorrect.

Now, for this particular case, I can take the correct variables from the tracepoint, but of course, this makes me worried that the context might also be wrong in other cases... Do you have any idea what could be going on here?

LTTng is Version 2.7.x+stable+bzr2948+pack17+201511192116~ubuntu14.04.1 and this is on a 3.19.0-33-generic kernel (btw, that's not the default kernel for Ubuntu 14.04, but the LTS vivid backport kernel).
Hi,

Looking at lttng-modules lttng-context-tid.c tid_record(), we see that it uses task_pid_nr(current).
It therefore gets the tid of the currently scheduled task. This is similar for procname.

Now looking at the Linux kernel kernel/sched/fair.c: enqueue_sleeper(), which calls
trace_sched_stat_sleep(), we see that it passes "tsk" as parameter to the tracepoint.
Already here, nothing seems to ensure that "tsk" is the currently scheduled task. It's
rather a task that is being put to sleep. Looking at the callers of enqueue_sleeper(),
we can understand that the current task is first scheduled out before being enqueued
as a sleeper. This is why, when we hit the sched_stat_sleep tracepoint, the current
task is not "tsk", which explains the difference between the context information
and the tracepoint payload information: they really target different tasks.

Does this help solve your concerns ?

Thanks,

Mathieu


Mit freundlichen Grüßen / Best regards

Ingo Luetkebohle

Application Software (CR/AEA2)
Tel. +49(711)811-12248 | Fax +49(711)811-0 | Ingo.Luetkebohle at de.bosch.com<mailto:Ingo.Luetkebohle at de.bosch.com>



_______________________________________________
lttng-dev mailing list
lttng-dev at lists.lttng.org
http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

--
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20151126/a4985e4b/attachment.html>