0.8.1: a measured call says what it was made of

CHANGELOG.md

@@ -1,5 +1,31 @@
 # Changelog
 
+## [0.8.1] - 2026-11-14
+
+- **A measured call says what it was made of** (`bench::each`, `mcpplibs.mtest.bench`). The body's
+  `bench::lap` takes `part(name, spent)` -- a part of the call the body timed, or `auto t =
+  l.time(name);` to the end of `t` -- reported over the calls as `name.<part>` (the median) with
+  `.p95`, `.p99`, `.max` and `.mean`, metrics a bound can name (`at_most{"draw.encode.p99",
+  0.004}`); `value(name, v)`, a quantity of the call, reported as `name.<quantity>` (the mean)
+  and `.max`; and `say(text)`, words about the call.
+- **The slowest calls are stated one by one** (`each_options::slowest`): each with its time, its
+  parts, its quantities and its words, a line in the case's output (`draw: call 412 took 9.100 ms:
+  encode 7.900 ms, glyphs 24570 -- zoom 0.43`) and in `distribution::slowest` -- why the slow
+  calls were slow, from the run that measured them, with no second run under a tool.
+- **A limit a call, and a run the body ends** (`each_options::limit`, `lap::last`). With a limit (a
+  frame's 8.33 ms) `name.over` is how many calls took more and `name.over.share` their part of
+  all -- `at_most{"frame.over", 0}` is no late frame -- and the calls over it are the ones stated
+  one by one. `l.last()` makes this call the last: what is measured has run out (a recorded
+  session's last frame), whatever the options still ask.
+- **Heap allocations a call** (`bench::allocated`). The library replaces no `operator new`; a
+  program that counts says so from its own (`bench::allocated(n)`), and `each` then reports
+  `name.allocations` (the mean a call), `name.allocations.max` and `name.allocated` (bytes), less
+  what a call paused for: `at_most{"draw.allocations.max", 0}` is a frame that allocates nothing.
+  Counted a thread -- the calling thread's allocations are the call's, and the count is no line
+  two threads write: a program whose workers allocate is not slowed by being measured.
+- Additive: a body that says none of these is measured and reported as it was; no event and no
+  clause changed.
+
 ## [0.8.0] - 2026-11-14
 
 - **Where a case runs is stated by the case** (`only{}`, `except{}`). A case or a suite names the

README.md

@@ -38,7 +38,7 @@ int main() {
 
 ```toml
 [dev-dependencies]
-mcpplibs.mtest = "0.8.0"
+mcpplibs.mtest = "0.8.1"
 ```
 
 A failure names its place and both sides (`expected 2, actual 3`). Under a runner the same program

README.zh-CN.md

@@ -37,7 +37,7 @@ int main() {
 
 ```toml
 [dev-dependencies]
-mcpplibs.mtest = "0.8.0"
+mcpplibs.mtest = "0.8.1"
 ```
 
 失败时给出位置与两侧的值（`expected 2, actual 3`）。在运行器之下，同一程序按协议报告；单独运行时每个用例输出一行。

adapters/gtest/mcpp.toml

@@ -13,7 +13,7 @@
 [package]
 namespace   = "mcpplibs.mtest"
 name        = "gtest"
-version     = "0.8.0"
+version     = "0.8.1"
 description = "GoogleTest speaking the mtest protocol: a test main that lists, selects and reports GoogleTest's cases"
 license     = "Apache-2.0"
 

adapters/gtest/src/protocol.cpp

@@ -128,7 +128,7 @@ int mcpplibs_mtest_gtest_main(int argc, char** argv) {
                   {"protocol", 1},
                   {"level", 1},
                   {"framework", "googletest"},
-                  {"version", "0.8.0"},
+                  {"version", "0.8.1"},
                   {"isolation", {"process", "case"}},
                   {"guide", "https://github.com/mcpp-community/mtest/blob/main/adapters/gtest/docs/"
                             "writing-tests.md"}});

capi/mcpp.toml

@@ -4,7 +4,7 @@
 [package]
 namespace   = "mcpplibs.mtest"
 name        = "capi"
-version     = "0.8.0"
+version     = "0.8.1"
 description = "mtest's C ABI: the protocol's events for any language with a C FFI"
 license     = "Apache-2.0"
 

capi/src/mtest.cpp

@@ -120,7 +120,7 @@ void mtest_init(const char* framework, int level) {
              {"protocol", 1},
              {"level", std::clamp(level, 1, 3)},
              {"framework", text(framework)},
-             {"version", "0.8.0"},
+             {"version", "0.8.1"},
              {"isolation", {"process", "case"}}});
 }
 

conformance/mcpp.toml

@@ -8,7 +8,7 @@
 [package]
 namespace   = "mcpplibs.mtest"
 name        = "conformance"
-version     = "0.8.0"
+version     = "0.8.1"
 description = "The conformance suite of the mtest protocol, for every implementation of its program side"
 license     = "Apache-2.0"
 

engine/mcpp.toml

@@ -10,7 +10,7 @@
 [package]
 namespace   = "mtest"
 name        = "mtest"
-version     = "0.8.0"
+version     = "0.8.1"
 description = "The mtest engine: run, schedule, store, explain and analyse tests of any language"
 license     = "Apache-2.0"
 authors     = ["mcpp-community"]

engine/src/commands.cpp

@@ -1958,7 +1958,7 @@ json catalog() {
         plain({{"out", {{"type", "string"}}},
                {"argv", {{"type", "array"}, {"items", {{"type", "string"}}}}}}),
         true);
-    return {{"schema", "mtest.catalog/1"}, {"version", "0.8.0"}, {"tools", tools}};
+    return {{"schema", "mtest.catalog/1"}, {"version", "0.8.1"}, {"tools", tools}};
 }
 
 }  // namespace mcpplibs::mtest::engine

engine/src/main.cpp

@@ -98,7 +98,7 @@ const json* tool_named(const json& tools, std::string_view name) {
 
 cmdline::App application(const json& tools) {
     auto app = cmdline::App("mtest")
-                   .version("0.8.0")
+                   .version("0.8.1")
                    .description("run tests of any language, and ask about their runs")
                    .option(cmdline::Option("json").global().help("print the answer's data"));
     for (const auto& t : tools)
@@ -253,7 +253,7 @@ int main(int argc, char** argv) {
     const std::string name(parsed->subcommand_name());
     const auto& sub = parsed->subcommand()->get();
     if (name == "version") {
-        std::println("mtest 0.8.0");
+        std::println("mtest 0.8.1");
         return 0;
     }
     const auto cwd = std::filesystem::current_path();

engine/src/service.cpp

@@ -56,7 +56,7 @@ int serve(const std::filesystem::path& cwd) {
                   {"result",
                    {{"protocolVersion", params.value("protocolVersion", std::string("2025-06-18"))},
                     {"capabilities", {{"tools", {{"listChanged", false}}}}},
-                    {"serverInfo", {{"name", "mtest"}, {"version", "0.8.0"}}},
+                    {"serverInfo", {{"name", "mtest"}, {"version", "0.8.1"}}},
                     {"instructions",
                      "Run tests and ask about runs: run, plan, explain, history, analyze, graph, "
                      "gate, ci. A test session (test/plan, test/run, test/add, test/cancel, "

lib/docs/writing-tests.md

@@ -53,7 +53,7 @@ E2E cli{"cli", resource{"serial:home"}, timeout{std::chrono::minutes{2}}, [] { /
   The entry enters the child before any case; the copy runs no case and reports nothing. The files of
   one directory are then one program (mcpp `[test] programs = "directory"`) however many of them start
   copies.
-- The manifest names the library once: `[dev-dependencies] mcpplibs.mtest = "0.8.0"`.
+- The manifest names the library once: `[dev-dependencies] mcpplibs.mtest = "0.8.1"`.
 - Identifiers are stable: a selection, a history and a shard name a case by them.
 
 ## Expectations
@@ -149,6 +149,16 @@ How the tests of a project are laid out, from the directory to the line, is in
   reports `draw` (the median), `draw.p95`, `draw.p99`, `draw.max`, `draw.mean`; `l.pause()` and
   `l.resume()` leave out what is not the call's, `l.items(n)` adds `draw.per_item`. A bound names
   any of them: `at_most{"draw.p95", 0.016}`.
+  A call may say what it was made of: `l.part("encode", spent)` (or `auto t = l.time("encode");`,
+  to the end of `t`) is a part of it, reported as `draw.encode` with the same `.p95`, `.p99`,
+  `.max`, `.mean`; `l.value("glyphs", n)` a quantity of it, `draw.glyphs` (the mean) and
+  `draw.glyphs.max`; `l.say("zoom 0.43")` words about it. With `{.slowest = 3}` the three slowest
+  calls are stated one by one in the case's output, each with its parts, quantities and words:
+  why the slow calls were slow, from the run that measured them. A program that replaces
+  `operator new` and calls `bench::allocated(n)` from it gets each call's allocations too:
+  `draw.allocations`, `draw.allocations.max`, `draw.allocated` (bytes). With `{.limit = 8333us}`,
+  `draw.over` counts the calls that took more (and they are the ones stated one by one);
+  `l.last()` ends the run at this call.
 
 ## Programs under test
 

lib/mcpp.toml

@@ -17,7 +17,7 @@
 [package]
 namespace   = "mcpplibs"
 name        = "mtest"
-version     = "0.8.0"
+version     = "0.8.1"
 description = "The C++ test library of mtest: cases, expectations, fixtures, bench, conformance and end-to-end helpers, with no macro and no header, speaking the mtest protocol"
 license     = "Apache-2.0"
 authors     = ["mcpp-community"]

lib/src/bench.cpp

@@ -65,6 +65,154 @@ distribution distribute(std::vector<double> samples, std::uint64_t items) {
     return d;
 }
 
+namespace {
+constexpr double unsaid = std::numeric_limits<double>::quiet_NaN();
+
+std::size_t column(std::vector<std::string>& names, std::string_view name) {
+    for (std::size_t i = 0; i < names.size(); ++i)
+        if (names[i] == name)
+            return i;
+    names.emplace_back(name);
+    return names.size() - 1;
+}
+
+double& cell(std::vector<double>& cells, std::size_t at) {
+    if (cells.size() <= at)
+        cells.resize(at + 1, unsaid);
+    return cells[at];
+}
+
+double said(const std::vector<double>& cells, std::size_t at) {
+    return at < cells.size() ? cells[at] : unsaid;
+}
+
+template <class Rows, class Pick>
+quantity over(std::string name, const Rows& rows, std::size_t at, Pick pick) {
+    quantity q;
+    q.name = std::move(name);
+    std::vector<double> sorted;
+    for (const auto& r : rows)
+        if (const double v = said(pick(r), at); !std::isnan(v))
+            sorted.push_back(v);
+    q.calls = sorted.size();
+    if (sorted.empty())
+        return q;
+    std::ranges::sort(sorted);
+    q.min = sorted.front();
+    q.max = sorted.back();
+    q.p50 = percentile(sorted, 0.50);
+    q.p95 = percentile(sorted, 0.95);
+    q.p99 = percentile(sorted, 0.99);
+    double sum = 0;
+    for (double x : sorted)
+        sum += x;
+    q.mean = sum / double(sorted.size());
+    return q;
+}
+
+// A time for a reader: 9.100 ms, 412.0 us, 1.250 s.
+std::string readable(double seconds) {
+    if (seconds >= 1)
+        return std::format("{:.3f} s", seconds);
+    if (seconds >= 1e-3)
+        return std::format("{:.3f} ms", seconds * 1e3);
+    if (seconds >= 1e-6)
+        return std::format("{:.1f} us", seconds * 1e6);
+    return std::format("{:.0f} ns", seconds * 1e9);
+}
+}  // namespace
+
+namespace {
+// A thread's own: an allocation costs it two additions and touches no line another thread writes,
+// so a program whose other threads allocate is not slowed by being counted.
+thread_local constinit std::uint64_t allocation_calls = 0;
+thread_local constinit std::uint64_t allocation_bytes = 0;
+}  // namespace
+
+void allocated(std::size_t bytes) noexcept {
+    ++allocation_calls;
+    allocation_bytes += bytes;
+}
+
+allocation_count allocations() noexcept {
+    return {allocation_calls, allocation_bytes};
+}
+
+void lap::part(std::string_view name, clock::duration spent) {
+    double& at = cell(now_.parts, column(part_names_, name));
+    const double seconds = std::chrono::duration<double>(spent).count();
+    at = std::isnan(at) ? seconds : at + seconds;
+}
+
+void lap::value(std::string_view name, double v) {
+    cell(now_.values, column(value_names_, name)) = v;
+}
+
+void lap_access::keep(lap& l) {
+    // A program that counts its allocations: each call's are quantities of it.
+    if (allocations().count > 0) {
+        l.value("allocations", double(l.now_count_));
+        l.value("allocated", double(l.now_bytes_));
+    }
+    if (l.part_names_.empty() && l.value_names_.empty() && l.now_.said.empty() && l.rows_.empty())
+        return;  // no call has said anything: nothing is kept
+    l.rows_.push_back(std::move(l.now_));
+    l.now_ = {};
+}
+
+void lap_access::drop(lap& l) {
+    l.now_ = {};
+}
+
+distribution distribute(std::vector<double> samples, const lap& l, std::size_t slowest,
+                        double limit) {
+    const std::vector<double> in_order = samples;
+    distribution d = distribute(std::move(samples), lap_access::items(l));
+    const lap_access::view said_by = lap_access::look(l);
+    // Rows begin at the first call that said anything: the calls before it said nothing.
+    const std::size_t before = in_order.size() - std::min(in_order.size(), said_by.rows.size());
+    for (std::size_t i = 0; i < said_by.parts.size(); ++i)
+        d.parts.push_back(
+            over(std::string{said_by.parts[i]}, said_by.rows, i,
+                 [](const auto& r) -> const std::vector<double>& { return r.parts; }));
+    for (std::size_t i = 0; i < said_by.values.size(); ++i)
+        d.values.push_back(
+            over(std::string{said_by.values[i]}, said_by.rows, i,
+                 [](const auto& r) -> const std::vector<double>& { return r.values; }));
+    std::vector<std::size_t> order(in_order.size());
+    std::ranges::iota(order, std::size_t{0});
+    d.limit = limit;
+    if (limit > 0) {
+        d.over = static_cast<std::size_t>(
+            std::ranges::count_if(in_order, [&](double x) { return x > limit; }));
+        if (slowest == 0)
+            slowest = std::min<std::size_t>(d.over, 8);
+    }
+    const std::size_t stated = std::min(slowest, order.size());
+    std::ranges::partial_sort(order, order.begin() + static_cast<std::ptrdiff_t>(stated),
+                              [&](std::size_t a, std::size_t b) {
+                                  return in_order[a] != in_order[b] ? in_order[a] > in_order[b]
+                                                                    : a < b;
+                              });
+    for (std::size_t k = 0; k < stated; ++k) {
+        slow_call c;
+        c.index = order[k];
+        c.seconds = in_order[c.index];
+        if (c.index >= before) {
+            const auto& r = said_by.rows[c.index - before];
+            for (std::size_t i = 0; i < said_by.parts.size(); ++i)
+                if (const double v = said(r.parts, i); !std::isnan(v))
+                    c.parts.emplace_back(std::string{said_by.parts[i]}, v);
+            for (std::size_t i = 0; i < said_by.values.size(); ++i)
+                if (const double v = said(r.values, i); !std::isnan(v))
+                    c.values.emplace_back(std::string{said_by.values[i]}, v);
+            c.said = r.said;
+        }
+        d.slowest.push_back(std::move(c));
+    }
+    return d;
+}
+
 // The calls differ by their nature, so the samples are not stated with the metrics: the verdict on
 // samples that spread (P6.2) is for a measurement meant to be one number.
 void record(std::string_view name, const distribution& d) {
@@ -76,6 +224,34 @@ void record(std::string_view name, const distribution& d) {
     metric(base + ".mean", d.mean, "s");
     if (d.items)
         metric(base + ".per_item", d.per_item, "s");
+    for (const quantity& q : d.parts) {
+        const std::string part = base + "." + q.name;
+        metric(part, q.p50, "s");
+        metric(part + ".p95", q.p95, "s");
+        metric(part + ".p99", q.p99, "s");
+        metric(part + ".max", q.max, "s");
+        metric(part + ".mean", q.mean, "s");
+    }
+    for (const quantity& q : d.values) {
+        metric(base + "." + q.name, q.mean, "");
+        metric(base + "." + q.name + ".max", q.max, "");
+    }
+    if (d.limit > 0) {
+        metric(base + ".over", double(d.over), "");
+        metric(base + ".over.share",
+               d.samples.empty() ? 0 : double(d.over) / double(d.samples.size()), "");
+    }
+    for (const slow_call& c : d.slowest) {
+        std::string line = std::format("{}: call {} took {}", name, c.index, readable(c.seconds));
+        const char* between = ": ";
+        for (const auto& [part, seconds] : c.parts)
+            line += std::format("{}{} {}", std::exchange(between, ", "), part, readable(seconds));
+        for (const auto& [value, v] : c.values)
+            line += std::format("{}{} {:g}", std::exchange(between, ", "), value, v);
+        if (!c.said.empty())
+            line += " -- " + c.said;
+        std::println("{}", line);
+    }
 }
 
 }  // namespace mcpplibs::mtest::bench