[lttng-dev] snapshot issue with 2.5

[Anders Wallin]

Hi,

using userspace snapshot mode in 2.5 seems to broken.

I have small stupid application(tracetest) generating 1000 events

Running the script (the below is simplified version of the script)
----------------------------------------------------------------------------------
#!/bin/bash
LTTNG='lttng -n'
lttng-sessiond --no-kernel &

$LTTNG create test --snapshot
$LTTNG enable-channel -u --subbuf-size 64k --num-subbuf 16 --overwrite ch1
$LTTNG enable-event -u -c ch1 "*"
$LTTNG start
$LTTNG list ch1

mkdir -p snapshot/

for i in $(seq 1 $LOOPS); do
    ./tracetest
    $LTTNG snapshot record -m 1G

    # 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
done

$LTTNG stop
$LTTNG destroy $SESSION
----------------------------------------------------------------------------------

The result of the run looks like this;
./test.run

Error: consumer err socket second poll error
Error: Health error occurred in thread_manage_consumer
PERROR - 13:36:59.685167 [23772/23781]: bind inet: Address already in use
(in lttcomm_bind_inet_sock() at inet.c:109)
Warning: Another session daemon is using this JUL port. JUL support will be
deactivated to prevent interfering with the tracing.

lttng (LTTng Trace Control) 2.5.2 - Fumisterie
BabelTrace Trace Viewer and Converter 1.2.4
        linux-vdso.so.1 =>  (0x00007fffba966000)
        liblttng-ctl.so.0 => /usr/lib/x86_64-linux-gnu/liblttng-ctl.so.0
(0x00007fbfe4b1d000)
        librt.so.1 => /lib/x86_64-linux-gnu/librt.so.1 (0x00007fbfe4915000)
        libxml2.so.2 => /usr/lib/x86_64-linux-gnu/libxml2.so.2
(0x00007fbfe45ae000)
        libpopt.so.0 => /lib/x86_64-linux-gnu/libpopt.so.0
(0x00007fbfe43a2000)
        libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0
(0x00007fbfe4184000)
        libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007fbfe3dbd000)
        /lib64/ld-linux-x86-64.so.2 (0x00007fbfe4fac000)
        liburcu.so.2 => /usr/lib/x86_64-linux-gnu/liburcu.so.2
(0x00007fbfe3bb6000)
        libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007fbfe39b2000)
        libz.so.1 => /lib/x86_64-linux-gnu/libz.so.1 (0x00007fbfe3798000)
        liblzma.so.5 => /lib/x86_64-linux-gnu/liblzma.so.5
(0x00007fbfe3576000)
        libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007fbfe3270000)

Session test created.
Default snapshot output set to:
/home/awallin/lttng-traces/test-20141112-133700
Snapshot mode set. Every channel enabled for that session will be set in
overwrite mode and mmap output.
UST channel ch1 enabled for session test
UST event * created in channel ch1
Tracing started for session test
Tracing session test: [active snapshot]
    Trace path:
    Live timer interval (usec): 4294967295

=== Domain: UST global ===

Channels:
-------------
- ch1: [enabled]

    Attributes:
      overwrite mode: 1
      subbufers size: 4096
      number of subbufers: 16
      switch timer interval: 0
      read timer interval: 0
      trace file count: 0
      trace file size (bytes): 0
      output: mmap()

    Events:
      * (type: tracepoint) [enabled]

Snapshot recorded successfully for session test
84
[13:37:00.852615950] (+?.?????????) arn-awallin-mint-l3
ust_baddr_statedump:soinfo: { cpu_id = 4 }, { baddr = 0x7FFFC6BC7000,
sopath = "[vdso]", size = 0, mtime = -1 }
[13:37:00.853798949] (+0.000000805) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }
Snapshot recorded successfully for session test
157
[13:37:00.853735195] (+?.?????????) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 6 }, { my_string_field = "test", my_integer_field = 927 }
[13:37:00.894839116] (+0.000000299) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }
Snapshot recorded successfully for session test
168
[13:37:00.853735195] (+?.?????????) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 6 }, { my_string_field = "test", my_integer_field = 927 }
[13:37:00.929447330] (+0.000000305) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }
Snapshot recorded successfully for session test
168
[13:37:00.894411117] (+?.?????????) arn-awallin-mint-l3
ust_baddr_statedump:soinfo: { cpu_id = 4 }, { baddr = 0x7FFF6BF81000,
sopath = "[vdso]", size = 0, mtime = -1 }
[13:37:00.972035546] (+0.000000597) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }
Snapshot recorded successfully for session test
168
[13:37:00.894411117] (+?.?????????) arn-awallin-mint-l3
ust_baddr_statedump:soinfo: { cpu_id = 4 }, { baddr = 0x7FFF6BF81000,
sopath = "[vdso]", size = 0, mtime = -1 }
[13:37:01.014060940] (+0.000000341) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 7 }, { my_string_field = "test", my_integer_field = 999 }
Snapshot recorded successfully for session test
168
[13:37:00.894411117] (+?.?????????) arn-awallin-mint-l3
ust_baddr_statedump:soinfo: { cpu_id = 4 }, { baddr = 0x7FFF6BF81000,
sopath = "[vdso]", size = 0, mtime = -1 }
[13:37:01.052555877] (+0.000000872) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }
Snapshot recorded successfully for session test
168
[13:37:01.014035993] (+?.?????????) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 7 }, { my_string_field = "test", my_integer_field = 927 }
[13:37:01.098620808] (+0.000001404) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 4 }, { my_string_field = "test", my_integer_field = 999 }
Snapshot recorded successfully for session test
168
[13:37:01.097087388] (+?.?????????) arn-awallin-mint-l3
ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF4BFFE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[13:37:01.129839830] (+0.000000533) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 7 }, { my_string_field = "test", my_integer_field = 999 }
Snapshot recorded successfully for session test
168
[13:37:01.097087388] (+?.?????????) arn-awallin-mint-l3
ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF4BFFE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[13:37:01.129839830] (+0.000000533) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 7 }, { my_string_field = "test", my_integer_field = 999 }
Snapshot recorded successfully for session test
168
[13:37:01.097087388] (+?.?????????) arn-awallin-mint-l3
ust_baddr_statedump:soinfo: { cpu_id = 6 }, { baddr = 0x7FFF4BFFE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[13:37:01.172829105] (+0.000000575) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 5 }, { my_string_field = "test", my_integer_field = 999 }
Snapshot recorded successfully for session test
168
[13:37:01.172021557] (+?.?????????) arn-awallin-mint-l3
ust_baddr_statedump:soinfo: { cpu_id = 7 }, { baddr = 0x7FFF653FE000,
sopath = "[vdso]", size = 0, mtime = -1 }
[13:37:01.220074165] (+0.000000553) arn-awallin-mint-l3 tracetest:first_tp:
{ cpu_id = 6 }, { my_string_field = "test", my_integer_field = 999 }
Waiting for data availability
Tracing stopped for session test
Session test destroyed

the result from the run on older versions of lttng creates bigger and
bigger event traces until reaching max size.

I have tested this on different architectures, with different buffer sizes
and number of buffer

Regards
Anders Wallin
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.lttng.org/pipermail/lttng-dev/attachments/20141112/a116401a/attachment.html>