<div dir="ltr">bug is introduced in  68808f4e0bbb3adccff72ff9dab6ec9f3a9e6866<div><br></div><div>Regards</div><div><br></div><div>Anders</div></div><div class="gmail_extra"><br clear="all"><div><div class="gmail_signature">Anders Wallin</div></div>
<br><div class="gmail_quote">On Thu, Nov 13, 2014 at 10:39 AM, Anders Wallin <span dir="ltr"><<a href="mailto:wallinux@gmail.com" target="_blank">wallinux@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><br><div class="gmail_extra"><br clear="all"><div><div>Anders Wallin</div></div>
<br><div class="gmail_quote"><div><div class="h5">On Thu, Nov 13, 2014 at 8:43 AM, Anders Wallin <span dir="ltr"><<a href="mailto:wallinux@gmail.com" target="_blank">wallinux@gmail.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div dir="ltr"><div class="gmail_extra"><div class="gmail_quote"><div><div>On Thu, Nov 13, 2014 at 12:11 AM, Julien Desfossez <span dir="ltr"><<a href="mailto:jdesfossez@efficios.com" target="_blank">jdesfossez@efficios.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">Hi,<br>
<div><div><br>
On 14-11-12 05:30 PM, Jérémie Galarneau wrote:<br>
> On Wed, Nov 12, 2014 at 7:39 AM, Anders Wallin <<a href="mailto:wallinux@gmail.com" target="_blank">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>
> 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>
><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>
> Is there a reason why you run two session daemons? I'm guessing this<br>
> is related to my "& vs -d" comment above.<br>
><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>
<br>
</div></div>Something is wrong from here:<br>
<span>>> 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.<a href="tel:014060940" value="+4614060940" target="_blank">014060940</a>] (+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.<a href="tel:052555877" value="+4652555877" target="_blank">052555877</a>] (+0.000000872) arn-awallin-mint-l3 tracetest:first_tp:<br>
>> { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }<br>
</span>... to here.<br>
<br>
The beginning timestamp is the same, the number of events is the same,<br>
but the end timestamp moves. We see also this pattern below.<br>
I would be really interested to see the whole snapshots when it happens.<br>
It seems like we are not be overwriting the beginning of the ring buffer<br>
in some conditions. Could you send us your tracetest program and the<br>
script so we can try to reproduce the problem ?<br></blockquote><div> </div></div></div><div>I will append it including a run with debug turned on and all the snapshot files created</div><div><div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
<div><div><br>
>> Snapshot recorded successfully for session test<br>
>> 168<br>
>> [13:37:01.<a href="tel:014035993" value="+4614035993" target="_blank">014035993</a>] (+?.?????????) 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.<a href="tel:097087388" value="+4697087388" target="_blank">097087388</a>] (+?.?????????) 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.<a href="tel:097087388" value="+4697087388" target="_blank">097087388</a>] (+?.?????????) 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.<a href="tel:097087388" value="+4697087388" target="_blank">097087388</a>] (+?.?????????) 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>
</div></div>We see this pattern here and the max size seems to be 168 events, was it<br>
similar in your previous tests ?<br></blockquote></div></div><div>If I'm running the same test on 2.4 or 2.3 the max number of events is much bigger, like ~10000 </div><div>(I don't have the exact number right now, I will rebuild and run the test again and get back </div><div>with traces from that run) </div></div></div></div></blockquote></div></div><div>For 2.4.2 the log looks like this:</div><div><div>./test.run ./tracetest</div><div><br></div><div>lttng (LTTng Trace Control) 2.4.2 - Époque Opaque</div><div>BabelTrace Trace Viewer and Converter 1.2.1</div><div><span style="white-space:pre-wrap"> </span>linux-vdso.so.1 =>  (0x00007fff775fe000)</div><div><span style="white-space:pre-wrap">     </span>liblttng-ctl.so.0 => /usr/local/lib/liblttng-ctl.so.0 (0x00002b2b016e4000)</div><div><span style="white-space:pre-wrap">    </span>libpopt.so.0 => /lib/x86_64-linux-gnu/libpopt.so.0 (0x00002b2b0190f000)</div><div><span style="white-space:pre-wrap">       </span>libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00002b2b01b1b000)</div><div><span style="white-space:pre-wrap"> </span>libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00002b2b01d39000)</div><div><span style="white-space:pre-wrap">     </span>librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00002b2b020ff000)</div><div><span style="white-space:pre-wrap">   </span>liburcu.so.3 => /usr/local/lib/liburcu.so.3 (0x00002b2b02307000)</div><div><span style="white-space:pre-wrap">      </span>/lib64/ld-linux-x86-64.so.2 (0x00002b2b014bf000)</div><div><br></div><div>Session test created.</div><div>Default snapshot output set to: //lttng-traces/test-20141113-093611</div><span class=""><div>Snapshot mode set. Every channel enabled for that session will be set in overwrite mode and mmap output.</div><div>UST channel ch1 enabled for session test</div><div>UST event * created in channel ch1</div><div>Tracing started for session test</div><div>Tracing session test: [active snapshot]</div><div>    Trace path: </div><div><br></div></span><span class=""><div>=== Domain: UST global ===</div><div><br></div></span><div>Buffer type: per UID</div><span class=""><div><br></div><div>Channels:</div><div>-------------</div><div>- ch1: [enabled]</div><div><br></div><div>    Attributes:</div><div>      overwrite mode: 1</div><div>      subbufers size: 4096</div><div>      number of subbufers: 16</div><div>      switch timer interval: 0</div><div>      read timer interval: 0</div></span><span class=""><div>      output: mmap()</div><div><br></div><div>    Events:</div><div>      * (type: tracepoint) [enabled]</div><div><br></div><div>Snapshot recorded successfully for session test</div></span><div>1000</div><div>[09:36:11.985319272] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[09:36:11.985857254] (+0.000000501) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }</div><span class=""><div>Snapshot recorded successfully for session test</div></span><div>2000</div><div>[09:36:11.985319272] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[09:36:12.<a href="tel:033066130" value="+4633066130" target="_blank">033066130</a>] (+0.000001663) 07f8cf84a38f tracetest:first_tp: { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }</div><span class=""><div>Snapshot recorded successfully for session test</div></span><div>3000</div><div>[09:36:11.985319272] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[09:36:12.<a href="tel:086888121" value="+4686888121" target="_blank">086888121</a>] (+0.000001273) 07f8cf84a38f tracetest:first_tp: { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }</div><span class=""><div>Snapshot recorded successfully for session test</div></span><div>4000</div><div>[09:36:11.985319272] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[09:36:12.147378251] (+0.000001257) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }</div><span class=""><div>Snapshot recorded successfully for session test</div></span><div>5000</div><div>[09:36:11.985319272] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[09:36:12.225584696] (+0.000000528) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }</div><span class=""><div>Snapshot recorded successfully for session test</div></span><div>6000</div><div>[09:36:11.985319272] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[09:36:12.288311172] (+0.000000571) 07f8cf84a38f tracetest:first_tp: { cpu_id = 7 }, { my_string_field = "test", my_integer_field = 999 }</div><span class=""><div>Snapshot recorded successfully for session test</div></span><div>7000</div><div>[09:36:11.985319272] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[09:36:12.375789307] (+0.000001238) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }</div><span class=""><div>Snapshot recorded successfully for session test</div></span><div>7000</div><div>[09:36:12.032314084] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[09:36:12.460756779] (+0.000001248) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }</div><span class=""><div>Snapshot recorded successfully for session test</div></span><div>8000</div><div>[09:36:12.032314084] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[09:36:12.540464090] (+0.000001292) 07f8cf84a38f tracetest:first_tp: { cpu_id = 7 }, { my_string_field = "test", my_integer_field = 999 }</div><span class=""><div>Snapshot recorded successfully for session test</div></span><div>9000</div><div>[09:36:12.032314084] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[09:36:12.621992931] (+0.000001298) 07f8cf84a38f tracetest:first_tp: { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }</div><span class=""><div>Waiting for data availability</div><div>Tracing stopped for session test</div><div>Session test destroyed</div></span></div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex"><div dir="ltr"><div class="gmail_extra"><div class="gmail_quote"><span><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
<span><br>
><span class=""><br>
> 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>
</span></span><span class="">Hum, no the behavior is still the same, consecutive snapshots can overlap.<br>
<br>
Could you tell us on which architecture you are experiencing the problem<br>
and the number of CPUs ?<br></span></blockquote></span><span class=""><div>The traces appended is from my laptop running Ubuntu 14.04 with "8" cpu's</div><div>model name      : Intel(R) Core(TM) i7-2760QM CPU @ 2.40GHz<br></div><div>I have also run this on ARM with 16 cores and a powerpc</div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-color:rgb(204,204,204);border-left-style:solid;padding-left:1ex">
<br>
Thanks,<br>
<br>
Julien<br>
</blockquote></span></div><br></div></div>
</blockquote></div><br></div></div>
</blockquote></div><br></div>