Actions
Bug #648
closedSomething is fishy with truncated event names
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
Updated by Mathieu Desnoyers over 10 years ago
- Assignee set to Jérémie Galarneau
Updated by Jérémie Galarneau over 10 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)
Actions
#3
Updated by Daniel U. Thibault over 10 years ago
- File Makefile Makefile added
- File simpletp.h simpletp.h added
- File simple.c simple.c added
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.
Updated by Jonathan Rajotte Julien almost 5 years 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.
Actions