Wrong procname if tracepoint is used before fork

Wrong procname if tracepoint is used before fork

[negoita catalin via lttng-dev]

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:

...
int main(int argc, char *argv[])
{
pid_t pid1;
//tracepoint(hello_world, my_first_tracepoint, pid1, "Before fork Pid: ");
pid1 = fork();
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 &
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 &
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;

Babeltrace:

babeltrace -i lttng-live net://localhost:53002/host/localhost/MySession

Output:

In the case of using without tracepoint before fork(), procname is correct:

[08:17:14.837643368] (+9.757680020) localhost hello_world:my_first_tracepoint: { cpu_id = 0 }, { vpid = 1305, vtid = 1305, procname = "lttng-test-pare" }, { my_string_field = "in else", my_integer_field = 23 }
[08:17:14.837720168] (+0.000076800) localhost hello_world:my_first_tracepoint: { cpu_id = 0 }, { vpid = 1305, vtid = 1305, procname = "lttng-test-pare" }, { my_string_field = "Before sleep Pid: ", my_integer_field = 1308 }
[08:17:14.838411370] (+0.000691202) localhost hello_world:my_first_tracepoint: { cpu_id = 1 }, { vpid = 1308, vtid = 1308, procname = "lttng-test-chil" }, { my_string_field = "in if", my_integer_field = 23 }
[08:17:14.838534250] (+0.000122880) localhost hello_world:my_first_tracepoint: { cpu_id = 1 }, { vpid = 1308, vtid = 1308, procname = "lttng-test-chil" }, { my_string_field = "Before sleep Pid: ", my_integer_field = 0 }
[08:17:19.851713164] (+5.013178914) localhost hello_world:my_first_tracepoint: { cpu_id = 1 }, { vpid = 1308, vtid = 1308, procname = "lttng-test-chil" }, { my_string_field = "After sleep Pid: ", my_integer_field = 0 }
[08:17:19.851713164] (+0.000000000) localhost hello_world:my_first_tracepoint: { cpu_id = 0 }, { vpid = 1305, vtid = 1305, procname = "lttng-test-pare" }, { my_string_field = "After sleep Pid: ", my_integer_field = 1308 } 

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 }

Any ideas how to fix this?

Thanks and regards!
Catalin
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: 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
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: Wrong procname if tracepoint is used before fork

[fmarianirinel]

Hi,

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

Created a patch with this suggestion:

---
diff --git a/include/lttng/ust-events.h b/include/lttng/ust-events.h
index caf7e63..fb1df1e 100644
--- a/include/lttng/ust-events.h
+++ b/include/lttng/ust-events.h
@@ -675,6 +675,7 @@ int lttng_add_cpu_id_to_ctx(struct lttng_ctx **ctx);
 int lttng_add_dyntest_to_ctx(struct lttng_ctx **ctx);
 void lttng_context_vtid_reset(void);
 void lttng_context_vpid_reset(void);
+void lttng_context_procname_reset(void);

 #ifdef LTTNG_UST_HAVE_PERF_EVENT
 int lttng_add_perf_counter_to_ctx(uint32_t type,
diff --git a/liblttng-ust/lttng-ust-comm.c b/liblttng-ust/lttng-ust-comm.c
index d98fae4..bd4d715 100644
--- a/liblttng-ust/lttng-ust-comm.c
+++ b/liblttng-ust/lttng-ust-comm.c
@@ -1988,6 +1988,7 @@ void ust_after_fork_child(sigset_t *restore_sigset)
                return;
        lttng_context_vpid_reset();
        lttng_context_vtid_reset();
+       lttng_context_procname_reset();
        DBG("process %d", getpid());
        /* Release urcu mutexes */
        rcu_bp_after_fork_child();
---

And I tested it with this reproducer:

https://github.com/Marian-Irinel/lttng-fork-procname-issue-reproducer.git

The results are what you would expect if you take in consideration the
man page. That is the child process can change it's name before leaving
any traces (could not do that before this, stuck with parent name if it
left traces before fork()).

Regards,
  Marian.

>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

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev