diff --git a/README.md b/README.md index 45873c2..897f771 100644 --- a/README.md +++ b/README.md @@ -61,6 +61,18 @@ See `examples/spans_c` and `examples/spans_cpp`. `decoder_tool/python/clltk_decoder.py ` 8. View your traces in `output.csv` +### Visual timelines + +`clltk export` converts trace files into Chrome/Perfetto trace event JSON: + +```bash +clltk export /tmp/traces -o trace.json +``` + +Open the file in https://ui.perfetto.dev to see tracepoints as instant events +and spans as async begin/end pairs on a timeline - including spans that were +still open when the process ended. + ## CLI Tool Commands The `clltk` command-line tool provides several commands for working with tracebuffers: diff --git a/VERSION.md b/VERSION.md index 9029c7a..9198bd5 100644 --- a/VERSION.md +++ b/VERSION.md @@ -1,6 +1,11 @@ -1.5.0 +1.5.1 # Change log +## 1.5.1 +- feat: `clltk export` converts trace files into Chrome/Perfetto trace event JSON + (open in ui.perfetto.dev): tracepoints as instant events, spans as async begin/end + pairs correlated by id, open spans visible. The decoder library gains a typed + `span_info()` accessor on tracepoints. ## 1.5.0 - feat: span tracking with carryable ids. `CLLTK_SPAN_BEGIN(buffer, parent, name)` evaluates to a plain uint64 span id that can be passed as a function argument, across threads, or diff --git a/command_line_tool/commands/export/CMakeLists.txt b/command_line_tool/commands/export/CMakeLists.txt new file mode 100644 index 0000000..9fa7584 --- /dev/null +++ b/command_line_tool/commands/export/CMakeLists.txt @@ -0,0 +1,16 @@ +# Copyright (c) 2024, International Business Machines +# SPDX-License-Identifier: BSD-2-Clause-Patent + +set(TARGET_NAME "clltk-cmd-export") + +add_library(${TARGET_NAME} OBJECT + export.cpp +) + +target_link_libraries(${TARGET_NAME} + PRIVATE + clltk-cmd-interface + clltk_decoder_static +) + +set(CLLTK_COMMAND_LINE_COMMANDS "${CLLTK_COMMAND_LINE_COMMANDS};${TARGET_NAME}" PARENT_SCOPE) diff --git a/command_line_tool/commands/export/export.cpp b/command_line_tool/commands/export/export.cpp new file mode 100644 index 0000000..69242c6 --- /dev/null +++ b/command_line_tool/commands/export/export.cpp @@ -0,0 +1,214 @@ +// Copyright (c) 2024, International Business Machines +// SPDX-License-Identifier: BSD-2-Clause-Patent + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "CommonLowLevelTracingKit/decoder/Tracebuffer.hpp" +#include "CommonLowLevelTracingKit/decoder/Tracepoint.hpp" +#include "commands/filter.hpp" +#include "commands/interface.hpp" +#include "commands/output.hpp" + +using namespace CommonLowLevelTracingKit::cmd::interface; +using Tracebuffer = CommonLowLevelTracingKit::decoder::Tracebuffer; +using SnapTracebuffer = CommonLowLevelTracingKit::decoder::SnapTracebuffer; +using SnapTracebufferPtr = CommonLowLevelTracingKit::decoder::SnapTracebufferPtr; +using Tracepoint = CommonLowLevelTracingKit::decoder::Tracepoint; +using TracepointPtr = CommonLowLevelTracingKit::decoder::TracepointPtr; +using SpanInfo = CommonLowLevelTracingKit::decoder::SpanInfo; + +static std::string hex64(uint64_t v) +{ + char buf[19]; + snprintf(buf, sizeof(buf), "0x%llx", static_cast(v)); + return buf; +} + +static void add_export_command(CLI::App &app) +{ + CLI::App *const command = + app.add_subcommand("export", "Export trace files as Chrome/Perfetto trace event JSON"); + command->alias("ex"); + command->description( + "Export one or multiple trace files to Chrome Trace Event Format JSON.\n" + "Output is compatible with chrome://tracing and Perfetto UI.\n" + "Supports single tracebuffer files, archives (.clltk snapshots), or directories."); + + static std::vector input_paths{}; + command + ->add_option("input", input_paths, + "Path(s) to trace data: file, .clltk archive, or directory\n" + "(default: CLLTK_TRACING_PATH or current directory)") + ->type_name("PATH"); + + static std::string output_path{}; + command + ->add_option("-o,--output", output_path, + "Output file path (default: stdout, use - for stdout)") + ->type_name("FILE"); + + static bool recursive = true; + command->add_flag("-r,--recursive,!--no-recursive", recursive, + "Recurse into subdirectories (default: yes)"); + + static std::string tracebuffer_filter_str = + CommonLowLevelTracingKit::cmd::interface::default_filter_pattern; + CommonLowLevelTracingKit::cmd::interface::add_filter_option(command, tracebuffer_filter_str); + + command->callback([&]() { + std::vector resolved_inputs; + if (input_paths.empty()) { + resolved_inputs.push_back(get_tracing_path().string()); + } else { + resolved_inputs = input_paths; + } + + const bool use_stdout = output_path.empty() || output_path == "-"; + FILE *raw_file = nullptr; + auto out = create_output(output_path, /*compress=*/false, &raw_file); + if (!out) { + log_error("Cannot open output: ", output_path.empty() ? "stdout" : output_path); + throw CLI::RuntimeError(1); + } + OutputFileGuard output_guard(use_stdout ? "" : output_path); + + const boost::regex tb_filter_regex{tracebuffer_filter_str}; + const auto tbFilter = [&](const Tracebuffer &tb) { + return match_tracebuffer_filter(tb.name(), tb_filter_regex); + }; + + // Collect all tracebuffers across all input paths + std::vector all_tbs; + for (const auto &input : resolved_inputs) { + auto tbs = SnapTracebuffer::collect(input, tbFilter, {}, recursive); + for (auto &tb : tbs) { + all_tbs.emplace_back(std::move(tb)); + } + } + + // Global sort by timestamp (ascending) using a min-heap via max-heap with inverted compare + static constexpr auto comp = [](const TracepointPtr &a, const TracepointPtr &b) { + return a->timestamp_ns > b->timestamp_ns; + }; + boost::heap::priority_queue> pq{comp}; + for (auto &tb : all_tbs) { + for (auto &tp : tb->tracepoints) { + pq.emplace(std::move(tp)); + } + } + + // Track span begin names so span_end events can carry the same name + std::unordered_map span_names; + + rapidjson::Document doc; + doc.SetObject(); + auto &alloc = doc.GetAllocator(); + rapidjson::Value trace_events(rapidjson::kArrayType); + + while (!pq.empty()) { + const Tracepoint &tp = *pq.top(); + const double ts_us = static_cast(tp.timestamp_ns) / 1000.0; + const int pid = static_cast(tp.pid()); + const int tid = static_cast(tp.tid()); + + const auto sv_val = [&](std::string_view sv) { + rapidjson::Value v; + v.SetString(sv.data(), static_cast(sv.size()), alloc); + return v; + }; + const auto str_val = [&](const std::string &s) { return sv_val(std::string_view(s)); }; + + auto si = tp.span_info(); + if (si.has_value()) { + const SpanInfo &s = *si; + if (s.kind == SpanInfo::Kind::Begin) { + span_names[s.id] = s.name; + const std::string id_str = hex64(s.id); + + rapidjson::Value ev(rapidjson::kObjectType); + ev.AddMember("name", str_val(s.name), alloc); + ev.AddMember("ph", rapidjson::Value("b", alloc), alloc); + ev.AddMember("cat", sv_val(tp.tracebuffer()), alloc); + ev.AddMember("id", str_val(id_str), alloc); + ev.AddMember("ts", rapidjson::Value(ts_us), alloc); + ev.AddMember("pid", rapidjson::Value(pid), alloc); + ev.AddMember("tid", rapidjson::Value(tid), alloc); + if (s.parent_id != 0) { + const std::string parent_str = hex64(s.parent_id); + rapidjson::Value args(rapidjson::kObjectType); + args.AddMember("parent", str_val(parent_str), alloc); + ev.AddMember("args", std::move(args), alloc); + } + trace_events.PushBack(std::move(ev), alloc); + } else { + // Kind::End + const std::string id_str = hex64(s.id); + std::string name; + auto it = span_names.find(s.id); + if (it != span_names.end()) + name = it->second; + + rapidjson::Value ev(rapidjson::kObjectType); + ev.AddMember("ph", rapidjson::Value("e", alloc), alloc); + ev.AddMember("cat", sv_val(tp.tracebuffer()), alloc); + ev.AddMember("id", str_val(id_str), alloc); + ev.AddMember("name", str_val(name), alloc); + ev.AddMember("ts", rapidjson::Value(ts_us), alloc); + ev.AddMember("pid", rapidjson::Value(pid), alloc); + ev.AddMember("tid", rapidjson::Value(tid), alloc); + trace_events.PushBack(std::move(ev), alloc); + } + } else { + // Regular (instant) tracepoint + rapidjson::Value ev(rapidjson::kObjectType); + ev.AddMember("name", sv_val(tp.msg()), alloc); + ev.AddMember("ph", rapidjson::Value("i", alloc), alloc); + ev.AddMember("s", rapidjson::Value("t", alloc), alloc); + ev.AddMember("ts", rapidjson::Value(ts_us), alloc); + ev.AddMember("pid", rapidjson::Value(pid), alloc); + ev.AddMember("tid", rapidjson::Value(tid), alloc); + ev.AddMember("cat", sv_val(tp.tracebuffer()), alloc); + rapidjson::Value args(rapidjson::kObjectType); + args.AddMember("file", sv_val(tp.file()), alloc); + args.AddMember("line", rapidjson::Value(static_cast(tp.line())), alloc); + ev.AddMember("args", std::move(args), alloc); + trace_events.PushBack(std::move(ev), alloc); + } + + pq.pop(); + } + + doc.AddMember("displayTimeUnit", rapidjson::Value("ms", alloc), alloc); + doc.AddMember("traceEvents", std::move(trace_events), alloc); + + rapidjson::StringBuffer buf; + rapidjson::Writer writer(buf); + doc.Accept(writer); + + out->printf("%s\n", buf.GetString()); + + if (!use_stdout && raw_file != nullptr) { + std::fclose(raw_file); + } + out.reset(); + + log_verbose("Exported trace events to ", + output_path.empty() ? std::string("stdout") : output_path); + return 0; + }); +} + +static void init_function() noexcept +{ + auto [app, lock] = CommonLowLevelTracingKit::cmd::interface::acquireMainApp(); + add_export_command(app); +} +COMMAND_INIT(init_function); diff --git a/decoder_tool/cpp/include/CommonLowLevelTracingKit/decoder/Tracepoint.hpp b/decoder_tool/cpp/include/CommonLowLevelTracingKit/decoder/Tracepoint.hpp index ff2c4f7..07dbdfd 100644 --- a/decoder_tool/cpp/include/CommonLowLevelTracingKit/decoder/Tracepoint.hpp +++ b/decoder_tool/cpp/include/CommonLowLevelTracingKit/decoder/Tracepoint.hpp @@ -2,6 +2,8 @@ #define DECODER_TOOL_TRACEPOINT_HEADER #include #include +#include +#include #include #include @@ -45,6 +47,21 @@ namespace CommonLowLevelTracingKit::decoder { using TracepointPtr = std::unique_ptr; using TracepointCollection = std::vector; + + /** + * @brief Span information for Static tracepoints of span_begin / span_end type. + * + * Only present when a Tracepoint is a span event (Static tracepoint with MetaType + * span_begin or span_end). Obtained via Tracepoint::span_info(). + */ + struct EXPORT SpanInfo { + enum class Kind { Begin, End }; + Kind kind; + uint64_t id; + uint64_t parent_id; ///< 0 when no parent (span_begin only; always 0 for span_end) + std::string name; ///< span name (format string); empty for span_end + }; + struct EXPORT Tracepoint { enum class Type { Dynamic = 1, @@ -65,6 +82,14 @@ namespace CommonLowLevelTracingKit::decoder { [[nodiscard]] virtual uint32_t tid() const noexcept = 0; [[nodiscard]] virtual const std::string_view msg() const = 0; + /** + * @brief Return span information if this is a span begin/end tracepoint. + * + * Returns nullopt for non-Static tracepoints and for Static tracepoints + * whose MetaType is printf or dump. + */ + [[nodiscard]] virtual std::optional span_info() const noexcept { return {}; } + [[nodiscard]] std::string timestamp_str() const noexcept; [[nodiscard]] std::string date_and_time_str() const noexcept; diff --git a/decoder_tool/cpp/source/Tracepoint.cpp b/decoder_tool/cpp/source/Tracepoint.cpp index dddda1d..1510879 100644 --- a/decoder_tool/cpp/source/Tracepoint.cpp +++ b/decoder_tool/cpp/source/Tracepoint.cpp @@ -167,6 +167,27 @@ const std::string_view TracepointStatic::msg() const { return m_msg; } +std::optional TracepointStatic::span_info() const noexcept { + if (m_type == MetaType::span_begin) { + const uint8_t *const arg_start = (e->size() > 22) ? &e->body()[22] : nullptr; + const size_t arg_size = (e->size() > 22) ? (e->size() - 22) : 0; + if (arg_size < 16) return {}; + std::span args_raw{arg_start, arg_size}; + const uint64_t id = get(args_raw, 0, e->foreignEndian()); + const uint64_t parent = get(args_raw, 8, e->foreignEndian()); + return SpanInfo{SpanInfo::Kind::Begin, id, parent, std::string(format())}; + } + if (m_type == MetaType::span_end) { + const uint8_t *const arg_start = (e->size() > 22) ? &e->body()[22] : nullptr; + const size_t arg_size = (e->size() > 22) ? (e->size() - 22) : 0; + if (arg_size < 8) return {}; + std::span args_raw{arg_start, arg_size}; + const uint64_t id = get(args_raw, 0, e->foreignEndian()); + return SpanInfo{SpanInfo::Kind::End, id, 0, {}}; + } + return {}; +} + std::string Tracepoint::date_and_time_str() const noexcept { return ToString::date_and_time(timestamp_ns); } diff --git a/decoder_tool/cpp/source/TracepointInternal.hpp b/decoder_tool/cpp/source/TracepointInternal.hpp index eda8030..2d2249f 100644 --- a/decoder_tool/cpp/source/TracepointInternal.hpp +++ b/decoder_tool/cpp/source/TracepointInternal.hpp @@ -124,6 +124,7 @@ namespace CommonLowLevelTracingKit::decoder { const std::string_view file() const noexcept override; uint64_t line() const noexcept override { return m_line; } const std::string_view msg() const override; + std::optional span_info() const noexcept override; private: const std::string_view format() const noexcept; diff --git a/docs/roadmap.asciidoc b/docs/roadmap.asciidoc index 38d2f7f..efc3008 100644 --- a/docs/roadmap.asciidoc +++ b/docs/roadmap.asciidoc @@ -102,8 +102,11 @@ surface for a feature this library deliberately does not want. Status: *accepted*. -`clltk export --perfetto` (Chrome/Perfetto track event JSON or protobuf) and -`--ctf` (Common Trace Format for babeltrace/TraceCompass). +`clltk export` producing Chrome/Perfetto trace event JSON (implemented +first: zero dependencies, opens directly in ui.perfetto.dev). CTF (Common +Trace Format for babeltrace/TraceCompass) remains a follow-up item - it +requires TSDL metadata generation and earns its complexity only on concrete +demand. * Spans map directly to track events, counters to counter tracks. * Pure decoder-side work with zero writer risk; the feature that makes spans diff --git a/tests/test_export_cmd.py b/tests/test_export_cmd.py new file mode 100644 index 0000000..ae98405 --- /dev/null +++ b/tests/test_export_cmd.py @@ -0,0 +1,89 @@ +#!/usr/bin/python3 +# Copyright (c) 2026, International Business Machines +# SPDX-License-Identifier: BSD-2-Clause-Patent + +""" +Tests for the 'clltk export' subcommand: Chrome/Perfetto trace event JSON +generated from the golden fixtures. +""" + +import json +import os +import pathlib +import sys +import tempfile +import unittest + +sys.path.insert(0, os.path.dirname(os.path.realpath(__file__))) + +from helpers.base import run_command +from helpers.clltk_cmd import clltk + +GOLDEN_DIR = pathlib.Path(__file__).parent / "golden" + + +def setUpModule(): + """Build clltk-cmd before running tests.""" + run_command("cmake --preset default") + run_command("cmake --build --preset default --target clltk-cmd") + + +def export_fixture(name: str) -> dict: + with tempfile.TemporaryDirectory() as tmp: + out = pathlib.Path(tmp) / "out.json" + result = clltk("export", str(GOLDEN_DIR / name), "-o", str(out)) + assert result.returncode == 0, result.stderr + with open(out) as fh: + return json.load(fh) + + +class export_golden_fixtures(unittest.TestCase): + def test_span_fixture_little_endian(self): + self._check_span_fixture("golden-1.5.0-le-aarch64.clltk_trace") + + def test_span_fixture_big_endian(self): + self._check_span_fixture("golden-1.5.0-be-s390x.clltk_trace") + + def _check_span_fixture(self, name: str): + data = export_fixture(name) + events = data["traceEvents"] + + begins = [e for e in events if e["ph"] == "b"] + ends = [e for e in events if e["ph"] == "e"] + instants = [e for e in events if e["ph"] == "i"] + + # golden writer: 3 span begins (one never ends), 2 ends, 7 tracepoints + self.assertEqual(3, len(begins)) + self.assertEqual(2, len(ends)) + self.assertEqual(7, len(instants)) + + # every end pairs with a begin; the open span has no end + begin_ids = {e["id"] for e in begins} + end_ids = {e["id"] for e in ends} + self.assertTrue(end_ids.issubset(begin_ids)) + self.assertEqual(1, len(begin_ids - end_ids)) + + # the inner span carries its parent's id + by_name = {e["name"]: e for e in begins} + self.assertIn("golden inner span", by_name) + self.assertEqual( + by_name["golden inner span"]["args"]["parent"], + by_name["golden outer span"]["id"], + ) + + # timestamps ascend and instants carry source location + timestamps = [e["ts"] for e in events] + self.assertEqual(timestamps, sorted(timestamps)) + for event in instants: + self.assertIn("file", event["args"]) + self.assertIn("line", event["args"]) + + def test_fixture_without_spans(self): + data = export_fixture("golden-1.3.0-le-aarch64.clltk_trace") + events = data["traceEvents"] + self.assertEqual(7, len([e for e in events if e["ph"] == "i"])) + self.assertEqual(0, len([e for e in events if e["ph"] in ("b", "e")])) + + +if __name__ == "__main__": + unittest.main()