[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