<div dir="ltr">Filed as <a href="https://bugs.lttng.org/issues/862">https://bugs.lttng.org/issues/862</a><div><br></div><div><br></div></div><div class="gmail_extra"><br clear="all"><div><div class="gmail_signature">Anders Wallin</div></div>
<br><div class="gmail_quote">On Mon, Nov 17, 2014 at 12:45 PM, Mathieu Desnoyers <span dir="ltr"><<a href="mailto:mathieu.desnoyers@efficios.com" target="_blank">mathieu.desnoyers@efficios.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div><div style="font-family:times new roman,new york,times,serif;font-size:12pt;color:#000000"><div>Hi Anders,<br></div><div><br></div><div>Yes, please file a feature request against Babeltrace on<br></div><div>the bug tracker pointing the this email thread and<br></div><div>describing the feature.<br></div><div><br></div><div>Thanks!<br></div><div><br></div><div>Mathieu<br></div><div><br></div><div><br></div><hr><blockquote style="border-left:2px solid #1010ff;margin-left:5px;padding-left:5px;color:#000;font-weight:normal;font-style:normal;text-decoration:none;font-family:Helvetica,Arial,sans-serif;font-size:12pt"><b>From: </b>"Anders Wallin" <<a href="mailto:wallinux@gmail.com" target="_blank">wallinux@gmail.com</a>><br><b>To: </b>"Mathieu Desnoyers" <<a href="mailto:mathieu.desnoyers@efficios.com" target="_blank">mathieu.desnoyers@efficios.com</a>><br><b>Cc: </b><a href="mailto:lttng-dev@lists.lttng.org" target="_blank">lttng-dev@lists.lttng.org</a><br><b>Sent: </b>Monday, November 17, 2014 10:45:37 AM<br><b>Subject: </b>Re: [lttng-dev] snapshot data corrupted after the output buffer is filled<div><div class="h5"><br><div><br></div><div dir="ltr">Thx Mathieu,<div><br></div><div>if I'm running my test on one cpu (taskset -c 1 ./test.run) it works as expected and described by you.</div><div>The babeltrace flag would be a good solution! Do you want me to file a bug/enhancement on this? </div><div><br></div><div>Regards</div><div><br></div><div><br></div></div><div class="gmail_extra"><br clear="all"><div><div>Anders Wallin</div></div>
<br><div class="gmail_quote">On Sat, Nov 15, 2014 at 6:59 PM, Mathieu Desnoyers <span dir="ltr"><<a href="mailto:mathieu.desnoyers@efficios.com" target="_blank">mathieu.desnoyers@efficios.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div><div style="font-family:times new roman,new york,times,serif;font-size:12pt;color:#000000"><hr><blockquote style="border-left:2px solid #1010ff;margin-left:5px;padding-left:5px;color:#000;font-weight:normal;font-style:normal;text-decoration:none;font-family:Helvetica,Arial,sans-serif;font-size:12pt"><b>From: </b>"Anders Wallin" <<a href="mailto:wallinux@gmail.com" target="_blank">wallinux@gmail.com</a>><br><b>To: </b><a href="mailto:lttng-dev@lists.lttng.org" target="_blank">lttng-dev@lists.lttng.org</a><br><b>Sent: </b>Friday, November 14, 2014 8:28:18 AM<br><b>Subject: </b>[lttng-dev] snapshot data corrupted after the output buffer is filled<span><br><div><br></div><div dir="ltr"><div>Hi,</div><div><br></div><div>it looks like snapshot events became faulty after the output max size is reached.</div><div>The next snapshot get mixed events from different buffers. I have tested it on 2.3, 2.4 and 2.5</div><div>and it's in all of them, but it hits earlier in 2.5 due to the problem reported in</div><div><a href="http://lists.lttng.org/pipermail/lttng-dev/2014-November/023773.html" target="_blank">http://lists.lttng.org/pipermail/lttng-dev/2014-November/023773.html</a><br></div><div><br></div><div>There should never be more then 2 HUNKS in a diff between 2 consecutive snapshots, here I got </div><div>11 as the worst case.</div></div></span></blockquote><div>Hi Anders,<br></div><div><br></div><div>This is not a bug, rather just per-cpu buffering at work.It does have some<br></div><div>rather non-obvious consequences in terms of snapshot event flow.<br></div><div><br></div><div>To understand this, we need to keep in mind that LTTng does everything<br></div><div>in per-cpu buffers, and that overwrite of oldest events in buffer full conditions<br></div><div>happens per-cpu.<br></div><div><br></div><div>The use-case you show below really makes sense when you start to consider<br></div><div>on which CPU (and thus per-cpu buffer) the application is running. Initially,<br></div><div>the first app runs on CPU 6. As long as the following applications run on<br></div><div>other cpus, we keep the same first event. Then when enough events are<br></div><div>written in cpu 6 buffer to overwrite the first event, we see a first event change.<br></div><div>Then, depending on the scheduling of applications, older parts of per-cpu<br></div><div>buffers are overwritten, and others are not (if there are less events in those<br></div><div>buffer). This means some per-cpu buffers will have events going further back<br></div><div>in time compared to other higher-throughput CPUs.<br></div><div><br></div><div>This is why you see more than 2 hunks in your diff. Babeltrace merges those<br></div><div>per-cpu buffers back into a single text output, and the fact that some events<br></div><div>have been overwritten for a time-range for high-throughput buffers, but not<br></div><div>for low-throughput buffers, make it appear as if events are missing in the<br></div><div>stream if your model is a single system-wide buffer, but the missing events<br></div><div>make sense if you see it as a merge of per-cpu buffers.<br></div><div><br></div><div>Our current behavior is to gather all available data when taking a snapshot,<br></div><div>and babeltrace behavior is to show all events available in the streams. We<br></div><div>could perhaps consider a different babeltrace behavior (a flag) that would<br></div><div>allow it to only show the events for the intersection of time range of all<br></div><div>streams, based on the packet header timestamp begin/end. This would<br></div><div>take care of hiding events that happen in low-throughput streams when<br></div><div>there is no intersection with snapshotted high-throughput streams.<br></div><div><br></div><div>And perhaps this should be the default ?<br></div><div><br></div><div>Thanks!<br></div><div><br></div><div>Mathieu<br></div><div><br></div><blockquote style="border-left:2px solid #1010ff;margin-left:5px;padding-left:5px;color:#000;font-weight:normal;font-style:normal;text-decoration:none;font-family:Helvetica,Arial,sans-serif;font-size:12pt"><div><div><div dir="ltr"><div><br></div><div>TESTCASE;</div><div><br></div><div>tracetest code:</div><div>---------------------------------------------------------------</div><div>#include <stdio.h></div><div>#include "tracetest-tp.h"</div><div><br></div><div>int main(int argc, char* argv[])</div><div>{</div><div> int i;</div><div> for (i = 0; i < 1000; i++) {</div><div> tracepoint(tracetest, first_tp, i, "test");</div><div> }</div><div> return 0;</div><div>}</div><div>---------------------------------------------------------------</div><div><br></div><div>test script:</div><div>---------------------------------------------------------------</div><div>#!/bin/bash </div><div>: ${NO_OF_SUBBUF:=6}</div><div>: ${SUBBUF_SIZE:=4096}</div><div>: ${KERNEL_TRACE:=NO}</div><div>: ${LOOPS:=10}</div><div><br></div><div>SESSION=test</div><div>CHANNEL1=ch1</div><div>CHANNEL2=ch2</div><div><br></div><div>CH2_SUBBUF_SIZE=$(($SUBBUF_SIZE*$NO_OF_SUBBUF))</div><div><br></div><div><br></div><div>LTTNG='lttng -n'</div><div>killall lttng-consumerd > /dev/null 2>&1</div><div>killall lttng-sessiond > /dev/null 2>&1</div><div>if [ -z $DEBUG ]; then</div><div> lttng-sessiond --no-kernel -d</div><div>else</div><div> lttng-sessiond -v --no-kernel --verbose-consumer -b</div><div>fi</div><div>sleep 1</div><div><br></div><div>if [ ! -z $DEBUG ]; then</div><div> export LTTNG_UST_DEBUG=1</div><div>fi</div><div><br></div><div>rm -rf $HOME/lttng-traces</div><div>rm snapshot/*.bt</div><div><br></div><div>$LTTNG --version</div><div><br></div><div>$LTTNG create $SESSION --snapshot</div><div>$LTTNG enable-channel -u --subbuf-size $SUBBUF_SIZE --num-subbuf $NO_OF_SUBBUF --overwrite $CHANNEL1</div><div>$LTTNG enable-channel -u --subbuf-size $CH2_SUBBUF_SIZE --num-subbuf 2 --overwrite $CHANNEL2</div><div>$LTTNG enable-event -u -c $CHANNEL1 "*"</div><div>$LTTNG start</div><div>$LTTNG list $SESSION</div><div><br></div><div>mkdir -p snapshot/</div><div><br></div><div>h=1</div><div>for i in $(seq 1 $LOOPS); do</div><div> $APP</div><div> $LTTNG snapshot record</div><div> # print no of events and first and last event </div><div> last=$(ls -1drt $HOME/lttng-traces/$SESSION*/* | tail -1)</div><div> babeltrace $last > snapshot/$<a href="http://i.bt" target="_blank">i.bt</a><br></div><div> cat snapshot/$<a href="http://i.bt" target="_blank">i.bt</a> | wc -l</div><div> cat snapshot/$<a href="http://i.bt" target="_blank">i.bt</a> | head -1</div><div> cat snapshot/$<a href="http://i.bt" target="_blank">i.bt</a> | tail -1</div><div> diff -u snapshot/$<a href="http://i.bt" target="_blank">i.bt</a> snapshot/$<a href="http://h.bt" target="_blank">h.bt</a> > snapshot/$i_$h.diff</div><div> cat snapshot/$i_$h.diff | grep "@@" | wc -l | xargs echo "NUMBER OF DIFF HUNKS = "</div><div> h=$i</div><div>done</div><div><br></div><div><div><div>$LTTNG stop</div><div>$LTTNG destroy $SESSION</div><div><br></div><div>---------------------------------------------------------------</div><div><br></div><div>result from run (removed some output lines for readability)</div><div>---------------------------------------------------------------</div><div>lttng (LTTng Trace Control) 2.4.2 - Époque Opaque</div><div>Snapshot mode set. Every channel enabled for that session will be set in overwrite mode and mmap output.</div><div>Warning: The number of subbuffers (6) is rounded to the next power of 2 (8)</div><div>UST channel ch1 enabled for session test</div><div>Warning: The subbuf size (24576) is rounded to the next power of 2 (32768)</div><div>UST channel ch2 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><div>=== Domain: UST global ===</div><div><br></div><div>Buffer type: per UID</div><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: 8</div><div> switch timer interval: 0</div><div> read timer interval: 0</div><div> output: mmap()</div><div><br></div><div> Events:</div><div> * (type: tracepoint) [enabled]</div><div>- ch2: [enabled]</div><div><br></div><div> Attributes:</div><div> overwrite mode: 1</div><div> subbufers size: 32768</div><div> number of subbufers: 2</div><div> switch timer interval: 0</div><div> read timer interval: 0</div><div> output: mmap()</div><div><br></div><div> Events:</div><div> None</div><div><br></div><div>Snapshot recorded successfully for session test</div><div>1011</div><div>[07:09:43.278933559] (+?.?????????) 07f8cf84a38f ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF645EE000, sopath = "[vdso]", size = 0, mtime = -1 }</div><div>[07:09:43.279975100] (+0.000000975) 07f8cf84a38f tracetest:first_tp: { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }</div><div>NUMBER OF DIFF HUNKS = 0</div><div>Snapshot recorded successfully for session test</div><div>2022</div><div>[07:09:43.278933559] (+?.?????????) 07f8cf84a38f ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF645EE000, sopath = "[vdso]", size = 0, mtime = -1 }</div><div>[07:09:43.337703508] (+0.000001238) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }</div><div>NUMBER OF DIFF HUNKS = 1</div><div>Snapshot recorded successfully for session test</div><div>3033</div><div>[07:09:43.278933559] (+?.?????????) 07f8cf84a38f ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF645EE000, sopath = "[vdso]", size = 0, mtime = -1 }</div><div>[07:09:43.432827051] (+0.000000308) 07f8cf84a38f tracetest:first_tp: { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }</div><div>NUMBER OF DIFF HUNKS = 1</div><div>Snapshot recorded successfully for session test</div><div>4044</div><div>[07:09:43.278933559] (+?.?????????) 07f8cf84a38f ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF645EE000, sopath = "[vdso]", size = 0, mtime = -1 }</div><div>[07:09:43.475784825] (+0.000000501) 07f8cf84a38f tracetest:first_tp: { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }</div><div>NUMBER OF DIFF HUNKS = 1</div><div>Snapshot recorded successfully for session test</div><div>4735</div><div>[07:09:43.279031320] (+?.?????????) 07f8cf84a38f tracetest:first_tp: { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 0 }</div><div>[07:09:43.549945106] (+0.000000517) 07f8cf84a38f tracetest:first_tp: { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }</div><div>NUMBER OF DIFF HUNKS = 12</div><div>Snapshot recorded successfully for session test</div><div>4437</div><div>[07:09:43.335916076] (+?.?????????) 07f8cf84a38f ust_baddr_statedump:soinfo: { cpu_id = 2 }, { baddr = 0x7FFFAD1FE000, sopath = "[vdso]", size = 0, mtime = -1 }</div><div>[07:09:43.654229030] (+0.000000436) 07f8cf84a38f tracetest:first_tp: { cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }</div><div>NUMBER OF DIFF HUNKS = 3</div><div>Snapshot recorded successfully for session test</div><div>4746</div><div>[07:09:43.335916076] (+?.?????????) 07f8cf84a38f ust_baddr_statedump:soinfo: { cpu_id = 2 }, { baddr = 0x7FFFAD1FE000, sopath = "[vdso]", size = 0, mtime = -1 }</div><div>[07:09:43.747509349] (+0.000000502) 07f8cf84a38f tracetest:first_tp: { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }</div><div>NUMBER OF DIFF HUNKS = 11</div><div>Snapshot recorded successfully for session test</div><div>5757</div><div>[07:09:43.335916076] (+?.?????????) 07f8cf84a38f ust_baddr_statedump:soinfo: { cpu_id = 2 }, { baddr = 0x7FFFAD1FE000, sopath = "[vdso]", size = 0, mtime = -1 }</div><div>[07:09:43.814938128] (+0.000001371) 07f8cf84a38f tracetest:first_tp: { cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }</div><div>NUMBER OF DIFF HUNKS = 1</div><div>Snapshot recorded successfully for session test</div><div>6066</div><div>[07:09:43.335916076] (+?.?????????) 07f8cf84a38f ust_baddr_statedump:soinfo: { cpu_id = 2 }, { baddr = 0x7FFFAD1FE000, sopath = "[vdso]", size = 0, mtime = -1 }</div><div>[07:09:43.919112586] (+0.000000990) 07f8cf84a38f tracetest:first_tp: { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }</div><div>NUMBER OF DIFF HUNKS = 11</div><div>Snapshot recorded successfully for session test</div><div>6077</div><div>[07:09:43.335916076] (+?.?????????) 07f8cf84a38f ust_baddr_statedump:soinfo: { cpu_id = 2 }, { baddr = 0x7FFFAD1FE000, sopath = "[vdso]", size = 0, mtime = -1 }</div><div>[07:09:44.004234933] (+0.000001213) 07f8cf84a38f tracetest:first_tp: { cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }</div><div>NUMBER OF DIFF HUNKS = 2</div><div>Waiting for data availability</div><div>Tracing stopped for session test</div><div>Session test destroyed</div><div>---------------------------------------------------------------</div><div><br></div><div>Regards</div><div><br></div><div>Anders Wallin</div></div></div></div><br></div></div><span>_______________________________________________<br>lttng-dev mailing list<br><a href="mailto:lttng-dev@lists.lttng.org" target="_blank">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></span></blockquote><span><span style="color:#888888" color="#888888"><div><br><div><br></div></div><div><br></div><div>-- <br></div><div><span></span>Mathieu Desnoyers<br>EfficiOS Inc.<br><a href="http://www.efficios.com" target="_blank">http://www.efficios.com</a><span></span><br></div></span></span></div></div></blockquote></div><br></div>
</div></div></blockquote><div><div class="h5"><div><br><br></div><div><br></div><div>-- <br></div><div><span name="x"></span>Mathieu Desnoyers<br>EfficiOS Inc.<br><a href="http://www.efficios.com" target="_blank">http://www.efficios.com</a><span name="x"></span><br></div></div></div></div></div></blockquote></div><br></div>