<div dir="ltr"><div class="gmail_extra"><div class="gmail_quote">On Wed, Nov 12, 2014 at 11:30 PM, Jérémie Galarneau <span dir="ltr"><<a href="mailto:jeremie.galarneau@efficios.com" target="_blank">jeremie.galarneau@efficios.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><span class="">On Wed, Nov 12, 2014 at 7:39 AM, Anders Wallin <<a href="mailto:wallinux@gmail.com">wallinux@gmail.com</a>> wrote:<br>
> Hi,<br>
><br>
> using userspace snapshot mode in 2.5 seems to broken.<br>
><br>
> I have small stupid application(tracetest) generating 1000 events<br>
><br>
> Running the script (the below is simplified version of the script)<br>
> ----------------------------------------------------------------------------------<br>
> #!/bin/bash<br>
> LTTNG='lttng -n'<br>
> lttng-sessiond --no-kernel &<br>
<br>
</span>You should use the "-d" flag to launch the sessiond as a daemon. Using<br>
"&" might cause the "create" command to launch a second session daemon<br>
since the first one would not have had the time to open create its<br>
command sockets.<br></blockquote><div>No reason, but I changed it now "-d". On my laptop I already have a sessiond running for kernelspace</div><div>and I wanted my test case to be as simple as possible to prove the faulty behavior.</div><div>I have an ARM and a powerpc target as well and on them I'm running the same test w/o a sessiond for the kernel </div><div>and not tracing kernel at all.</div><div> </div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div><div class="h5"><br>
><br>
> $LTTNG create test --snapshot<br>
> $LTTNG enable-channel -u --subbuf-size 64k --num-subbuf 16 --overwrite ch1<br>
> $LTTNG enable-event -u -c ch1 "*"<br>
> $LTTNG start<br>
> $LTTNG list ch1<br>
><br>
> mkdir -p snapshot/<br>
><br>
> for i in $(seq 1 $LOOPS); do<br>
>     ./tracetest<br>
>     $LTTNG snapshot record -m 1G<br>
><br>
>     # print no of events and first and last event<br>
>     last=$(ls -1drt $HOME/lttng-traces/$SESSION*/* | tail -1)<br>
>     babeltrace $last > snapshot/$<a href="http://i.bt" target="_blank">i.bt</a><br>
>     cat snapshot/$<a href="http://i.bt" target="_blank">i.bt</a> | wc -l<br>
>     cat snapshot/$<a href="http://i.bt" target="_blank">i.bt</a> | head -1<br>
>     cat snapshot/$<a href="http://i.bt" target="_blank">i.bt</a> | tail -1<br>
> done<br>
><br>
> $LTTNG stop<br>
> $LTTNG destroy $SESSION<br>
> ----------------------------------------------------------------------------------<br>
><br>
> The result of the run looks like this;<br>
> ./test.run<br>
> Error: consumer err socket second poll error<br>
> Error: Health error occurred in thread_manage_consumer<br>
> PERROR - 13:36:59.685167 [23772/23781]: bind inet: Address already in use<br>
> (in lttcomm_bind_inet_sock() at inet.c:109)<br>
> Warning: Another session daemon is using this JUL port. JUL support will be<br>
> deactivated to prevent interfering with the tracing.<br>
><br>
<br>
</div></div>Is there a reason why you run two session daemons? I'm guessing this<br>
is related to my "& vs -d" comment above. </blockquote><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div><div class="h5"><br>
> lttng (LTTng Trace Control) 2.5.2 - Fumisterie<br>
> BabelTrace Trace Viewer and Converter 1.2.4<br>
>         linux-vdso.so.1 =>  (0x00007fffba966000)<br>
>         liblttng-ctl.so.0 => /usr/lib/x86_64-linux-gnu/liblttng-ctl.so.0<br>
> (0x00007fbfe4b1d000)<br>
>         librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007fbfe4915000)<br>
>         libxml2.so.2 => /usr/lib/x86_64-linux-gnu/libxml2.so.2<br>
> (0x00007fbfe45ae000)<br>
>         libpopt.so.0 => /lib/x86_64-linux-gnu/libpopt.so.0<br>
> (0x00007fbfe43a2000)<br>
>         libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0<br>
> (0x00007fbfe4184000)<br>
>         libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007fbfe3dbd000)<br>
>         /lib64/ld-linux-x86-64.so.2 (0x00007fbfe4fac000)<br>
>         liburcu.so.2 => /usr/lib/x86_64-linux-gnu/liburcu.so.2<br>
> (0x00007fbfe3bb6000)<br>
>         libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007fbfe39b2000)<br>
>         libz.so.1 => /lib/x86_64-linux-gnu/libz.so.1 (0x00007fbfe3798000)<br>
>         liblzma.so.5 => /lib/x86_64-linux-gnu/liblzma.so.5<br>
> (0x00007fbfe3576000)<br>
>         libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007fbfe3270000)<br>
><br>
> Session test created.<br>
> Default snapshot output set to:<br>
> /home/awallin/lttng-traces/test-20141112-133700<br>
> Snapshot mode set. Every channel enabled for that session will be set in<br>
> overwrite mode and mmap output.<br>
> UST channel ch1 enabled for session test<br>
> UST event * created in channel ch1<br>
> Tracing started for session test<br>
> Tracing session test: [active snapshot]<br>
>     Trace path:<br>
>     Live timer interval (usec): 4294967295<br>
><br>
> === Domain: UST global ===<br>
><br>
> Channels:<br>
> -------------<br>
> - ch1: [enabled]<br>
><br>
>     Attributes:<br>
>       overwrite mode: 1<br>
>       subbufers size: 4096<br>
>       number of subbufers: 16<br>
>       switch timer interval: 0<br>
>       read timer interval: 0<br>
>       trace file count: 0<br>
>       trace file size (bytes): 0<br>
>       output: mmap()<br>
><br>
>     Events:<br>
>       * (type: tracepoint) [enabled]<br>
><br>
> Snapshot recorded successfully for session test<br>
> 84<br>
> [13:37:00.852615950] (+?.?????????) arn-awallin-mint-l3<br>
> ust_baddr_statedump:soinfo: { cpu_id = 4 }, { baddr = 0x7FFFC6BC7000, sopath<br>
> = "[vdso]", size = 0, mtime = -1 }<br>
> [13:37:00.853798949] (+0.000000805) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Snapshot recorded successfully for session test<br>
> 157<br>
> [13:37:00.853735195] (+?.?????????) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 927 }<br>
> [13:37:00.894839116] (+0.000000299) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Snapshot recorded successfully for session test<br>
> 168<br>
> [13:37:00.853735195] (+?.?????????) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 927 }<br>
> [13:37:00.929447330] (+0.000000305) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Snapshot recorded successfully for session test<br>
> 168<br>
> [13:37:00.894411117] (+?.?????????) arn-awallin-mint-l3<br>
> ust_baddr_statedump:soinfo: { cpu_id = 4 }, { baddr = 0x7FFF6BF81000, sopath<br>
> = "[vdso]", size = 0, mtime = -1 }<br>
> [13:37:00.972035546] (+0.000000597) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Snapshot recorded successfully for session test<br>
> 168<br>
> [13:37:00.894411117] (+?.?????????) arn-awallin-mint-l3<br>
> ust_baddr_statedump:soinfo: { cpu_id = 4 }, { baddr = 0x7FFF6BF81000, sopath<br>
> = "[vdso]", size = 0, mtime = -1 }<br>
> [13:37:01.014060940] (+0.000000341) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 7 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Snapshot recorded successfully for session test<br>
> 168<br>
> [13:37:00.894411117] (+?.?????????) arn-awallin-mint-l3<br>
> ust_baddr_statedump:soinfo: { cpu_id = 4 }, { baddr = 0x7FFF6BF81000, sopath<br>
> = "[vdso]", size = 0, mtime = -1 }<br>
> [13:37:01.052555877] (+0.000000872) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Snapshot recorded successfully for session test<br>
> 168<br>
> [13:37:01.014035993] (+?.?????????) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 7 }, { my_string_field = "test", my_integer_field = 927 }<br>
> [13:37:01.098620808] (+0.000001404) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Snapshot recorded successfully for session test<br>
> 168<br>
> [13:37:01.097087388] (+?.?????????) arn-awallin-mint-l3<br>
> ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF4BFFE000, sopath<br>
> = "[vdso]", size = 0, mtime = -1 }<br>
> [13:37:01.129839830] (+0.000000533) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 7 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Snapshot recorded successfully for session test<br>
> 168<br>
> [13:37:01.097087388] (+?.?????????) arn-awallin-mint-l3<br>
> ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF4BFFE000, sopath<br>
> = "[vdso]", size = 0, mtime = -1 }<br>
> [13:37:01.129839830] (+0.000000533) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 7 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Snapshot recorded successfully for session test<br>
> 168<br>
> [13:37:01.097087388] (+?.?????????) arn-awallin-mint-l3<br>
> ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF4BFFE000, sopath<br>
> = "[vdso]", size = 0, mtime = -1 }<br>
> [13:37:01.172829105] (+0.000000575) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Snapshot recorded successfully for session test<br>
> 168<br>
> [13:37:01.172021557] (+?.?????????) arn-awallin-mint-l3<br>
> ust_baddr_statedump:soinfo: { cpu_id = 7 }, { baddr = 0x7FFF653FE000, sopath<br>
> = "[vdso]", size = 0, mtime = -1 }<br>
> [13:37:01.220074165] (+0.000000553) arn-awallin-mint-l3 tracetest:first_tp:<br>
> { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }<br>
> Waiting for data availability<br>
> Tracing stopped for session test<br>
> Session test destroyed<br>
><br>
> the result from the run on older versions of lttng creates bigger and bigger<br>
> event traces until reaching max size.<br>
><br>
<br>
</div></div>Unless I'm mistaken, the behavior of the snapshot mode has changed<br>
between 2.4 and 2.5.<br>
<br>
In the 2.4 series, consecutive snapshots could overlap; that is,<br>
events could be present in multiple snapshots. As of 2.5, an event is<br>
guaranteed to only appear in one snapshot as the events are considered<br>
as having been "consumed" at that point.<br>
<br>
Julien (cc'ed) might be able to confirm this.<br>
<br>
Regards,<br>
Jérémie<br>
<span class=""><br>
> I have tested this on different architectures, with different buffer sizes<br>
> and number of buffer<br>
><br>
> Regards<br>
> Anders Wallin<br>
><br>
</span>> _______________________________________________<br>
> lttng-dev mailing list<br>
> <a href="mailto:lttng-dev@lists.lttng.org">lttng-dev@lists.lttng.org</a><br>
> <a href="http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev" target="_blank">http://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev</a><br>
><br>
<span class="HOEnZb"><font color="#888888"><br>
<br>
<br>
--<br>
Jérémie Galarneau<br>
EfficiOS Inc.<br>
<a href="http://www.efficios.com" target="_blank">http://www.efficios.com</a><br>
</font></span></blockquote></div><br></div></div>