YAETS: Yet Another Execution Tracing System

YAETS is a library designed to trace function execution in C++ asynchronously, combined with Python tools to analyze the results through Gantt charts and histograms.

Features

• Function tracing using the TraceSession, TraceGuard, NamedSharedTrace, and TraceRegistry classes.
• Asynchronous logging of trace events to prevent performance overhead.
• Python scripts to visualize traces as Gantt charts or analyze timing gaps between traces using histograms.

Table of Contents

• YAETS: Yet Another Execution Tracing System
  • Features
  • Table of Contents
  • Installation
    • Requirements
    • Building the C++ Library without ROS
    • Building the C++ Library with ROS 2
  • Usage
    • C++ Tracing Library
      • Example
    • Advanced Tracing with NamedSharedTrace and TraceRegistry
      • NamedSharedTrace
      • Using TraceRegistry to Manage Shared Traces by ID
    • Using Macros with NamedSharedTrace
      • Example 1
      • Example 2
    • How It Works
      • Key Methods
    • Python Gantt Chart Script
      • Usage
      • Options
    • Python Histogram Script for ellapsed time
      • Usage
      • Options
    • Python Histogram Script for execution time
      • Usage
      • Options
  • Building and Running Tests
  • Tracing Session
    • Code to trace:
    • Running and getting graphs
  • License

Installation

Requirements

• C++17 or later
• CMake for building the project
• Python 3.6+ for running the scripts
• Matplotlib for visualizing data in Python

Building the C++ Library without ROS

1. Clone the repository and navigate to the project directory:

    git clone https://github.com/fmrico/yaets.git
    cd yaets
    

1. Build the library using CMake:

    mkdir build
    cd build
    cmake ..
    make
    

1. Install the library:

    sudo make install
    

Building the C++ Library with ROS 2

1. Clone the repository and navigate to the project directory:

    cd my_ros_ws/src
    git clone https://github.com/fmrico/yaets.git
    cd ..
    

1. Build the library using Colcon:

    colcon build
    

Usage

C++ Tracing Library

YAETS provides a simple C++ library for tracing function execution times. The key classes are TraceSession and TraceGuard.

Example

#include <yaets/tracing.hpp>

void example_function(yaets::TraceSession& session) {
    TRACE_EVENT(session);  // Automatically traces function entry and exit
    // Your function logic here
}

int main() {
    yaets::TraceSession session("trace_output.log");

    example_function(session);

    session.stop();  // Stop the session and flush all trace events
    return 0;
}

Advanced Tracing with NamedSharedTrace and TraceRegistry

For scenarios where you need to trace shared events across multiple parts of your application, you can use NamedSharedTrace and TraceRegistry.

NamedSharedTrace

The NamedSharedTrace class allows you to start and stop traces from different parts of the code, under a shared trace name.

#include <yaets/tracing.hpp>

int main() {
    yaets::TraceSession session("shared_trace_output.log");

    yaets::NamedSharedTrace trace1(session, "shared_event");
    trace1.start();
    // Perform operations
    trace1.end();

    session.stop();
    return 0;
}

Using TraceRegistry to Manage Shared Traces by ID

With TraceRegistry, you can register and manage multiple NamedSharedTrace instances by ID, allowing you to start and stop traces throughout the application without directly referencing NamedSharedTrace objects.

1. Initialize TraceRegistry: Register traces with IDs for centralized management.
2. Start and Stop Traces by ID: Use macros to simplify starting and stopping traces.

#include <yaets/tracing.hpp>

int main() {
    yaets::TraceSession session("registry_trace_output.log");

    // Register traces with unique IDs
    yaets::TraceRegistry::getInstance().registerTrace("trace1", session);
    yaets::TraceRegistry::getInstance().registerTrace("trace2", session);

    // Start and end traces by ID
    yaets::TraceRegistry::getInstance().startTrace("trace1");
    // Operations for trace1
    yaets::TraceRegistry::getInstance().endTrace("trace1");

    yaets::TraceRegistry::getInstance().startTrace("trace2");
    // Operations for trace2
    yaets::TraceRegistry::getInstance().endTrace("trace2");

    session.stop();
    return 0;
}

Using Macros with NamedSharedTrace

To streamline the usage of NamedSharedTrace with TraceRegistry, YAETS provides macros for initializing, starting, and stopping traces by ID. This simplifies code readability and reduces the need to call methods directly on TraceRegistry.

Example 1

include <yaets/tracing.hpp>

int main() {
    yaets::TraceSession session("macro_trace_output.log");

    // Initialize traces by ID
    SHARED_TRACE_INIT(session, "macro_trace1");
    SHARED_TRACE_INIT(session, "macro_trace2");

    // Start and stop traces by ID
    SHARED_TRACE_START("macro_trace1");
    // Operations under macro_trace1
    SHARED_TRACE_END("macro_trace1");

    SHARED_TRACE_START("macro_trace2");
    // Operations under macro_trace2
    SHARED_TRACE_END("macro_trace2");

    session.stop();
    return 0;
}

Example 2

class SensorDriverNode : public rclcpp::Node
{
  ...
  void produce_data()
  {
    SHARED_TRACE_START("brake_process");
    waste_time(shared_from_this(), 200us);

    sensor_msgs::msg::Image image_msg;
    pub_->publish(image_msg);
  }
...
class BrakeActuatorNode : public rclcpp::Node
{
  ...
  void react_obstacle(vision_msgs::msg::Detection3D::SharedPtr msg)
  {
    waste_time(shared_from_this(), 2ms);
    SHARED_TRACE_END("brake_process");
  } 
...
int main(int argc, char * argv[])
{
  ...
  SHARED_TRACE_INIT(session, "brake_process");

How It Works

• TraceSession: Manages the tracing session and writes events asynchronously to a log file.
• TraceGuard: Automatically traces the start and end of a function. It is created at the start of the function and destroyed when the function exits, capturing the execution time.
• NamedSharedTrace: Allows you to create named traces that can be started and stopped independently across different parts of your code.
• TraceRegistry: Provides centralized management of NamedSharedTrace instances, allowing you to register, start, and stop traces by ID.

Key Methods

• TraceSession::TraceSession(const std::string & filename): Initializes the session and specifies the output file for trace events.
• TraceSession::stop(): Stops the session and writes any remaining events to the file.
• TraceGuard::TraceGuard(TraceSession & session, const std::string & function_name): Captures the function name and start time.
• TraceGuard::~TraceGuard(): Logs the end time and registers the trace event.
• NamedSharedTrace::start(): Begins a trace event.
• NamedSharedTrace::end(): Ends a trace event and logs it to the associated TraceSession.
• TraceRegistry::registerTrace(const std::string& id, TraceSession& session): Registers a new trace with a unique ID.
• TraceRegistry::startTrace(const std::string& id): Starts a trace by its ID.
• TraceRegistry::endTrace(const std::string& id): Ends a trace by its ID.

Python Gantt Chart Script

The Python script gantt.py allows you to visualize the traced functions as a Gantt chart.

Usage

1. Ensure the trace log file is generated from your C++ program (e.g., trace_output.log).
2. Run the gantt.py script:

    python3 scripts/gantt.py trace_output.log --max_traces 100
    

or altenativelly

    ros2 run yaest gantt.py trace_output.log --max_traces 100
    

Options

• --max_traces: The maximum number of trace events to display in the Gantt chart.

The resulting Gantt chart shows each function’s execution times, allowing you to visualize the sequence and duration of function calls.

Python Histogram Script for ellapsed time

The Python script elaspsed_histogram.py analyzes the intervals between function executions and visualizes them as a histogram.

Usage

1. Run the elaspsed_histogram.py script, specifying the function name you want to analyze:

    python3 scripts/elaspsed_histogram.py trace_output.log --function example_function --bins 50
    

or altenativelly

    ros2 run yaest elaspsed_histogram.py trace_output.log --function example_function --bins 50
    

Options

• --function: The name of the function whose execution intervals you want to analyze.
• --bins: The number of bins for the histogram (to control the resolution).

This tool helps you understand how frequently functions are called and whether there are patterns in the execution intervals.

Python Histogram Script for execution time

The Python script execution_histogram.py analyzes execution time of a function and visualizes them as a histogram.

Usage

1. Run the execution_histogram.py script, specifying the function name you want to analyze:

    python3 scripts/execution_histogram.py trace_output.log --function example_function --bins 50
    

or altenativelly

    ros2 run yaest execution_histogram.py trace_output.log --function example_function --bins 50
    

Options

• --function: The name of the function whose execution execution time you want to analyze.
• --bins: The number of bins for the histogram (to control the resolution).

Building and Running Tests

YAETS includes unit tests to verify the functionality of the tracing library. To build and run the tests:

1. In the build directory, run the following commands:

    cd tests
    cmake ..
    make
    ./yaets_test
    

or

    colcon test
    

This will run the tests in tests/yaets_test.cpp and verify the correctness of the tracing system.

Tracing Session

We got the graphs at the initial of this document following these instructions:

Code to trace:

#include <fstream>

#include "yaets/tracing.hpp"

#include "rclcpp/rclcpp.hpp"
#include "std_msgs/msg/int32.hpp"

using namespace std::chrono_literals;
using std::placeholders::_1;


yaets::TraceSession session("session1.log");

class ProducerNode : public rclcpp::Node
{
public:
  ProducerNode() : Node("producer_node")
  {
    pub_1_ = create_publisher<std_msgs::msg::Int32>("topic_1", 100);
    pub_2_ = create_publisher<std_msgs::msg::Int32>("topic_2", 100);
    timer_ = create_wall_timer(1ms, std::bind(&ProducerNode::timer_callback, this));
  }

  void timer_callback()
  {
    TRACE_EVENT(session);
    message_.data += 1;
    pub_1_->publish(message_);
    message_.data += 1;
    pub_2_->publish(message_);
  }

private:
  rclcpp::Publisher<std_msgs::msg::Int32>::SharedPtr pub_1_, pub_2_;
  rclcpp::TimerBase::SharedPtr timer_;
  std_msgs::msg::Int32 message_;
};

class ConsumerNode : public rclcpp::Node
{
public:
  ConsumerNode() : Node("consumer_node")
  {
    sub_2_ = create_subscription<std_msgs::msg::Int32>(
      "topic_2", 100, std::bind(&ConsumerNode::cb_2, this, _1));
    sub_1_ = create_subscription<std_msgs::msg::Int32>(
      "topic_1", 100, std::bind(&ConsumerNode::cb_1, this, _1));
 
    timer_ = create_wall_timer(10ms, std::bind(&ConsumerNode::timer_callback, this));
  }

  void cb_1(const std_msgs::msg::Int32::SharedPtr msg)
  {
    TRACE_EVENT(session);

    waste_time(200us);
  }

  void cb_2(const std_msgs::msg::Int32::SharedPtr msg)
  {
    TRACE_EVENT(session);

    waste_time(200us);
  }

  void timer_callback()
  {
    TRACE_EVENT(session);

    waste_time(3ms);
  }

  void waste_time(const rclcpp::Duration & duration)
  {
    auto start = now();
    while (now() - start < duration);
  }

private:
  rclcpp::Subscription<std_msgs::msg::Int32>::SharedPtr sub_1_;
  rclcpp::Subscription<std_msgs::msg::Int32>::SharedPtr sub_2_;
  rclcpp::TimerBase::SharedPtr timer_;
};

int main(int argc, char * argv[])
{
  rclcpp::init(argc, argv);

  auto node_pub = std::make_shared<ProducerNode>();
  auto node_sub = std::make_shared<ConsumerNode>();

  rclcpp::executors::MultiThreadedExecutor executor;

  executor.add_node(node_pub);
  executor.add_node(node_sub);

  executor.spin();

  rclcpp::shutdown();
  return 0;
}

Running and getting graphs

Stress the system to have significant results:

stress-ng -c $(nproc) -t 300 # In terminal 1
ros2 run yaets executors     # In terminal 2

Stop both processes and

ros2 run yaest gantt.py ./session1.log --max_traces 200
ros2 run yaest elaspsed_histogram.py ../session1.log  --function ConsumerNode::timer_callback --bins 40

And we get the two graphs:

License

YAETS is licensed under the Apache License 2.0. See the LICENSE file for more details.

Contribution Guidelines

As an open-source project, we welcome and encourage the community to submit patches directly to the YAETS. In our collaborative open source environment, standards and methods for submitting changes help reduce the chaos that can result from an active development community.

This document explains how to participate in project conversations, log and track bugs and enhancement requests, and submit patches to the project so your patch will be accepted quickly in the codebase.

Licensing Licensing is very important to open source projects. It helps ensure the software continues to be available under the terms that the author desired.

Contributions should be made under the predominant license of that package. Entirely new packages should be made available under the Apache 2.0 license.

A license tells you what rights you have as a developer, as provided by the copyright holder. It is important that the contributor fully understands the licensing rights and agrees to them. Sometimes the copyright holder isn’t the contributor, such as when the contributor is doing work on behalf of a company.

Developer Certification of Origin (DCO)

To make a good faith effort to ensure licensing criteria are met, YAETS requires the Developer Certificate of Origin (DCO) process to be followed.

The DCO is an attestation attached to every contribution made by every developer. In the commit message of the contribution, (described more fully later in this document), the developer simply adds a Signed-off-by statement and thereby agrees to the DCO.

When a developer submits a patch, it is a commitment that the contributor has the right to submit the patch per the license. The DCO agreement is shown below and at http://developercertificate.org/.

Developer's Certificate of Origin 1.1

By making a contribution to this project, I certify that:

(a) The contribution was created in whole or in part by me and I
    have the right to submit it under the open source license
    indicated in the file; or

(b) The contribution is based upon previous work that, to the
    best of my knowledge, is covered under an appropriate open
    source license and I have the right under that license to
    submit that work with modifications, whether created in whole
    or in part by me, under the same open source license (unless
    I am permitted to submit under a different license), as
    Indicated in the file; or

(c) The contribution was provided directly to me by some other
    person who certified (a), (b) or (c) and I have not modified
    it.

(d) I understand and agree that this project and the contribution
    are public and that a record of the contribution (including
    all personal information I submit with it, including my
    sign-off) is maintained indefinitely and may be redistributed
    consistent with this project or the open source license(s)
    involved.

DCO Sign-Off Methods

The DCO requires that a sign-off message, in the following format, appears on each commit in the pull request:

Signed-off-by: Sofforus Jones <sjones@gmail.com>

The DCO text can either be manually added to your commit body, or you can add either -s or --signoff to your usual Git commit commands. If you forget to add the sign-off you can also amend a previous commit with the sign-off by running git commit --amend -s. If you’ve pushed your changes to GitHub already you’ll need to force push your branch after this with git push -f.

Note: The name and email address of the account you use to submit your PR must match the name and email address on the Signed-off-by line in your commit message.