Project

General

Profile

Bug #648

Something is fishy with truncated event names

Added by Daniel U. Thibault over 6 years ago. Updated 10 days ago.

Status:
Invalid
Priority:
Normal
Category:
-
Target version:
Start date:
10/10/2013
Due date:
% Done:

0%

Estimated time:

Description

I was fooling around with too-long event names when I stumbled into what seems to be corruption of the output trace (local session). I have unfortunately been unable so far to reliably reproduce the "bug" (virgin and corrupt sessions). The real question is how come the trace passed the babeltrace semantic check but then caused an "event id outside of range" error.

Here are the two console sessions (the first to run the sessions and babeltrace them, the second to compile/run the long-name user-space event provider). Some lines have already scrolled off the top of the second console, unfortunately:

$ lttng list
Available tracing sessions:
  1) local (/home/daniel/lttng-traces/local-20131007-163851) [inactive]

Use lttng list <session_name> for more details
$ lttng set-session local 
Session set to local
$ lttng enable-event -a -u
All UST events are enabled in channel channel0
$ lttng start
Tracing started for session local
$ lttng stop
Waiting for data availability
Tracing stopped for session local
$ babeltrace ~/lttng-traces/local-20131007-163851/ -w ~/lttng-traces/local -n all -f all
$ lttng start
Tracing started for session local
$ lttng stop
Waiting for data availability
Tracing stopped for session local
$ babeltrace ~/lttng-traces/local-20131007-163851/ -w ~/lttng-traces/local2 -n all -f all -v
[verbose] Verbose mode active.
[verbose] Converting from directory(ies):
[verbose]     /home/daniel/lttng-traces/local-20131007-163851/
[verbose] Converting from format: ctf <default>
[verbose] Converting to target: /home/daniel/lttng-traces/local2
[verbose] Converting to format: text <default>
[verbose] CTF visitor: parent links creation... [verbose] done.
[verbose] CTF visitor: semantic check... [verbose] done.
[verbose] CTF visitor: metadata construction...
[verbose] env.hostname = "sds-dut-vb" 
[verbose] env.domain = "ust" 
[verbose] env.tracer_name = "lttng-ust" 
[verbose] env.tracer_major = 2
[verbose] env.tracer_minor = 3
[verbose] done.
[error] Event id 8 is outside range.
[error] Reading event failed.
Error printing trace.

$ lttng create virgin
Session virgin created.
Traces will be written in /home/daniel/lttng-traces/virgin-20131010-093725
$ lttng enable-event -a -u
All UST events are enabled in channel channel0
$ lttng start
Tracing started for session virgin
$ lttng stop
Waiting for data availability
Tracing stopped for session virgin
$ babeltrace ~/lttng-traces/virgin-20131010-093725/ -w ~/lttng-traces/virgin -n all -f all
$ lttng create corrupt
Session corrupt created.
Traces will be written in /home/daniel/lttng-traces/corrupt-20131010-093928
$ lttng enable-event -a -u
All UST events are enabled in channel channel0
$ lttng start
Tracing started for session corrupt
$ lttng stop
Waiting for data availability
Tracing stopped for session corrupt
$ babeltrace ~/lttng-traces/corrupt-20131010-093928/ -w ~/lttng-traces/corrupt -n all -f all -v
[verbose] Verbose mode active.
[verbose] Converting from directory(ies):
[verbose]     /home/daniel/lttng-traces/corrupt-20131010-093928/
[verbose] Converting from format: ctf <default>
[verbose] Converting to target: /home/daniel/lttng-traces/corrupt
[verbose] Converting to format: text <default>
[verbose] CTF visitor: parent links creation... [verbose] done.
[verbose] CTF visitor: semantic check... [verbose] done.
[verbose] CTF visitor: metadata construction...
[verbose] env.hostname = "sds-dut-vb" 
[verbose] env.domain = "ust" 
[verbose] env.tracer_name = "lttng-ust" 
[verbose] env.tracer_major = 2
[verbose] env.tracer_minor = 3
[verbose] done.
[verbose] finished converting. Output written to:
/home/daniel/lttng-traces/corrupt
$ lttng start
Tracing started for session corrupt
$ lttng stop
Waiting for data availability
Tracing stopped for session corrupt
$ babeltrace ~/lttng-traces/corrupt-20131010-093928/ -w ~/lttng-traces/corrupt2 -n all -f all -v
[verbose] Verbose mode active.
[verbose] Converting from directory(ies):
[verbose]     /home/daniel/lttng-traces/corrupt-20131010-093928/
[verbose] Converting from format: ctf <default>
[verbose] Converting to target: /home/daniel/lttng-traces/corrupt2
[verbose] Converting to format: text <default>
[verbose] CTF visitor: parent links creation... [verbose] done.
[verbose] CTF visitor: semantic check... [verbose] done.
[verbose] CTF visitor: metadata construction...
[verbose] env.hostname = "sds-dut-vb" 
[verbose] env.domain = "ust" 
[verbose] env.tracer_name = "lttng-ust" 
[verbose] env.tracer_major = 2
[verbose] env.tracer_minor = 3
[verbose] done.
[verbose] finished converting. Output written to:
/home/daniel/lttng-traces/corrupt2
$ lttng start
Tracing started for session corrupt
$ lttng stop
Waiting for data availability
Tracing stopped for session corrupt
$ babeltrace ~/lttng-traces/corrupt-20131010-093928/ -w ~/lttng-traces/corrupt3 -n all -f all -v
[verbose] Verbose mode active.
[verbose] Converting from directory(ies):
[verbose]     /home/daniel/lttng-traces/corrupt-20131010-093928/
[verbose] Converting from format: ctf <default>
[verbose] Converting to target: /home/daniel/lttng-traces/corrupt3
[verbose] Converting to format: text <default>
[verbose] CTF visitor: parent links creation... [verbose] done.
[verbose] CTF visitor: semantic check... [verbose] done.
[verbose] CTF visitor: metadata construction...
[verbose] env.hostname = "sds-dut-vb" 
[verbose] env.domain = "ust" 
[verbose] env.tracer_name = "lttng-ust" 
[verbose] env.tracer_major = 2
[verbose] env.tracer_minor = 3
[verbose] done.
[verbose] finished converting. Output written to:
/home/daniel/lttng-traces/corrupt3
$ lttng start
Tracing started for session corrupt
$ lttng stop
Waiting for data availability
Tracing stopped for session corrupt
$ babeltrace ~/lttng-traces/corrupt-20131010-093928/ -w ~/lttng-traces/corrupt4 -n all -f all -v
[verbose] Verbose mode active.
[verbose] Converting from directory(ies):
[verbose]     /home/daniel/lttng-traces/corrupt-20131010-093928/
[verbose] Converting from format: ctf <default>
[verbose] Converting to target: /home/daniel/lttng-traces/corrupt4
[verbose] Converting to format: text <default>
[verbose] CTF visitor: parent links creation... [verbose] done.
[verbose] CTF visitor: semantic check... [verbose] done.
[verbose] CTF visitor: metadata construction...
[verbose] env.hostname = "sds-dut-vb" 
[verbose] env.domain = "ust" 
[verbose] env.tracer_name = "lttng-ust" 
[verbose] env.tracer_major = 2
[verbose] env.tracer_minor = 3
[verbose] done.
[verbose] finished converting. Output written to:
/home/daniel/lttng-traces/corrupt4
$ ./sample_static
liblttng_ust_tracepoint[14686/14686]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in add_callsite() at tracepoint.c:326)
liblttng_ust_tracepoint[14686/14686]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
sample starting
sample done

$ make clean
[...]
$ make static
[...]
$ ./sample_static
liblttng_ust_tracepoint[14900/14900]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in add_callsite() at tracepoint.c:326)
liblttng_ust_tracepoint[14900/14900]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
sample starting
sample done

$ make clean
[...]
$ make static
[...]
$ ./sample_static
sample starting
sample done
$ ./sample_static
sample starting
sample done
$ ./sample_static
sample starting
sample done
$ make clean
[...]
$ make static
[...]
$ ./sample_static
liblttng_ust_tracepoint[15378/15378]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in add_callsite() at tracepoint.c:326)
liblttng_ust_tracepoint[15378/15378]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[15378/15378]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[15378/15378]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in add_tracepoint() at tracepoint.c:276)
liblttng_ust_tracepoint[15378/15378]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[15378/15378]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in tracepoint_sync_callsites() at tracepoint.c:412)
sample starting
sample done
liblttng_ust_tracepoint[15378/15378]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[15378/15378]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[15378/15378]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256 which exceeds size limits of 255 chars (in tracepoint_sync_callsites() at tracepoint.c:412)

$ make clean
[...]
$ make static
[...]
$ ./sample_static
sample starting
sample done
$ ./sample_static
sample starting
sample done
$ make clean
[...]
$ make static
[...]
$ ./sample_static
liblttng_ust_tracepoint[15853/15853]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in add_callsite() at tracepoint.c:326)
liblttng_ust_tracepoint[15853/15853]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[15853/15853]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[15853/15853]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in add_tracepoint() at tracepoint.c:276)
liblttng_ust_tracepoint[15853/15853]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[15853/15853]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in tracepoint_sync_callsites() at tracepoint.c:412)
sample starting
sample done
liblttng_ust_tracepoint[15853/15853]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[15853/15853]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[15853/15853]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256_ which exceeds size limits of 255 chars (in tracepoint_sync_callsites() at tracepoint.c:412)

$ make clean
[...]
$ make static
[...]
$ ./sample_static
liblttng_ust_tracepoint[16086/16086]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256__ which exceeds size limits of 255 chars (in add_callsite() at tracepoint.c:326)
liblttng_ust_tracepoint[16086/16086]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256__ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[16086/16086]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256__ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[16086/16086]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256__ which exceeds size limits of 255 chars (in add_tracepoint() at tracepoint.c:276)
liblttng_ust_tracepoint[16086/16086]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256__ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[16086/16086]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256__ which exceeds size limits of 255 chars (in tracepoint_sync_callsites() at tracepoint.c:412)
sample starting
sample done
liblttng_ust_tracepoint[16086/16086]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256__ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[16086/16086]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256__ which exceeds size limits of 255 chars (in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[16086/16086]: Warning: Truncating tracepoint name sample_component:event24____30________40________50________60________70________80________90_______100_______110_______120_______130_______140_______150_______160_______170_______180_______190_______200_______210_______220_______230_______240_______250___256__ which exceeds size limits of 255 chars (in tracepoint_sync_callsites() at tracepoint.c:412)
  • Question: Why is it some runs of the too-long event provider raise only two "Warning: Truncating tracepoint name" but others do it 6+3 times?
  • Observation: Even if two different events whose names truncate to the same string are assigned to the same ID in the trace, this should not be a problem since we've seen in the past that babeltrace has no problem with two identically-named user-space events having completely different payloads. Or are different mechanisms in play here?

Using:
lttng-tools 2.3.0-1 c9dc128,
lttng-ust 2.3.0-1 9f00ce3,
userspace-rcu 0.8.0-1 ca617ca and
babeltrace 1.1.1-31-513413e


Files

local-20131007-163851.tar.gz (135 KB) local-20131007-163851.tar.gz The un-babeltraceable trace Daniel U. Thibault, 10/10/2013 10:27 AM
Makefile (1.81 KB) Makefile The Makefile for the simple project Daniel U. Thibault, 02/28/2014 04:54 PM
simpletp.h (2 KB) simpletp.h The simple project tracepoint provider (257 case) Daniel U. Thibault, 02/28/2014 04:54 PM
simple.c (1.77 KB) simple.c The simple project (257 case) Daniel U. Thibault, 02/28/2014 04:54 PM
#1

Updated by Mathieu Desnoyers about 6 years ago

  • Assignee set to Jérémie Galarneau
#2

Updated by Jérémie Galarneau almost 6 years ago

  • Status changed from New to Feedback

To answer your questions...

The real question is how come the trace passed the babeltrace semantic check but then caused an "event id outside of range" error.

The semantic check will validate the trace's metadata. The trace you provided seems fine in this regard. This check will not verify that each event in the trace is valid. The event id outside of range error is encountered because, for some reason, your stream contains an event which can't be mapped to an event description in the metadata.

Why is it some runs of the too-long event provider raise only two "Warning: Truncating tracepoint name" but others do it 6+3 times?

This is entirely dependent on your application. This warning is printed in four places in liblttng-ust.

Can you provide your application's source along with reproduction steps in chronological order? (in a single terminal)

#3

Updated by Daniel U. Thibault almost 6 years ago

I have not been able to reproduce the problem, but there are nevertheless several issues that need addressing here. (Or we could open a distinct bug report)

Observation: the 255 character limit applies to the 'provider:event' string, not the 'event' string.

Outside of two separate tracepoint providers registering the same provider and event names, the only event name collision we can get is when two events (from the same provider, to keep things simple) have the same first 255 characters in their names. When this happens, something odd goes on: whenever one event is invoked, the provider responds with each match, effectively duplicating the events.

For example, we have a simple application (simple.c, attached) that loops 10 000 times and emits 4 events in each loop:

int main(int argc, char **argv)
{
[...]
    fprintf(stderr, "sample starting\n");
    for (i = 0; i < 10000; i++) {
        sprintf(themessage, "Hello World %u %u", i, 254);
        tracepoint(simpletp, event____20_[...]_250___4,
        themessage);
        sprintf(themessage, "Hello World %u %u", i, 255);
        tracepoint(simpletp, event____20_[...]_250____5,
        themessage);
        sprintf(themessage, "Hello World %u %u", i, 256);
        tracepoint(simpletp, event____20_[...]_250_____6,
        themessage);
        sprintf(themessage, "Hello World %u %u", i, 257);
        tracepoint(simpletp, event____20_[...]_250______7,
        themessage);
        usleep(1);
    }
    fprintf(stderr, "sample done\n");
    return 0;
}

Both events event____20_[...]_250_____6 and event____20_[...]_250______7 will have their names truncated to "simpletp:event____20_[...]_250_____". Each call to event____20_[...]_250_____6 will generate two records, as will each call to event____20_[...]_250______7. The first record uses the ...7 tracepoint handler, the second record the ...6 tracepoint handler (you can find that out by playing with both events' TP_FIELDS definitions). Babeltrace will confuse the two events because their names truncate to the same event____20_[...]_250_____

If we had three events that truncated to the same name, each would generate three records, and so on. The trace grows as the square of the number of colliding event names.

Somehow LTTng accepts that a given tracepoint call can be serviced by a list of tracepoint handlers. That's the problem: any given tracepoint call ought to be serviced by only one tracepoint handler.

We also get an awful lot of warnings. When this is run, we get (the names have been shortened for legibility):

$ make clean
[...]
$ make
~~~~~~Compiling static.o:
gcc  -I.  -D TRACEPOINT_DEFINE -c -o static.o simple.c
~~~~~~Compiling simpletp.o:
gcc  -I.  -c \
    -x c -D TRACEPOINT_CREATE_PROBES -o simpletp.o simpletp.h
~~~~~~Linking simple_static:
gcc -o simple_static static.o simpletp.o -L/usr/local/lib  -ldl  -llttng-ust
   Use './simple_static' to run simple_static
$ lttng create s254-257
Session s254-257 created.
Traces will be written in /home/daniel/lttng-traces/s254-257-20140228-124109
$ lttng enable-event -u -a
All UST events are enabled in channel channel0
$ lttng start
Tracing started for session s254-257
$ ./simple_static
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_6 which exceeds size limits of 255 chars
(in add_callsite() at tracepoint.c:326)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_7 which exceeds size limits of 255 chars
(in add_callsite() at tracepoint.c:326)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_6 which exceeds size limits of 255 chars
(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_7 which exceeds size limits of 255 chars
(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_7 which exceeds size limits of 255 chars
(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_7 which exceeds size limits of 255 chars
(in add_tracepoint() at tracepoint.c:276)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_7 which exceeds size limits of 255 chars
(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_7 which exceeds size limits of 255 chars
(in tracepoint_sync_callsites() at tracepoint.c:412)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_6 which exceeds size limits of 255 chars
(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_6 which exceeds size limits of 255 chars
(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_6 which exceeds size limits of 255 chars
(in tracepoint_sync_callsites() at tracepoint.c:412)
sample starting
sample done
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_7 which exceeds size limits of 255 chars
(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_7 which exceeds size limits of 255 chars
(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_7 which exceeds size limits of 255 chars
(in tracepoint_sync_callsites() at tracepoint.c:412)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_6 which exceeds size limits of 255 chars
(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_6 which exceeds size limits of 255 chars
(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating tracepoint name
simpletp:event____20_[...]_6 which exceeds size limits of 255 chars
(in tracepoint_sync_callsites() at tracepoint.c:412)
$ lttng destroy
Session s254-257 destroyed
$ babeltrace ../../lttng-traces/s254-257-20140228-124109/
-w ../../lttng-traces/s254-257_nafav -v -n all -f all
[verbose] Verbose mode active.
[verbose] Converting from directory(ies):
[verbose]     ../../lttng-traces/s254-257-20140228-124109/
[verbose] Converting from format: ctf <default>
[verbose] Converting to target: ../../lttng-traces/s254-257_nafav
[verbose] Converting to format: text <default>
[verbose] CTF visitor: parent links creation... [verbose] done.
[verbose] CTF visitor: semantic check... [verbose] done.
[verbose] CTF visitor: metadata construction...
[verbose] env.hostname = "edge-vb-u12" 
[verbose] env.domain = "ust" 
[verbose] env.tracer_name = "lttng-ust" 
[verbose] env.tracer_major = 2
[verbose] env.tracer_minor = 3
[verbose] done.
[verbose] finished converting. Output written to:
../../lttng-traces/s254-257_nafav

During initialization, we are warned about truncation 11 times:

(in add_callsite() at tracepoint.c:326)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 257

(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 257
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 257

(in add_tracepoint() at tracepoint.c:276)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 257

(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 257

(in tracepoint_sync_callsites() at tracepoint.c:412)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 257

(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

(in tracepoint_sync_callsites() at tracepoint.c:412)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

During finalization, 6 times:

(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 257
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 257

(in tracepoint_sync_callsites() at tracepoint.c:412)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 257

(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

(in tracepoint_sync_callsites() at tracepoint.c:412)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

By comparison, if the tracepoint provider has just one event that needs truncation, we are warned only 5 and 2 times, respectively:

During initialization:

(in add_callsite() at tracepoint.c:326)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

(in add_tracepoint() at tracepoint.c:276)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

(in tracepoint_sync_callsites() at tracepoint.c:412)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

During finalization:

(in get_tracepoint() at tracepoint.c:250)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

(in tracepoint_sync_callsites() at tracepoint.c:412)
liblttng_ust_tracepoint[3369/3369]: Warning: Truncating 256

In the above case, all events had the same payload, a string 'message' field. If we change the name of the payload field of the 257-character event, interestingly, babeltrace doesn't see this and uses the 256-character event payload field name for the 257-character event instances.

If we change the payload of the 257-character event (to an int instead of a char *, for instance), we do get a warning during the app's initialization ("Tracepoint signature mismatch, not enabling one or more tracepoints. [...]") and the rest of the warnings only concern the 256-character event, making it look like the 257-character event was dropped correctly. But the app then promptly causes a segmentation fault. LTTng survives, luckily. Inspection of the babeltrace shows that the 256-character event was created but not the 257-character event. Babeltrace interprets the 256-character event using the 257-character event format.

The lttng-sessiond log sheds minimal light on what is going on:

DEBUG3 [4460/4565]: UST registry event simpletp:event____20_[...]_5 with id 1
added successfully (in add_event_ust_registry() at ust-app.c:4768)
[...]
DEBUG3 [4460/4565]: UST registry creating event with event:
simpletp:event____20_[...]_250_____, sig: const char *, text, id: 0, chan_objd: 2,
sess_objd: 1, chan_id: 0 (in ust_registry_create_event() at ust-registry.c:298)
DEBUG3 [4460/4565]: Append to metadata: "event {
    name = "simpletp:event____20_[...]_250_____";
    id = 2;
    stream_id = 0;
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [4460/4565]: Append to metadata: "    loglevel = 13;
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [4460/4565]: Append to metadata: "    fields := struct {
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [4460/4565]: Append to metadata: "        string _message;
" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [4460/4565]: Append to metadata: "    };
};

" (in lttng_metadata_printf() at ust-metadata.c:144)
DEBUG3 [4460/4565]: UST registry event simpletp:event____20_[...]_250_____ with id 2
added successfully (in add_event_ust_registry() at ust-app.c:4768)
[...]
DEBUG3 [4460/4565]: UST registry creating event with event:
simpletp:event____20_[...]_250_____, sig: const char *, text, id: 0, chan_objd: 2,
sess_objd: 1, chan_id: 0 (in ust_registry_create_event() at ust-registry.c:298)
DEBUG3 [4460/4565]: UST registry event simpletp:event____20_[...]__250_____ with id 2
added successfully (in add_event_ust_registry() at ust-app.c:4768)
[...]

Somehow both the ...6 event and the ...7 event ended up not only with the same truncated name, but also with the same ID.

Looking at the /lttng-ust/liblttng-ust/tracepoint.c code, set_tracepoint is instructive: it avoids flooding the console with repeated warnings of tracepoint signature mismatches. Clearly add_callsite / get_tracepoint / add_tracepoint / tracepoint_sync_callsites should do the same.

Note that set_tracepoint compares the tracepoint signatures using strcmp (not length-limited) to reject mismatches. Something in the add_callsite ... tracepoint_sync_callsites suite should likewise reject tracepoint names that differ when using strcmp but which truncate to the same names (that is to say, accept the first one, reject later arrivals). Since this test would only need to be done inside a 'if (name_len > LTTNG_UST_SYM_NAME_LEN - 1)' then branch, it wouldn't be too onerous.

#4

Updated by Jonathan Rajotte Julien 10 days ago

  • Status changed from Feedback to Invalid

State of babeltrace moved a lot since.

Closing this ticket as invalid. Reopen it if it stills apply to Babeltrace 2.

Also available in: Atom PDF