Allow creating a live tracing session with `ros2 trace`/`Trace`

[christophebedard]

By "live tracing," we mean processing or analyzing the trace data live as it gets generated. This is different from the usual workflow, which is to collect the trace data and then process it offline later, after the execution.

When using the lttng CLI, this is done with the --live option: https://lttng.org/docs/v2.13/#doc-lttng-live.

It would be good to expose it through the ros2 trace command and the Trace launch action. A live session can be created using lttng-ctl's lttng_create_session_live(); this would need to be exposed through lttngpy.

---

In the meantime, here's an example script to enable tracing for ROS 2 with a live session using the lttng CLI directly:

Click to expand: live_trace.sh

# live_trace.sh

if [ $# -eq 0 ]; then
  echo "Provide trace session name"
  exit 1
fi

session_name="$1"
hostname=$(hostname)

lttng create $session_name --live
lttng enable-channel -u ros --subbuf-size=8M
lttng enable-event -c ros -u 'ros2:*'
lttng add-context -u -t vtid -t vpid -t procname
lttng start

echo
echo "Live trace URI: net://localhost/host/$hostname/$session_name"
echo "Press any key to stop & destroy"
read
lttng stop
lttng destroy

Here's a simple Python script that can receive and process some trace data live using the babeltrace2 Python bindings (just an example script):

Click to expand: bt2_lttng_live.py

# bt2_lttng_live.py

import datetime
import sys
from typing import List

import bt2


def handle_trace_event(msg: bt2._EventMessageConst) -> None:
    event = msg.event
    ns_from_origin = msg.default_clock_snapshot.ns_from_origin
    timestamp = datetime.datetime.fromtimestamp(ns_from_origin / 1e9)
    print(f'{timestamp} {event.name}')
    # Accces field with event['field_name']
    # See:
    #   https://babeltrace.org/docs/v2.0/python/bt2/examples.html#get-a-specific-event-field-s-value
    # TODO
    if event.name == 'ros2:rclcpp_intra_publish':
        publisher_handle = event['publisher_handle']
        print(f'\tpub handle: {publisher_handle}')
    elif event.name == 'ros2:rclcpp_ring_buffer_dequeue':
        buffer = event['buffer']
        print(f'\tbuffer: {buffer}')


def process_live_trace(uri: str) -> None:
    # See example here:
    #   https://babeltrace.org/docs/v2.0/python/bt2/examples.html#create-explicit-source-components

    # Just switch source component to lttng-live:
    #   https://babeltrace.org/docs/v2.0/man7/babeltrace2-source.ctf.lttng-live.7/
    msg_it = bt2.TraceCollectionMessageIterator(
        bt2.ComponentSpec.from_named_plugin_and_component_class('ctf', 'lttng-live', {
            # See:
            #   https://babeltrace.org/docs/v2.0/man7/babeltrace2-source.ctf.lttng-live.7/#doc-_initialization_parameters
            'inputs': [uri],
        }),
    )

    # Ignore exception raised when we run out of events (i.e., consume too quickly)
    # TODO(christophebedard) not sure if there is a better way to do this
    while True:
        try:
            for msg in msg_it:
                if type(msg) is bt2._EventMessageConst:
                    handle_trace_event(msg)
        except bt2.TryAgain:
            pass


def main(argv: List[str]) -> int:
    if 1 != len(argv):
        print('provide 1 LTTng live path, e.g.: net://localhost/host/$HOSTNAME/session-name')
        print('print available session: babeltrace2 --input-format=lttng-live net://localhost')
        return 1
    live_uri = argv[0]
    print(f'LTTng live URI: {live_uri}')
    process_live_trace(live_uri)
    return 0


if __name__ == '__main__':
    sys.exit(main(sys.argv[1:]))

How to use:

1. ./live_trace.sh test
   • This should print a URI starting with net://
   • The goal of this issue is to do this using ros2 trace/Trace, but for now this script can be used
2. python3 bt2_lttng_live.py <URI>
   • With the URI from step 1
   • This should be started before the application (step 3), otherwise some important data may be missing depending on the analysis use-case. See also Find solution to allow starting to trace from any point in time #44 regarding finding a solution for this limitation.
3. Start your application

[ros-discourse]

This issue has been mentioned on ROS Discourse. There might be relevant details there:

https://discourse.ros.org/t/how-do-you-monitor-your-robot-diagnostics-topic-rates/41191/9

[ros-discourse]

This issue has been mentioned on ROS Discourse. There might be relevant details there:

https://discourse.ros.org/t/how-do-you-monitor-your-robot-diagnostics-topic-rates/41191/12

[suchetanrs]

Hey @christophebedard !

I've been looking to contribute to this work since a while. I've gone through the issues related to this ticket.
I used your scripts to setup live tracing on a simple talker node. However, I received no outputs when I ran babeltrace2 --input-format=lttng-live net://localhost/host/cluttered/my-trace-test. Same with the python bindings.

It seems like an issue with the --subbuf-size=8M. When I don't specify a buffer size, all works well. I assume lttng is picking up a default size in the latter case. I am not sure about the root cause of this issue.

[christophebedard]

Interesting, not sure why. Have you tried increasing the subbuffer value to, say, 16M? If there are too many events, LTTng may have to write over some of them. For a simple talker node, it should be fine, though. Not sure if the live mode could have anything to do with it, but I can take a look tomorrow.

[suchetanrs]

Thanks a lot for your reply! I restarted the container I was running and I have not been able to reproduce it since. Not sure what the issue was. It works for me with the 8M subbuffer value.

I tried to create a live session using lttngpy. The PR for that is raised here #164.
The live session can be started using the below python file which mimics the live_trace.sh using lttngpy on the rolling branch.

trace_live_lttngpy.py

# trace_live_lttngpy.py

#!/usr/bin/env python3
import os
import sys
import socket
from lttngpy import impl as lttngpy

def main():
    if len(sys.argv) < 2:
        print("Provide trace session name")
        sys.exit(1)
    session_name = sys.argv[1]
    hostname = socket.gethostname()

    # trace_dir = os.path.join("/root/lttng-traces", session_name)

    # Create a live session
    ret = lttngpy.lttng_create_session_live(session_name=session_name, url="net://localhost", timer_interval=1000000)
    if ret < 0:
        error = lttngpy.lttng_strerror(ret)
        raise RuntimeError(f"failed to create live session '{session_name}': {error}")

    # Enable channel ros
    ret = lttngpy.enable_channel(
        session_name=session_name,
        domain_type=lttngpy.LTTNG_DOMAIN_UST,
        buffer_type=lttngpy.LTTNG_BUFFER_PER_UID,
        channel_name="ros",
        overwrite=0,
        subbuf_size=8 * 4096,
        num_subbuf=2,
        switch_timer_interval=200,
        read_timer_interval=200,
        output=lttngpy.LTTNG_EVENT_MMAP,
    )
    if ret < 0:
        error = lttngpy.lttng_strerror(ret)
        raise RuntimeError(f"failed to enable channel 'ros': {error}")

    # enable events ros2:*
    ret = lttngpy.enable_events(
        session_name=session_name,
        domain_type=lttngpy.LTTNG_DOMAIN_UST,
        event_type=lttngpy.LTTNG_EVENT_TRACEPOINT,
        channel_name="ros",
        events={"ros2:*"},
    )
    if ret < 0:
        error = lttngpy.lttng_strerror(ret)
        raise RuntimeError(f"failed to enable event 'ros2:*': {error}")

    # add more context fields to trace
    ret = lttngpy.add_contexts(
        session_name=session_name,
        domain_type=lttngpy.LTTNG_DOMAIN_UST,
        channel_name="ros",
        context_fields={"vtid", "vpid", "procname"},
    )
    if ret < 0:
        error = lttngpy.lttng_strerror(ret)
        raise RuntimeError(f"failed to add context fields: {error}")

    # start tracing
    ret = lttngpy.lttng_start_tracing(session_name=session_name)
    if ret < 0:
        error = lttngpy.lttng_strerror(ret)
        raise RuntimeError(f"failed to start tracing: {error}")

    print("")
    print(f"Live trace URI: net://localhost/host/{hostname}/{session_name}")
    input("Press Enter to stop & destroy...")

    # stop tracing
    ret = lttngpy.lttng_stop_tracing(session_name=session_name)
    if ret < 0:
        error = lttngpy.lttng_strerror(ret)
        raise RuntimeError(f"failed to stop tracing: {error}")

    # destroy session
    ret = lttngpy.lttng_destroy_session(session_name=session_name)
    if ret < 0:
        error = lttngpy.lttng_strerror(ret)
        raise RuntimeError(f"failed to destroy session: {error}")

if __name__ == '__main__':
    if not lttngpy.is_available():
        print("LTTng control is not available.")
        sys.exit(1)
    main()

I will attempt to integrate the live tracing feature further with the tracing codebase. Please let me know if there are any issues with my PR or the python script :D

[christophebedard]

I restarted the container I was running and I have not been able to reproduce it since. Not sure what the issue was. It works for me with the 8M subbuffer value.

Weird! But good to hear that it works.

I will attempt to integrate the live tracing feature further with the tracing codebase. Please let me know if there are any issues with my PR or the python script :D

I'll take a look at your PR.

[suchetanrs]

Hello! @christophebedard 😄

Thanks for sharing your branch. It gave me a good headstart and helped me understanding the code better!
I continued from where you left. Although it's still a WIP after my updates, I added a few things.
Description of what I added and the PR is here #165.

I modified the --live argument because figuring out if it was a live session through this made specifying the timer interval mandatory. I also added the option to specify the url_origin which defaults to net://localhost.

We can now trigger live mode with ros2 trace --live with the interval and url being optional.

I am sure there is a cleaner way to do this instead of passing the live_mode parameter around everywhere but I am not sure what the best approach for that is.

[ashwinvkNV]

Hi,

Thanks for your ros2_tracing contributions and your efforts to help integrate the live tracing feature.

I’m exploring the use of this tool as part of a live monitoring system that could publish to ROS 2 diagnostics. I'm evaluating whether it's practical to run this continuously in a production environment for real-time monitoring.

The overhead figures presented in this paper seem reasonable for some live monitoring scenarios. However, ROS graphs with many small messages might experience more noticeable overhead.

For live monitoring, persistent logging to disk may not be necessary. Has anyone looked into disabling disk writes and relying solely on trace callbacks(perhaps using something like Babeltrace) for real-time monitoring?

Additionally, monitoring every topic or interface might not be required. Are there any efforts or existing mechanisms to selectively enable or disable tracing based on trace types or the names of interfaces (e.g., topics, services, actions)?

[suchetanrs]

Hi,

There seems to be a similar discussion here #157 about tracing specific nodes/topics/services etc. I am not entirely sure but I think the only way is to do this in post-processing after you know the pid/procname since the trace output contains that information.

From what I've read, there's no direct solution to completely disable writing to the disk in live mode. However, the workaround is to limit the tracefile size for each channel and write to the tmpfs file system so that it only resides in memory. This can be done using the --output command when starting the LTTng relay daemon. More details here: https://lttng.org/man/8/lttng-relayd/v2.13/#doc-opt--output. A solution for a similar question is here: https://www.mail-archive.com/lttng-dev@lists.lttng.org/msg13246.html

There is another paper here https://www.landley.net/kdocs/ols/2006/ols2006v1-pages-209-224.pdf by the maintainer of LTTng which has some results about the overhead.

[KARTOFF8xE]

Hi,

Like mentioned, we discussed a similar topic here #157.
What exactly do you mean with "trace callbacks"? If I understood you correctly, you ask if there is a way to trigger specific functions depending on which type of trace-message and e.g. topic-Name. You can do this by using BabelTrace2 :). You don't need to write to disk for that, but could process a single trace-Message right within your BabelTrace trace-Graph and trigger something right within there. Another possibility would be a communication from the trace-Graph to something else (e.g. using MQTT) and trigger a more complex function there.

Sorry, I hope this message isn't too messy.