[lttng-dev] faulty context for sched_stat_ tracepoints?

[Mathieu Desnoyers]

---- 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

> _______________________________________________
> 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/3fbd969a/attachment-0001.html>