[lttng-dev] snapshot data corrupted after the output buffer is filled
Anders Wallin
wallinux at gmail.com
Fri Nov 14 02:28:18 EST 2014
Hi,
it looks like snapshot events became faulty after the output max size is
reached.
The next snapshot get mixed events from different buffers. I have tested it
on 2.3, 2.4 and 2.5
and it's in all of them, but it hits earlier in 2.5 due to the problem
reported in
http://lists.lttng.org/pipermail/lttng-dev/2014-November/023773.html
There should never be more then 2 HUNKS in a diff between 2 consecutive
snapshots, here I got
11 as the worst case.
TESTCASE;
tracetest code:
---------------------------------------------------------------
#include <stdio.h>
#include "tracetest-tp.h"
int main(int argc, char* argv[])
{
int i;
for (i = 0; i < 1000; i++) {
tracepoint(tracetest, first_tp, i, "test");
}
return 0;
}
---------------------------------------------------------------
test script:
---------------------------------------------------------------
#!/bin/bash
: ${NO_OF_SUBBUF:=6}
: ${SUBBUF_SIZE:=4096}
: ${KERNEL_TRACE:=NO}
: ${LOOPS:=10}
SESSION=test
CHANNEL1=ch1
CHANNEL2=ch2
CH2_SUBBUF_SIZE=$(($SUBBUF_SIZE*$NO_OF_SUBBUF))
LTTNG='lttng -n'
killall lttng-consumerd > /dev/null 2>&1
killall lttng-sessiond > /dev/null 2>&1
if [ -z $DEBUG ]; then
lttng-sessiond --no-kernel -d
else
lttng-sessiond -v --no-kernel --verbose-consumer -b
fi
sleep 1
if [ ! -z $DEBUG ]; then
export LTTNG_UST_DEBUG=1
fi
rm -rf $HOME/lttng-traces
rm snapshot/*.bt
$LTTNG --version
$LTTNG create $SESSION --snapshot
$LTTNG enable-channel -u --subbuf-size $SUBBUF_SIZE --num-subbuf
$NO_OF_SUBBUF --overwrite $CHANNEL1
$LTTNG enable-channel -u --subbuf-size $CH2_SUBBUF_SIZE --num-subbuf 2
--overwrite $CHANNEL2
$LTTNG enable-event -u -c $CHANNEL1 "*"
$LTTNG start
$LTTNG list $SESSION
mkdir -p snapshot/
h=1
for i in $(seq 1 $LOOPS); do
$APP
$LTTNG snapshot record
# print no of events and first and last event
last=$(ls -1drt $HOME/lttng-traces/$SESSION*/* | tail -1)
babeltrace $last > snapshot/$i.bt
cat snapshot/$i.bt | wc -l
cat snapshot/$i.bt | head -1
cat snapshot/$i.bt | tail -1
diff -u snapshot/$i.bt snapshot/$h.bt > snapshot/$i_$h.diff
cat snapshot/$i_$h.diff | grep "@@" | wc -l | xargs echo "NUMBER OF
DIFF HUNKS = "
h=$i
done
$LTTNG stop
$LTTNG destroy $SESSION
---------------------------------------------------------------
result from run (removed some output lines for readability)
---------------------------------------------------------------
lttng (LTTng Trace Control) 2.4.2 - Époque Opaque
Snapshot mode set. Every channel enabled for that session will be set in
overwrite mode and mmap output.
Warning: The number of subbuffers (6) is rounded to the next power of 2 (8)
UST channel ch1 enabled for session test
Warning: The subbuf size (24576) is rounded to the next power of 2 (32768)
UST channel ch2 enabled for session test
UST event * created in channel ch1
Tracing started for session test
Tracing session test: [active snapshot]
Trace path:
=== Domain: UST global ===
Buffer type: per UID
Channels:
-------------
- ch1: [enabled]
Attributes:
overwrite mode: 1
subbufers size: 4096
number of subbufers: 8
switch timer interval: 0
read timer interval: 0
output: mmap()
Events:
* (type: tracepoint) [enabled]
- ch2: [enabled]
Attributes:
overwrite mode: 1
subbufers size: 32768
number of subbufers: 2
switch timer interval: 0
read timer interval: 0
output: mmap()
Events:
None
Snapshot recorded successfully for session test
1011
[07:09:43.278933559] (+?.?????????) 07f8cf84a38f
ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF645EE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[07:09:43.279975100] (+0.000000975) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }
NUMBER OF DIFF HUNKS = 0
Snapshot recorded successfully for session test
2022
[07:09:43.278933559] (+?.?????????) 07f8cf84a38f
ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF645EE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[07:09:43.337703508] (+0.000001238) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }
NUMBER OF DIFF HUNKS = 1
Snapshot recorded successfully for session test
3033
[07:09:43.278933559] (+?.?????????) 07f8cf84a38f
ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF645EE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[07:09:43.432827051] (+0.000000308) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }
NUMBER OF DIFF HUNKS = 1
Snapshot recorded successfully for session test
4044
[07:09:43.278933559] (+?.?????????) 07f8cf84a38f
ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF645EE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[07:09:43.475784825] (+0.000000501) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }
NUMBER OF DIFF HUNKS = 1
Snapshot recorded successfully for session test
4735
[07:09:43.279031320] (+?.?????????) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 5 }, { my_string_field = "test", my_integer_field = 0 }
[07:09:43.549945106] (+0.000000517) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }
NUMBER OF DIFF HUNKS = 12
Snapshot recorded successfully for session test
4437
[07:09:43.335916076] (+?.?????????) 07f8cf84a38f
ust_baddr_statedump:soinfo: { cpu_id = 2 }, { baddr = 0x7FFFAD1FE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[07:09:43.654229030] (+0.000000436) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }
NUMBER OF DIFF HUNKS = 3
Snapshot recorded successfully for session test
4746
[07:09:43.335916076] (+?.?????????) 07f8cf84a38f
ust_baddr_statedump:soinfo: { cpu_id = 2 }, { baddr = 0x7FFFAD1FE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[07:09:43.747509349] (+0.000000502) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }
NUMBER OF DIFF HUNKS = 11
Snapshot recorded successfully for session test
5757
[07:09:43.335916076] (+?.?????????) 07f8cf84a38f
ust_baddr_statedump:soinfo: { cpu_id = 2 }, { baddr = 0x7FFFAD1FE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[07:09:43.814938128] (+0.000001371) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }
NUMBER OF DIFF HUNKS = 1
Snapshot recorded successfully for session test
6066
[07:09:43.335916076] (+?.?????????) 07f8cf84a38f
ust_baddr_statedump:soinfo: { cpu_id = 2 }, { baddr = 0x7FFFAD1FE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[07:09:43.919112586] (+0.000000990) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }
NUMBER OF DIFF HUNKS = 11
Snapshot recorded successfully for session test
6077
[07:09:43.335916076] (+?.?????????) 07f8cf84a38f
ust_baddr_statedump:soinfo: { cpu_id = 2 }, { baddr = 0x7FFFAD1FE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[07:09:44.004234933] (+0.000001213) 07f8cf84a38f tracetest:first_tp: {
cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }
NUMBER OF DIFF HUNKS = 2
Waiting for data availability
Tracing stopped for session test
Session test destroyed
---------------------------------------------------------------
Regards
Anders Wallin
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20141114/f2507f62/attachment-0001.html>
More information about the lttng-dev
mailing list