From 5b513e860c680f77ad3f1dc4595f3c15ce055182 Mon Sep 17 00:00:00 2001 From: Sunrisepeak Date: Sat, 14 Nov 2026 07:33:00 +0900 Subject: [PATCH 1/2] 0.8.1: a measured call says what it was made of (parts, quantities, the slowest calls one by one, a limit, allocations) --- CHANGELOG.md | 24 +++++ README.md | 2 +- README.zh-CN.md | 2 +- adapters/gtest/mcpp.toml | 2 +- adapters/gtest/src/protocol.cpp | 2 +- capi/mcpp.toml | 2 +- capi/src/mtest.cpp | 2 +- conformance/mcpp.toml | 2 +- engine/mcpp.toml | 2 +- engine/src/commands.cpp | 2 +- engine/src/main.cpp | 4 +- engine/src/service.cpp | 2 +- lib/docs/writing-tests.md | 12 ++- lib/mcpp.toml | 2 +- lib/src/bench.cpp | 174 ++++++++++++++++++++++++++++++++ lib/src/bench.cppm | 141 ++++++++++++++++++++++++-- lib/src/mtest.cpp | 2 +- lib/tests/companions.cpp | 86 ++++++++++++++++ manifest/mcpp.toml | 2 +- 19 files changed, 440 insertions(+), 27 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 2da2b64..3965a5a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,29 @@ # 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.` (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.` (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. +- 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 diff --git a/README.md b/README.md index 0dd14b5..aa0ce1b 100644 --- a/README.md +++ b/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 diff --git a/README.zh-CN.md b/README.zh-CN.md index 3330b3b..89fcd8f 100644 --- a/README.zh-CN.md +++ b/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`)。在运行器之下,同一程序按协议报告;单独运行时每个用例输出一行。 diff --git a/adapters/gtest/mcpp.toml b/adapters/gtest/mcpp.toml index 7835dca..f4a187e 100644 --- a/adapters/gtest/mcpp.toml +++ b/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" diff --git a/adapters/gtest/src/protocol.cpp b/adapters/gtest/src/protocol.cpp index 19d541c..d939a09 100644 --- a/adapters/gtest/src/protocol.cpp +++ b/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"}}); diff --git a/capi/mcpp.toml b/capi/mcpp.toml index dfab92f..a05631d 100644 --- a/capi/mcpp.toml +++ b/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" diff --git a/capi/src/mtest.cpp b/capi/src/mtest.cpp index ba8afb3..9f3c578 100644 --- a/capi/src/mtest.cpp +++ b/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"}}}); } diff --git a/conformance/mcpp.toml b/conformance/mcpp.toml index efa275e..446454b 100644 --- a/conformance/mcpp.toml +++ b/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" diff --git a/engine/mcpp.toml b/engine/mcpp.toml index c080e32..4c4240a 100644 --- a/engine/mcpp.toml +++ b/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"] diff --git a/engine/src/commands.cpp b/engine/src/commands.cpp index ea59fcc..458dd6d 100644 --- a/engine/src/commands.cpp +++ b/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 diff --git a/engine/src/main.cpp b/engine/src/main.cpp index fa222fe..37085bc 100644 --- a/engine/src/main.cpp +++ b/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(); diff --git a/engine/src/service.cpp b/engine/src/service.cpp index 95f997f..19aa0ff 100644 --- a/engine/src/service.cpp +++ b/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, " diff --git a/lib/docs/writing-tests.md b/lib/docs/writing-tests.md index 95df479..a1b4956 100644 --- a/lib/docs/writing-tests.md +++ b/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 diff --git a/lib/mcpp.toml b/lib/mcpp.toml index 82b5659..43d0035 100644 --- a/lib/mcpp.toml +++ b/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"] diff --git a/lib/src/bench.cpp b/lib/src/bench.cpp index ddf3abf..4f1159b 100644 --- a/lib/src/bench.cpp +++ b/lib/src/bench.cpp @@ -65,6 +65,152 @@ distribution distribute(std::vector samples, std::uint64_t items) { return d; } +namespace { +constexpr double unsaid = std::numeric_limits::quiet_NaN(); + +std::size_t column(std::vector& 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& cells, std::size_t at) { + if (cells.size() <= at) + cells.resize(at + 1, unsaid); + return cells[at]; +} + +double said(const std::vector& cells, std::size_t at) { + return at < cells.size() ? cells[at] : unsaid; +} + +template +quantity over(std::string name, const Rows& rows, std::size_t at, Pick pick) { + quantity q; + q.name = std::move(name); + std::vector 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 { +std::atomic allocation_calls{0}, allocation_bytes{0}; +} + +void allocated(std::size_t bytes) noexcept { + allocation_calls.fetch_add(1, std::memory_order_relaxed); + allocation_bytes.fetch_add(bytes, std::memory_order_relaxed); +} + +allocation_count allocations() noexcept { + return {allocation_calls.load(std::memory_order_relaxed), + allocation_bytes.load(std::memory_order_relaxed)}; +} + +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(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 samples, const lap& l, std::size_t slowest, + double limit) { + const std::vector 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& { 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& { return r.values; })); + std::vector order(in_order.size()); + std::ranges::iota(order, std::size_t{0}); + d.limit = limit; + if (limit > 0) { + d.over = static_cast( + std::ranges::count_if(in_order, [&](double x) { return x > limit; })); + if (slowest == 0) + slowest = std::min(d.over, 8); + } + const std::size_t stated = std::min(slowest, order.size()); + std::ranges::partial_sort(order, order.begin() + static_cast(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 +222,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 diff --git a/lib/src/bench.cppm b/lib/src/bench.cppm index cfb4a6c..f67a30b 100644 --- a/lib/src/bench.cppm +++ b/lib/src/bench.cppm @@ -78,13 +78,39 @@ summary measure(std::string_view name, F&& f, options o = {}) { // l.items(scene.nodes()); // what this call worked through // }); // }}; +// A call may also say what it was made of, so a slow call explains itself: +// l.part("encode", spent) a part of the call the body timed (or `auto t = l.time("encode");`, +// to +// the end of `t`): `draw.encode`, with `.p95`, `.p99`, `.max`, `.mean` +// l.value("glyphs", n) a quantity of this call: `draw.glyphs` its mean, `draw.glyphs.max` +// l.say("zoom 0.43") words about this call +// and with `slowest = N` the N slowest calls are stated with all of it, in the case's output: +// draw: call 412 took 9.100 ms: encode 7.900 ms, glyphs 24570 -- zoom 0.43 struct each_options { std::size_t least = 12; // calls measured, at least std::size_t most = 100'000; // and at most std::chrono::nanoseconds time = std::chrono::milliseconds{400}; // measured for this long - std::size_t warmup = 3; // calls before the first measured one + std::size_t warmup = 3; // calls before the first measured one + std::size_t slowest = 0; // the slowest calls stated one by one, this many + // What one call may take (a frame's 8.33 ms). Stated: `name.over` is how many calls took more, + // `name.over.share` their part of all, and those calls are the ones stated one by one where + // `slowest` is 0 (the eight slowest of them). + std::chrono::nanoseconds limit{0}; }; +// HEAP ALLOCATIONS A CALL. The library replaces no `operator new`; a program that counts replaces +// it and says so from there: +// void* operator new(std::size_t n) { bench::allocated(n); return std::malloc(n); } +// `each` then reports `name.allocations` (the mean a call) and `name.allocations.max`, and +// `name.allocated` (bytes, the mean) -- less what a call paused for; +// `at_most{"draw.allocations.max", 0}` is a frame that allocates nothing. A program that never says +// so reports none of them. +void allocated(std::size_t bytes) noexcept; +struct allocation_count { + std::uint64_t count = 0, bytes = 0; +}; +allocation_count allocations() noexcept; + // One call: what the body may say of it. class lap { public: @@ -92,11 +118,15 @@ public: // The time from `pause` to `resume` is not this call's. void pause() noexcept { if (!paused_) - paused_ = true, paused_at_ = clock::now(); + paused_ = true, paused_at_ = clock::now(), paused_with_ = allocations(); } void resume() noexcept { - if (paused_) + if (paused_) { + const allocation_count now = allocations(); + out_count_ += now.count - paused_with_.count; + out_bytes_ += now.bytes - paused_with_.bytes; paused_ = false, out_ += clock::now() - paused_at_; + } } // What this call worked through (nodes, cells, bytes): `name.per_item` is the mean time of one. void items(std::uint64_t n) noexcept { @@ -109,13 +139,54 @@ public: bool warmup() const noexcept { return warmup_; } + // A part of this call, timed by the body. Said again in the same call: added to. + void part(std::string_view name, clock::duration spent); + // The part `name` is the time from here to the end of what this returns. + class timed { + public: + timed(lap& of, std::string_view name) : of_(of), name_(name), from_(clock::now()) {} + timed(const timed&) = delete; + timed& operator=(const timed&) = delete; + ~timed() { + of_.part(name_, clock::now() - from_); + } + private: + lap& of_; + std::string name_; + clock::time_point from_; + }; + [[nodiscard]] timed time(std::string_view name) { + return timed{*this, name}; + } + // A quantity of this call (what it drew, what it sent). Said again in the same call: replaced. + void value(std::string_view name, double v); + // This call is the last: what is measured has run out (a recorded session's last frame). + void last() noexcept { + last_ = true; + } + // Words about this call, stated with it when it is among the slowest. + void say(std::string text) { + now_.said = std::move(text); + } private: friend struct lap_access; - bool paused_ = false, warmup_ = false; + bool paused_ = false, warmup_ = false, last_ = false; clock::time_point paused_at_{}; clock::duration out_{}; + allocation_count paused_with_{}, began_with_{}; + std::uint64_t out_count_ = 0, out_bytes_ = 0; std::uint64_t items_ = 0; std::size_t index_ = 0; + // What the calls said: a column a name, a row a measured call (not a number where a call did + // not say). + struct row { + std::vector parts, values; + std::string said; + }; + std::uint64_t now_count_ = 0, now_bytes_ = 0; // the call that ended allocated + std::vector part_names_, value_names_; + row now_; + std::vector rows_; }; // What `each` does with a lap (not for a test). @@ -124,29 +195,72 @@ struct lap_access { l.warmup_ = on; } static void begin(lap& l) noexcept { - l.paused_ = false, l.out_ = {}; + l.paused_ = false, l.out_ = {}, l.out_count_ = l.out_bytes_ = 0; + l.began_with_ = allocations(); } static lap::clock::duration end(lap& l) noexcept { l.resume(); ++l.index_; + const allocation_count now = allocations(); + l.now_count_ = now.count - l.began_with_.count - l.out_count_; + l.now_bytes_ = now.bytes - l.began_with_.bytes - l.out_bytes_; return l.out_; } + // The call that ended was a measured one: what it said is kept, in the order of the samples. + static void keep(lap& l); + // What it said is dropped (a warm-up call's). + static void drop(lap& l); + static bool last(const lap& l) noexcept { + return l.last_; + } + // What the measured calls said. + struct view { + std::span parts, values; + std::span rows; + }; + static view look(const lap& l) noexcept { + return {l.part_names_, l.value_names_, l.rows_}; + } static std::uint64_t items(const lap& l) noexcept { return l.items_; } }; +// Where one part (seconds) or one quantity lies over the calls that said it. +struct quantity { + std::string name; + std::size_t calls = 0; // that said it + double min = 0, mean = 0, p50 = 0, p95 = 0, p99 = 0, max = 0; +}; + +// One call, with what it said. +struct slow_call { + std::size_t index = 0; // among the measured calls, from 0 + double seconds = 0; + std::vector> parts, values; + std::string said; +}; + struct distribution { std::vector samples; // seconds a call, in the order measured double min = 0, mean = 0, p50 = 0, p95 = 0, p99 = 0, max = 0; - std::uint64_t items = 0; // a call's, as the last call that said so stated it - double per_item = 0; // mean / items; 0 when no call stated any + std::uint64_t items = 0; // a call's, as the last call that said so stated it + double per_item = 0; // mean / items; 0 when no call stated any + std::vector parts, values; // what the calls said (lap::part, lap::value) + std::vector slowest; // the slowest first (each_options::slowest) + double limit = 0; // seconds a call may take (each_options::limit); 0: none stated + std::size_t over = 0; // the calls that took more }; // The value `q` of the way (0 to 1) through `sorted`, between the two nearest by position. double percentile(std::span sorted, double q); distribution distribute(std::vector samples, std::uint64_t items = 0); -// The metrics of a distribution (see `each`), in seconds; `per_item` when a call stated items. +// The same, with what the calls of `l` said and the `slowest` of them one by one. +distribution distribute(std::vector samples, const lap& l, std::size_t slowest, + double limit = 0); +// The metrics of a distribution (see `each`), in seconds; `per_item` when a call stated items; a +// part's as the calls' (`name.`, `.p95`, `.p99`, `.max`, `.mean`), a quantity's mean and +// `.max`; the slowest calls a line each in the case's output. void record(std::string_view name, const distribution& d); template @@ -165,18 +279,23 @@ distribution each(std::string_view name, F&& f, each_options o = {}) { return std::max(clock::duration{}, t1 - t0 - lap_access::end(l)); }; lap_access::warmup(l, true); - for (std::size_t i = 0; i < o.warmup; ++i) + for (std::size_t i = 0; i < o.warmup && !lap_access::last(l); ++i) { call(); + lap_access::drop(l); + } lap_access::warmup(l, false); std::vector samples; samples.reserve(std::min(o.most, 4096)); clock::duration total{}; - while (samples.size() < o.most && (samples.size() < o.least || total < o.time)) { + while (!lap_access::last(l) && samples.size() < o.most && + (samples.size() < o.least || total < o.time)) { const auto spent = call(); total += spent; samples.push_back(std::chrono::duration(spent).count()); + lap_access::keep(l); } - auto d = distribute(std::move(samples), lap_access::items(l)); + auto d = distribute(std::move(samples), l, o.slowest, + std::chrono::duration(o.limit).count()); record(name, d); return d; } diff --git a/lib/src/mtest.cpp b/lib/src/mtest.cpp index fc21cbb..ce6c547 100644 --- a/lib/src/mtest.cpp +++ b/lib/src/mtest.cpp @@ -324,7 +324,7 @@ void write_program() { {"protocol", 1}, {"level", 3}, {"framework", "mcpplibs.mtest"}, - {"version", "0.8.0"}, + {"version", "0.8.1"}, {"isolation", {"process", "case"}}, {"guide", "https://github.com/mcpp-community/mtest/blob/main/lib/docs/writing-tests.md"}}); } diff --git a/lib/tests/companions.cpp b/lib/tests/companions.cpp index 378442b..5f9511f 100644 --- a/lib/tests/companions.cpp +++ b/lib/tests/companions.cpp @@ -61,6 +61,92 @@ int main(int argc, char** argv) { expect(ge(d.max, 0.0004)) << "the slow calls are seen: " << d.max; expect(eq(d.items, std::uint64_t(50)) && gt(d.per_item, 0.0) && lt(d.per_item, d.mean)); }; + "a call says what it was made of: parts, quantities, and the slowest calls one by one"_test + [kind::bench] = [] { + const auto spin = [](std::chrono::microseconds d) { + const auto end = std::chrono::steady_clock::now() + d; + while (std::chrono::steady_clock::now() < end) {} + }; + auto d = bench::each("frame", + [&](bench::lap& l) { + const bool slow = !l.warmup() && l.index() == 2 + 7; + { + auto encoding = l.time("encode"); + spin(std::chrono::microseconds{slow ? 900 : 100}); + } + l.part("upload", std::chrono::microseconds{30}); + l.part("upload", std::chrono::microseconds{20}); // added to + l.value("glyphs", slow ? 24570 : 922); + if (l.index() % 2 == 0) + l.value("lists", 11); // some calls say it + if (slow) + l.say("zoom 0.43"); + }, + {.least = 20, .most = 20, .warmup = 2, .slowest = 2}); + expect(eq(d.parts.size(), std::size_t(2)) && eq(d.values.size(), std::size_t(2))); + expect(eq(d.parts[0].name, std::string("encode")) && + eq(d.parts[0].calls, std::size_t(20))); + expect(ge(d.parts[0].max, 0.0009) && lt(d.parts[0].p50, 0.0005)) << d.parts[0].max; + expect(eq(d.parts[1].name, std::string("upload")) && eq(d.parts[1].max, 0.00005)); + expect(eq(d.values[0].name, std::string("glyphs")) && eq(d.values[0].max, 24570.0) && + eq(d.values[0].min, 922.0)); + expect(eq(d.values[1].calls, std::size_t(10)) && eq(d.values[1].mean, 11.0)) + << "over the calls that said it"; + expect(eq(d.slowest.size(), std::size_t(2)) && eq(d.slowest[0].index, std::size_t(7)) && + eq(d.slowest[0].said, std::string("zoom 0.43")) && + ge(d.slowest[0].seconds, d.slowest[1].seconds)); + expect(eq(d.slowest[0].parts.size(), std::size_t(2)) && + ge(d.slowest[0].parts[0].second, 0.0009) && + eq(d.slowest[0].values[0].second, 24570.0)); + }; + "a limit a call: how many passed it, and those are the ones stated; a body ends the run"_test + [kind::bench] = [] { + const auto spin = [](std::chrono::microseconds d) { + const auto end = std::chrono::steady_clock::now() + d; + while (std::chrono::steady_clock::now() < end) {} + }; + std::size_t calls = 0; + auto d = bench::each("sweep", + [&](bench::lap& l) { + ++calls; + spin(std::chrono::microseconds{ + l.index() == 4 || l.index() == 9 ? 700 : 50}); + if (l.index() == 11) + l.last(); // the sweep has run out + }, + {.least = 100, + .most = 100, + .warmup = 0, + .limit = std::chrono::microseconds{400}}); + expect(eq(calls, std::size_t(12)) && eq(d.samples.size(), std::size_t(12))); + expect(eq(d.over, std::size_t(2)) && eq(d.slowest.size(), std::size_t(2)) && + eq(d.limit, 0.0004)); + const std::array late{d.slowest[0].index, d.slowest[1].index}; + expect((late[0] == 4 && late[1] == 9) || (late[0] == 9 && late[1] == 4)); + }; + "calls that say nothing keep nothing"_test[kind::bench] = [] { + auto d = bench::each("quiet", [](bench::lap&) {}, + {.least = 5, .most = 5, .warmup = 1, .slowest = 1}); + expect(d.parts.empty() && d.values.empty() && eq(d.slowest.size(), std::size_t(1)) && + d.slowest[0].parts.empty() && d.slowest[0].said.empty()); + }; + "a program that counts its allocations: a call's, less what it paused for"_test[kind::bench] = + [] { + auto d = bench::each("alloc", + [](bench::lap& l) { + l.pause(); + bench::allocated(1000); // not the call's + l.resume(); + bench::allocated(64); + if (l.index() == 3) + bench::allocated(32); + }, + {.least = 6, .most = 6, .warmup = 1}); + expect(eq(d.values.size(), std::size_t(2)) && + eq(d.values[0].name, std::string("allocations"))); + expect(eq(d.values[0].min, 1.0) && eq(d.values[0].max, 2.0) && + eq(d.values[1].max, 96.0) && eq(d.values[1].min, 64.0)); + }; "a body that takes no lap is measured the same"_test[kind::bench] = [] { int x = 0; auto d = diff --git a/manifest/mcpp.toml b/manifest/mcpp.toml index 2a6381c..8fb71f5 100644 --- a/manifest/mcpp.toml +++ b/manifest/mcpp.toml @@ -8,7 +8,7 @@ [package] namespace = "mcpplibs.mtest" name = "manifest" -version = "0.8.0" +version = "0.8.1" description = "The static case manifest of mtest: the cases a source file declares, read without building it" license = "Apache-2.0" authors = ["mcpp-community"] From 1c024c0a0c7223fc97cb039c77ebfddb50209fb7 Mon Sep 17 00:00:00 2001 From: Sunrisepeak Date: Sat, 14 Nov 2026 07:41:56 +0900 Subject: [PATCH 2/2] bench::allocated counts a thread: the calling thread's allocations are the call's, and no line is shared --- CHANGELOG.md | 2 ++ lib/src/bench.cpp | 14 ++++++++------ lib/src/bench.cppm | 4 +++- 3 files changed, 13 insertions(+), 7 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 3965a5a..63b3f4a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,8 @@ 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. diff --git a/lib/src/bench.cpp b/lib/src/bench.cpp index 4f1159b..e42bf43 100644 --- a/lib/src/bench.cpp +++ b/lib/src/bench.cpp @@ -123,17 +123,19 @@ std::string readable(double seconds) { } // namespace namespace { -std::atomic allocation_calls{0}, allocation_bytes{0}; -} +// 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.fetch_add(1, std::memory_order_relaxed); - allocation_bytes.fetch_add(bytes, std::memory_order_relaxed); + ++allocation_calls; + allocation_bytes += bytes; } allocation_count allocations() noexcept { - return {allocation_calls.load(std::memory_order_relaxed), - allocation_bytes.load(std::memory_order_relaxed)}; + return {allocation_calls, allocation_bytes}; } void lap::part(std::string_view name, clock::duration spent) { diff --git a/lib/src/bench.cppm b/lib/src/bench.cppm index f67a30b..911059e 100644 --- a/lib/src/bench.cppm +++ b/lib/src/bench.cppm @@ -105,11 +105,13 @@ struct each_options { // `name.allocated` (bytes, the mean) -- less what a call paused for; // `at_most{"draw.allocations.max", 0}` is a frame that allocates nothing. A program that never says // so reports none of them. +// Counted a thread: a call's allocations are those of the thread that runs it (what its workers +// allocate meanwhile is not the call's), and counting costs a thread two additions. void allocated(std::size_t bytes) noexcept; struct allocation_count { std::uint64_t count = 0, bytes = 0; }; -allocation_count allocations() noexcept; +allocation_count allocations() noexcept; // this thread's, so far // One call: what the body may say of it. class lap {