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.