make TGID available also in binary ring buffer?

make TGID available also in binary ring buffer?

[Claudio]

Hello all,

I am currently facing the issue of having to efficiently read the events
from a user-space application for tracing for programmatic use in automotive
(AUTOSAR AP).

It is for programmatically reacting to events on the system,
and I am currently using the trace_pipe_raw to do that, to reduce the
overhead compared with parsing the textual output of trace_pipe.

After merging the sorted streams from all cpus, in order to reconstruct
the task state, we are still way more CPU-efficient compared with using the
textual output.

I would like to make use of the implemented support for recording tgids,

commit d914ba37d714 ("tracing: Add support for recording tgid of tasks")
commit 441dae8f2f29 ("tracing: Add support for display of tgid in trace output")

but it seems to me that, while for COMM recording there is explicit support in
the binary events for the information, it seems that tgid is not stored in the
binary format.

Is such an extension of the binary format a possibility for sched-class
events, that takes into account backward compatibility, or is there some
better way to do it? Is this problem addressed by libtracevent / trace-cmd?

Currently I was thinking to look into the NETLINK interface to get the task
information, however the issue is the race condition between the time of
tracing and the time of reading the trace, to be fully correct, but if
nothing else is possible I will have to accept the compromise.

Thank you for any hints on this.

Ciao,

Claudio

Re: make TGID available also in binary ring buffer?

[Steven Rostedt]

On Mon, 4 Mar 2019 11:01:39 +0100
Claudio <claudio.fontana@gliwa.com> wrote:

> Hello all,
> 
> I am currently facing the issue of having to efficiently read the events
> from a user-space application for tracing for programmatic use in automotive
> (AUTOSAR AP).
> 
> It is for programmatically reacting to events on the system,
> and I am currently using the trace_pipe_raw to do that, to reduce the
> overhead compared with parsing the textual output of trace_pipe.
> 
> After merging the sorted streams from all cpus, in order to reconstruct
> the task state, we are still way more CPU-efficient compared with using the
> textual output.
> 
> I would like to make use of the implemented support for recording tgids,
> 
> commit d914ba37d714 ("tracing: Add support for recording tgid of tasks")
> commit 441dae8f2f29 ("tracing: Add support for display of tgid in trace output")
> 
> but it seems to me that, while for COMM recording there is explicit support in
> the binary events for the information, it seems that tgid is not stored in the
> binary format.
> 
> Is such an extension of the binary format a possibility for sched-class
> events, that takes into account backward compatibility, or is there some
> better way to do it? Is this problem addressed by libtracevent / trace-cmd?
> 
> Currently I was thinking to look into the NETLINK interface to get the task
> information, however the issue is the race condition between the time of
> tracing and the time of reading the trace, to be fully correct, but if
> nothing else is possible I will have to accept the compromise.
> 
> Thank you for any hints on this.

It looks to be outputted into /sys/kernel/debug/tracing/saved_tgids

Interesting, we should probably save that in trace-cmd as well.

-- Steve

Re: make TGID available also in binary ring buffer?

[Claudio]

On 3/4/19 7:51 PM, Steven Rostedt wrote:
> On Mon, 4 Mar 2019 11:01:39 +0100
> Claudio <claudio.fontana@gliwa.com> wrote:
> 
>> Hello all,
>>
>> I am currently facing the issue of having to efficiently read the events
>> from a user-space application for tracing for programmatic use in automotive
>> (AUTOSAR AP).
>>
>> It is for programmatically reacting to events on the system,
>> and I am currently using the trace_pipe_raw to do that, to reduce the
>> overhead compared with parsing the textual output of trace_pipe.
>>
>> After merging the sorted streams from all cpus, in order to reconstruct
>> the task state, we are still way more CPU-efficient compared with using the
>> textual output.
>>
>> I would like to make use of the implemented support for recording tgids,
>>
>> commit d914ba37d714 ("tracing: Add support for recording tgid of tasks")
>> commit 441dae8f2f29 ("tracing: Add support for display of tgid in trace output")
>>
>> but it seems to me that, while for COMM recording there is explicit support in
>> the binary events for the information, it seems that tgid is not stored in the
>> binary format.
>>
>> Is such an extension of the binary format a possibility for sched-class
>> events, that takes into account backward compatibility, or is there some
>> better way to do it? Is this problem addressed by libtracevent / trace-cmd?
>>
>> Currently I was thinking to look into the NETLINK interface to get the task
>> information, however the issue is the race condition between the time of
>> tracing and the time of reading the trace, to be fully correct, but if
>> nothing else is possible I will have to accept the compromise.
>>
>> Thank you for any hints on this.
> 
> It looks to be outputted into /sys/kernel/debug/tracing/saved_tgids
> 
> Interesting, we should probably save that in trace-cmd as well.
> 
> -- Steve
> 

Hi Steve,

I have two questions regarding saved_tgids which are currently blocking and confusing me.

1) Are the saved_tgids not present in a tracing instance?
I am currently interacting with ftrace from the application doing everything in an instance,

tracefs on /usr/local/var/run/T1/tracing type tracefs (rw,relatime)

but the saved_tgids is not present in my instance directory.

2) Which state does "saved_tgids" represent, ie when is it updated?

The ftrace.rst doc says at each context switch, but wouldn't sched_process_fork / sched_process_free tracepoints be a better place to update?

When I read an event for a new process or thread (sched_process_fork),
I need to know if it is a new thread or a new process at that time, and collect the tgid of the child.

How can I get that information, if the update is done only at the time of the first "child" context-switch?

3) Is the saved_tgids map in sync with the reader of trace_pipe_raw,
so that when reading an event from the pipe, the saved_tgids represent the particular state of the tid to tgid maps at the timestamp indicated in the event?

Or is the saved_tgids map updated asynchronously with the reader?

Thank you for any advice on this..

Ciao,

Claudio

Re: make TGID available also in binary ring buffer?

[Steven Rostedt]

On Wed, 13 Mar 2019 09:26:33 +0100
Claudio <claudio.fontana@gliwa.com> wrote:


> 1) Are the saved_tgids not present in a tracing instance?
> I am currently interacting with ftrace from the application doing everything in an instance,

Currently save_cmdlines and saved_tgids are only in the top level
tracing directory, and are global for all tracing.

Thinking about this a bit more, it does make sense to make this an
instance file, as we don't want instance tracing to remove the top
level cached cmdlines.

> 
> tracefs on /usr/local/var/run/T1/tracing type tracefs (rw,relatime)
> 
> but the saved_tgids is not present in my instance directory.
> 
> 2) Which state does "saved_tgids" represent, ie when is it updated?
> 
> The ftrace.rst doc says at each context switch, but wouldn't sched_process_fork / sched_process_free tracepoints be a better place to update?

Well, forks and free can happen after tracing, and they are only
updated during the trace. We mostly want to see the tasks when they
run, and the sched_switch is the best place to save them.

> 
> When I read an event for a new process or thread (sched_process_fork),
> I need to know if it is a new thread or a new process at that time, and collect the tgid of the child.

You are reading this at the time of tracing?

> 
> How can I get that information, if the update is done only at the time of the first "child" context-switch?
> 
> 3) Is the saved_tgids map in sync with the reader of trace_pipe_raw,
> so that when reading an event from the pipe, the saved_tgids represent the particular state of the tid to tgid maps at the timestamp indicated in the event?

Currently, it's only taken at the end of the trace.

-- Steve

> 
> Or is the saved_tgids map updated asynchronously with the reader?
> 
> Thank you for any advice on this..
> 
> Ciao,
> 
> Claudio

Re: make TGID available also in binary ring buffer?

[Claudio]

Hi Steve,

thank you for your answer,

On 3/13/19 2:44 PM, Steven Rostedt wrote:
> On Wed, 13 Mar 2019 09:26:33 +0100
> Claudio <claudio.fontana@gliwa.com> wrote:
> 
> 
>> 1) Are the saved_tgids not present in a tracing instance?
>> I am currently interacting with ftrace from the application doing everything in an instance,
> 
> Currently save_cmdlines and saved_tgids are only in the top level
> tracing directory, and are global for all tracing.
> 
> Thinking about this a bit more, it does make sense to make this an
> instance file, as we don't want instance tracing to remove the top
> level cached cmdlines.
> 
>>
>> tracefs on /usr/local/var/run/T1/tracing type tracefs (rw,relatime)
>>
>> but the saved_tgids is not present in my instance directory.
>>
>> 2) Which state does "saved_tgids" represent, ie when is it updated?
>>
>> The ftrace.rst doc says at each context switch, but wouldn't sched_process_fork / sched_process_free tracepoints be a better place to update?
> 
> Well, forks and free can happen after tracing, and they are only
> updated during the trace. We mostly want to see the tasks when they
> run, and the sched_switch is the best place to save them.
> 
>>
>> When I read an event for a new process or thread (sched_process_fork),
>> I need to know if it is a new thread or a new process at that time, and collect the tgid of the child.
> 
> You are reading this at the time of tracing?

Yes, my requirements are for live tracing of the low level events, and correlation of the events from all cores, in order to be able to immediately respond to the events from the tracing application.

Tracing is expected to be always on in the system (no expected trace-first/analyze later pattern - everything related to the analysis of the events is automated and occurs at runtime).

This works fine for the real time timing analysis at the thread level, but for the process level I need to know the tgid of the thread at the time I see the event.
 
>>
>> How can I get that information, if the update is done only at the time of the first "child" context-switch?
>>
>> 3) Is the saved_tgids map in sync with the reader of trace_pipe_raw,
>> so that when reading an event from the pipe, the saved_tgids represent the particular state of the tid to tgid maps at the timestamp indicated in the event?
> 
> Currently, it's only taken at the end of the trace.

I wonder what the concept of the "end of the trace" is..

> 
> -- Steve

Thank you very much,

Claudio

Re: make TGID available also in binary ring buffer?

[Steven Rostedt]

On Wed, 13 Mar 2019 15:03:35 +0100
Claudio <claudio.fontana@gliwa.com> wrote:


> >>
> >> When I read an event for a new process or thread
> >> (sched_process_fork), I need to know if it is a new thread or a
> >> new process at that time, and collect the tgid of the child.  
> > 
> > You are reading this at the time of tracing?  
> 
> Yes, my requirements are for live tracing of the low level events,
> and correlation of the events from all cores, in order to be able to
> immediately respond to the events from the tracing application.
> 
> Tracing is expected to be always on in the system (no expected
> trace-first/analyze later pattern - everything related to the
> analysis of the events is automated and occurs at runtime).

You could add a kprobe to find out the tgid as well.

> 
> This works fine for the real time timing analysis at the thread
> level, but for the process level I need to know the tgid of the
> thread at the time I see the event. 
> >>
> >> How can I get that information, if the update is done only at the
> >> time of the first "child" context-switch?
> >>
> >> 3) Is the saved_tgids map in sync with the reader of
> >> trace_pipe_raw, so that when reading an event from the pipe, the
> >> saved_tgids represent the particular state of the tid to tgid maps
> >> at the timestamp indicated in the event?  
> > 
> > Currently, it's only taken at the end of the trace.  
> 
> I wonder what the concept of the "end of the trace" is..


I meant for "trace-cmd record", the saved_cmdlines are stored when the
tracing is finished, not during the trace. But the saved_cmdlines is
updated at each sched_switch, and so is the tgid.

Now, we could add that info to the fork part as well.

-- Steve

Re: make TGID available also in binary ring buffer?

[Claudio]

Hi Steve,

On 3/13/19 3:50 PM, Steven Rostedt wrote:
> On Wed, 13 Mar 2019 15:03:35 +0100
> Claudio <claudio.fontana@gliwa.com> wrote:
> 
> 
>>>>
>>>> When I read an event for a new process or thread
>>>> (sched_process_fork), I need to know if it is a new thread or a
>>>> new process at that time, and collect the tgid of the child.  
>>>
>>> You are reading this at the time of tracing?  
>>
>> Yes, my requirements are for live tracing of the low level events,
>> and correlation of the events from all cores, in order to be able to
>> immediately respond to the events from the tracing application.
>>
>> Tracing is expected to be always on in the system (no expected
>> trace-first/analyze later pattern - everything related to the
>> analysis of the events is automated and occurs at runtime).
> 
> You could add a kprobe to find out the tgid as well.

I think I am going to try this next.


>>
>> This works fine for the real time timing analysis at the thread
>> level, but for the process level I need to know the tgid of the
>> thread at the time I see the event. 
>>>>
>>>> How can I get that information, if the update is done only at the
>>>> time of the first "child" context-switch?
>>>>
>>>> 3) Is the saved_tgids map in sync with the reader of
>>>> trace_pipe_raw, so that when reading an event from the pipe, the
>>>> saved_tgids represent the particular state of the tid to tgid maps
>>>> at the timestamp indicated in the event?  
>>>
>>> Currently, it's only taken at the end of the trace.  
>>
>> I wonder what the concept of the "end of the trace" is..
> 
> 
> I meant for "trace-cmd record", the saved_cmdlines are stored when the
> tracing is finished, not during the trace. But the saved_cmdlines is
> updated at each sched_switch, and so is the tgid.
> 
> Now, we could add that info to the fork part as well.
> 
> -- Steve
> 

I have experimented with mainline, and then with mainline plus a patch to add the info for fork as well like this:

diff --git a/kernel/trace/trace_sched_switch.c b/kernel/trace/trace_sched_switch.c
index e288168..c5339ed 100644
--- a/kernel/trace/trace_sched_switch.c
+++ b/kernel/trace/trace_sched_switch.c
@@ -47,6 +47,20 @@ probe_sched_wakeup(void *ignore, struct task_struct *wakee)
 	tracing_record_taskinfo(current, flags);
 }
 
+static void
+probe_sched_fork(void *ignore,
+		 struct task_struct *parent, struct task_struct *child)
+{
+	int flags;
+
+	flags = (RECORD_TGID * !!sched_tgid_ref) +
+		(RECORD_CMDLINE * !!sched_cmdline_ref);
+
+	if (!flags)
+		return;
+	tracing_record_taskinfo(child, flags);
+}
+
 static int tracing_sched_register(void)
 {
 	int ret;
@@ -72,7 +86,16 @@ static int tracing_sched_register(void)
 		goto fail_deprobe_wake_new;
 	}
 
+	ret = register_trace_sched_process_fork(probe_sched_fork, NULL);
+	if (ret) {
+		pr_info("sched trace: Couldn't activate tracepoint"
+			" probe to kernel_sched_process_fork\n");
+		goto fail_deprobe_switch;
+	}
+
 	return ret;
+fail_deprobe_switch:
+	unregister_trace_sched_switch(probe_sched_switch, NULL);
 fail_deprobe_wake_new:
 	unregister_trace_sched_wakeup_new(probe_sched_wakeup, NULL);
 fail_deprobe:
@@ -82,6 +105,7 @@ static int tracing_sched_register(void)
 
 static void tracing_sched_unregister(void)
 {
+	unregister_trace_sched_process_fork(probe_sched_fork, NULL);
 	unregister_trace_sched_switch(probe_sched_switch, NULL);
 	unregister_trace_sched_wakeup_new(probe_sched_wakeup, NULL);
 	unregister_trace_sched_wakeup(probe_sched_wakeup, NULL);


--

It seems to work, but the model seems not to apply very well to my use case.

saved_tgids cannot be reset, not even by disabling tracing completely

echo 0 > tracing_on

or 

echo 0 > options/record-tgids

and the list just keeps growing, no entries are ever removed when tasks are destroyed etc,
so my lookups become more and more expensive as the list grows.
I don't think this is suited to be looked up frequently for my tracing scenario.

Next I will experiment with:

1) kprobes, trying to generate an event before every sched class event carrying the tid to tgid mapping.

2) if everything fails, revert to use /proc/PID/stat, which however can be slow and racy if the process does not exist anymore when I read back the ftrace buffers.

Thanks & ciao,

Claudio

Re: make TGID available also in binary ring buffer?

[Steven Rostedt]

On Thu, 14 Mar 2019 17:06:11 +0100
Claudio <claudio.fontana@gliwa.com> wrote:

> Hi Steve,
> 
> I have experimented with mainline, and then with mainline plus a patch to add the info for fork as well like this:
> 
> diff --git a/kernel/trace/trace_sched_switch.c b/kernel/trace/trace_sched_switch.c
> index e288168..c5339ed 100644
> --- a/kernel/trace/trace_sched_switch.c
> +++ b/kernel/trace/trace_sched_switch.c
> @@ -47,6 +47,20 @@ probe_sched_wakeup(void *ignore, struct task_struct *wakee)
>  	tracing_record_taskinfo(current, flags);
>  }
>  
> +static void
> +probe_sched_fork(void *ignore,
> +		 struct task_struct *parent, struct task_struct *child)
> +{
> +	int flags;
> +
> +	flags = (RECORD_TGID * !!sched_tgid_ref) +
> +		(RECORD_CMDLINE * !!sched_cmdline_ref);
> +
> +	if (!flags)
> +		return;
> +	tracing_record_taskinfo(child, flags);
> +}
> +
>  static int tracing_sched_register(void)
>  {
>  	int ret;
> @@ -72,7 +86,16 @@ static int tracing_sched_register(void)
>  		goto fail_deprobe_wake_new;
>  	}
>  
> +	ret = register_trace_sched_process_fork(probe_sched_fork, NULL);
> +	if (ret) {
> +		pr_info("sched trace: Couldn't activate tracepoint"
> +			" probe to kernel_sched_process_fork\n");
> +		goto fail_deprobe_switch;
> +	}
> +
>  	return ret;
> +fail_deprobe_switch:
> +	unregister_trace_sched_switch(probe_sched_switch, NULL);
>  fail_deprobe_wake_new:
>  	unregister_trace_sched_wakeup_new(probe_sched_wakeup, NULL);
>  fail_deprobe:
> @@ -82,6 +105,7 @@ static int tracing_sched_register(void)
>  
>  static void tracing_sched_unregister(void)
>  {
> +	unregister_trace_sched_process_fork(probe_sched_fork, NULL);
>  	unregister_trace_sched_switch(probe_sched_switch, NULL);
>  	unregister_trace_sched_wakeup_new(probe_sched_wakeup, NULL);
>  	unregister_trace_sched_wakeup(probe_sched_wakeup, NULL);
> 
> 
> --
> 
> It seems to work, but the model seems not to apply very well to my use case.
> 
> saved_tgids cannot be reset, not even by disabling tracing completely
> 
> echo 0 > tracing_on
> 
> or 
> 
> echo 0 > options/record-tgids
> 
> and the list just keeps growing, no entries are ever removed when tasks are destroyed etc,
> so my lookups become more and more expensive as the list grows.
> I don't think this is suited to be looked up frequently for my tracing scenario.
> 

It shouldn't grow when you disable tracing though.

Hmm, we could add a reset if one writes to the saved_* files.

> Next I will experiment with:
> 
> 1) kprobes, trying to generate an event before every sched class event carrying the tid to tgid mapping.

Just plop a kprobe on top of __schedule()

-- Steve

> 
> 2) if everything fails, revert to use /proc/PID/stat, which however can be slow and racy if the process does not exist anymore when I read back the ftrace buffers.
> 
> Thanks & ciao,
> 
> Claudio

Re: make TGID available also in binary ring buffer?

[Claudio]

Evening Steve,

On 3/14/19 7:20 PM, Steven Rostedt wrote:
> On Thu, 14 Mar 2019 17:06:11 +0100
> Claudio <claudio.fontana@gliwa.com> wrote:
> 
>> Hi Steve,
>>
>> I have experimented with mainline, and then with mainline plus a patch to add the info for fork as well like this:
>>
>> diff --git a/kernel/trace/trace_sched_switch.c b/kernel/trace/trace_sched_switch.c
>> index e288168..c5339ed 100644
>> --- a/kernel/trace/trace_sched_switch.c
>> +++ b/kernel/trace/trace_sched_switch.c
>> @@ -47,6 +47,20 @@ probe_sched_wakeup(void *ignore, struct task_struct *wakee)
>>  	tracing_record_taskinfo(current, flags);
>>  }
>>  
>> +static void
>> +probe_sched_fork(void *ignore,
>> +		 struct task_struct *parent, struct task_struct *child)
>> +{
>> +	int flags;
>> +
>> +	flags = (RECORD_TGID * !!sched_tgid_ref) +
>> +		(RECORD_CMDLINE * !!sched_cmdline_ref);
>> +
>> +	if (!flags)
>> +		return;
>> +	tracing_record_taskinfo(child, flags);
>> +}
>> +
>>  static int tracing_sched_register(void)
>>  {
>>  	int ret;
>> @@ -72,7 +86,16 @@ static int tracing_sched_register(void)
>>  		goto fail_deprobe_wake_new;
>>  	}
>>  
>> +	ret = register_trace_sched_process_fork(probe_sched_fork, NULL);
>> +	if (ret) {
>> +		pr_info("sched trace: Couldn't activate tracepoint"
>> +			" probe to kernel_sched_process_fork\n");
>> +		goto fail_deprobe_switch;
>> +	}
>> +
>>  	return ret;
>> +fail_deprobe_switch:
>> +	unregister_trace_sched_switch(probe_sched_switch, NULL);
>>  fail_deprobe_wake_new:
>>  	unregister_trace_sched_wakeup_new(probe_sched_wakeup, NULL);
>>  fail_deprobe:
>> @@ -82,6 +105,7 @@ static int tracing_sched_register(void)
>>  
>>  static void tracing_sched_unregister(void)
>>  {
>> +	unregister_trace_sched_process_fork(probe_sched_fork, NULL);
>>  	unregister_trace_sched_switch(probe_sched_switch, NULL);
>>  	unregister_trace_sched_wakeup_new(probe_sched_wakeup, NULL);
>>  	unregister_trace_sched_wakeup(probe_sched_wakeup, NULL);
>>
>>
>> --
>>
>> It seems to work, but the model seems not to apply very well to my use case.
>>
>> saved_tgids cannot be reset, not even by disabling tracing completely
>>
>> echo 0 > tracing_on
>>
>> or 
>>
>> echo 0 > options/record-tgids
>>
>> and the list just keeps growing, no entries are ever removed when tasks are destroyed etc,
>> so my lookups become more and more expensive as the list grows.
>> I don't think this is suited to be looked up frequently for my tracing scenario.
>>
> 
> It shouldn't grow when you disable tracing though.
> 
> Hmm, we could add a reset if one writes to the saved_* files.
> 
>> Next I will experiment with:
>>
>> 1) kprobes, trying to generate an event before every sched class event carrying the tid to tgid mapping.
> 
> Just plop a kprobe on top of __schedule()
> 
> -- Steve

I seem to need a few of those; but it works.
However the userspace application becomes very tied to the specific kernel version and arch,
or am I missing something? Maybe there is something less tied to the kernel than the following example?

echo 'p:kprobes/wakeup_tgid ttwu_do_wakeup arg1=+2220($arg2):x32' > kprobe_events

>>
>> 2) if everything fails, revert to use /proc/PID/stat, which however can be slow and racy if the process does not exist anymore when I read back the ftrace buffers.

indeed it breaks easiy; If I just had a tgid inside the sched events format..

Anyway, will pick it up tomorrow.

Thank you, ciao,

Claudio