From 49d8dbb49bb5de02eaaf13b97f0ecb33fbf865dd Mon Sep 17 00:00:00 2001 From: Yaraslau Tamashevich Date: Sat, 3 Oct 2026 20:17:37 +0200 Subject: [PATCH 1/4] core, build: MORPH_ENABLE_TRACY and the MORPH_ZONE profiler macros MORPH_ENABLE_TRACY (default OFF) finds an installed Tracy, or fetches wolfpld/tracy v0.13.1 through CPM under Lightweight's package name, tag and options, so a process linking both libraries ends up with one TracyClient. MORPH_TRACY_ENABLED and Tracy::TracyClient are INTERFACE properties of morph::morph, and an installed morph finds Tracy for its consumer. A found client without TRACY_ENABLE is a configure error, since every zone would compile to nothing. include/morph/core/profiler.hpp defines MORPH_ZONE, MORPH_ZONE_TEXT, MORPH_PLOT, MORPH_THREAD_NAME and MORPH_MESSAGE, never Tracy's own names: Lightweight stubs those, and the two share translation units. With Tracy off each macro names its arguments only in decltype, so nothing is evaluated and no argument goes unused; tests/test_profiler.cpp holds both under the full warning set. The header and docs/spec/core/profiler.md state the ODR rule: every translation unit must agree on MORPH_TRACY_ENABLED; MSVC and clang-cl get a detect_mismatch link check. Tracy is added before core-cpp: core-cpp's own CORE_CPP_WITH_TRACY takes the client its parent provides, so a build with both on runs the one v0.13.1 client instead of failing to find one. Co-Authored-By: Claude Opus 5.5 --- CMakeLists.txt | 55 ++++++++++++ cmake/morphConfig.cmake.in | 7 ++ docs/CMakeLists.txt | 2 + docs/spec/README.md | 3 +- docs/spec/core/observability.md | 4 + docs/spec/core/profiler.md | 142 ++++++++++++++++++++++++++++++ include/morph/core/profiler.hpp | 150 ++++++++++++++++++++++++++++++++ tests/CMakeLists.txt | 1 + tests/test_profiler.cpp | 58 ++++++++++++ 9 files changed, 421 insertions(+), 1 deletion(-) create mode 100644 docs/spec/core/profiler.md create mode 100644 include/morph/core/profiler.hpp create mode 100644 tests/test_profiler.cpp diff --git a/CMakeLists.txt b/CMakeLists.txt index 71c67c84..937f6e10 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -198,6 +198,56 @@ if(NOT glaze_FOUND) OPTIONS "glaze_ENABLE_TESTS OFF") endif() +# ── Tracy (optional) ──────────────────────────────────────────────────────── +# MORPH_ENABLE_TRACY turns morph's MORPH_ZONE/MORPH_PLOT/... macros +# (include/morph/core/profiler.hpp) into Tracy calls. Found first, as glaze +# is, and fetched only when no installed Tracy is found. +# +# Before core-cpp, because core-cpp has Tracy instrumentation of its own +# (CORE_CPP_WITH_TRACY) and, with morph passing CORE_CPP_FETCH_DEPS OFF, takes +# the Tracy::TracyClient its parent has already provided. Added after it, a +# build with both on would have no client for core-cpp to find. +# +# The tag and the CPM name are Lightweight's, deliberately: an application +# that links both libraries must end up with exactly one TracyClient, because +# two copies of the client -- let alone two versions -- in one process do not +# work. With the same NAME, whichever of the two adds Tracy first fetches it +# and the other's CPMAddPackage reuses that copy; with the same tag, neither +# side is handed a version it did not ask for. TRACY_ON_DEMAND is +# Lightweight's choice too, and the one a library should make: without it the +# client buffers every event from process start until a profiler connects, +# which in a process nobody profiles is a leak. +# +# The define and the link are INTERFACE: morph is header-only, so the macros +# expand in the consumer's own translation units, and every one of them has +# to agree on MORPH_TRACY_ENABLED (see profiler.hpp on why that is an ODR +# matter). +option(MORPH_ENABLE_TRACY "Instrument morph's hot paths with Tracy profiler zones (fetches Tracy if not installed)" OFF) +set(MORPH_TRACY_GIT_TAG v0.13.1) +if(MORPH_ENABLE_TRACY) + find_package(Tracy CONFIG QUIET) + if(NOT Tracy_FOUND AND NOT TARGET Tracy::TracyClient) + morph_use_cpm(Tracy) + CPMAddPackage( + NAME tracy + GITHUB_REPOSITORY wolfpld/tracy + GIT_TAG ${MORPH_TRACY_GIT_TAG} + EXCLUDE_FROM_ALL YES + SYSTEM YES + OPTIONS "TRACY_ENABLE ON" "TRACY_ON_DEMAND ON") + endif() + # A TracyClient built without TRACY_ENABLE compiles every Tracy macro to + # nothing: the build would report profiling on and record no zone at all. + get_target_property(_morph_tracy_defs Tracy::TracyClient INTERFACE_COMPILE_DEFINITIONS) + if(NOT "${_morph_tracy_defs}" MATCHES "TRACY_ENABLE") + message(FATAL_ERROR + "MORPH_ENABLE_TRACY=ON, but the Tracy::TracyClient this configure found does not define " + "TRACY_ENABLE in its interface, so every zone would compile to nothing. Use a Tracy " + "built with TRACY_ENABLE=ON, or let morph fetch ${MORPH_TRACY_GIT_TAG}.") + endif() + unset(_morph_tracy_defs) +endif() + # ── core-cpp ──────────────────────────────────────────────────────────────── # The shared C++23 foundation of the Contour Terminal projects: morph takes # its event loop and timers, base64 and the wakeup primitive from it. Only the @@ -310,6 +360,10 @@ endif() if(MORPH_CLIENT_ONLY) target_compile_definitions(morph INTERFACE MORPH_CLIENT_ONLY) endif() +if(MORPH_ENABLE_TRACY) + target_compile_definitions(morph INTERFACE MORPH_TRACY_ENABLED) + target_link_libraries(morph INTERFACE Tracy::TracyClient) +endif() set_target_properties(morph PROPERTIES VERIFY_INTERFACE_HEADER_SETS ON @@ -324,6 +378,7 @@ target_sources(morph include/morph/attributes.hpp include/morph/core/logger.hpp include/morph/core/observability.hpp + include/morph/core/profiler.hpp include/morph/core/executor.hpp include/morph/core/strand.hpp include/morph/core/owner_strand.hpp diff --git a/cmake/morphConfig.cmake.in b/cmake/morphConfig.cmake.in index 0726057e..1c13a4de 100644 --- a/cmake/morphConfig.cmake.in +++ b/cmake/morphConfig.cmake.in @@ -39,6 +39,13 @@ if(NOT WIN32 AND NOT EMSCRIPTEN) find_dependency(Threads) endif() +# An install built with MORPH_ENABLE_TRACY=ON carries MORPH_TRACY_ENABLED and +# Tracy::TracyClient in morph::morph's interface, so the consumer links the +# same one client the build did. +if(@MORPH_ENABLE_TRACY@) + find_dependency(Tracy CONFIG) +endif() + # Optional components, each present only if its MORPH_BUILD_* option was on # for the build that produced this install. A component that was not built is # absent here, so find_package(morph COMPONENTS qt REQUIRED) fails with diff --git a/docs/CMakeLists.txt b/docs/CMakeLists.txt index cb6b4cdb..bc397b9e 100644 --- a/docs/CMakeLists.txt +++ b/docs/CMakeLists.txt @@ -58,6 +58,8 @@ set(DOXYGEN_EXCLUDE_SYMBOLS "morph::log::detail::*" "morph::observe::detail" "morph::observe::detail::*" + "morph::profiler::detail" + "morph::profiler::detail::*" "morph::exec::detail" "morph::exec::detail::*" "morph::async::detail" diff --git a/docs/spec/README.md b/docs/spec/README.md index 29ad02ce..b042cb4b 100644 --- a/docs/spec/README.md +++ b/docs/spec/README.md @@ -103,7 +103,8 @@ behavioural differences between the two, collected in one table, are in [`error_handling.md`](error_handling.md) · [`core/post_commit_tail.md`](core/post_commit_tail.md) · [`core/logger.md`](core/logger.md) · -[`core/observability.md`](core/observability.md) +[`core/observability.md`](core/observability.md) · +[`core/profiler.md`](core/profiler.md) **Working offline** [`offline/offline.md`](offline/offline.md) · diff --git a/docs/spec/core/observability.md b/docs/spec/core/observability.md index 7ec291c3..96ae5b83 100644 --- a/docs/spec/core/observability.md +++ b/docs/spec/core/observability.md @@ -279,3 +279,7 @@ See [backend.md](backend.md)'s `RemoteServer` API reference table. `reconnectOutcome` metrics report on. - [session.md](../session/session.md) — `Context::requestId`, reused as the trace correlation id. +- [profiler.md](profiler.md) — compile-time Tracy instrumentation behind + `MORPH_ENABLE_TRACY`. A build option rather than a sink: it is not wired + through this seam, and it links the phases of one call by the same + `requestId`. diff --git a/docs/spec/core/profiler.md b/docs/spec/core/profiler.md new file mode 100644 index 00000000..650aa13b --- /dev/null +++ b/docs/spec/core/profiler.md @@ -0,0 +1,142 @@ +# Profiler zones (`MORPH_ZONE` and friends) — design + +`include/morph/core/profiler.hpp` gives morph compile-time profiler +instrumentation: [Tracy](https://github.com/wolfpld/tracy) zones, thread +names, plots and messages, behind morph's own macro names. It is off by default and costs nothing when off: the +macros are stubs that do not evaluate their arguments, and the build has no +Tracy dependency. + +It is the compile-time counterpart of [`morph::observe`](observability.md), +not a part of it. `morph::observe` is a runtime seam a host wires to its own +metrics backend; this is a build option a developer turns on to look at a +timeline. + +## Contents + +- [Turning it on](#turning-it-on) +- [The macros](#the-macros) +- [Zones, phases and threads](#zones-phases-and-threads) +- [One definition everywhere](#one-definition-everywhere) +- [One Tracy client per process](#one-tracy-client-per-process) +- [Design decisions](#design-decisions) +- [Limitations](#limitations) + +## Turning it on + +```sh +cmake -S . -B build -DMORPH_ENABLE_TRACY=ON +``` + +CMake first looks for an installed Tracy (`find_package(Tracy CONFIG)`) and +otherwise fetches `wolfpld/tracy` at `v0.13.1` through CPM. Either way +`morph::morph` gains, as `INTERFACE` properties, the definition +`MORPH_TRACY_ENABLED` and a link to `Tracy::TracyClient`. A found +`TracyClient` that does not define `TRACY_ENABLE` is a configure error: every +Tracy macro would compile to nothing, and the build would claim profiling while +recording no zone. + +A fetched client is built with `TRACY_ON_DEMAND`, so a process records only +while a profiler is connected; without it, the client buffers every event from +process start until one connects. + +An installed morph built with Tracy on carries both properties in its exported +target, and its package config finds Tracy for the consumer. + +## The macros + +| Macro | Tracy on | Tracy off | +|---|---|---| +| `MORPH_ZONE(name)` | A zone named `name` (a string literal) that ends with the enclosing scope. At most one per scope. | Nothing. | +| `MORPH_ZONE_TEXT(text)` | Attaches `text` (anything convertible to `std::string_view`) to the innermost `MORPH_ZONE`; an empty text attaches nothing. | Nothing; `text` is not evaluated. | +| `MORPH_PLOT(name, value)` | Records `value`, as a `double`, on the plot `name` (a string literal). | Nothing; `value` is not evaluated. | +| `MORPH_THREAD_NAME(name)` | Names the calling thread. | Nothing. | +| `MORPH_MESSAGE(text)` | Sends `text` to the timeline. | Nothing; `text` is not evaluated. | + +A disabled macro discards an empty object whose type names each argument +through `decltype`. The operand of `decltype` is unevaluated, so a zone's text +costs nothing to compute in a build without Tracy, and naming each argument +there is what keeps a local used only by a macro from tripping +`-Wunused-variable` or `-Wunused-but-set-variable`. Not `sizeof`, which would +do the same for the compiler: clang-tidy reads `sizeof` of a string or a +pointer as a mistaken size computation (`bugprone-sizeof-container`, +`bugprone-sizeof-expression`). `tests/test_profiler.cpp` holds both properties: +every local in it is used only by a macro, under the project's full warning +set, and it counts how many times a zone text was computed. + +The names are morph's own. Lightweight defines stubs under Tracy's names +(`ZoneScoped`, `ZoneScopedN`, `TracyPlot`, …) when its Tracy option is off, and +an application can include Lightweight and morph in one translation unit. Were +morph to define the same names, a build with one library's Tracy on and the +other's off would have one header's stubs redefine the other's real macros. +`profiler.hpp` defines no Tracy name. + +## Zones, phases and threads + +A Tracy zone begins and ends on one thread, and zones on a thread must nest. A +dispatch does neither: it starts on the caller, runs on the model's strand, and +settles on whichever thread the backend settles from, with its callbacks on the +callback executor. So: + +- **Each phase is its own zone, on the thread that runs it.** No zone spans a + hand-off between threads. +- **No zone stays open across a `co_await`.** A suspended coroutine's thread + goes on to run other work, whose zones would close out of order with the + open one. +- **The phases of one call are linked by `session::Context::requestId`,** + written as zone text where the phase can see the call's session. A request + that carries no request id leaves its zones without text. + +## One definition everywhere + +morph is header-only, so these macros change the bodies of inline functions. +A program in which one translation unit is compiled with +`MORPH_TRACY_ENABLED` and another without it holds two definitions of the same +inline function — an ODR violation the linker resolves by keeping one, +silently. CMake consumers cannot get there: the definition is an `INTERFACE` +property of `morph::morph`, so every target that links it agrees. A build that +does not use morph's CMake package must define `MORPH_TRACY_ENABLED` for all +of its translation units or for none. + +MSVC and clang-cl turn a mismatch into a link error: `profiler.hpp` emits +`#pragma detect_mismatch("morph_tracy_enabled", "0" | "1")`. GCC and Clang +have no equivalent, and a mismatch there is undetected. + +## One Tracy client per process + +Two copies of Tracy's client in one process do not work, and two versions +certainly do not. Lightweight fetches Tracy itself when its own Tracy option is +on, so morph's fetch uses Lightweight's CPM name (`tracy`), tag (`v0.13.1`) and +options (`TRACY_ENABLE`, `TRACY_ON_DEMAND`). Whichever library adds Tracy +first fetches it; the other's `CPMAddPackage` finds the package already added +under that name and reuses it. Moving morph's tag means moving Lightweight's +with it. + +core-cpp has Tracy instrumentation of its own (`CORE_CPP_WITH_TRACY`, its +`CORE_*` macros) and pins `v0.14.1` when it fetches Tracy itself. Under morph +it fetches nothing (`CORE_CPP_FETCH_DEPS OFF`) and takes the +`Tracy::TracyClient` its parent has already provided, which is why morph adds +Tracy before core-cpp: a build with both options on runs the one `v0.13.1` +client, and core-cpp's instrumentation compiles against it. Such a build +cannot also install morph with a fetched Tracy — core-cpp's install rules do +not export a client it did not install — so it needs `MORPH_INSTALL=OFF` or an +installed Tracy. + +## Design decisions + +| Decision | Choice | Why | +|---|---|---| +| Macro names | `MORPH_*`, never Tracy's | Lightweight stubs Tracy's names; sharing them breaks a translation unit that includes both libraries with their Tracy options set differently. | +| Disabled form | `decltype` over the arguments | Unevaluated, so a zone's text is free when off, and still a use of every argument, so no unused-variable warnings. | +| Zone variable | `morphProfilerZone`, a nested one shadowing the outer one under a suppressed `-Wshadow` | `MORPH_ZONE_TEXT` has to find the innermost zone by name. Tracy's own `___tracy_scoped_zone` would be a reserved identifier once spelled in morph's header. | +| `MORPH_ZONE` on Tracy | `ZoneNamedN` with morph's own shadow suppression, followed by `static_assert(true)` | Tracy's `ZoneScopedN` ends in a `;` on some compilers and not on others, so the call site's `;` would be an empty statement on some. The `static_assert` consumes it on all. | +| Linking phases | `Context::requestId` as zone text | It is already the correlation id `morph::observe`'s trace sink uses, and every phase that can see the call can see it. | +| Tracy version | `v0.13.1`, Lightweight's tag and CPM name | One client per process. | +| Fetched client mode | `TRACY_ON_DEMAND` | A library must not make an unprofiled process buffer events forever. | + +## Limitations + +- **core-cpp is not instrumented.** Its event loop and strand pump are its own. +- **No statistics collector and no `morph::observe` → Tracy sink.** Both are + separate decisions about `morph::observe`, whose spec rules out aggregation + inside morph. +- **The ODR rule is enforced only under MSVC and clang-cl.** diff --git a/include/morph/core/profiler.hpp b/include/morph/core/profiler.hpp new file mode 100644 index 00000000..28d5896d --- /dev/null +++ b/include/morph/core/profiler.hpp @@ -0,0 +1,150 @@ +// SPDX-License-Identifier: Apache-2.0 + +#pragma once + +/// @file +/// @brief Compile-time profiler instrumentation: Tracy zones, plots, messages +/// and thread names, behind morph's own macro names. +/// +/// Configure with `-DMORPH_ENABLE_TRACY=ON` and the macros below forward to +/// Tracy (`MORPH_TRACY_ENABLED` is then defined on every target that links +/// `morph::morph`). Otherwise each macro is a stub that names its arguments +/// only inside `decltype`, an unevaluated operand: a disabled build evaluates +/// nothing, warns about no unused argument, and needs no Tracy headers. +/// +/// @par Why morph's names and not Tracy's +/// Lightweight defines stubs under Tracy's own names (`ZoneScoped`, +/// `ZoneScopedN`, `TracyPlot`, ...) when its own Tracy option is off, and an +/// application may include Lightweight and morph in one translation unit. Were +/// morph to do the same, a build with one library's Tracy on and the other's +/// off would have one header's stubs redefine the other's real macros. Every +/// macro here is spelled `MORPH_*` and none of Tracy's names is defined. +/// +/// @par One zone, one phase, one thread +/// A Tracy zone must begin and end on the same thread. A dispatch crosses +/// threads -- the caller, the model's strand, the callback executor -- so each +/// phase is its own zone on the thread that runs it, and the phases of one +/// call are linked by writing `session::Context::requestId` as zone text +/// (`MORPH_ZONE_TEXT`). No zone spans a hand-off, and none stays open across a +/// `co_await`: a suspended coroutine's thread goes on to run other work, whose +/// zones would then close out of order with the open one. +/// +/// @par Every translation unit must agree +/// morph is header-only, so these macros change the bodies of inline +/// functions. A program in which one translation unit sees +/// `MORPH_TRACY_ENABLED` and another does not holds two different definitions +/// of the same inline function, which is an ODR violation: the linker keeps +/// one of them, silently. CMake consumers get agreement by construction, +/// because the definition is an `INTERFACE` property of `morph::morph`. A +/// build that does not use morph's CMake package must define +/// `MORPH_TRACY_ENABLED` for all of its translation units or for none, and +/// link exactly one `TracyClient`. MSVC and clang-cl turn a mismatch into a +/// link error (`detect_mismatch` below); other toolchains do not detect it. + +// NOLINTBEGIN(cppcoreguidelines-macro-usage) — the macros are the API: a zone +// is a scoped local the call site's scope has to own, and a disabled argument +// must not be evaluated, neither of which a function can do. + +#ifdef MORPH_TRACY_ENABLED + +#include +#include + +namespace morph::profiler::detail { + +/// Attaches @p text to @p zone, skipping an empty one so a zone without a +/// request id carries no blank annotation. +inline void zoneText(::tracy::ScopedZone& zone, std::string_view text) { + if (!text.empty()) { + zone.Text(text.data(), text.size()); + } +} + +/// Sends @p text to the timeline as a message. +inline void message(std::string_view text) { TracyMessage(text.data(), text.size()); } + +} // namespace morph::profiler::detail + +// Every zone is a local named `morphProfilerZone`, so MORPH_ZONE_TEXT finds +// the innermost one; a nested zone therefore shadows the outer one on +// purpose, and the warning is silenced around the declaration. Not Tracy's +// own `___tracy_scoped_zone`: spelled in this header, a name with a double +// underscore is a reserved identifier at every call site. +// Not Tracy's ZoneScopedN: whether that expansion ends in a ';' depends on +// the compiler, and the one the call site writes would then be an empty +// statement. The trailing static_assert takes the call site's ';' instead. +#if defined(__clang__) +#define MORPH_ZONE(name) \ + _Pragma("clang diagnostic push") _Pragma("clang diagnostic ignored \"-Wshadow\"") \ + ZoneNamedN(morphProfilerZone, name, true); \ + _Pragma("clang diagnostic pop") static_assert(true) +#elif defined(__GNUC__) +#define MORPH_ZONE(name) \ + _Pragma("GCC diagnostic push") _Pragma("GCC diagnostic ignored \"-Wshadow\"") \ + ZoneNamedN(morphProfilerZone, name, true); \ + _Pragma("GCC diagnostic pop") static_assert(true) +#elif defined(_MSC_VER) +#define MORPH_ZONE(name) \ + _Pragma("warning(push)") _Pragma("warning(disable : 4456)") ZoneNamedN(morphProfilerZone, name, true); \ + _Pragma("warning(pop)") static_assert(true) +#else +#define MORPH_ZONE(name) ZoneNamedN(morphProfilerZone, name, true) +#endif +#define MORPH_ZONE_TEXT(text) ::morph::profiler::detail::zoneText(morphProfilerZone, (text)) +#define MORPH_PLOT(name, value) TracyPlot(name, static_cast(value)) +#define MORPH_THREAD_NAME(name) ::tracy::SetThreadName(name) +#define MORPH_MESSAGE(text) ::morph::profiler::detail::message((text)) + +#ifdef _MSC_VER +#pragma detect_mismatch("morph_tracy_enabled", "1") +#endif + +#else + +namespace morph::profiler::detail { + +/// What a disabled macro builds from its arguments' types: naming an argument +/// in `decltype` uses it without evaluating it, and an empty object costs +/// nothing to discard. +template +struct Unevaluated {}; + +} // namespace morph::profiler::detail + +/// @brief Opens a profiler zone named @p name that ends with the enclosing +/// scope. At most one per scope. +/// @param name A string literal: Tracy keeps a pointer to it for the life of +/// the process. +#define MORPH_ZONE(name) static_cast(::morph::profiler::detail::Unevaluated{}) + +/// @brief Attaches @p text to the enclosing scope's `MORPH_ZONE`; an empty +/// text attaches nothing. +/// +/// Only valid after a `MORPH_ZONE` in the same or an enclosing scope. +/// @param text Anything convertible to `std::string_view`; Tracy copies it. +/// Not evaluated in a build without Tracy. +#define MORPH_ZONE_TEXT(text) static_cast(::morph::profiler::detail::Unevaluated{}) + +/// @brief Records @p value on the plot named @p name. +/// @param name A string literal, the plot's identity in the capture. +/// @param value An arithmetic value, recorded as a `double`. Not evaluated in +/// a build without Tracy. +#define MORPH_PLOT(name, value) \ + static_cast(::morph::profiler::detail::Unevaluated{}) + +/// @brief Names the calling thread in the capture. +/// @param name A NUL-terminated string; Tracy copies it. +#define MORPH_THREAD_NAME(name) static_cast(::morph::profiler::detail::Unevaluated{}) + +/// @brief Sends @p text to the capture's timeline as a message. +/// @param text Anything convertible to `std::string_view`; Tracy copies it. +/// Not evaluated in a build without Tracy. +#define MORPH_MESSAGE(text) static_cast(::morph::profiler::detail::Unevaluated{}) + +#ifdef _MSC_VER +#pragma detect_mismatch("morph_tracy_enabled", "0") +#endif + +#endif + +// NOLINTEND(cppcoreguidelines-macro-usage) diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index e5043d1c..7d93f895 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -38,6 +38,7 @@ add_executable(morph_tests test_post_commit_tail.cpp test_logger.cpp test_observability.cpp + test_profiler.cpp test_backend_extra.cpp test_backend_registration_surface.cpp test_registry_extra.cpp diff --git a/tests/test_profiler.cpp b/tests/test_profiler.cpp new file mode 100644 index 00000000..7296a736 --- /dev/null +++ b/tests/test_profiler.cpp @@ -0,0 +1,58 @@ +// SPDX-License-Identifier: Apache-2.0 + +// The profiler macros in both configurations. Compiled under the project's +// full warning set: every local below is used by nothing but a macro, so a +// stub that dropped an argument instead of consuming it would fail this file +// with -Wunused-variable or -Wunused-but-set-variable. + +#include +#include +#include +#include +#include + +TEST_CASE("profiler macros: every macro accepts a local as its only use", "[profiler]") { + std::string const requestId = "request-1"; + double const depth = 3.0; + std::size_t const inFlight = 2; + std::string_view const note = "note"; + // With Tracy off a macro names its argument only in an unevaluated + // context, so the analyzer sees this store as never read -- which is the + // property under test, not a defect. + char const* const threadName = "morph.test"; // NOLINT(clang-analyzer-deadcode.DeadStores) + + MORPH_THREAD_NAME(threadName); + MORPH_ZONE("profiler test"); + MORPH_ZONE_TEXT(requestId); + MORPH_PLOT("morph.test.depth", depth); + MORPH_PLOT("morph.test.inFlight", inFlight); + MORPH_MESSAGE(note); + SUCCEED(); +} + +TEST_CASE("profiler macros: a zone's text may be empty", "[profiler]") { + MORPH_ZONE("profiler test, empty text"); + MORPH_ZONE_TEXT(std::string_view{}); + SUCCEED(); +} + +TEST_CASE("profiler macros: arguments are evaluated only when Tracy is on", "[profiler]") { + int evaluations = 0; + // NOLINTNEXTLINE(clang-analyzer-deadcode.DeadStores): unread with Tracy off, by design (see above) + auto const countedText = [&evaluations] { + ++evaluations; + return std::string_view{"request-1"}; + }; + { + MORPH_ZONE("profiler test, counted"); + MORPH_ZONE_TEXT(countedText()); + MORPH_MESSAGE(countedText()); + } +#ifdef MORPH_TRACY_ENABLED + CHECK(evaluations == 2); +#else + // A disabled build pays for nothing at the call site, not even the + // computation of a zone's text. + CHECK(evaluations == 0); +#endif +} From be43d9681d9e8e9feea11d7d10ffb189523265f9 Mon Sep 17 00:00:00 2001 From: Yaraslau Tamashevich Date: Sat, 3 Oct 2026 20:17:43 +0200 Subject: [PATCH 2/4] core, net, offline: profiler zones on the hot paths, and thread names One zone per phase, on the thread that runs it: a dispatch crosses from the caller to the model's strand to the settling thread, and a Tracy zone has to begin and end on one thread, so no zone spans a hand-off or a co_await. The phases of one call are linked by writing Context::requestId as zone text where the phase can see the call's session. Zoned: Bridge::executeVia (and its attached/creating forms), dispatchNow, the ActionCall codec, BridgeSink's settles and forward; LocalBackend's executeInto, start and finish; every model strand task (the around-task hook); ActionDispatcher's dispatch, dispatchAsync and prepareAction; the journal's outcome recording; wire::encode/decode; SocketBackend's file, receive and frame drain, and the WebSocket send queue; the offline queues' enqueue and SyncWorker's drain and per-item replay. The pool workers are named morph.pool and the IoLoop thread, which carries every socket and TimeoutScheduler deadline, morph.io. RemoteServer is not zoned here; its dispatchMessage and dispatchExecute are the next two. Co-Authored-By: Claude Opus 5.5 --- docs/spec/core/profiler.md | 51 ++++++++++++++++++-- include/morph/core/backend.hpp | 9 ++++ include/morph/core/bridge.hpp | 15 ++++++ include/morph/core/executor.hpp | 2 + include/morph/core/io_loop.hpp | 9 +++- include/morph/core/registry.hpp | 17 +++++++ include/morph/core/strand.hpp | 4 ++ include/morph/core/wire.hpp | 5 ++ include/morph/net/detail/ws_connection.hpp | 5 ++ include/morph/net/socket_backend.hpp | 6 +++ include/morph/offline/file_offline_queue.hpp | 2 + include/morph/offline/offline_queue.hpp | 2 + include/morph/offline/sync_worker.hpp | 3 ++ scripts/branch_partial_allowlist.json | 6 +-- 14 files changed, 128 insertions(+), 8 deletions(-) diff --git a/docs/spec/core/profiler.md b/docs/spec/core/profiler.md index 650aa13b..e315b42a 100644 --- a/docs/spec/core/profiler.md +++ b/docs/spec/core/profiler.md @@ -1,8 +1,9 @@ # Profiler zones (`MORPH_ZONE` and friends) — design `include/morph/core/profiler.hpp` gives morph compile-time profiler -instrumentation: [Tracy](https://github.com/wolfpld/tracy) zones, thread -names, plots and messages, behind morph's own macro names. It is off by default and costs nothing when off: the +instrumentation: [Tracy](https://github.com/wolfpld/tracy) zones on the +framework's hot paths, names for the threads morph owns, and plot and message +macros for anything else. It is off by default and costs nothing when off: the macros are stubs that do not evaluate their arguments, and the build has no Tracy dependency. @@ -16,6 +17,8 @@ timeline. - [Turning it on](#turning-it-on) - [The macros](#the-macros) - [Zones, phases and threads](#zones-phases-and-threads) +- [Zone list](#zone-list) +- [Thread names](#thread-names) - [One definition everywhere](#one-definition-everywhere) - [One Tracy client per process](#one-tracy-client-per-process) - [Design decisions](#design-decisions) @@ -81,11 +84,48 @@ callback executor. So: hand-off between threads. - **No zone stays open across a `co_await`.** A suspended coroutine's thread goes on to run other work, whose zones would close out of order with the - open one. + open one. This is why the WebSocket send side is zoned at `enqueueFrame`, not + in the coroutine that writes the frames. - **The phases of one call are linked by `session::Context::requestId`,** written as zone text where the phase can see the call's session. A request that carries no request id leaves its zones without text. +## Zone list + +| Zone | Where | Thread | Text | +|---|---|---|---| +| `Bridge::executeVia`, `Bridge::executeAttachedVia`, `Bridge::executeCreatingVia` | `bridge.hpp` | the bridge's owner | — | +| `Bridge::dispatchNow` | `bridge.hpp` | the owner; later than `executeVia` for a call that waited for its bind | the bridge's session's `requestId` | +| `ActionTraits::toJson`, `ActionTraits::resultFromJson` | the `ActionCall` codec a remote backend calls | the backend's thread | — | +| `BridgeSink::settleValue`, `BridgeSink::settleException` | `bridge.hpp` | wherever the backend settles | — | +| `BridgeSink::forward` | `bridge.hpp` | the settling thread, or the owner when bridge-side work is posted there | — | +| `LocalBackend::executeInto` | `backend.hpp` | the caller | the call's `requestId` | +| `LocalBackend::startLocal`, `LocalBackend::startTaskLocal`, `LocalBackend::finishLocal` | `backend.hpp` | the model's strand | the call's `requestId` | +| `ModelStrands::task` | `strand.hpp`, the strands' around-task hook | the pool thread running one strand task | — | +| `ActionDispatcher::dispatch`, `ActionDispatcher::dispatchAsync` | `registry.hpp` | the model's strand | the installed session's `requestId` | +| `ActionDispatcher::prepareAction` | `registry.hpp`: decode and the pre-handler gates | the model's strand | — | +| `recordActionSuccess`, `recordActionFailure` | `registry.hpp`, the journal write of an outcome | the model's strand | — | +| `wire::encode`, `wire::decode` | `wire.hpp` | the encoding or decoding thread | the envelope's `requestId` | +| `SocketBackend::fileExecute` | `net/socket_backend.hpp` | the I/O loop | the envelope's `requestId` | +| `SocketBackend::fileControl`, `SocketBackend::dispatchIncomingEnvelope`, `SocketBackend::drainFrames` | `net/socket_backend.hpp` | the I/O loop | — | +| `ws::enqueueFrame` | `net/detail/ws_connection.hpp`, the send side | the I/O loop | — | +| `InMemoryOfflineQueue::enqueue`, `FileOfflineQueue::enqueue` | `offline/` | the queue's owner | — | +| `SyncWorker::drain`, `SyncWorker::replay` (one per item) | `offline/sync_worker.hpp` | the worker's owner | — | + +`RemoteServer`'s own phases (`dispatchMessage`, `dispatchExecute`) are not +zoned yet; the dispatcher, strand and codec zones inside them are. + +## Thread names + +| Name | Thread | +|---|---| +| `morph.pool` | every `ThreadPoolExecutor` worker | +| `morph.io` | the thread an `IoLoop` runs; it carries every socket, every `TimeoutScheduler` deadline and the connectivity probe built on that loop | + +An application runs one `IoLoop`, so there is one `morph.io` thread; a +`TimeoutScheduler` constructed without a loop owns one of its own, which is +named the same. + ## One definition everywhere morph is header-only, so these macros change the bodies of inline functions. @@ -135,7 +175,10 @@ installed Tracy. ## Limitations -- **core-cpp is not instrumented.** Its event loop and strand pump are its own. +- **No zones in `RemoteServer` yet.** `RemoteServer::dispatchMessage` and + `RemoteServer::dispatchExecute` are the obvious next two. +- **core-cpp is not instrumented.** Its event loop and strand pump are its own; + morph's zones start at morph's around-task hook. - **No statistics collector and no `morph::observe` → Tracy sink.** Both are separate decisions about `morph::observe`, whose spec rules out aggregation inside morph. diff --git a/include/morph/core/backend.hpp b/include/morph/core/backend.hpp index da0992f8..5d442904 100644 --- a/include/morph/core/backend.hpp +++ b/include/morph/core/backend.hpp @@ -28,6 +28,7 @@ #include "detail/owner_affinity.hpp" #include "model.hpp" #include "observability.hpp" +#include "profiler.hpp" #include "registry.hpp" #include "strand.hpp" @@ -1262,6 +1263,8 @@ class LocalBackend : public detail::IBackend { void executeInto(::morph::exec::detail::ModelId mid, detail::ActionCall call, ::morph::exec::IExecutor* cbExec, std::shared_ptr<::morph::async::detail::ISettleSink> sink) override { (void)cbExec; + MORPH_ZONE("LocalBackend::executeInto"); + MORPH_ZONE_TEXT(call.session.requestId); note("LocalBackend::executeInto"); std::shared_ptr<::morph::model::detail::IModelHolder> holder; @@ -1567,6 +1570,8 @@ class LocalBackend : public detail::IBackend { /// Runs an ordinary handler's dispatch once it holds its instance's action /// gate, on the strand, and finishes it. static void startLocal(LocalRun& run) { + MORPH_ZONE("LocalBackend::startLocal"); + MORPH_ZONE_TEXT(run.session.requestId); if (!admitLocal(run)) { return; } @@ -1594,6 +1599,8 @@ class LocalBackend : public detail::IBackend { /// gate, on the strand. It finishes when its Task completes, through the /// callback it is handed. static void startTaskLocal(const std::shared_ptr& run) { + MORPH_ZONE("LocalBackend::startTaskLocal"); + MORPH_ZONE_TEXT(run->session.requestId); if (!admitLocal(*run)) { return; } @@ -1624,6 +1631,8 @@ class LocalBackend : public detail::IBackend { /// Records a finished dispatch and settles its sink, then leaves the action /// gate so the next action on the instance can start. On the strand. static void finishLocal(LocalRun& run, std::shared_ptr value, const std::exception_ptr& error) { + MORPH_ZONE("LocalBackend::finishLocal"); + MORPH_ZONE_TEXT(run.session.requestId); bool const succeeded = error == nullptr; // Resolve the sink only after every metric and `endSpan` below are // recorded — nothing synchronizes a `.then()`/`.onError()` callback diff --git a/include/morph/core/bridge.hpp b/include/morph/core/bridge.hpp index 4de17a7b..b803316f 100644 --- a/include/morph/core/bridge.hpp +++ b/include/morph/core/bridge.hpp @@ -32,6 +32,7 @@ #include "detail/owner_affinity.hpp" #include "detail/subscription_registry.hpp" #include "model_key.hpp" +#include "profiler.hpp" #include "registry.hpp" #include "timeout_scheduler.hpp" @@ -471,6 +472,7 @@ class BridgeSink final : public ::morph::async::detail::CompletionState, /// `opaque` rather than `value` only because `CompletionState` /// already has a member of that name, and -Wshadow-field is on. void settleValue(std::shared_ptr opaque) override { + MORPH_ZONE("BridgeSink::settleValue"); if (!settleOnce()) { return; } @@ -494,6 +496,7 @@ class BridgeSink final : public ::morph::async::detail::CompletionState, /// @brief Settles with a failure from the backend. /// @param exc The exception to deliver to the caller's `.onError`. void settleException(const std::exception_ptr& exc) override { + MORPH_ZONE("BridgeSink::settleException"); if (settleOnce()) { _pendingCalls->fetch_sub(1, std::memory_order_relaxed); } @@ -508,6 +511,9 @@ class BridgeSink final : public ::morph::async::detail::CompletionState, /// @param opaque The backend's result. /// @param onOwner Whether this runs on the bridge's owner. void forward(const std::shared_ptr& opaque, bool onOwner) { + // Its own zone: when the bridge has work to do, this runs on the owner + // in a task `settleValue` posted, not inside `settleValue`'s zone. + MORPH_ZONE("BridgeSink::forward"); try { auto* const typedResult = static_cast(opaque.get()); if (onOwner && _liveness.active()) { @@ -1274,6 +1280,7 @@ class Bridge { const std::shared_ptr& binding, Action action, ::morph::exec::IExecutor* cbExec, std::function::Result&)> onResult = {}) { using R = ::morph::model::ActionTraits::Result; + MORPH_ZONE("Bridge::executeVia"); note("Bridge::executeVia"); auto sink = makeSink(std::move(onResult)); ::morph::async::Completion typed{sink, cbExec}; @@ -1314,6 +1321,7 @@ class Bridge { const std::shared_ptr& binding, Action action, ::morph::exec::IExecutor* cbExec, std::string key) { using R = ::morph::model::ActionTraits::Result; + MORPH_ZONE("Bridge::executeAttachedVia"); note("Bridge::executeVia"); auto sink = makeSink({}); ::morph::async::Completion typed{sink, cbExec}; @@ -1359,6 +1367,7 @@ class Bridge { ::morph::async::Completion::Result> executeCreatingVia( const std::shared_ptr& binding, Action action, ::morph::exec::IExecutor* cbExec) { using R = ::morph::model::ActionTraits::Result; + MORPH_ZONE("Bridge::executeCreatingVia"); note("Bridge::executeVia"); std::weak_ptr const weak{binding}; auto sink = makeSink([this, weak](const R& result) { @@ -1807,6 +1816,10 @@ class Bridge { detail::HandlerBinding& binding, const std::shared_ptr::Result>>& sink, Action action, ::morph::exec::IExecutor* cbExec, bool held) { + // Its own zone, not part of `executeVia`'s: a call that waited for a + // bind is dispatched later, from the bind's settle. + MORPH_ZONE("Bridge::dispatchNow"); + MORPH_ZONE_TEXT(_defaultSession.requestId); note("Bridge::dispatch"); auto const raw = binding.currentId.load(); if (raw == 0U) { @@ -1863,9 +1876,11 @@ class Bridge { auto sharedAction = std::make_shared(std::move(action)); call.action = sharedAction; call.serializeAction = [](const void* actionPtr) { + MORPH_ZONE("ActionTraits::toJson"); return ::morph::model::ActionTraits::toJson(*static_cast(actionPtr)); }; call.deserializeResult = [](std::string_view jsonStr) -> std::shared_ptr { + MORPH_ZONE("ActionTraits::resultFromJson"); return std::make_shared(::morph::model::ActionTraits::resultFromJson(jsonStr)); }; if constexpr (taskHandler) { diff --git a/include/morph/core/executor.hpp b/include/morph/core/executor.hpp index 65cf7521..d61419c5 100644 --- a/include/morph/core/executor.hpp +++ b/include/morph/core/executor.hpp @@ -17,6 +17,7 @@ #include "../attributes.hpp" #include "logger.hpp" +#include "profiler.hpp" namespace morph::exec { @@ -210,6 +211,7 @@ class ThreadPoolExecutor : public IExecutor { private: void loop() { + MORPH_THREAD_NAME("morph.pool"); for (;;) { std::function task; { diff --git a/include/morph/core/io_loop.hpp b/include/morph/core/io_loop.hpp index ab635acf..3de676cc 100644 --- a/include/morph/core/io_loop.hpp +++ b/include/morph/core/io_loop.hpp @@ -11,6 +11,7 @@ #include "executor.hpp" #include "logger.hpp" +#include "profiler.hpp" #if defined(__EMSCRIPTEN__) && !defined(__EMSCRIPTEN_PTHREADS__) #define MORPH_IO_LOOP_HOST_DRIVEN 1 @@ -87,7 +88,13 @@ class IoLoop { #ifndef MORPH_IO_LOOP_HOST_DRIVEN /// @brief Creates the loop and starts the thread that runs it. - IoLoop() : _impl{std::make_shared()}, _thread{[impl = _impl] { impl->loop.run(); }} {} + IoLoop() + : _impl{std::make_shared()}, _thread{[impl = _impl] { + // One name for every IoLoop thread: an application runs one, and + // its sockets, deadlines and probe all turn on it. + MORPH_THREAD_NAME("morph.io"); + impl->loop.run(); + }} {} /// @brief Stops the loop and joins its thread. /// diff --git a/include/morph/core/registry.hpp b/include/morph/core/registry.hpp index c237dfb8..c37500f0 100644 --- a/include/morph/core/registry.hpp +++ b/include/morph/core/registry.hpp @@ -21,6 +21,7 @@ #include "../forms/forms.hpp" #include "model.hpp" #include "payload_schema.hpp" +#include "profiler.hpp" namespace morph::model { @@ -445,6 +446,15 @@ inline std::string actionPayloadSchema() { } } +/// @brief The request id of the session installed on the calling thread, or +/// empty when there is none: the text that links one dispatch's +/// profiler zones across the threads it crosses. +/// @return A view into the installed session, valid while it stays installed. +[[nodiscard]] inline std::string_view currentRequestId() noexcept { + auto const* const ctx = ::morph::session::current(); + return ctx != nullptr ? std::string_view{ctx->requestId} : std::string_view{}; +} + /// @brief Records one executed action's *successful* outcome to @p holder's /// attached action log, if any (`IModelHolder::recordIfAttached` is /// itself a no-op with none attached). @@ -467,6 +477,7 @@ inline std::string actionPayloadSchema() { /// @param result JSON-encoded result (`ActionTraits::resultToJson`). inline void recordActionSuccess(IModelHolder& holder, std::string modelType, std::string actionType, std::string payload, std::string schema, std::string result) { + MORPH_ZONE("recordActionSuccess"); holder.recordIfAttached(::morph::journal::LogEntry{ .seq = 0, .modelType = std::move(modelType), @@ -493,6 +504,7 @@ inline void recordActionSuccess(IModelHolder& holder, std::string modelType, std /// @param error `std::exception::what()`. inline void recordActionFailure(IModelHolder& holder, std::string modelType, std::string actionType, std::string payload, std::string schema, std::string error) { + MORPH_ZONE("recordActionFailure"); holder.recordIfAttached(::morph::journal::LogEntry{ .seq = 0, .modelType = std::move(modelType), @@ -734,6 +746,7 @@ class ActionDispatcher { /// @throws ValidationError if the action fails `ActionValidator::ready`. template static Action prepareAction(std::string_view payloadJson) { + MORPH_ZONE("ActionDispatcher::prepareAction"); auto action = ActionTraits::fromJson(payloadJson); // Retag any Quantity fields to their declared precision so a // hand-built wire payload matches the schema's advertised @@ -938,6 +951,8 @@ class ActionDispatcher { /// @brief Dispatches an action against @p holder and returns the JSON-encoded result. std::string dispatch(std::string_view modelId, std::string_view actionId, IModelHolder& holder, std::string_view payload) { + MORPH_ZONE("ActionDispatcher::dispatch"); + MORPH_ZONE_TEXT(detail::currentRequestId()); // A dispatch means the maps are being read, which in the registration // model means the registration phase is over. Debug builds only; see // `detail::noteRegistryRead`. @@ -972,6 +987,8 @@ class ActionDispatcher { void dispatchAsync(std::string_view modelId, std::string_view actionId, IModelHolder& holder, std::string_view payload, const std::shared_ptr<::morph::exec::detail::TaskResumer>& executor, ::core::async::StopToken token, DispatchDone done) { + MORPH_ZONE("ActionDispatcher::dispatchAsync"); + MORPH_ZONE_TEXT(detail::currentRequestId()); const ActionEntry* entry = nullptr; try { detail::noteRegistryRead(this == &defaultDispatcher()); diff --git a/include/morph/core/strand.hpp b/include/morph/core/strand.hpp index 9b9d4b56..7a03a138 100644 --- a/include/morph/core/strand.hpp +++ b/include/morph/core/strand.hpp @@ -24,6 +24,7 @@ #include "../session/session.hpp" #include "executor.hpp" #include "logger.hpp" +#include "profiler.hpp" /// @file /// @brief morph's strands: one per model instance, from core-cpp's @@ -383,6 +384,9 @@ class TaskResumer final : public ::core::async::IExecutor, public std::enable_sh }; inline void ModelStrands::AroundTask::operator()(const ModelId& key, ::core::async::RunTask run) const { + // Every task a model strand runs passes through here, on the thread that + // runs it, so this zone is one strand task and nothing more. + MORPH_ZONE("ModelStrands::task"); if (run.kind() != ::core::async::TaskKind::Resumption || self->_enrolledCount.load(std::memory_order_acquire) == 0) { run(); diff --git a/include/morph/core/wire.hpp b/include/morph/core/wire.hpp index a86d9ea5..f1160054 100644 --- a/include/morph/core/wire.hpp +++ b/include/morph/core/wire.hpp @@ -14,6 +14,7 @@ #include #include "../session/session.hpp" +#include "profiler.hpp" namespace morph::wire { @@ -650,6 +651,8 @@ struct WireCodecOps { /// @return The serialized envelope as valid, re-decodable JSON. /// @throws std::runtime_error on serialisation failure (should never happen for valid input). inline std::string encode(const Envelope& env, const WireCodecOps& ops = defaultWireCodecOps()) { + MORPH_ZONE("wire::encode"); + MORPH_ZONE_TEXT(env.session.requestId); std::string out; if (auto errCode = ops.writeEnvelope(env, out)) { // Unreachable through any `Envelope` value -- see `WireCodecOps` for @@ -679,6 +682,7 @@ inline std::string encode(const Envelope& env, const WireCodecOps& ops = default /// @throws std::runtime_error if @p json exceeds `kMaxEnvelopeBytes` or is not a /// valid envelope. inline Envelope decode(std::string_view json) { + MORPH_ZONE("wire::decode"); if (json.size() > kMaxEnvelopeBytes) { throw std::runtime_error("envelope decode failed: input exceeds maximum size (" + std::to_string(json.size()) + " > " + std::to_string(kMaxEnvelopeBytes) + " bytes)"); @@ -699,6 +703,7 @@ inline Envelope decode(std::string_view json) { if (auto errCode = glz::read(env, json)) { throw std::runtime_error("envelope decode failed: " + glz::format_error(errCode, json)); } + MORPH_ZONE_TEXT(env.session.requestId); return env; } diff --git a/include/morph/net/detail/ws_connection.hpp b/include/morph/net/detail/ws_connection.hpp index 15898024..ebd0282c 100644 --- a/include/morph/net/detail/ws_connection.hpp +++ b/include/morph/net/detail/ws_connection.hpp @@ -16,6 +16,7 @@ #include #include +#include "../../core/profiler.hpp" #include "ws_handshake.hpp" /// @file @@ -124,6 +125,10 @@ inline ::core::async::Task writerFlow(std::shared_ptr conn /// @param frame One complete, encoded WebSocket frame. /// @return `false` if the connection is closed and the frame was dropped. inline bool enqueueFrame(std::shared_ptr const& conn, std::string frame) { + // The send side's zone is here and not in `writerFlow`: a zone must not + // stay open across a `co_await`, where the loop runs other work on the + // same thread before the writer resumes. + MORPH_ZONE("ws::enqueueFrame"); if (conn->closed || conn->closeWhenFlushed) { return false; } diff --git a/include/morph/net/socket_backend.hpp b/include/morph/net/socket_backend.hpp index eacdc45d..f6d3716b 100644 --- a/include/morph/net/socket_backend.hpp +++ b/include/morph/net/socket_backend.hpp @@ -20,6 +20,7 @@ #include #include #include +#include #include #include #include @@ -595,6 +596,8 @@ class SocketBackend : public ::morph::backend::detail::IBackend { /// Assigns @p env a call id, files @p pending under it and writes it. void fileExecute(::morph::wire::Envelope env, PendingExecute pending) { + MORPH_ZONE("SocketBackend::fileExecute"); + MORPH_ZONE_TEXT(env.session.requestId); note("SocketBackend::execute"); if (!connected.load() || !conn) { pending.state->setException(std::make_exception_ptr(::morph::backend::DisconnectedError{})); @@ -618,6 +621,7 @@ class SocketBackend : public ::morph::backend::detail::IBackend { /// The control-call counterpart of `fileExecute`. void fileControl(::morph::wire::Envelope env, PendingControl pending) { + MORPH_ZONE("SocketBackend::fileControl"); note("SocketBackend::bindModel"); if (!connected.load() || !conn) { pending.reject(std::make_exception_ptr(::morph::backend::DisconnectedError{})); @@ -743,6 +747,7 @@ class SocketBackend : public ::morph::backend::detail::IBackend { } void dispatchIncomingEnvelope(const std::string& payload) { + MORPH_ZONE("SocketBackend::dispatchIncomingEnvelope"); ::morph::wire::Envelope env; try { env = ::morph::wire::decode(payload); @@ -803,6 +808,7 @@ class SocketBackend : public ::morph::backend::detail::IBackend { /// Close, a protocol error, or this backend closed meanwhile). bool drainFrames(const std::shared_ptr<::morph::net::detail::LoopConnection>& connection, ::morph::net::detail::WsFrameReader& reader) { + MORPH_ZONE("SocketBackend::drainFrames"); using ::morph::net::detail::WsOpcode; for (;;) { std::optional<::morph::net::detail::WsFrame> frame; diff --git a/include/morph/offline/file_offline_queue.hpp b/include/morph/offline/file_offline_queue.hpp index 0861aac3..cd31de19 100644 --- a/include/morph/offline/file_offline_queue.hpp +++ b/include/morph/offline/file_offline_queue.hpp @@ -24,6 +24,7 @@ #include "../core/file_io_ops.hpp" #include "../core/logger.hpp" #include "../core/observability.hpp" +#include "../core/profiler.hpp" #include "offline_queue.hpp" #ifdef _WIN32 @@ -327,6 +328,7 @@ class FileOfflineQueue : public IOfflineQueue { State& operator=(State&&) = delete; uint64_t enqueue(std::string payload, std::string idempotencyKey, std::optional maxDepth) { + MORPH_ZONE("FileOfflineQueue::enqueue"); if (!idempotencyKey.empty()) { for (const auto& [existingId, item] : _items) { if (item.idempotencyKey == idempotencyKey) { diff --git a/include/morph/offline/offline_queue.hpp b/include/morph/offline/offline_queue.hpp index 86d09ee5..3ad2a012 100644 --- a/include/morph/offline/offline_queue.hpp +++ b/include/morph/offline/offline_queue.hpp @@ -18,6 +18,7 @@ #include "../core/detail/owned_state.hpp" #include "../core/executor.hpp" #include "../core/observability.hpp" +#include "../core/profiler.hpp" namespace morph::offline { @@ -546,6 +547,7 @@ class InMemoryOfflineQueue : public IOfflineQueue { /// Inserts one item into @p state, refusing past @p maxDepth. static uint64_t insert(State& state, std::optional maxDepth, std::string payload, std::string idempotencyKey) { + MORPH_ZONE("InMemoryOfflineQueue::enqueue"); if (maxDepth && state.items.size() >= *maxDepth) { ::morph::observe::detail::emitMetric(::morph::observe::Metric::queueOverflow, static_cast(state.items.size())); diff --git a/include/morph/offline/sync_worker.hpp b/include/morph/offline/sync_worker.hpp index 350c2696..9ebf6ce5 100644 --- a/include/morph/offline/sync_worker.hpp +++ b/include/morph/offline/sync_worker.hpp @@ -16,6 +16,7 @@ #include "../core/executor.hpp" #include "../core/logger.hpp" #include "../core/observability.hpp" +#include "../core/profiler.hpp" #include "offline_queue.hpp" namespace morph::offline { @@ -259,6 +260,7 @@ class SyncWorker { /// @brief The drain itself. On the owner. /// @return Counts of successful / failed / dead-lettered replays. SyncResult drainHere() { + MORPH_ZONE("SyncWorker::drain"); ::morph::exec::detail::noteOwner("SyncWorker::run", _owner.coreExecutor(), ::morph::exec::runningOn(_owner)); bool const wasStoppedBeforeRun = _stopped.exchange(false); SyncResult result; @@ -272,6 +274,7 @@ class SyncWorker { if (_stopped.load()) { break; } + MORPH_ZONE("SyncWorker::replay"); ReplayOutcome outcome = ReplayOutcome::Rejected; try { outcome = _replay(item.payload); diff --git a/scripts/branch_partial_allowlist.json b/scripts/branch_partial_allowlist.json index 9796199a..573327f2 100644 --- a/scripts/branch_partial_allowlist.json +++ b/scripts/branch_partial_allowlist.json @@ -97,7 +97,7 @@ }, { "file": "include/morph/core/backend.hpp", - "line": 1211, + "line": 1212, "source": "if (const auto* inst = _instances.find(modelId)) {", "reason": "Unreachable by construction given the `_changeAware`/`_instances` invariant (core audit finding BK2). `_changeAware` is an index over the instance directory: an id enters it in `createHolder` (this file, when the holder answers `isBackendChangeAware()`) in the same `_regMtx`-held critical section that files the instance, and leaves it in `deregisterModel` only when `InstanceDirectory::release` reports the instance actually destroyed. `notifyBackendChanged()` (this function) holds the same `_regMtx` while walking `_changeAware` and looking each id up at this line, so every id it walks is still live -- the null arm cannot occur without a code change that breaks that subset invariant." }, @@ -109,13 +109,13 @@ }, { "file": "include/morph/core/bridge.hpp", - "line": 1763, + "line": 1772, "source": "if (_executeDeadline.count() <= 0 || !_timeoutScheduler) {", "reason": "The `!_timeoutScheduler` disjunct is unreachable by construction. `setExecuteDeadline` is the only writer of both `_executeDeadline` and `_timeoutScheduler`, and it creates `_timeoutScheduler` in the same call that makes `_executeDeadline` positive; nothing resets `_timeoutScheduler` to null afterwards (setting the deadline back to 0 only stops new calls from arming it, per that method's doc comment). So `_executeDeadline > 0 && !_timeoutScheduler` cannot hold once any positive deadline has been set." }, { "file": "include/morph/net/socket_backend.hpp", - "line": 792, + "line": 797, "source": "default:", "reason": "Unreachable except via the adjacent `Error` case it deliberately shares a body with (net audit, `socket_backend.hpp` extra finding #7). `detail::ExecuteReplyKind` is a closed 3-value enum (`Value`/`Timeout`/`Error`), all three handled explicitly above this label; `default:` exists only to satisfy this project's `-Wswitch-default`, per the source's own inline comment directly below this line. Reaching it via any value other than through the `Error` case falling through would require an out-of-range `static_cast` producing a value outside the enum's domain -- undefined behavior, not a legitimate test target." } From 353964e2a92fb92563c484ab40b0a0b0b97dc37f Mon Sep 17 00:00:00 2001 From: Yaraslau Tamashevich Date: Sat, 3 Oct 2026 20:17:49 +0200 Subject: [PATCH 3/4] ci: nightly Tracy capture asserts the named zones fire A tracy-capture job on the nightly workflow builds tracy-capture and tracy-csvexport at v0.13.1, builds morph_bench and morph_bench_alloc with MORPH_ENABLE_TRACY=ON, runs each under a capture and fails unless every named zone has a non-zero count: the codec, dispatcher and strand zones from RemoteServer's dispatch, and Bridge/LocalBackend/BridgeSink from the local path. Its result is reconciled into an issue like the other nightly legs. scripts/check_tracy_capture.sh fails closed: no CSV, no rows, an unexpected column layout, a named zone absent or counted zero, a program built without Tracy, and a program or capture that does not exit are all failures. scripts/test_check_tracy_capture.sh drives the assertion through each of those from synthetic CSVs and runs first in the job. MORPH_TRACY_ON_DEMAND (advanced, default ON) lets the job build the fetched client to record from the first zone; with TRACY_NO_EXIT=1 the result then does not depend on when the capture connects. Co-Authored-By: Claude Opus 5.5 --- .github/workflows/nightly-slow-checks.yml | 137 ++++++++++++++++++++- CMakeLists.txt | 11 +- docs/spec/core/profiler.md | 29 ++++- scripts/check_tracy_capture.sh | 143 ++++++++++++++++++++++ scripts/test_check_tracy_capture.sh | 108 ++++++++++++++++ 5 files changed, 422 insertions(+), 6 deletions(-) create mode 100644 scripts/check_tracy_capture.sh create mode 100644 scripts/test_check_tracy_capture.sh diff --git a/.github/workflows/nightly-slow-checks.yml b/.github/workflows/nightly-slow-checks.yml index a17bf0fb..43f86ddf 100644 --- a/.github/workflows/nightly-slow-checks.yml +++ b/.github/workflows/nightly-slow-checks.yml @@ -23,6 +23,10 @@ name: Nightly slow checks # `github.event_name` is `schedule`/`workflow_dispatch`, never `push`, so the # unmodified "Save sccache" `if:` condition they inherit is always false and # they only ever restore what the last push already wrote. +# +# A third job, `tracy-capture`, is not a copy of anything in ci.yml: it is +# the check that morph's profiler zones fire under a real capture. See its +# own comment. on: schedule: @@ -309,9 +313,132 @@ jobs: path: /tmp/failure-excerpt-all-features-${{ matrix.compiler }}.txt retention-days: 7 + # ── Tracy capture: the profiler zones fire ──────────────────────────── + # Builds the benchmarks with MORPH_ENABLE_TRACY=ON, runs each under + # tracy-capture, exports the zone statistics with tracy-csvexport, and + # fails unless every named zone has a non-zero count. A capture that + # "succeeds" with no zones would prove nothing, so + # scripts/check_tracy_capture.sh fails closed: no CSV, no rows, a zone + # missing or counted zero, or a capture that never connected is a failure. + # + # morph_bench drives RemoteServer's dispatch (the wire codec, the + # dispatcher, the model strands); morph_bench_alloc drives Bridge over + # LocalBackend. Between them they reach the zones named below. Nightly, + # not on pull_request: it builds Tracy's tools and a release morph, and a + # missing zone is a slow regression, not one a PR needs to wait on. + # + # MORPH_TRACY_ON_DEMAND=OFF and TRACY_NO_EXIT=1 make the result + # independent of when tracy-capture connects: the client records from the + # first zone and waits, at exit, until the capture has drained it. + tracy-capture: + name: Tracy capture (nightly) + runs-on: ubuntu-24.04 + env: + TRACY_TAG: v0.13.1 + steps: + - uses: actions/checkout@v4 + + - name: Install clang, ninja, catch2 + run: | + sudo apt-get update -q + sudo apt-get install -y ninja-build catch2 + curl -sSL --fail -o /tmp/llvm.sh https://apt.llvm.org/llvm.sh + test -s /tmp/llvm.sh + sudo bash /tmp/llvm.sh ${{ env.CLANG_VERSION }} + + - name: Self-test the capture checker + run: bash scripts/test_check_tracy_capture.sh + + - name: Restore Tracy's tools + id: tracy-tools + uses: actions/cache@v4 + with: + path: /home/runner/tracy-tools + key: tracy-tools-${{ env.TRACY_TAG }}-ubuntu-24.04-clang-${{ env.CLANG_VERSION }} + + # The tag morph's own CMake fetches the client at, so the capture + # protocol matches the client the benchmarks link. + - name: Build tracy-capture and tracy-csvexport + if: steps.tracy-tools.outputs.cache-hit != 'true' + run: | + git clone --depth 1 --branch "$TRACY_TAG" https://github.com/wolfpld/tracy.git /tmp/tracy + for tool in capture csvexport; do + cmake -S "/tmp/tracy/${tool}" -B "/tmp/tracy-build/${tool}" -G Ninja \ + -DCMAKE_BUILD_TYPE=Release -DNO_ISA_EXTENSIONS=ON \ + -DCMAKE_C_COMPILER=clang-${{ env.CLANG_VERSION }} \ + -DCMAKE_CXX_COMPILER=clang++-${{ env.CLANG_VERSION }} + cmake --build "/tmp/tracy-build/${tool}" + done + mkdir -p /home/runner/tracy-tools + cp /tmp/tracy-build/capture/tracy-capture /tmp/tracy-build/csvexport/tracy-csvexport \ + /home/runner/tracy-tools/ + + - name: Configure (Tracy on, recording from the first zone) + run: | + cmake -S . -B build/tracy -G Ninja \ + -DCMAKE_BUILD_TYPE=Release \ + -DCMAKE_C_COMPILER=clang-${{ env.CLANG_VERSION }} \ + -DCMAKE_CXX_COMPILER=clang++-${{ env.CLANG_VERSION }} \ + -DMORPH_ENABLE_TRACY=ON \ + -DMORPH_TRACY_ON_DEMAND=OFF \ + -DMORPH_BUILD_LOAD_TESTS=ON \ + -DMORPH_BUILD_EXAMPLES=OFF + + - name: Build the benchmarks + run: cmake --build build/tracy --target morph_bench morph_bench_alloc -- -j 4 + + - name: Capture morph_bench (RemoteServer dispatch) + run: | + bash scripts/check_tracy_capture.sh capture \ + /home/runner/tracy-tools/tracy-capture /home/runner/tracy-tools/tracy-csvexport \ + build/tracy/capture \ + "wire::encode,wire::decode,ModelStrands::task,ActionDispatcher::dispatch,ActionDispatcher::prepareAction" \ + -- build/tracy/tests/bench/morph_bench + + - name: Capture morph_bench_alloc (Bridge over LocalBackend) + run: | + bash scripts/check_tracy_capture.sh capture \ + /home/runner/tracy-tools/tracy-capture /home/runner/tracy-tools/tracy-csvexport \ + build/tracy/capture \ + "Bridge::executeVia,Bridge::dispatchNow,LocalBackend::executeInto,LocalBackend::startLocal,LocalBackend::finishLocal,BridgeSink::settleValue,ModelStrands::task" \ + -- build/tracy/tests/bench/morph_bench_alloc + + - name: Upload the zone tables + if: always() + uses: actions/upload-artifact@v4 + with: + name: tracy-capture-zones + path: | + build/tracy/capture/*.csv + build/tracy/capture/*.log + if-no-files-found: ignore + retention-days: 14 + + - name: Capture a failure excerpt for the issue filer + if: failure() + run: | + { + echo "Job: Tracy capture (nightly)" + echo "Run: ${{ github.server_url }}/${{ github.repository }}/actions/runs/${{ github.run_id }}" + echo "Commit: ${{ github.sha }}" + for log in build/tracy/capture/*.log; do + [ -f "$log" ] || continue + echo "── ${log} (last 30 lines) ──" + tail -n 30 "$log" + done + } > /tmp/failure-excerpt-tracy-capture.txt + + - name: Upload failure excerpt + if: failure() + uses: actions/upload-artifact@v4 + with: + name: failure-excerpt-tracy-capture + path: /tmp/failure-excerpt-tracy-capture.txt + retention-days: 7 + # ── Reconcile GitHub issues against tonight's result ────────────────── # - # Runs regardless of the two jobs above (`if: always()`), because a + # Runs regardless of the jobs above (`if: always()`), because a # recovery (a previously-red job going green) has to close a stale issue # just as reliably as a new failure has to open one -- an `if: failure()` # gate here would only ever open issues and never close them. @@ -330,7 +457,7 @@ jobs: # same auth every workflow already has; no new secret. reconcile-issues: name: File or close issues for tonight's result - needs: [valgrind, linux-all-features] + needs: [valgrind, linux-all-features, tracy-capture] if: always() runs-on: ubuntu-24.04 permissions: @@ -362,6 +489,9 @@ jobs: gh label create "nightly-check:all-features" --repo "$REPO" \ --description "Auto-filed by nightly-slow-checks.yml for the all-optional-features leg" \ --color BFDADC 2>/dev/null || true + gh label create "nightly-check:tracy-capture" --repo "$REPO" \ + --description "Auto-filed by nightly-slow-checks.yml for the Tracy capture leg" \ + --color BFDADC 2>/dev/null || true - name: Reconcile env: @@ -371,6 +501,7 @@ jobs: SHA: ${{ github.sha }} VALGRIND_RESULT: ${{ needs.valgrind.result }} ALL_FEATURES_RESULT: ${{ needs.linux-all-features.result }} + TRACY_CAPTURE_RESULT: ${{ needs.tracy-capture.result }} run: | set -euo pipefail @@ -451,3 +582,5 @@ jobs: "/tmp/excerpts/failure-excerpt-valgrind.txt" reconcile_one "nightly-check:all-features" "Linux / all optional features" "$ALL_FEATURES_RESULT" \ "/tmp/excerpts/failure-excerpt-all-features-clang.txt" + reconcile_one "nightly-check:tracy-capture" "Tracy capture" "$TRACY_CAPTURE_RESULT" \ + "/tmp/excerpts/failure-excerpt-tracy-capture.txt" diff --git a/CMakeLists.txt b/CMakeLists.txt index 937f6e10..ef975038 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -216,13 +216,20 @@ endif() # side is handed a version it did not ask for. TRACY_ON_DEMAND is # Lightweight's choice too, and the one a library should make: without it the # client buffers every event from process start until a profiler connects, -# which in a process nobody profiles is a leak. +# which in a process nobody profiles is a leak. MORPH_TRACY_ON_DEMAND=OFF is +# for a capture that must see a program from its first zone -- the nightly +# capture job -- and, like the tag, applies only when morph is the one that +# fetches Tracy. It is a morph option rather than TRACY_ON_DEMAND itself +# because CPM passes OPTIONS as normal variables, which a -D on the command +# line cannot override. # # The define and the link are INTERFACE: morph is header-only, so the macros # expand in the consumer's own translation units, and every one of them has # to agree on MORPH_TRACY_ENABLED (see profiler.hpp on why that is an ODR # matter). option(MORPH_ENABLE_TRACY "Instrument morph's hot paths with Tracy profiler zones (fetches Tracy if not installed)" OFF) +option(MORPH_TRACY_ON_DEMAND "Build a fetched Tracy client that records only while a profiler is connected" ON) +mark_as_advanced(MORPH_TRACY_ON_DEMAND) set(MORPH_TRACY_GIT_TAG v0.13.1) if(MORPH_ENABLE_TRACY) find_package(Tracy CONFIG QUIET) @@ -234,7 +241,7 @@ if(MORPH_ENABLE_TRACY) GIT_TAG ${MORPH_TRACY_GIT_TAG} EXCLUDE_FROM_ALL YES SYSTEM YES - OPTIONS "TRACY_ENABLE ON" "TRACY_ON_DEMAND ON") + OPTIONS "TRACY_ENABLE ON" "TRACY_ON_DEMAND ${MORPH_TRACY_ON_DEMAND}") endif() # A TracyClient built without TRACY_ENABLE compiles every Tracy macro to # nothing: the build would report profiling on and record no zone at all. diff --git a/docs/spec/core/profiler.md b/docs/spec/core/profiler.md index e315b42a..de5215f1 100644 --- a/docs/spec/core/profiler.md +++ b/docs/spec/core/profiler.md @@ -21,6 +21,7 @@ timeline. - [Thread names](#thread-names) - [One definition everywhere](#one-definition-everywhere) - [One Tracy client per process](#one-tracy-client-per-process) +- [The capture check](#the-capture-check) - [Design decisions](#design-decisions) - [Limitations](#limitations) @@ -40,7 +41,9 @@ recording no zone. A fetched client is built with `TRACY_ON_DEMAND`, so a process records only while a profiler is connected; without it, the client buffers every event from -process start until one connects. +process start until one connects. `MORPH_TRACY_ON_DEMAND=OFF` (advanced) +builds it to record from the first zone, which is what a capture of a +short-lived program needs. An installed morph built with Tracy on carries both properties in its exported target, and its package config finds Tracy for the consumer. @@ -161,6 +164,23 @@ cannot also install morph with a fetched Tracy — core-cpp's install rules do not export a client it did not install — so it needs `MORPH_INSTALL=OFF` or an installed Tracy. +## The capture check + +The nightly workflow's `tracy-capture` job builds `morph_bench` and +`morph_bench_alloc` with `MORPH_ENABLE_TRACY=ON` and +`MORPH_TRACY_ON_DEMAND=OFF`, runs each under `tracy-capture` with +`TRACY_NO_EXIT=1`, exports zone statistics with `tracy-csvexport`, and fails +unless every named zone has a non-zero count +(`scripts/check_tracy_capture.sh`). `morph_bench` drives `RemoteServer`'s +dispatch and so the codec, dispatcher and strand zones; `morph_bench_alloc` +drives `Bridge` over `LocalBackend`. + +The check fails closed. No CSV, a CSV with no rows, a column layout other than +the one it reads, a named zone absent or counted zero, a program that was built +without Tracy (the capture never connects), and a program or capture that does +not exit are all failures. `scripts/test_check_tracy_capture.sh` feeds the +assertion each of those as a synthetic CSV and runs first in the job. + ## Design decisions | Decision | Choice | Why | @@ -171,7 +191,7 @@ installed Tracy. | `MORPH_ZONE` on Tracy | `ZoneNamedN` with morph's own shadow suppression, followed by `static_assert(true)` | Tracy's `ZoneScopedN` ends in a `;` on some compilers and not on others, so the call site's `;` would be an empty statement on some. The `static_assert` consumes it on all. | | Linking phases | `Context::requestId` as zone text | It is already the correlation id `morph::observe`'s trace sink uses, and every phase that can see the call can see it. | | Tracy version | `v0.13.1`, Lightweight's tag and CPM name | One client per process. | -| Fetched client mode | `TRACY_ON_DEMAND` | A library must not make an unprofiled process buffer events forever. | +| Fetched client mode | `TRACY_ON_DEMAND` by default | A library must not make an unprofiled process buffer events forever. | ## Limitations @@ -183,3 +203,8 @@ installed Tracy. separate decisions about `morph::observe`, whose spec rules out aggregation inside morph. - **The ODR rule is enforced only under MSVC and clang-cl.** +- **macOS captures of a short program can be empty.** Tracy's client on Apple + starts lazily and is never destroyed, so `TRACY_NO_EXIT` does not hold the + process open for the capture; a program that finishes before + `tracy-capture` connects is lost. The nightly check runs on Linux, where the + client is a static object and waits. diff --git a/scripts/check_tracy_capture.sh b/scripts/check_tracy_capture.sh new file mode 100644 index 00000000..7f508893 --- /dev/null +++ b/scripts/check_tracy_capture.sh @@ -0,0 +1,143 @@ +#!/usr/bin/env bash +# Usage: +# bash scripts/check_tracy_capture.sh capture -- [args...] +# bash scripts/check_tracy_capture.sh assert +# +# is a comma-separated list of zone names, e.g. +# "Bridge::executeVia,wire::decode". +# +# `capture` runs under `tracy-capture`, exports the capture's zone +# statistics with `tracy-csvexport` to /.csv, and then +# runs `assert` on that CSV. `assert` passes only when every named zone has a +# row in the CSV with a non-zero count. +# +# It fails closed. A capture that "succeeds" with no zones proves nothing, and +# every way of getting no zones is a failure here rather than a pass with an +# empty table: no CSV, a CSV with no rows, a header that is not the column +# layout this script reads, a named zone that is absent, a named zone whose +# count is zero, a program built without Tracy (the capture never connects +# and the wait below runs out), and a program or capture that does not exit. +# +# The program is expected to come from a build with MORPH_ENABLE_TRACY=ON and +# MORPH_TRACY_ON_DEMAND=OFF, and is run with TRACY_NO_EXIT=1: the client then +# records from the first instruction and, at exit, waits until the capture has +# drained it. With an on-demand client, whatever ran before `tracy-capture` +# connected would be missing, and whether a short program's zones appeared +# would depend on that race. +set -euo pipefail + +readonly wait_seconds="${MORPH_TRACY_CAPTURE_WAIT:-600}" + +die() { + printf 'error: %s\n' "$*" >&2 + exit 1 +} + +# Waits for to exit, for at most . Returns the process's own +# exit status, or kills it and returns 124 if it has not exited by then. +wait_bounded() { + local pid="$1" seconds="$2" what="$3" + local waited=0 + while kill -0 "$pid" 2>/dev/null; do + if [ "$waited" -ge "$seconds" ]; then + kill "$pid" 2>/dev/null || true + wait "$pid" 2>/dev/null || true + printf 'error: %s did not exit within %ss; killed it\n' "$what" "$seconds" >&2 + return 124 + fi + sleep 1 + waited=$((waited + 1)) + done + local status=0 + wait "$pid" || status=$? + return "$status" +} + +assert_zones() { + local csv="$1" zones="$2" + [ -f "$csv" ] || die "no CSV at ${csv}: the export produced nothing" + [ -n "$zones" ] || die "no zone names given: an empty list would pass any capture" + + # The column layout `tracy-csvexport` writes without -u; `counts` is the + # sixth column. A different header means this parser would read the wrong + # column, so it is a failure, not something to guess around. + local expected_header="name,src_file,src_line,total_ns,total_perc,counts" + local header + header="$(head -n 1 "$csv")" + case "$header" in + "${expected_header}"*) ;; + *) die "unexpected CSV header in ${csv}: '${header}' (expected it to start with '${expected_header}')" ;; + esac + + local rows + rows="$(($(wc -l < "$csv") - 1))" + [ "$rows" -gt 0 ] || die "${csv} has a header and no rows: the capture recorded no zones at all" + printf 'ok: %s holds %d zone rows\n' "$csv" "$rows" + + local failures=0 zone count + local IFS=',' + for zone in $zones; do + # One name can have several rows (one per source location); a zone + # counts as present when their counts sum to more than zero. + count="$(awk -F',' -v zone="$zone" 'NR > 1 && $1 == zone { sum += $6 } END { print sum + 0 }' "$csv")" + if [ "$count" -gt 0 ]; then + printf 'ok: zone %-40s %s\n' "$zone" "$count" + else + printf 'error: zone %s has no events in %s\n' "$zone" "$csv" >&2 + failures=$((failures + 1)) + fi + done + [ "$failures" -eq 0 ] || die "${failures} named zone(s) missing from ${csv}" +} + +capture() { + [ "$#" -ge 6 ] || die "capture needs: -- [args...]" + local capture_bin="$1" csvexport_bin="$2" out_dir="$3" zones="$4" + shift 4 + [ "$1" = "--" ] || die "expected '--' before the program" + shift + local program="$1" + [ -x "$program" ] || die "program ${program} is not an executable file" + + mkdir -p "$out_dir" + local name trace csv + name="$(basename "$program")" + trace="${out_dir}/${name}.tracy" + csv="${out_dir}/${name}.csv" + rm -f "$trace" "$csv" + + "$capture_bin" -o "$trace" -a 127.0.0.1 -f > "${out_dir}/${name}.capture.log" 2>&1 & + local capture_pid=$! + + TRACY_NO_EXIT=1 "$@" > "${out_dir}/${name}.program.log" 2>&1 & + local program_pid=$! + + local program_status=0 + wait_bounded "$program_pid" "$wait_seconds" "${name}" || program_status=$? + local capture_status=0 + wait_bounded "$capture_pid" 120 "tracy-capture" || capture_status=$? + + printf '── %s (exit %d) ──\n' "$name" "$program_status" + tail -n 20 "${out_dir}/${name}.program.log" + printf '── tracy-capture (exit %d) ──\n' "$capture_status" + tail -n 20 "${out_dir}/${name}.capture.log" + + [ "$program_status" -eq 0 ] || die "${name} exited ${program_status}" + [ "$capture_status" -eq 0 ] || die "tracy-capture exited ${capture_status}" + [ -s "$trace" ] || die "tracy-capture wrote no trace at ${trace}" + + "$csvexport_bin" "$trace" > "$csv" || die "tracy-csvexport failed on ${trace}" + assert_zones "$csv" "$zones" +} + +[ "$#" -ge 1 ] || die "usage: $0 capture|assert ..." +mode="$1" +shift +case "$mode" in + capture) capture "$@" ;; + assert) + [ "$#" -eq 2 ] || die "assert needs: " + assert_zones "$1" "$2" + ;; + *) die "unknown mode '${mode}' (expected capture or assert)" ;; +esac diff --git a/scripts/test_check_tracy_capture.sh b/scripts/test_check_tracy_capture.sh new file mode 100644 index 00000000..6dfbd854 --- /dev/null +++ b/scripts/test_check_tracy_capture.sh @@ -0,0 +1,108 @@ +#!/usr/bin/env bash +# Usage: bash scripts/test_check_tracy_capture.sh +# +# Self-test for the assertion half of scripts/check_tracy_capture.sh, the gate +# the nightly Tracy capture job ends in. Every way a capture can carry no +# evidence -- no CSV, no rows, a different column layout, a named zone absent +# or counted zero, no zone named at all -- is fed to it from synthetic CSVs and +# must be refused for the stated reason, not merely with a nonzero exit; one +# CSV holding every named zone must pass. The capture half needs a profiled +# program and is exercised by the job itself. +set -euo pipefail + +repo_root="$(cd "$(dirname "${BASH_SOURCE[0]}")/.." && pwd)" +readonly repo_root +readonly checker="${repo_root}/scripts/check_tracy_capture.sh" + +failures=0 +scratch="$(mktemp -d)" +trap 'rm -rf "$scratch"' EXIT + +readonly header="name,src_file,src_line,total_ns,total_perc,counts,mean_ns,min_ns,max_ns,std_ns" + +# expect_fail +expect_fail() { + local name="$1" fragment="$2" csv="$3" zones="$4" + local out status=0 + out="$(bash "$checker" assert "$csv" "$zones" 2>&1)" || status=$? + if [ "$status" -eq 0 ]; then + printf 'error: %s: the checker passed\n%s\n' "$name" "$out" >&2 + failures=$((failures + 1)) + elif ! grep -qF -- "$fragment" <<<"$out"; then + printf 'error: %s: failed, but not for "%s":\n%s\n' "$name" "$fragment" "$out" >&2 + failures=$((failures + 1)) + else + printf 'ok: %s\n' "$name" + fi +} + +expect_pass() { + local name="$1" csv="$2" zones="$3" + local out + if out="$(bash "$checker" assert "$csv" "$zones" 2>&1)"; then + printf 'ok: %s\n' "$name" + else + printf 'error: %s: the checker refused a complete capture:\n%s\n' "$name" "$out" >&2 + failures=$((failures + 1)) + fi +} + +complete="${scratch}/complete.csv" +cat > "$complete" < "$split" < "$headerOnly" +expect_fail "a header with no rows" "has a header and no rows" "$headerOnly" "Bridge::executeVia" + +empty="${scratch}/empty.csv" +: > "$empty" +expect_fail "an empty file" "unexpected CSV header" "$empty" "Bridge::executeVia" + +unwrapped="${scratch}/unwrapped.csv" +cat > "$unwrapped" < "$zeroed" < "$prefix" <&2 + exit 1 +fi +printf 'ok: every case behaved\n' From 834791a042cda2f93c26f0498dc3c69b7515cc1d Mon Sep 17 00:00:00 2001 From: Yaraslau Tamashevich Date: Sat, 3 Oct 2026 21:57:31 +0200 Subject: [PATCH 4/4] core: profiler zones on RemoteServer's dispatch phases RemoteServer::dispatchMessage covers every decoded message and RemoteServer::dispatchExecute covers an execute's admission gates, both on the server strand. The admitted run is zoned separately on the model's strand (startRemote, startTaskRemote, finishRemote), so no zone spans the hand-off. Each zone carries the envelope's requestId as its text. The nightly capture now also requires the four zones morph_bench reaches. Co-Authored-By: Claude Opus 5.5 --- .github/workflows/nightly-slow-checks.yml | 2 +- docs/spec/core/profiler.md | 10 ++++------ include/morph/core/remote.hpp | 13 +++++++++++++ 3 files changed, 18 insertions(+), 7 deletions(-) diff --git a/.github/workflows/nightly-slow-checks.yml b/.github/workflows/nightly-slow-checks.yml index 43f86ddf..c34d66bc 100644 --- a/.github/workflows/nightly-slow-checks.yml +++ b/.github/workflows/nightly-slow-checks.yml @@ -392,7 +392,7 @@ jobs: bash scripts/check_tracy_capture.sh capture \ /home/runner/tracy-tools/tracy-capture /home/runner/tracy-tools/tracy-csvexport \ build/tracy/capture \ - "wire::encode,wire::decode,ModelStrands::task,ActionDispatcher::dispatch,ActionDispatcher::prepareAction" \ + "RemoteServer::dispatchMessage,RemoteServer::dispatchExecute,RemoteServer::startRemote,RemoteServer::finishRemote,wire::encode,wire::decode,ModelStrands::task,ActionDispatcher::dispatch,ActionDispatcher::prepareAction" \ -- build/tracy/tests/bench/morph_bench - name: Capture morph_bench_alloc (Bridge over LocalBackend) diff --git a/docs/spec/core/profiler.md b/docs/spec/core/profiler.md index de5215f1..7c71903b 100644 --- a/docs/spec/core/profiler.md +++ b/docs/spec/core/profiler.md @@ -114,9 +114,9 @@ callback executor. So: | `ws::enqueueFrame` | `net/detail/ws_connection.hpp`, the send side | the I/O loop | — | | `InMemoryOfflineQueue::enqueue`, `FileOfflineQueue::enqueue` | `offline/` | the queue's owner | — | | `SyncWorker::drain`, `SyncWorker::replay` (one per item) | `offline/sync_worker.hpp` | the worker's owner | — | - -`RemoteServer`'s own phases (`dispatchMessage`, `dispatchExecute`) are not -zoned yet; the dispatcher, strand and codec zones inside them are. +| `RemoteServer::dispatchMessage` | `remote.hpp`, every message after its decode | the server strand | the envelope's `requestId` | +| `RemoteServer::dispatchExecute` | `remote.hpp`, an `execute`'s admission gates | the server strand | the envelope's `requestId` | +| `RemoteServer::startRemote`, `RemoteServer::startTaskRemote`, `RemoteServer::finishRemote` | `remote.hpp` | the model's strand | the envelope's `requestId` | ## Thread names @@ -172,7 +172,7 @@ The nightly workflow's `tracy-capture` job builds `morph_bench` and `TRACY_NO_EXIT=1`, exports zone statistics with `tracy-csvexport`, and fails unless every named zone has a non-zero count (`scripts/check_tracy_capture.sh`). `morph_bench` drives `RemoteServer`'s -dispatch and so the codec, dispatcher and strand zones; `morph_bench_alloc` +dispatch and so its own zones and the codec, dispatcher and strand zones; `morph_bench_alloc` drives `Bridge` over `LocalBackend`. The check fails closed. No CSV, a CSV with no rows, a column layout other than @@ -195,8 +195,6 @@ assertion each of those as a synthetic CSV and runs first in the job. ## Limitations -- **No zones in `RemoteServer` yet.** `RemoteServer::dispatchMessage` and - `RemoteServer::dispatchExecute` are the obvious next two. - **core-cpp is not instrumented.** Its event loop and strand pump are its own; morph's zones start at morph's around-task hook. - **No statistics collector and no `morph::observe` → Tracy sink.** Both are diff --git a/include/morph/core/remote.hpp b/include/morph/core/remote.hpp index d1a7d8fb..f796f256 100644 --- a/include/morph/core/remote.hpp +++ b/include/morph/core/remote.hpp @@ -32,6 +32,7 @@ #include "logger.hpp" #include "observability.hpp" #include "owner_strand.hpp" +#include "profiler.hpp" #include "timeout_scheduler.hpp" #include "wire.hpp" @@ -1060,11 +1061,13 @@ class RemoteServer : public std::enable_shared_from_this { /// `execute`) from the model's strand. /// @param cid Connection scope; `0` means unscoped. void dispatchDecoded(Decoded decoded, std::function& reply, ConnectionId cid) { + MORPH_ZONE("RemoteServer::dispatchMessage"); noteOwner("RemoteServer::dispatch"); if (!decoded.env) { replyUndecodable(decoded.raw, decoded.error, reply, cid); return; } + MORPH_ZONE_TEXT(decoded.env->session.requestId); dispatchEnvelope(std::move(*decoded.env), reply, cid); } @@ -1296,6 +1299,10 @@ class RemoteServer : public std::enable_shared_from_this { // server strand; the admitted run is posted to the model's strand. // NOLINTNEXTLINE(readability-function-cognitive-complexity) void dispatchExecute(::morph::wire::Envelope env, std::function reply) { + // The admission phase only, on the server strand: the run itself is + // posted to the model's strand and zoned there, in startRemote. + MORPH_ZONE("RemoteServer::dispatchExecute"); + MORPH_ZONE_TEXT(env.session.requestId); noteOwner("RemoteServer::admitExecute"); auto reject = [&env, &reply](const char* message) { reply(::morph::wire::encode(::morph::wire::makeErr(message, env.callId))); @@ -1524,6 +1531,8 @@ class RemoteServer : public std::enable_shared_from_this { /// Runs an ordinary handler's execute once it holds its instance's action /// gate, on the strand, and replies. static void startRemote(RemoteRun& run) { + MORPH_ZONE("RemoteServer::startRemote"); + MORPH_ZONE_TEXT(run.env.session.requestId); admitRemote(run); std::string result; std::exception_ptr error; @@ -1539,6 +1548,8 @@ class RemoteServer : public std::enable_shared_from_this { /// Starts a Task handler's execute once it holds its instance's action /// gate, on the strand. It replies when its Task completes. static void startTaskRemote(const std::shared_ptr& run) { + MORPH_ZONE("RemoteServer::startTaskRemote"); + MORPH_ZONE_TEXT(run->env.session.requestId); admitRemote(*run); std::shared_ptr<::morph::exec::detail::TaskResumer> executor; try { @@ -1569,6 +1580,8 @@ class RemoteServer : public std::enable_shared_from_this { /// Records a finished execute, replies, and leaves the action gate so the /// next execute on the instance can start. On the strand. static void finishRemote(RemoteRun& run, std::string result, const std::exception_ptr& error) { + MORPH_ZONE("RemoteServer::finishRemote"); + MORPH_ZONE_TEXT(run.env.session.requestId); auto& self = *run.self; if (self._executeTimeouts) { self._executeTimeouts->cancel(run.timeoutHandle);