Repository navigation
Trace core: events, buffers, Perfetto emitter, scope macro #6
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from all commits
a974ef5
5eeb708
ba93c26
62f8c9e
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change | ||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| @@ -0,0 +1,258 @@ | ||||||||||||||
| #pragma once | ||||||||||||||
|
|
||||||||||||||
| #include <atomic> | ||||||||||||||
| #include <chrono> | ||||||||||||||
| #include <cinttypes> | ||||||||||||||
| #include <cstdint> | ||||||||||||||
| #include <cstdio> | ||||||||||||||
| #include <memory> | ||||||||||||||
| #include <mutex> | ||||||||||||||
| #include <new> | ||||||||||||||
| #include <string> | ||||||||||||||
| #include <vector> | ||||||||||||||
|
|
||||||||||||||
| // Scope tracing core. Threads record complete events (name, start, | ||||||||||||||
| // duration) into their own buffers; a collector owns every buffer and | ||||||||||||||
| // writes the whole trace as chrome trace-event JSON, which the Perfetto UI | ||||||||||||||
| // and chrome://tracing both load. | ||||||||||||||
| // | ||||||||||||||
| // Contracts: | ||||||||||||||
| // - Event names must outlive the collector (string literals, __func__, or | ||||||||||||||
| // otherwise static storage); the buffer stores the pointer, not a copy. | ||||||||||||||
| // - Recording is safe from any thread. Each thread locks only its own | ||||||||||||||
| // buffer's mutex, which is uncontended except while a flush snapshots it. | ||||||||||||||
| // - Buffers are bounded (set_capacity_per_thread); overflow drops events | ||||||||||||||
| // and counts the drops, and write_json reports the total dropped. | ||||||||||||||
|
|
||||||||||||||
| namespace cyclescope { | ||||||||||||||
|
|
||||||||||||||
| namespace detail { | ||||||||||||||
| // Trivially destructible, so reading it stays defined even after this | ||||||||||||||
| // thread's nontrivial thread_locals (including the buffer handle) are | ||||||||||||||
| // gone. Set during TLS teardown; record() then drops late events. | ||||||||||||||
| inline thread_local bool tls_shutdown = false; | ||||||||||||||
| } // namespace detail | ||||||||||||||
|
|
||||||||||||||
| struct trace_event { | ||||||||||||||
| const char* name; | ||||||||||||||
| std::uint64_t start_ns; | ||||||||||||||
| std::uint64_t duration_ns; | ||||||||||||||
| }; | ||||||||||||||
|
|
||||||||||||||
| // Nanoseconds since the first use in the process; monotonic. | ||||||||||||||
| inline std::uint64_t trace_now_ns() { | ||||||||||||||
| static const auto anchor = std::chrono::steady_clock::now(); | ||||||||||||||
| return static_cast<std::uint64_t>( | ||||||||||||||
| std::chrono::duration_cast<std::chrono::nanoseconds>( | ||||||||||||||
| std::chrono::steady_clock::now() - anchor) | ||||||||||||||
| .count()); | ||||||||||||||
| } | ||||||||||||||
|
|
||||||||||||||
| class collector { | ||||||||||||||
| public: | ||||||||||||||
| static collector& instance() { | ||||||||||||||
| static collector self; | ||||||||||||||
| return self; | ||||||||||||||
| } | ||||||||||||||
|
|
||||||||||||||
| void set_capacity_per_thread(std::size_t capacity) { | ||||||||||||||
| capacity_.store(capacity, std::memory_order_relaxed); | ||||||||||||||
| } | ||||||||||||||
|
|
||||||||||||||
| // Hot path: records into the calling thread's buffer. Never throws: | ||||||||||||||
| // trace_scope destructors call this, and an allocation failure counts | ||||||||||||||
| // as a dropped event rather than terminating the program. | ||||||||||||||
| void record(const char* name, std::uint64_t start_ns, | ||||||||||||||
| std::uint64_t duration_ns) noexcept { | ||||||||||||||
| if (detail::tls_shutdown) { | ||||||||||||||
| // A traced destructor ran after this thread's buffer handle was | ||||||||||||||
| // destroyed; the event is dropped rather than touching dead TLS. | ||||||||||||||
| return; | ||||||||||||||
| } | ||||||||||||||
| thread_buffer& mine = local_buffer(); | ||||||||||||||
| std::lock_guard guard(mine.mutex); | ||||||||||||||
| if (mine.events.size() >= capacity_.load(std::memory_order_relaxed)) { | ||||||||||||||
|
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. OOM in destructor →
Minimal fix — catch and count:
Suggested change
Alternatively, |
||||||||||||||
| ++mine.dropped; | ||||||||||||||
| return; | ||||||||||||||
| } | ||||||||||||||
| try { | ||||||||||||||
| mine.events.push_back({name, start_ns, duration_ns}); | ||||||||||||||
| } catch (const std::bad_alloc&) { | ||||||||||||||
| ++mine.dropped; | ||||||||||||||
| } | ||||||||||||||
| } | ||||||||||||||
|
|
||||||||||||||
| // Writes every buffer as chrome trace-event JSON. Returns false when the | ||||||||||||||
| // file cannot be opened or written. `dropped_total`, when non-null, is | ||||||||||||||
| // always written with the number of events lost to capacity limits, | ||||||||||||||
| // including when the function returns false. | ||||||||||||||
| // | ||||||||||||||
| // No lock is held across file I/O: the registry and each buffer are | ||||||||||||||
| // snapshotted first (a transient copy of the event data), so recording | ||||||||||||||
| // threads and thread registration never stall behind a slow disk. | ||||||||||||||
| bool write_json(const char* path, std::uint64_t* dropped_total = nullptr) { | ||||||||||||||
| std::vector<std::shared_ptr<thread_buffer>> registered; | ||||||||||||||
| { | ||||||||||||||
| std::lock_guard registry_guard(registry_mutex_); | ||||||||||||||
| registered = buffers_; | ||||||||||||||
| } | ||||||||||||||
|
|
||||||||||||||
| struct buffer_snapshot { | ||||||||||||||
| std::vector<trace_event> events; | ||||||||||||||
| std::uint64_t tid = 0; | ||||||||||||||
| }; | ||||||||||||||
| std::vector<buffer_snapshot> snapshots; | ||||||||||||||
| snapshots.reserve(registered.size()); | ||||||||||||||
| std::uint64_t dropped = 0; | ||||||||||||||
| for (const auto& buffer : registered) { | ||||||||||||||
| std::lock_guard buffer_guard(buffer->mutex); | ||||||||||||||
|
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more.
|
||||||||||||||
| dropped += buffer->dropped; | ||||||||||||||
| snapshots.push_back({buffer->events, buffer->tid}); | ||||||||||||||
| } | ||||||||||||||
| if (dropped_total != nullptr) { | ||||||||||||||
| *dropped_total = dropped; | ||||||||||||||
| } | ||||||||||||||
|
Comment on lines
+112
to
+114
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Logic error: output parameter
A caller that passes a non-null ok = (std::fclose(out) == 0) && ok;
if (dropped_total != nullptr && ok) {
*dropped_total = dropped;
}
return ok;Alternatively, document explicitly that |
||||||||||||||
|
|
||||||||||||||
| std::FILE* out = std::fopen(path, "w"); | ||||||||||||||
| if (out == nullptr) { | ||||||||||||||
| return false; | ||||||||||||||
| } | ||||||||||||||
| const bool header_ok = std::fputs("{\"traceEvents\":[", out) >= 0; | ||||||||||||||
| bool ok = header_ok; | ||||||||||||||
| if (header_ok) { | ||||||||||||||
| bool first = true; | ||||||||||||||
| for (const auto& snapshot : snapshots) { | ||||||||||||||
| for (const trace_event& event : snapshot.events) { | ||||||||||||||
| const std::string name = escape(event.name); | ||||||||||||||
| ok = ok && | ||||||||||||||
| std::fprintf( | ||||||||||||||
| out, | ||||||||||||||
| "%s\n{\"name\":\"%s\",\"cat\":\"scope\",\"ph\":\"X\"," | ||||||||||||||
| "\"ts\":%.3f,\"dur\":%.3f,\"pid\":1,\"tid\":%" PRIu64 "}", | ||||||||||||||
| first ? "" : ",", name.c_str(), | ||||||||||||||
| static_cast<double>(event.start_ns) / 1e3, | ||||||||||||||
| static_cast<double>(event.duration_ns) / 1e3, | ||||||||||||||
| snapshot.tid) >= 0; | ||||||||||||||
| first = false; | ||||||||||||||
| } | ||||||||||||||
| } | ||||||||||||||
| // Whenever the header made it out, the footer is written even after | ||||||||||||||
| // an event-write failure, so the file on disk stays syntactically | ||||||||||||||
| // complete JSON if the filesystem allows. | ||||||||||||||
| const bool footer_ok = std::fputs("\n]}\n", out) >= 0; | ||||||||||||||
| ok = ok && footer_ok; | ||||||||||||||
| } | ||||||||||||||
| ok = (std::fclose(out) == 0) && ok; | ||||||||||||||
| return ok; | ||||||||||||||
| } | ||||||||||||||
|
|
||||||||||||||
| // Empties every buffer and drop counter, and prunes buffers whose | ||||||||||||||
| // threads have exited. Live buffers stay registered. Call only while no | ||||||||||||||
| // thread is recording. Buffers of exited threads are retained until this | ||||||||||||||
| // runs so their events still reach the trace; long-running programs with | ||||||||||||||
| // thread churn should clear() after each flush. | ||||||||||||||
| void clear() { | ||||||||||||||
| std::lock_guard registry_guard(registry_mutex_); | ||||||||||||||
| std::vector<std::shared_ptr<thread_buffer>> kept; | ||||||||||||||
| kept.reserve(buffers_.size()); | ||||||||||||||
| for (const auto& buffer : buffers_) { | ||||||||||||||
| std::lock_guard buffer_guard(buffer->mutex); | ||||||||||||||
| buffer->events.clear(); | ||||||||||||||
| buffer->dropped = 0; | ||||||||||||||
| if (buffer->alive) { | ||||||||||||||
| kept.push_back(buffer); | ||||||||||||||
| } | ||||||||||||||
| } | ||||||||||||||
| buffers_.swap(kept); | ||||||||||||||
| } | ||||||||||||||
|
|
||||||||||||||
| private: | ||||||||||||||
| struct thread_buffer { | ||||||||||||||
| std::mutex mutex; | ||||||||||||||
| std::vector<trace_event> events; | ||||||||||||||
| std::uint64_t dropped = 0; | ||||||||||||||
| std::uint64_t tid = 0; | ||||||||||||||
| bool alive = true; // Guarded by mutex; false once the thread exits. | ||||||||||||||
| }; | ||||||||||||||
|
|
||||||||||||||
| // Marks the buffer dead when its thread exits, so clear() can prune it, | ||||||||||||||
| // and flags TLS teardown so later record() calls bail out safely. | ||||||||||||||
| struct buffer_handle { | ||||||||||||||
| std::shared_ptr<thread_buffer> buffer; | ||||||||||||||
| ~buffer_handle() { | ||||||||||||||
| detail::tls_shutdown = true; | ||||||||||||||
| if (buffer != nullptr) { | ||||||||||||||
| std::lock_guard guard(buffer->mutex); | ||||||||||||||
| buffer->alive = false; | ||||||||||||||
| } | ||||||||||||||
| } | ||||||||||||||
| }; | ||||||||||||||
|
|
||||||||||||||
| collector() = default; | ||||||||||||||
|
|
||||||||||||||
| // Registered once per thread; the registry keeps the buffer alive after | ||||||||||||||
| // the thread exits so its events still reach the trace. Tids come from a | ||||||||||||||
| // monotonic counter, so pruning never recycles them. | ||||||||||||||
| thread_buffer& local_buffer() { | ||||||||||||||
| thread_local buffer_handle handle = [this] { | ||||||||||||||
|
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. Potential UB: "phoenix singleton" — accessing a destroyed thread-local during thread exit
The hazard: any thread-local object that was constructed before the first call to This is the classic "phoenix singleton" problem. A minimal mitigation is a thread_local bool tls_dead = false;
~buffer_handle() {
tls_dead = true; // mark before locking, so record() can check
if (buffer != nullptr) { ... }
}
void record(...) noexcept {
if (tls_dead) return; // thread is unwinding, buffer gone
...
}The |
||||||||||||||
| auto buffer = std::make_shared<thread_buffer>(); | ||||||||||||||
| std::lock_guard guard(registry_mutex_); | ||||||||||||||
| buffer->tid = next_tid_++; | ||||||||||||||
| buffers_.push_back(buffer); | ||||||||||||||
| return buffer_handle{buffer}; | ||||||||||||||
| }(); | ||||||||||||||
| return *handle.buffer; | ||||||||||||||
| } | ||||||||||||||
|
|
||||||||||||||
| static std::string escape(const char* raw) { | ||||||||||||||
| std::string out; | ||||||||||||||
| for (const char* p = raw != nullptr ? raw : "(null)"; *p != '\0'; ++p) { | ||||||||||||||
| const unsigned char c = static_cast<unsigned char>(*p); | ||||||||||||||
| if (c == '"' || c == '\\') { | ||||||||||||||
| out += '\\'; | ||||||||||||||
| out += static_cast<char>(c); | ||||||||||||||
| } else if (c < 0x20) { | ||||||||||||||
| char buf[8]; | ||||||||||||||
| std::snprintf(buf, sizeof(buf), "\\u%04x", c); | ||||||||||||||
| out += buf; | ||||||||||||||
| } else { | ||||||||||||||
| out += static_cast<char>(c); | ||||||||||||||
| } | ||||||||||||||
| } | ||||||||||||||
| return out; | ||||||||||||||
| } | ||||||||||||||
|
|
||||||||||||||
| std::mutex registry_mutex_; | ||||||||||||||
| std::vector<std::shared_ptr<thread_buffer>> buffers_; | ||||||||||||||
| std::uint64_t next_tid_ = 1; // Guarded by registry_mutex_; never wraps. | ||||||||||||||
| std::atomic<std::size_t> capacity_{std::size_t{1} << 20}; | ||||||||||||||
| }; | ||||||||||||||
|
|
||||||||||||||
| // RAII scope: records one complete event covering its lifetime. | ||||||||||||||
| class trace_scope { | ||||||||||||||
| public: | ||||||||||||||
| explicit trace_scope(const char* name) | ||||||||||||||
| : name_(name), start_ns_(trace_now_ns()) {} | ||||||||||||||
| trace_scope(const trace_scope&) = delete; | ||||||||||||||
| trace_scope& operator=(const trace_scope&) = delete; | ||||||||||||||
| ~trace_scope() { | ||||||||||||||
| collector::instance().record(name_, start_ns_, | ||||||||||||||
| trace_now_ns() - start_ns_); | ||||||||||||||
| } | ||||||||||||||
|
|
||||||||||||||
| private: | ||||||||||||||
| const char* name_; | ||||||||||||||
| std::uint64_t start_ns_; | ||||||||||||||
| }; | ||||||||||||||
|
|
||||||||||||||
| } // namespace cyclescope | ||||||||||||||
|
|
||||||||||||||
| #define CYCLESCOPE_CONCAT_INNER(a, b) a##b | ||||||||||||||
| #define CYCLESCOPE_CONCAT(a, b) CYCLESCOPE_CONCAT_INNER(a, b) | ||||||||||||||
|
|
||||||||||||||
| // Names one scope explicitly; the argument must have static lifetime. | ||||||||||||||
| #define CYCLESCOPE_SCOPE(name) \ | ||||||||||||||
| ::cyclescope::trace_scope CYCLESCOPE_CONCAT(cs_scope_, __LINE__)(name) | ||||||||||||||
|
|
||||||||||||||
| // Names the scope after the enclosing function. | ||||||||||||||
| #define CYCLESCOPE_SCOPE_FUNC() CYCLESCOPE_SCOPE(__func__) | ||||||||||||||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -29,3 +29,4 @@ function(cyclescope_add_test name) | |
| endfunction() | ||
|
|
||
| cyclescope_add_test(log_test) | ||
| cyclescope_add_test(trace_test) | ||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This contract claim is inaccurate.
write_jsonholdsbuffer->mutexfor the entire inner event loop, including everyfprintfcall (lines 86–100). That is not a brief snapshot — it is a full file-write under lock. If the underlying I/O stalls (NFS, disk pressure, full buffer), any thread trying torecord()into that buffer blocks for the same duration.The fix is to copy events under the lock and then write without holding it:
The comment should then read "uncontended except while a flush copies it."