Re: Malformed Tracefiles

[Kienan Stewart via lttng-dev <lttng-dev@lists.lttng.org>]

Hi Georg,

On 6/25/25 1:27 PM, Georg Muck wrote:
> Hi Kienan,
> 
> thanks for your quick response. :)
> 
> I replaced "--daemonize" with "--background".
> 
> I guess I should briefly describe my goal to avoid confusion: I want to
> trace a ROS2-session online (tried LTTng-live, but it costs too much
> ressources, hence the aggressive rotation of 1s). LTTng gives me the path
> to a newly created trace-file as soon as it is created. This path is
> forwarded to a Thread-Pool that does the rest (analyses each tracefile by
> itself)… . However, the tracefiles are removed in the end, cause I'm not
> interested in them, only the program should be interested in them (forgot
> to remove it in the example). The problem only occurs when I start to many
> ROS2 instances at once, meaning gathering too many tracepoints at once (at
> once meaning in a very short amount of time). It works fine for 1-2
> instances, but it doesn't work for 16 instances.
> 
>> 1. *Before any traced application is run, babeltrace2 has the following
> error output:* Ah ok, thought I would be on the right track.
>> 2. *After a traced application is run whether is produces enabled events
> or not, I see the events recorded*: What do you mean by that? There is no
> babeltrace2 error if traced instances are running, even tho they are not
> creating events?

This is what I observed with a fresh start:

before running any traced application: bt2 error with no traced content

after running a traced application with no events: bt2 no longer 
produced an error, but output 0 events (as expected).

In this case I expect that it is because the consumer started and basic 
metadata was available so that was written in the snapshot. If I recall 
correctly, the consumer daemon only starts when the first application 
connects

after running a traced application with some events: as usual
>> 3. *When your session script stops, the output folder is deleted*: like
> described, forgot to remove, but it is on purpose
> 
> I tried *tp**:tptest*, but there is no output shown by babeltrace2 (is that
> intended?):
> 

I had the 100 events produced by gen-ust-events binary that invoked. You 
ran it but the events weren't recorded? Regardless I think we're on the 
same page that the session setup program you are using is fine right now.

> [georg@KARTOFF8xE-zenbook /tmp/structural_traces]$ babeltrace2 archives
> [georg@KARTOFF8xE-zenbook /tmp/structural_traces]$
> 
> 
> However, I figured something out:
> When I trace the "ros:rcl_node_init"-Tracepoint and start 12 ROS2
> Instances, I receive the following output for the entire archive-directory:
> [georg@KARTOFF8xE-zenbook /tmp/structural_traces/archives]$ babeltrace2 .
> 
> [19:01:41.474172508] (+?.?????????) KARTOFF8xE-zenbook:listener:(24897)
> ros2:rcl_node_init: { cpu_id = 1 }, { procname = "listener", vpid = 24897
> }, { node_handle = 0x5CCBD0EFA280, rmw_handle = 0x5CCBD107A420, node_name =
> "saturn_listener", namespace = "/hallo/saturn" }
> [19:01:41.493613263] (+0.019440755) KARTOFF8xE-zenbook:talker:(24898)
> ros2:rcl_node_init: { cpu_id = 4 }, { procname = "talker", vpid = 24898 },
> { node_handle = 0x5A8E10DFC6E0, rmw_handle = 0x5A8E10F8AA60, node_name =
> "erde_talker", namespace = "/hallo/erde" }
> 
> All coming from archive-file number 10:
> [georg@KARTOFF8xE-zenbook
> /tmp/structural_traces/archives/20250625T190141+0200-20250625T190142+0200-10]$
> babeltrace2 .
> 
> [19:01:41.474172508] (+?.?????????) KARTOFF8xE-zenbook:listener:(*24897*)
> ros2:rcl_node_init: { cpu_id = 1 }, { procname = "listener", vpid = 24897
> }, { node_handle = 0x5CCBD0EFA280, rmw_handle = 0x5CCBD107A420, node_name =
> "saturn_listener", namespace = "/hallo/saturn" }
> [19:01:41.493613263] (+0.019440755) KARTOFF8xE-zenbook:talker:(24898)
> ros2:rcl_node_init: { cpu_id = 4 }, { procname = "talker", vpid = 24898 },
> { node_handle = 0x5A8E10DFC6E0, rmw_handle = 0x5A8E10F8AA60, node_name =
> "erde_talker", namespace = "/hallo/erde" }
> 
> However, looking deeper into that file I saw that there are all 12
> instances (+some of ros2 itself) I started within the trace-directory
> number 10!
> [georg@KARTOFF8xE-zenbook
> /tmp/structural_traces/archives/20250625T190141+0200-20250625T190142+0200-10/ust/pid]$
> ls
> 
> listener-24897-20250625-190141  listener-24903-20250625-190141
>   ros2-24447-20250625-190131  ros2-24887-20250625-190141
>   talker-24900-20250625-190141  talker-24916-20250625-190141
> listener-24899-20250625-190141  listener-24914-20250625-190141
>   ros2-24451-20250625-190131  talker-24896-20250625-190141
>   talker-24902-20250625-190141
> listener-24901-20250625-190141  listener-24917-20250625-190141
>   ros2-24834-20250625-190134  talker-24898-20250625-190141
>   talker-24904-20250625-190141
> 
> BUT:
> I looked into the specific directory of a traced instance (underlined it)
> [georg@KARTOFF8xE-zenbook
> /tmp/structural_traces/archives/20250625T190141+0200-20250625T190142+0200-10/ust/pid]$
> ls listener-*24897*-20250625-190141/
> 
> index     structuralChannel_0  structuralChannel_2  structuralChannel_4
>   structuralChannel_6  structuralChannel_8  structuralChannel_10
> *metadata*  structuralChannel_1  structuralChannel_3  structuralChannel_5
>   structuralChannel_7  structuralChannel_9  structuralChannel_11
> 
> and of a non-traced instance:
> [georg@KARTOFF8xE-zenbook	
> /tmp/structural_traces/archives/20250625T190141+0200-20250625T190142+0200-10/ust/pid]$
> ls listener-24899-20250625-190141
> 
> index                structuralChannel_1  structuralChannel_3
>   structuralChannel_5  structuralChannel_7  structuralChannel_9
> structuralChannel_11
> structuralChannel_0  structuralChannel_2  structuralChannel_4
>   structuralChannel_6  structuralChannel_8  structuralChannel_10
> 
> Turns out: There is no metadata file within the second one. Therefore
> babeltrace2 is not able to parse the file. Do you have an idea why?
> 

 From your later e-mail with the updated sessiond log which shows the 
PERROR for too many open files it sounds like you have a thread to pull on.

You can try using the per-uid buffering scheme to reduce the number of 
FDs required when running 12 concurrent instances of ros.

> Best regards,
> Georg
> 
> Never burn the bridges before you
> If you've burned the bridges behind
> Never burn the one that you're walking upon
> Or you're sure to hit the water in time. *(Savatage, Streets, 1991)*
> 
> 
> Am Mi., 25. Juni 2025 um 17:50 Uhr schrieb Kienan Stewart <
> kstewart@efficios.com>:
> 
>> Hi Georg,
>>
>> On 6/25/25 9:36 AM, Georg Muck wrote:
>>> Hi Kienan,
>>>
>>> I did exactly that, without success.
>>>
>>> The log of the lttng-sessiond (lttng.log) did not change after starting
>> the
>>> ROS2 instances. I have also added the output of "lttng list
>>> structuralSession"
>>> I start my tracing instance as follows:
>>>
>>> At first there is a bash-script that sets everything up, it does the
>>> following:
>>>
>>> lttng destroy -a # to destroy all existing sessions
>>> lttng-sessiond --daemonize --verbose-consumer -vvv &> "/tmp/lttng.log" #
>>
>> When started with '--daemonize', the file descriptors are closed[1]
>> after forking which is why you don't see any further output to
>> /tmp/lttng.log. Try with '--background' instead.
>>
>>> starting a new session Deamon
>>> ./exemplary_tracing_session # starting my exemplary tracing session
>>>
>>> The exemplary tracing session is written by the help of the c Api
>>> (appendix).
>>>
>>
>> I modified your script to add 'tp:tptest' (a tracepoint from the
>> lttng-tools test suite program gen-ust-events) and did the following:
>>
>> ```
>> $ lttng-sessiond --background --verbose-consumer -vvv &> sessiond.log
>> $ ./exemplary_tracing_session &
>> $ lttng-tools/./tests/utils/testapp/gen-ust-events/gen-ust-events
>> babeltrace2 /tmp/structural_traces | wc -l
>> 100
>> ```
>>
>> It seems to be working fine for me. A couple of notes:
>>
>> 1. Before any traced application is run, babeltrace2 has the following
>> error output: No trace was found based on input `/tmp/structural_traces`
>> 2. After a traced application is run whether is produces enabled events
>> or not, I see the events recorded.
>> 3. When your session script stops, the output folder is deleted.
>>
>>> I started the the same procedure on another machine. The same fault
>>
>> The fault is that the babeltrace2 has an error, right? Are you willing
>> to share your trace that has the problem and/or show the output of
>> babeltrace2's error?
>>
>>> occurred. I think I need to configure more within the `lttngDomain`. But
>> I
>>> don't know how, would you have an idea/hint?
>>>
>>> Thanks for your help.
>>>
>>> Best regards,
>>> Georg
>>>
>>> Ps.: I also added the log of my tracing tool (structural.log)
>>>
>>> Never burn the bridges before you
>>> If you've burned the bridges behind
>>> Never burn the one that you're walking upon
>>> Or you're sure to hit the water in time. *(Savatage, Streets, 1991)*
>>>
>>>
>>> Am Mo., 23. Juni 2025 um 16:26 Uhr schrieb Kienan Stewart <
>>> kstewart@efficios.com>:
>>>
>>>> Hi Georg,
>>>>
>>>> a good first step is to run lttng-session with `-vvv --verbose-consumer`
>>>> and inspect the log file and `LTTNG_UST_DEBUG=1` in the environment.
>>>>
>>>> It may also be useful to run your traced applications with
>>>> `LTTNG_UST_DEBUG=1` set in the environment.
>>>>
>>>> Do you have steps that reproduce the issue? E.g., all the commands to
>>>> set up the tracing session and so forth.
>>>>
>>>> thanks,
>>>> kienan
>>>>
>>>> On 6/19/25 10:58 AM, Georg Muck via lttng-dev wrote:
>>>>> Hey,
>>>>>
>>>>> I am using the LTTng tracer (2.13.11, C-API, rotation=1s) to trace my
>>>> ROS2
>>>>> system (userspace only). Everything works just fine within my Docker
>>>>> Container (Ubuntu 24.04), but if I start the same procedure on the host
>>>>> itself (also Ubuntu 24.04), it does not create a TraceFile if to many
>>>>> tracepoints occur (speaking of roundabout 1500+ per second) (sometimes
>> it
>>>>> malformed the tracefile, but I was not able to recreate that. If I
>>>> remember
>>>>> correctly, Babeltrace2 threw an error that said that there was no
>>>>> metadata-file). I played around with some configurations (like
>> increasing
>>>>> the buffer size from ~16kB to ~512kB or a less aggressive rotation),
>> but
>>>>> the problem stayed.
>>>>>
>>>>> Would be thankful for help. I guess I delivered to less information,
>>>> please
>>>>> reach out what is interesting at this point, I am not sure about that
>> :).
>>>>>
>>>>> Best regards,
>>>>> Georg
>>>>>
>>>>>
>>>>>
>>>>> Never burn the bridges before you
>>>>> If you've burned the bridges behind
>>>>> Never burn the one that you're walking upon
>>>>> Or you're sure to hit the water in time. *(Savatage, Streets, 1991)*
>>>>>
>>>>
>>>>
>>>
>>
>> thanks,
>> kienan
>>
>> [1]: https://lttng.org/man/8/lttng-sessiond/v2.13/#doc-opt--daemonize
>>
>