LTTng » Babeltrace

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