[lttng-dev] Wrong procname if tracepoint is used before fork

[Jonathan Rajotte-Julien]

Hi,

On Tue, Apr 17, 2018 at 11:44:36AM +0000, negoita catalin via lttng-dev wrote:
> Hello,
> 
> Using the following test app, it can be seen that if tracepoint is used before fork(), procname value is wrong in babeltrace output live session.
> 
> Test application:

Please provide a link to the complete source code of this reproducer.

I was able to reproduce the behaviour described here but it would have been
faster if you linked a github repo or something like it. Something to keep in
mind for next time.

> 
> ...
> int main(int argc, char *argv[])
> {
> pid_t pid1;
> //tracepoint(hello_world, my_first_tracepoint, pid1, "Before fork Pid: ");
> pid1 = fork();

Side note, you will need to use the fork library utility when launching your
application. https://lttng.org/docs/v2.10/#doc-using-lttng-ust-with-daemons

The current issue is not related to this.

> if (pid1 == 0){
> 	prctl(PR_SET_NAME,"lttng-test-child\0", NULL, NULL, NULL);
> 	tracepoint(hello_world, my_first_tracepoint, 23, "in if");
> 	}
> else{
> 	prctl(PR_SET_NAME,"lttng-test-parent\0", NULL, NULL, NULL);
> 	tracepoint(hello_world, my_first_tracepoint, 23, "in else");
> 	}
> 
> tracepoint(hello_world, my_first_tracepoint, pid1, "Before sleep Pid: ");
> sleep(5);
> tracepoint(hello_world, my_first_tracepoint, pid1, "After sleep Pid: ");
> 
> 
> return 0;
> } 
> ...
> 
> Lttng session:
> 
> export TC=MySession
> lttng-sessiond &

Side note, doing this in a script is not a good idea since you do not have any
guarantee that lttng-sessiond is ready for further command. Either use the -b,
-d, -S argument. See man page of lttng-sessiond for more details.

> lttng create $TC --live 1000000 -U net://localhost:53000:53001/./
> lttng-relayd -C tcp://localhost:53000 -D tcp://localhost:53001 -L net://localhost:53002 -o /tmp/$TC &

The previous comment also applies to lttng-relayd

> lttng enable-channel chan1 -u --buffers-uid 
> lttng enable-event   -c chan1 --userspace hello_world:my_first_tracepoint
> lttng add-context --userspace -t vpid -t vtid -t procname
> lttng start $TC;

This behaviour is unrelated to lttng-relayd. It can be reproduced locally.

This cut down to:

lttng create
lttng enable-event --userspace hello_world:my_first_tracepoint
lttng add-context --userspace -t vpid -t vtid -t procname
lttng start
./run_app
lttng stop
lttng view
lttng destroy

> In the case of using  tracepoint before fork(), procname is incorrect:
> 
> [14:46:38.115359889] (+14.734455640) localhost hello_world:my_first_tracepoint: { cpu_id = 1 }, { vpid = 1858, vtid = 1858, procname = "tst_app" }, { my_string_field = "Before fork Pid: ", my_integer_field = 0 }
> [14:46:38.127171759] (+0.011811870) localhost hello_world:my_first_tracepoint: { cpu_id = 1 }, { vpid = 1858, vtid = 1858, procname = "tst_app" }, { my_string_field = "in else", my_integer_field = 23 }
> [14:46:38.127187119] (+0.000015360) localhost hello_world:my_first_tracepoint: { cpu_id = 1 }, { vpid = 1858, vtid = 1858, procname = "tst_app" }, { my_string_field = "Before sleep Pid: ", my_integer_field = 1861 }
> [14:46:38.127939761] (+0.000752642) localhost hello_world:my_first_tracepoint: { cpu_id = 1 }, { vpid = 1861, vtid = 1858, procname = "tst_app" }, { my_string_field = "in if", my_integer_field = 23 }
> [14:46:38.128078002] (+0.000138241) localhost hello_world:my_first_tracepoint: { cpu_id = 1 }, { vpid = 1861, vtid = 1858, procname = "tst_app" }, { my_string_field = "Before sleep Pid: ", my_integer_field = 0 }
> [14:46:43.139997392] (+5.011919390) localhost hello_world:my_first_tracepoint: { cpu_id = 1 }, { vpid = 1858, vtid = 1858, procname = "tst_app" }, { my_string_field = "After sleep Pid: ", my_integer_field = 1861 }
> [14:46:43.140473554] (+0.000476162) localhost hello_world:my_first_tracepoint: { cpu_id = 1 }, { vpid = 1861, vtid = 1858, procname = "tst_app" }, { my_string_field = "After sleep Pid: ", my_integer_field = 0 }

Based on the code found in liblttng-ust/lttng-context-procname.c [1] of lttng-ust,
the procname is cached on the first hit and never reseted even after fork. The
following comment indicate that an exec after fork will "clear" the cache. The
comment also hint as to why we see identical value for procname event if prctl is
used. The man page of lttng-ust also hint this limitation [2].

[1] https://github.com/lttng/lttng-ust/blob/master/liblttng-ust/lttng-context-procname.c
[2] https://lttng.org/man/3/lttng-ust/v2.10/#doc-_context_information 

The comment:

    /*                                                                     
     * We cache the result to ensure we don't trigger a system call for    
     * each event.                                                         
     * Upon exec, procname changes, but exec takes care of throwing away   
     * this cached version.                                                
     * The procname can also change by calling prctl(). The procname should
     * be set for a thread before the first event is logged within this    
     * thread.                                                             
     */                                                                    

The man page:

    Thread name, as set by exec(3) or prctl(2). It is recommended that programs
    set their thread name with prctl(2) before hitting the first tracepoint for
    that thread.

We could force a reset of the cache on fork as done with the vtid and ptid [3] but
this does not alleviate the prctl problem.

[2] https://github.com/lttng/lttng-ust/blob/6d9b54d845b08d54d3f483f1130b499516588db3/liblttng-ust/lttng-ust-comm.c#L2010

The real solution would probably be to "shim" prctl and catch the change of
procname.

Mathieu Desnoyers most probably have more insight regarding all this.

Cheers

-- 
Jonathan Rajotte-Julien
EfficiOS