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

negoita catalin negoitacatalin at yahoo.com
Tue Apr 17 07:44:36 EDT 2018


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


More information about the lttng-dev mailing list