From 56149820415330d44f98bb4ffb56c1c468c32b3b Mon Sep 17 00:00:00 2001 From: ii14 Date: Wed, 24 Apr 2024 22:48:15 +0200 Subject: [PATCH] trace --- src/fzx/fzx.cpp | 16 +++++++++++- src/fzx/fzx.hpp | 6 +++++ src/fzx/macros.hpp | 6 +++++ src/fzx/trace.cpp | 57 +++++++++++++++++++++++++++++++++++++++++ src/fzx/trace.hpp | 60 ++++++++++++++++++++++++++++++++++++++++++++ src/fzx/tui/main.cpp | 3 +++ src/fzx/worker.cpp | 18 +++++++++++-- src/fzx/worker.hpp | 2 ++ 8 files changed, 165 insertions(+), 3 deletions(-) create mode 100644 src/fzx/trace.cpp create mode 100644 src/fzx/trace.hpp diff --git a/src/fzx/fzx.cpp b/src/fzx/fzx.cpp index 616326c..5c6c51f 100644 --- a/src/fzx/fzx.cpp +++ b/src/fzx/fzx.cpp @@ -35,19 +35,31 @@ void Fzx::setThreads(unsigned threads) noexcept void Fzx::start() { + // TODO: assert this object can't be reused if (mRunning) return; mRunning = true; ASSERT(mCallback); +#ifdef FZX_TRACE + ASSERT(mTracer == nullptr); + mTracer = mTrace.createTracer('m'); +#endif + for (size_t i = 0; i < mThreads; ++i) { auto& worker = mWorkers.emplace_back(std::make_unique()); worker->mIndex = i; worker->mPool = this; +#ifdef FZX_TRACE + worker->mTracer = mTrace.createTracer("0123456789ABCDEF"[i]); +#endif } - for (const auto& worker : mWorkers) + + mTrace.start(); + for (const auto& worker : mWorkers) { worker->mThread = std::thread { &Worker::run, worker.get() }; + } } void Fzx::stop() @@ -118,6 +130,8 @@ CommitResult Fzx::commit() mJobVersion.fetch_add(1, std::memory_order_release); } + TRACE(mTracer, "commit"); + // Wake up worker threads for (auto& worker : mWorkers) worker->mEvents.post(Worker::kJob); diff --git a/src/fzx/fzx.hpp b/src/fzx/fzx.hpp index f8fb233..692b3a9 100644 --- a/src/fzx/fzx.hpp +++ b/src/fzx/fzx.hpp @@ -17,6 +17,7 @@ #include "fzx/matched_item.hpp" #include "fzx/query.hpp" #include "fzx/worker.hpp" +#include "fzx/trace.hpp" namespace fzx { @@ -125,6 +126,11 @@ struct Fzx std::shared_ptr mQuery; std::shared_ptr mQueue; +public: + Trace mTrace; +private: + TraceTLS* mTracer { nullptr }; + /// Worker threads. This vector is shared with workers, so after /// starting and before joining threads, it cannot be modified. std::vector> mWorkers {}; diff --git a/src/fzx/macros.hpp b/src/fzx/macros.hpp index c34147c..74687ee 100644 --- a/src/fzx/macros.hpp +++ b/src/fzx/macros.hpp @@ -102,6 +102,12 @@ # define FZX_PRAGMA_MSVC(x) #endif +#define STR_(x) #x +#define STR(x) STR_(x) + +#define CAT_(a, b) a ## b +#define CAT(a, b) CAT_(a, b) + namespace fzx { template diff --git a/src/fzx/trace.cpp b/src/fzx/trace.cpp new file mode 100644 index 0000000..8b0935c --- /dev/null +++ b/src/fzx/trace.cpp @@ -0,0 +1,57 @@ +// Licensed under LGPLv3 - see LICENSE file for details. + +#include "fzx/trace.hpp" + +namespace fzx { + +static struct timespec tsSub(struct timespec a, struct timespec b) +{ + struct timespec r; // NOLINT(cppcoreguidelines-pro-type-member-init) + r.tv_sec = a.tv_sec - b.tv_sec; + r.tv_nsec = a.tv_nsec - b.tv_nsec; + if (r.tv_nsec < 0) { + --r.tv_sec; + r.tv_nsec += 1000000000L; + } + return r; +} + +TraceTLS* Trace::createTracer(char name) +{ + auto p = std::make_unique(); + p->mName = name; + return mTracers.emplace_back(std::move(p)).get(); +} + +void Trace::start() +{ + clock_gettime(CLOCK_MONOTONIC, &mTimestamp); +} + +void Trace::dump(FILE* file) const +{ + // auto positions = std::make_unique(mTracers.size()); + // for (size_t i = 0; i < mTracers.size(); ++i) + // positions[i] = 0; + + + for (const auto& tracer : mTracers) { + uint64_t prev = 0; + for (const auto& event : tracer->mEvents) { + auto ts = tsSub(event.mTimestamp, mTimestamp); + uint64_t time = static_cast(ts.tv_nsec) + + static_cast(ts.tv_sec) * 1000000000ULL; + uint64_t diff = time - prev; + uint64_t tms = time / 1000000ULL; + uint64_t tus = time % 1000000ULL; + uint64_t dus = diff % 1000000ULL; + uint64_t dms = diff / 1000000ULL; + fprintf(file, "%6zu.%06zu %c %6zu.%06zu %s\n", + tms, tus, tracer->mName, dms, dus, event.mMessage); + prev = time; + } + } + fflush(file); +} + +} // namespace fzx diff --git a/src/fzx/trace.hpp b/src/fzx/trace.hpp new file mode 100644 index 0000000..2a0578d --- /dev/null +++ b/src/fzx/trace.hpp @@ -0,0 +1,60 @@ +// Licensed under LGPLv3 - see LICENSE file for details. + +#pragma once + +#include +#include +#include +#include +#include +#include +#include + +#include "fzx/macros.hpp" + +#define FZX_TRACE + +namespace fzx { + +struct TraceEvent +{ + struct timespec mTimestamp; + const char* mMessage; + const char* mSource; +}; + +struct TraceTLS +{ + TraceTLS() noexcept = default; + + char mName { 0 }; + std::vector mEvents; + + void trace(const char* msg, const char* file) + { + TraceEvent ev; // NOLINT(cppcoreguidelines-pro-type-member-init) + clock_gettime(CLOCK_MONOTONIC, &ev.mTimestamp); + ev.mMessage = msg; + ev.mSource = file; + mEvents.push_back(ev); + } +}; + +struct Trace +{ + Trace() noexcept = default; + TraceTLS* createTracer(char name); + void start(); + void dump(FILE* file) const; + + std::vector> mTracers; + struct timespec mTimestamp { 0, 0 }; +}; + +#ifdef FZX_TRACE +# define TRACE(ptr, msg) (ptr)->trace(msg, __FILE__ ":" STR(__LINE__)) +#else +# define TRACE(ptr, msg) +#endif + +} // namespace fzx diff --git a/src/fzx/tui/main.cpp b/src/fzx/tui/main.cpp index 17a6298..dc17f19 100644 --- a/src/fzx/tui/main.cpp +++ b/src/fzx/tui/main.cpp @@ -119,7 +119,10 @@ int main(int argc, char** argv) } } } + app.mFzx.stop(); app.mTTY.close(); + app.mFzx.mTrace.dump(stdout); + if (app.mStatus == fzx::Status::ExitSuccess) { if (app.mSelection.empty()) { std::cout << app.currentItem() << std::endl; diff --git a/src/fzx/worker.cpp b/src/fzx/worker.cpp index 06159fa..8033de6 100644 --- a/src/fzx/worker.cpp +++ b/src/fzx/worker.cpp @@ -51,14 +51,19 @@ try { auto loadJob = [&]() -> bool { return mPool->loadJob(job, jobVersion); }; wait: + TRACE(mTracer, "wait"); // Wait until we get a new event. uint32_t ev = mEvents.wait(); + TRACE(mTracer, "wakeup"); - if (ev & kStop) + if (ev & kStop) { + TRACE(mTracer, "stop"); return; + } if ((ev & kJob) && loadJob()) { match: + TRACE(mTracer, "match"); // A new job invalidates any merged results we got so far. mergeState.reset(); @@ -76,6 +81,7 @@ try { const auto& query = *job.mQuery; results.mItems.reserve(job.mItems.size()); for (;;) { + TRACE(mTracer, "chunk"); // Reserve a chunk of items. // TODO: I think there might be a possibility of internal queue counter overflowing here? const size_t start = std::min(queue.take(kChunkSize), job.mItems.size()); @@ -93,14 +99,18 @@ try { // Ignore kMerge events from other workers, we don't care about // them at this stage, as we don't even have out own results yet. ev = mEvents.get(); - if (ev & kStop) + if (ev & kStop) { + TRACE(mTracer, "stop"); return; + } if ((ev & kJob) && loadJob()) goto match; } + TRACE(mTracer, "sort enter"); // Sort the local batch of items. std::sort(results.mItems.begin(), results.mItems.end()); + TRACE(mTracer, "sort leave"); // For workers with no children, jump straight to publishing results. if (mergeState.done()) @@ -110,6 +120,7 @@ try { goto wait; // No new job, no merging left to do. } + TRACE(mTracer, "merge enter"); // Merge results from other threads. for (uint8_t i = 0; i < mergeState.size(); ++i) { // Already got results from this worker, try the next one. @@ -147,12 +158,14 @@ try { mergeState.set(i); // Mark this worker as merged. } + TRACE(mTracer, "merge leave"); // Not all results have been merged yet, we're still waiting for someone. if (!mergeState.done()) goto wait; publish: + TRACE(mTracer, "publish enter"); // Store results and notify whoever is responsible for handling them. mOutput.store(std::move(results)); results = {}; @@ -165,6 +178,7 @@ try { mPool->mWorkers[MergeState::parent(mIndex)]->mEvents.post(kMerge); } + TRACE(mTracer, "publish leave"); goto wait; } catch (const std::exception& e) { std::strncpy(mErrorMsg, e.what(), std::size(mErrorMsg)); diff --git a/src/fzx/worker.hpp b/src/fzx/worker.hpp index ad52cf8..98ea9b0 100644 --- a/src/fzx/worker.hpp +++ b/src/fzx/worker.hpp @@ -13,6 +13,7 @@ #include "fzx/matched_item.hpp" #include "fzx/query.hpp" #include "fzx/string.hpp" +#include "fzx/trace.hpp" namespace fzx { @@ -45,6 +46,7 @@ struct Worker Events mEvents; Fzx* mPool { nullptr }; uint8_t mIndex { 0 }; + TraceTLS* mTracer { nullptr }; char mErrorMsg[256] {}; ///< Populated before mError becomes true. std::atomic mError { false }; ///< A critical error has occurred.