tracing: wip i am going to regret not splitting this right now

Change-Id: I1b7f828127d69e8567f4faa96c4ace961cfc0be9

meson.build

@@ -41,7 +41,7 @@
 project('lix', 'cpp',
   version : run_command('bash', '-c', 'echo -n $(jq -r .version < ./version.json)$VERSION_SUFFIX', check : true).stdout().strip(),
   default_options : [
-    'cpp_std=c++2a',
+    'cpp_std=c++23',
     # TODO(Qyriad): increase the warning level
     'warning_level=1',
     'debug=true',

src/libexpr/eval.cc

@@ -18,10 +18,12 @@
 #include "fetch-to-store.hh"
 #include "flake/flakeref.hh"
 #include "parser-tab.hh"
+#include "fast-function-tracer.hh"
 
 #include <algorithm>
 #include <chrono>
 #include <iostream>
+#include <memory>
 #include <sstream>
 #include <cstring>
 #include <optional>
@@ -394,6 +396,7 @@ EvalState::EvalState(
     , debugStop(false)
     , trylevel(0)
     , regexCache(makeRegexCache())
+    , tracer(nullptr)
 #if HAVE_BOEHMGC
     , valueAllocCache(std::allocate_shared<void *>(traceable_allocator<void *>(), nullptr))
     , env1AllocCache(std::allocate_shared<void *>(traceable_allocator<void *>(), nullptr))
@@ -441,6 +444,11 @@ EvalState::EvalState(
     }
 
     createBaseEnv();
+
+    // TODO: do this sensibly
+    if (auto traceFunctionsEnv = getEnv("NIX_TRACE_FUNCTIONS_FILE"); traceFunctionsEnv.has_value()) {
+        tracer = std::make_unique<FastFunctionTracer>(*this, *traceFunctionsEnv);
+    }
 }
 
 
@@ -1542,6 +1550,9 @@ void EvalState::callFunction(Value & fun, size_t nrArgs, Value * * args, Value &
     auto trace = evalSettings.traceFunctionCalls
         ? std::make_unique<FunctionCallTrace>(positions[pos])
         : nullptr;
+    auto fastTraceTs = tracer ? std::optional{tracing::Timestamp::now()} : std::nullopt;
+    // TODO: this should never need to be a pointer to begin with! References are bad.
+    std::unique_ptr<FastFunctionTracer::Guard> fastTraceGuard = nullptr;
 
     forceValue(fun, pos);
 
@@ -1565,6 +1576,10 @@ void EvalState::callFunction(Value & fun, size_t nrArgs, Value * * args, Value &
 
             ExprLambda & lambda(*vCur.lambda.fun);
 
+            if (tracer && !fastTraceGuard) {
+                fastTraceGuard = std::make_unique<FastFunctionTracer::Guard>(tracer->enterFunction(lambda.name, lambda.pos, *fastTraceTs));
+            }
+
             auto size =
                 (!lambda.arg ? 0 : 1) +
                 (lambda.hasFormals() ? lambda.formals->formals.size() : 0);
@@ -1678,6 +1693,10 @@ void EvalState::callFunction(Value & fun, size_t nrArgs, Value * * args, Value &
                 /* We have all the arguments, so call the primop. */
                 auto * fn = vCur.primOp;
 
+                if (tracer && !fastTraceGuard) {
+                    fastTraceGuard = std::make_unique<FastFunctionTracer::Guard>(tracer->enterFunction(symbols.create(fn->name), PosIdx(), *fastTraceTs));
+                }
+
                 nrPrimOpCalls++;
                 if (countCalls) primOpCalls[fn->name]++;
 
@@ -1712,7 +1731,6 @@ void EvalState::callFunction(Value & fun, size_t nrArgs, Value * * args, Value &
             } else {
                 /* We have all the arguments, so call the primop with
                    the previous and new arguments. */
-
                 Value * vArgs[maxPrimOpArity];
                 auto n = argsDone;
                 for (Value * arg = &vCur; arg->isPrimOpApp(); arg = arg->primOpApp.left)
@@ -1725,6 +1743,10 @@ void EvalState::callFunction(Value & fun, size_t nrArgs, Value * * args, Value &
                 nrPrimOpCalls++;
                 if (countCalls) primOpCalls[fn->name]++;
 
+                if (tracer && !fastTraceGuard) {
+                    fastTraceGuard = std::make_unique<FastFunctionTracer::Guard>(tracer->enterFunction(symbols.create(fn->name), PosIdx(), *fastTraceTs));
+                }
+
                 try {
                     // TODO:
                     // 1. Unify this and above code. Heavily redundant.
@@ -2760,6 +2782,12 @@ Expr * EvalState::parseExprFromFile(const SourcePath & path)
 
 Expr * EvalState::parseExprFromFile(const SourcePath & path, std::shared_ptr<StaticEnv> & staticEnv)
 {
+    // TODO: turning these into symbols is kind of unfortunate because it leaks memory
+    // TODO: This API loses the category of the things!
+    std::optional<FastFunctionTracer::Guard> _g = tracer
+        ? std::optional{tracer->enterFunction(symbols.create(path.to_string()), PosIdx())}
+        : std::nullopt;
+
     auto buffer = path.readFile();
     // readFile hopefully have left some extra space for terminators
     buffer.append("\0\0", 2);

src/libexpr/eval.hh

@@ -14,6 +14,7 @@
 #include "repl-exit-status.hh"
 
 #include <map>
+#include <memory>
 #include <optional>
 #include <unordered_map>
 #include <mutex>
@@ -34,6 +35,7 @@ class StorePath;
 struct SingleDerivedPath;
 enum RepairFlag : bool;
 
+class FastFunctionTracer;
 
 /**
  * Function that implements a primop.
@@ -274,6 +276,11 @@ private:
      */
     std::shared_ptr<RegexCache> regexCache;
 
+    /**
+     * A function tracer. May be null!
+     */
+    std::unique_ptr<FastFunctionTracer> tracer;
+
 #if HAVE_BOEHMGC
     /**
      * Allocation cache for GC'd Value objects.

src/libexpr/fast-function-tracer.cc

@@ -0,0 +1,118 @@
+#include "fast-function-tracer.hh"
+#include "eval.hh"
+#include "pos-idx.hh"
+#include "symbol-table.hh"
+#include "trace-writer.hh"
+#include "types.hh"
+#include <fstream>
+#include <memory>
+
+namespace nix {
+
+using std::operator""s;
+
+class EvalStateRetriever : public tracing::InternedRetriever
+{
+public:
+    EvalState & evalState_;
+
+    EvalStateRetriever(EvalState & evalState) : evalState_(evalState) {}
+
+    virtual auto getName(tracing::InternedName idx) const -> std::string override;
+    virtual auto getPos(tracing::InternedPos idx, std::string const funcName) const
+        -> tracing::TracePos override;
+
+    virtual ~EvalStateRetriever() = default;
+};
+
+class FastFunctionTracer::Impl
+{
+public:
+    tracing::TraceWriter writer_;
+    Path outputPath_;
+    tracing::TraceWriter::Track rootTrack_;
+
+    Impl(EvalState & evalState, Path outputFile)
+        : writer_{std::make_unique<EvalStateRetriever>(evalState)}
+        , outputPath_{outputFile}
+        , rootTrack_{writer_.trackByTid(getpid(), gettid(), "Functions")}
+    {
+    }
+};
+
+FastFunctionTracer::FastFunctionTracer(EvalState & evalState, Path outputFile)
+    : impl_{std::make_unique<Impl>(evalState, std::move(outputFile))}
+{
+}
+
+FastFunctionTracer::~FastFunctionTracer()
+{
+    try {
+        std::ofstream ofs(impl_->outputPath_);
+        auto buf = impl_->writer_.splat();
+        ofs.write(reinterpret_cast<const char *>(buf.data()), buf.size());
+    } catch (std::exception & e) {
+        std::cerr << "Exception ignored while writing trace file: " << e.what();
+    }
+}
+
+FastFunctionTracer::Guard
+FastFunctionTracer::enterFunction(const Symbol sym, const PosIdx pos, tracing::Timestamp ts)
+{
+    return Guard{*this, ts, sym, pos};
+}
+
+FastFunctionTracer::Guard::Guard(
+    FastFunctionTracer & tracer, tracing::Timestamp ts, const Symbol sym, const PosIdx idx
+)
+    : tracer_(tracer)
+{
+    tracer.impl_->rootTrack_.begin(tracing::InternedPos{idx.id}, tracing::InternedName{sym.id}, ts);
+}
+
+FastFunctionTracer::Guard::~Guard()
+{
+    tracer_.impl_->rootTrack_.end(tracing::Timestamp::now());
+}
+
+auto EvalStateRetriever::getName(tracing::InternedName name) const -> std::string
+{
+    if (name.key == 0) {
+        return "";
+    }
+    // XXX: This reaches into the internals of SymbolTable in order to be able
+    // to do its work while keeping libtracing decoupled from the precise
+    // implementation of Nix
+    return evalState_.symbols[Symbol(name.key)];
+}
+
+auto EvalStateRetriever::getPos(tracing::InternedPos idx, std::string const funcName) const
+    -> tracing::TracePos
+{
+    // XXX: This reaches into the internals of PosTable in order to be able
+    // to do its work while keeping libtracing decoupled from the precise
+    // implementation of Nix
+    //
+    // TODO: figure out a better way, maybe just giving it an opaque reference
+    // ideally without allocating
+    auto pos = evalState_.positions[PosIdx(idx.key)];
+
+    std::string out;
+    auto fileName = std::visit(
+        overloaded{
+            [](const std::monostate &) { return "«none»"s; },
+            [](const Pos::Stdin &) { return "«stdin»"s; },
+            [](const Pos::String & s) { return "«string»"s; },
+            [](const SourcePath & path) { return path.to_string(); }
+        },
+        pos.origin
+    );
+
+    return tracing::TracePos{
+        .fileName = fileName,
+        .functionName = funcName,
+        .lineNumber = pos.line,
+    };
+}
+
+}

src/libexpr/fast-function-tracer.hh

@@ -0,0 +1,42 @@
+#pragma once
+/**
+ * @file
+ * @brief This is a fast function tracer based on libtracing. It integrates
+ * with Nix's interning infrastructure to produce relatively reasonably
+ * processable traces compared to the existing function-trace.
+ */
+
+#include "types.hh"
+#include "trace-writer.hh"
+#include <memory>
+
+namespace nix {
+
+class Symbol;
+class PosIdx;
+class EvalState;
+
+class FastFunctionTracer {
+    class Impl;
+
+    std::unique_ptr<Impl> impl_;
+
+    public:
+    /** FIXME(threading): this is not thread safe */
+    class Guard {
+        FastFunctionTracer &tracer_;
+        explicit Guard(FastFunctionTracer &tracer, tracing::Timestamp ts, const Symbol sym, const PosIdx idx);
+        friend class FastFunctionTracer;
+
+        public:
+        ~Guard();
+    };
+
+    explicit FastFunctionTracer(EvalState &evalState, Path outputFile);
+
+    /** Get a guard that on destruction ends a trace-level scope (i.e. function call) */
+    Guard enterFunction(const Symbol sym, const PosIdx pos, tracing::Timestamp ts = tracing::Timestamp::now());
+
+    ~FastFunctionTracer();
+};
+}

src/libexpr/meson.build

@@ -71,6 +71,7 @@ libexpr_sources = files(
   'eval-error.cc',
   'eval-settings.cc',
   'eval.cc',
+  'fast-function-tracer.cc',
   'function-trace.cc',
   'get-drvs.cc',
   'json-to-value.cc',
@@ -102,6 +103,7 @@ libexpr_headers = files(
   'eval-inline.hh',
   'eval-settings.hh',
   'eval.hh',
+  'fast-function-tracer.cc',
   'flake/flake.hh',
   'flake/flakeref.hh',
   'flake/lockfile.hh',
@@ -133,6 +135,7 @@ libexpr = library(
   lexer_tab,
   libexpr_generated_headers,
   dependencies : [
+    liblixtracing,
     liblixutil,
     liblixstore,
     liblixfetchers,

src/libexpr/pos-idx.hh

@@ -10,6 +10,10 @@ class PosIdx
     friend struct LazyPosAcessors;
     friend class PosTable;
 
+    // FastFunctionTracer internals
+    friend class EvalStateRetriever;
+    friend class FastFunctionTracer;
+
 private:
     uint32_t id;
 

src/libexpr/symbol-table.hh

@@ -52,6 +52,10 @@ class Symbol
 {
     friend class SymbolTable;
 
+    // FastFunctionTracer internals
+    friend class EvalStateRetriever;
+    friend class FastFunctionTracer;
+
 private:
     uint32_t id;
 

src/libmain/loggers.cc

@@ -1,6 +1,9 @@
 #include "environment-variables.hh"
 #include "loggers.hh"
+#include "logging/chain-logger.hh"
+#include "logging/trace-logger.hh"
 #include "progress-bar.hh"
+#include <memory>
 
 namespace nix {
 
@@ -21,22 +24,34 @@ LogFormat parseLogFormat(const std::string & logFormatStr) {
 }
 
 std::shared_ptr<Logger> makeDefaultLogger() {
-    switch (defaultLogFormat) {
+    auto pickMainLogger = []() {
-    case LogFormat::raw:
+        switch (defaultLogFormat) {
-        return makeSimpleLogger(false);
+        case LogFormat::raw:
-    case LogFormat::rawWithLogs:
+            return makeSimpleLogger(false);
-        return makeSimpleLogger(true);
+        case LogFormat::rawWithLogs:
-    case LogFormat::internalJSON:
+            return makeSimpleLogger(true);
-        return makeJSONLogger(*makeSimpleLogger(true));
+        case LogFormat::internalJSON:
-    case LogFormat::bar:
+            return makeJSONLogger(*makeSimpleLogger(true));
-        return makeProgressBar();
+        case LogFormat::bar:
-    case LogFormat::barWithLogs: {
+            return makeProgressBar();
-        auto logger = makeProgressBar();
+        case LogFormat::barWithLogs: {
-        logger->setPrintBuildLogs(true);
+            auto logger = makeProgressBar();
-        return logger;
+            logger->setPrintBuildLogs(true);
-    }
+            return logger;
-    default:
+        }
-        abort();
+        default:
+            abort();
+        }
+    };
+
+    auto mainLogger = pickMainLogger();
+
+    // TODO: this is absolutely not the way to configure this
+    auto traceFile = getEnv("NIX_TRACE_FILE");
+    if (traceFile.has_value()) {
+        return std::shared_ptr<Logger>(std::make_shared<ChainLogger>(std::vector{mainLogger, std::shared_ptr<Logger>(std::make_shared<TraceLogger>(*traceFile))}));
+    } else {
+        return mainLogger;
     }
 }
 

src/libtracing/main.cc

@@ -10,7 +10,7 @@ class MyInternedRetriever : public InternedRetriever
         return "meow";
     }
 
-    virtual auto getPos(InternedPos idx, std::string funcName) const -> TracePos override
+    virtual auto getPos(InternedPos idx, std::string const funcName) const -> TracePos override
     {
         return TracePos{
             .fileName = "file.nix",
@@ -32,8 +32,10 @@ int main(int argc, char **argv)
     }
     nix::tracing::TraceWriter tw{std::make_unique<MyInternedRetriever>()};
 
-    tw.begin(InternedPos{1}, InternedName{3}, Timestamp{250});
+    auto track = tw.trackByTid(1, 2, "track");
-    tw.end(Timestamp{1235});
+
+    track.begin(InternedPos{1}, InternedName{3}, Timestamp{250});
+    track.end(Timestamp{1235});
 
     std::ofstream ofs(argv[1]);
     auto buf = tw.splat();

src/libtracing/meson.build

@@ -31,7 +31,7 @@ libtracing = library(
   # FIXME(Qyriad): is this right?
   install_rpath : libdir,
   cpp_args : [ '-DPERFETTO_DISABLE_LOG' ],
-  include_directories : include_directories('./perfetto/base/build_configs/bazel'),
+  include_directories : include_directories('./perfetto/base/build_configs/bazel')
 )
 
 liblixtracing = declare_dependency(

src/libtracing/trace-writer.cc

@@ -1,12 +1,17 @@
+#include <chrono>
+#include <memory>
+#include <optional>
+#include <string_view>
+#include <unordered_map>
+#include <utility>
+#include <random>
+
 #include "meow/protos/perfetto/trace/perfetto_trace.pbzero.h"
 #include "perfetto/protozero/message.h"
 #include "perfetto/protozero/message_handle.h"
 #include "perfetto/protozero/scattered_heap_buffer.h"
 #include "perfetto/protozero/scattered_stream_writer.h"
 #include "trace-writer.hh"
-#include <memory>
-#include <optional>
-#include <unordered_map>
 
 template<>
 struct std::hash<nix::tracing::InternedPos>
@@ -56,15 +61,27 @@ struct TraceWriter::Impl
     Trace trace_;
     protozero::MessageHandle<Trace> traceHandle_;
 
-    std::unordered_map<InternedPos, ProtoInternedPos> posMap_;
+    std::unordered_map<InternedPos, ProtoInternedPos> posMap_{};
     uint64_t posIid_ = 1;
 
-    std::unordered_map<InternedName, ProtoInternedName> nameMap_;
+    std::unordered_map<InternedName, ProtoInternedName> nameMap_{};
     uint64_t nameIid_ = 1;
 
-    auto getName(InternedName name, std::optional<std::string> &outName) -> ProtoInternedName;
+    uint64_t logMessageIid_ = 1;
 
-    auto getPos(InternedPos pos, InternedName funcName, std::optional<TracePos> &outPos) -> ProtoInternedPos;
+    /** Mapping between TID and track */
+    std::unordered_map<uint64_t, Track> tracks_{};
+
+    std::mt19937_64 rand_;
+
+    /** trusted_packet_sequence_id, which appears as the same value in every packet written by a
+     * writer */
+    uint64_t trustedSequenceId_;
+
+    auto getName(InternedName name, std::optional<std::string> & outName) -> ProtoInternedName;
+
+    auto getPos(InternedPos pos, InternedName funcName, std::optional<TracePos> & outPos)
+        -> ProtoInternedPos;
 
     Impl(std::unique_ptr<InternedRetriever> retriever)
         : retriever_(std::move(retriever))
@@ -74,19 +91,25 @@ struct TraceWriter::Impl
         buf_.set_writer(&this->writer_);
         trace_.Reset(&this->writer_, &this->arena_);
 
-        auto p = protozero::MessageHandle<TracePacket>(trace_.add_packet());
+        std::random_device rd;
-        auto td = protozero::MessageHandle<TrackDescriptor>(p->set_track_descriptor());
+        rand_ = std::mt19937_64(rd());
-        td->set_name("track");
-        td->set_uuid(1);
 
-        p->set_trusted_packet_sequence_id(1337);
+        trustedSequenceId_ = rand_();
-        p->set_sequence_flags(perfetto_pbzero_enum_TracePacket::SEQ_INCREMENTAL_STATE_CLEARED);
-        p->set_previous_packet_dropped(true);
-        p->set_first_packet_on_sequence(true);
     }
 };
 
-auto TraceWriter::Impl::getName(InternedName name, std::optional<std::string> &outName) -> ProtoInternedName
+auto Timestamp::now() -> Timestamp
+{
+    auto point = std::chrono::steady_clock::now();
+    return tracing::Timestamp{
+        .monotonic_nanos = static_cast<uint64_t>(
+            std::chrono::duration_cast<std::chrono::nanoseconds>(point.time_since_epoch()).count()
+        )
+    };
+}
+
+auto TraceWriter::Impl::getName(InternedName name, std::optional<std::string> & outName)
+    -> ProtoInternedName
 {
     if (auto it = nameMap_.find(name); it != nameMap_.end()) {
         // one already there, return it
@@ -101,7 +124,9 @@ auto TraceWriter::Impl::getName(InternedName name, std::optional<std::string> &o
     }
 }
 
-auto TraceWriter::Impl::getPos(InternedPos pos, InternedName funcName, std::optional<TracePos> &outPos) -> ProtoInternedPos
+auto TraceWriter::Impl::getPos(
+    InternedPos pos, InternedName funcName, std::optional<TracePos> & outPos
+) -> ProtoInternedPos
 {
     if (auto it = posMap_.find(pos); it != posMap_.end()) {
         // one already there, return it
@@ -122,18 +147,78 @@ TraceWriter::TraceWriter(std::unique_ptr<InternedRetriever> retriever)
 {
 }
 
+TraceWriter::Track TraceWriter::trackByTid(uint64_t pid, uint64_t tid, std::string_view const name)
+{
+    auto it = impl_->tracks_.find(tid);
+    if (it != impl_->tracks_.end()) {
+        return it->second;
+    }
+
+    auto newTrack = Track(*this, pid, tid, name, std::nullopt, impl_->tracks_.empty());
+    impl_->tracks_.emplace(std::make_pair(tid, newTrack));
+
+    return newTrack;
+}
+
 TraceWriter::~TraceWriter() = default;
 
-void TraceWriter::begin(InternedPos pos, InternedName name, Timestamp ts)
+TraceWriter::Track::Track(
+    TraceWriter & w,
+    std::optional<uint64_t> pid,
+    std::optional<uint64_t> tid,
+    const std::string_view name,
+    std::optional<uint64_t> parentUuid,
+    bool initial
+)
+    : w_(w)
+{
+    auto p = protozero::MessageHandle<TracePacket>(w_.impl_->trace_.add_packet());
+
+    {
+        auto td = protozero::MessageHandle<TrackDescriptor>(p->set_track_descriptor());
+
+        td->set_name(name.data(), name.size());
+        uuid_ = w_.impl_->rand_();
+        td->set_uuid(uuid_);
+
+        if (parentUuid.has_value()) {
+            td->set_parent_uuid(*parentUuid);
+        }
+
+        if (tid.has_value() && pid.has_value()) {
+            auto thread = protozero::MessageHandle<ThreadDescriptor>(td->set_thread());
+            thread->set_pid(*pid);
+            thread->set_tid(*tid);
+        }
+    }
+
+    p->set_trusted_packet_sequence_id(w_.impl_->trustedSequenceId_);
+    if (initial) {
+        p->set_sequence_flags(perfetto_pbzero_enum_TracePacket::SEQ_INCREMENTAL_STATE_CLEARED);
+        p->set_previous_packet_dropped(true);
+        p->set_first_packet_on_sequence(true);
+    }
+}
+
+auto TraceWriter::Track::child(std::string_view const name) -> TraceWriter::Track
+{
+    return Track(w_, std::nullopt, std::nullopt, name, uuid_);
+}
+
+// XXX: Frustratingly, this has to be implemented twice, since you more or less
+// otherwise have to invert control to do this reasonably while maintaining the
+// sequencing invariants (that you can't write to the parent message while a
+// child message is still open)
+void TraceWriter::Track::begin(InternedPos pos, InternedName name, Timestamp ts)
 {
 
     std::optional<std::string> nameToIntern;
     std::optional<TracePos> posToIntern;
 
-    auto nameIid = impl_->getName(name, nameToIntern);
+    auto nameIid = w_.impl_->getName(name, nameToIntern);
-    auto posIid = impl_->getPos(pos, name, posToIntern);
+    auto posIid = w_.impl_->getPos(pos, name, posToIntern);
 
-    auto packet = protozero::MessageHandle<TracePacket>(impl_->trace_.add_packet());
+    auto packet = protozero::MessageHandle<TracePacket>(w_.impl_->trace_.add_packet());
 
     packet->set_sequence_flags(perfetto_pbzero_enum_TracePacket::SEQ_NEEDS_INCREMENTAL_STATE);
 
@@ -147,7 +232,8 @@ void TraceWriter::begin(InternedPos pos, InternedName name, Timestamp ts)
         }
 
         if (posToIntern.has_value()) {
-            auto sourceLoc = protozero::MessageHandle<SourceLocation>(internedData->add_source_locations());
+            auto sourceLoc =
+                protozero::MessageHandle<SourceLocation>(internedData->add_source_locations());
             sourceLoc->set_iid(posIid.key);
             sourceLoc->set_file_name(posToIntern->fileName);
             sourceLoc->set_function_name(posToIntern->functionName);
@@ -156,29 +242,108 @@ void TraceWriter::begin(InternedPos pos, InternedName name, Timestamp ts)
     }
 
     packet->set_timestamp(ts.monotonic_nanos);
-    packet->set_trusted_packet_sequence_id(1337);
+    packet->set_trusted_packet_sequence_id(w_.impl_->trustedSequenceId_);
-    auto te = protozero::MessageHandle<TrackEvent>(packet->set_track_event());
-    te->set_type(perfetto_pbzero_enum_TrackEvent::TYPE_SLICE_BEGIN);
-    te->set_name_iid(nameIid.key);
-    te->set_source_location_iid(posIid.key);
 
-    // TODO: make a real value
+    {
-    te->set_track_uuid(1);
+        auto te = protozero::MessageHandle<TrackEvent>(packet->set_track_event());
+        te->set_type(perfetto_pbzero_enum_TrackEvent::TYPE_SLICE_BEGIN);
+        te->set_name_iid(nameIid.key);
+        te->set_source_location_iid(posIid.key);
 
-    // te->set_name_iid(nameIid.key);
+        te->set_track_uuid(uuid_);
-    // te->set_name("meow");
+    }
-    // TODO: te->set_source_location_iid();
 }
 
-void TraceWriter::end(Timestamp ts)
+void TraceWriter::Track::begin(
+    std::string_view const name, std::optional<std::string_view> category, Timestamp ts
+)
 {
-    protozero::MessageHandle<TracePacket> tp(impl_->trace_.add_packet());
+    auto packet = protozero::MessageHandle<TracePacket>(w_.impl_->trace_.add_packet());
+
+    packet->set_timestamp(ts.monotonic_nanos);
+    packet->set_trusted_packet_sequence_id(w_.impl_->trustedSequenceId_);
+    auto te = protozero::MessageHandle<TrackEvent>(packet->set_track_event());
+    te->set_type(perfetto_pbzero_enum_TrackEvent::TYPE_SLICE_BEGIN);
+    te->set_name(name.data(), name.size());
+    if (category.has_value()) {
+        te->add_categories(category->data(), category->length());
+    }
+
+    te->set_track_uuid(uuid_);
+}
+
+void TraceWriter::Track::end(Timestamp ts)
+{
+    protozero::MessageHandle<TracePacket> tp{w_.impl_->trace_.add_packet()};
     tp->set_timestamp(ts.monotonic_nanos);
-    tp->set_trusted_packet_sequence_id(1337);
+    tp->set_trusted_packet_sequence_id(w_.impl_->trustedSequenceId_);
 
     protozero::MessageHandle<TrackEvent> te(tp->set_track_event());
     te->set_type(perfetto_pbzero_enum_TrackEvent::TYPE_SLICE_END);
-    te->set_track_uuid(1);
+    te->set_track_uuid(uuid_);
+}
+
+/** "Interns" a log message. That is to say, does not intern a log message and just sends it. */
+static void internLogMessage(InternedData * id, uint64_t iid, std::string_view const message)
+{
+    protozero::MessageHandle internedData{id};
+
+    {
+        protozero::MessageHandle body{internedData->add_log_message_body()};
+        body->set_body(message.data(), message.size());
+        body->set_iid(iid);
+    }
+}
+
+static constexpr LogMessage_Priority mapLogLevel(LogLevel level)
+{
+    switch (level) {
+    case LogLevel::VERBOSE:
+        return LogMessage_Priority::PRIO_VERBOSE;
+    case LogLevel::DEBUG:
+        return LogMessage_Priority::PRIO_DEBUG;
+    case LogLevel::INFO:
+        return LogMessage_Priority::PRIO_INFO;
+    case LogLevel::WARN:
+        return LogMessage_Priority::PRIO_WARN;
+    case LogLevel::ERROR:
+        return LogMessage_Priority::PRIO_ERROR;
+    case LogLevel::FATAL:
+        return LogMessage_Priority::PRIO_FATAL;
+    }
+}
+
+void TraceWriter::Track::logMessage(
+    std::string_view const message,
+    std::optional<std::string_view> const category,
+    Timestamp ts,
+    LogLevel level
+)
+{
+    protozero::MessageHandle tp{w_.impl_->trace_.add_packet()};
+    tp->set_timestamp(ts.monotonic_nanos);
+    tp->set_trusted_packet_sequence_id(w_.impl_->trustedSequenceId_);
+    tp->set_sequence_flags(perfetto_pbzero_enum_TracePacket::SEQ_NEEDS_INCREMENTAL_STATE);
+
+    uint64_t iid = w_.impl_->logMessageIid_++;
+    internLogMessage(tp->set_interned_data(), iid, message);
+
+    {
+        protozero::MessageHandle<TrackEvent> te{tp->set_track_event()};
+        te->set_type(perfetto_pbzero_enum_TrackEvent::TYPE_INSTANT);
+        te->set_track_uuid(uuid_);
+        te->set_name(message.data(), message.size());
+
+        if (category.has_value()) {
+            te->add_categories(category->data(), category->length());
+        }
+
+        {
+            protozero::MessageHandle<LogMessage> logMessage{te->set_log_message()};
+            logMessage->set_body_iid(iid);
+            logMessage->set_prio(mapLogLevel(level));
+        }
+    }
 }
 
 auto TraceWriter::splat() const -> std::vector<uint8_t>

src/libtracing/trace-writer.hh

@@ -1,15 +1,23 @@
 #pragma once
 ///@file
 
-#include <stddef.h>
 #include <memory>
+#include <optional>
 #include <stdint.h>
 #include <string>
-#include <utility>
 #include <vector>
 
 namespace nix::tracing {
 
+enum class LogLevel {
+    VERBOSE,
+    DEBUG,
+    INFO,
+    WARN,
+    ERROR,
+    FATAL,
+};
+
 struct InternedPos
 {
     uint32_t key;
@@ -29,6 +37,8 @@ struct InternedName
 struct Timestamp
 {
     uint64_t monotonic_nanos;
+
+    static auto now() -> Timestamp;
 };
 
 struct TracePos
@@ -43,7 +53,7 @@ struct TracePos
 struct InternedRetriever
 {
     virtual auto getName(InternedName idx) const -> std::string = 0;
-    virtual auto getPos(InternedPos idx, std::string funcName) const -> TracePos = 0;
+    virtual auto getPos(InternedPos idx, std::string const funcName) const -> TracePos = 0;
 
     virtual ~InternedRetriever() = default;
 };
@@ -53,10 +63,55 @@ class TraceWriter
     struct Impl;
     std::unique_ptr<Impl> impl_;
 public:
+    class Track
+    {
+        TraceWriter & w_;
+        uint64_t uuid_;
+
+        explicit Track(
+            TraceWriter & w,
+            std::optional<uint64_t> pid,
+            std::optional<uint64_t> tid,
+            std::string_view const name,
+            std::optional<uint64_t> parentUuid,
+            bool initial = false
+        );
+
+        friend class TraceWriter;
+
+    public:
+        /** Begins an event on the track using interning machinery */
+        void begin(InternedPos pos, InternedName name, Timestamp ts);
+
+        /** Begins an event on the track, without using the interning machinery */
+        void begin(
+            std::string_view const name,
+            std::optional<std::string_view> const category,
+            Timestamp ts
+        );
+
+        /** Ends the active event on this track */
+        void end(Timestamp ts);
+
+        /** Send a log message */
+        void logMessage(
+            std::string_view const message,
+            std::optional<std::string_view> const category,
+            Timestamp ts,
+            LogLevel level
+        );
+
+        /** Makes a child track parented to this one
+         *
+         * This is useful for doing async traces (since async spans are just,
+         * you invent a track per event).
+         */
+        Track child(std::string_view const name);
+    };
+
     TraceWriter(std::unique_ptr<InternedRetriever> retriever);
 
-    void begin(InternedPos pos, InternedName name, Timestamp ts);
+    Track trackByTid(uint64_t pid, uint64_t tid, std::string_view const name);
-    void end(Timestamp ts);
 
     /** Splats the trace out into a buffer */
     auto splat() const -> std::vector<uint8_t>;

src/libutil/logging/chain-logger.cc

@@ -0,0 +1,53 @@
+#include "logging/chain-logger.hh"
+
+namespace nix {
+
+void ChainLogger::log(Verbosity level, std::string_view s)
+{
+    for (auto && child : children_) {
+        child->log(level, s);
+    }
+}
+
+void ChainLogger::logEI(const ErrorInfo &ei) {
+    for (auto && child : children_) {
+        child->logEI(ei);
+    }
+}
+
+void ChainLogger::startActivity(
+    ActivityId act,
+    Verbosity level,
+    ActivityType type,
+    const std::string & s,
+    const Fields & fields,
+    ActivityId parent
+)
+{
+    for (auto && child : children_) {
+        child->startActivity(act, level, type, s, fields, parent);
+    }
+}
+
+void ChainLogger::stopActivity(ActivityId act)
+{
+    for (auto && child : children_) {
+        child->stopActivity(act);
+    }
+}
+
+void ChainLogger::result(ActivityId act, ResultType type, const Fields & fields)
+{
+    for (auto && child : children_) {
+        child->result(act, type, fields);
+    }
+}
+
+void ChainLogger::setPrintBuildLogs(bool printBuildLogs)
+{
+    for (auto && child : children_) {
+        child->setPrintBuildLogs(printBuildLogs);
+    }
+}
+
+}

src/libutil/logging/chain-logger.hh

@@ -0,0 +1,40 @@
+#pragma once
+///@file
+
+#include <memory>
+#include <vector>
+
+#include "logging.hh"
+
+namespace nix {
+
+/** Logs to a chain of other loggers */
+class ChainLogger : public Logger
+{
+    std::vector<std::shared_ptr<Logger>> children_;
+
+public:
+    ChainLogger(std::vector<std::shared_ptr<Logger>> children) : children_{std::move(children)} {}
+
+    virtual void log(Verbosity level, std::string_view s) override;
+    virtual void startActivity(
+        ActivityId act,
+        Verbosity level,
+        ActivityType type,
+        const std::string & s,
+        const Fields & fields,
+        ActivityId parent
+    ) override;
+    virtual void stopActivity(ActivityId act) override;
+    virtual void result(ActivityId act, ResultType type, const Fields & fields) override;
+
+    virtual void logEI(const ErrorInfo &ei) override;
+
+    // FIXME: ask()
+    // It needs some API fixes to figure out if loggers even support it.
+
+    virtual void setPrintBuildLogs(bool printBuildLogs) override;
+
+    virtual ~ChainLogger() {}
+};
+}

src/libutil/logging/trace-logger.cc

@@ -0,0 +1,232 @@
+#include <iostream>
+#include <memory>
+#include <mutex>
+#include <sstream>
+#include <string_view>
+#include <unordered_map>
+#include <fstream>
+
+#include "error.hh"
+#include "logging.hh"
+#include "trace-writer.hh"
+#include "logging/trace-logger.hh"
+
+namespace nix {
+
+using std::operator""sv;
+
+struct FakeRetriever : tracing::InternedRetriever
+{
+    virtual auto getName(tracing::InternedName idx) const -> std::string override
+    {
+        assert(false);
+    }
+
+    virtual auto getPos(tracing::InternedPos idx, std::string const funcName) const
+        -> tracing::TracePos override
+    {
+        assert(false);
+    }
+};
+
+struct TraceLogger::Impl
+{
+    nix::Path outputPath_;
+
+    std::mutex lock_;
+    tracing::TraceWriter writer_;
+    std::unordered_map<ActivityId, tracing::TraceWriter::Track> activityToTrack_;
+
+    tracing::TraceWriter::Track mainTrack_;
+
+    Impl(nix::Path outputPath)
+        : outputPath_(outputPath)
+        , writer_(std::make_unique<FakeRetriever>())
+        , mainTrack_(writer_.trackByTid(getpid(), gettid(), "Lix"))
+    {
+    }
+};
+
+TraceLogger::TraceLogger(const nix::Path outputPath)
+    : impl_{std::make_unique<TraceLogger::Impl>(outputPath)}
+{
+    std::cerr << "TraceLogger!!\n";
+}
+
+TraceLogger::~TraceLogger()
+{
+    try {
+        std::ofstream ofs(impl_->outputPath_);
+        auto buf = impl_->writer_.splat();
+        ofs.write(reinterpret_cast<const char *>(buf.data()), buf.size());
+    } catch (std::exception & e) {
+        std::cerr << "Exception ignored while writing trace file: " << e.what();
+    }
+}
+
+static tracing::LogLevel mapLogLevel(Verbosity v)
+{
+    switch (v) {
+    case lvlError:
+        return tracing::LogLevel::ERROR;
+    case lvlWarn:
+        return tracing::LogLevel::WARN;
+    case lvlNotice:
+    case lvlInfo:
+        return tracing::LogLevel::INFO;
+    case lvlTalkative:
+        return tracing::LogLevel::DEBUG;
+    case lvlChatty:
+    case lvlDebug:
+    case lvlVomit:
+        return tracing::LogLevel::VERBOSE;
+    }
+}
+
+void TraceLogger::log(Verbosity level, std::string_view s)
+{
+    std::lock_guard _g{impl_->lock_};
+    impl_->mainTrack_.logMessage(s, "logs"sv, tracing::Timestamp::now(), mapLogLevel(level));
+}
+
+void TraceLogger::logEI(const ErrorInfo & ei)
+{
+    std::stringstream oss;
+    showErrorInfo(oss, ei, loggerSettings.showTrace.get());
+
+    log(ei.level, oss.str());
+}
+
+static constexpr const std::string_view activityTypeName(ActivityType type)
+{
+    switch (type) {
+    case actUnknown:
+        return "Unknown";
+    case actCopyPath:
+        return "CopyPath";
+    case actFileTransfer:
+        return "FileTransfer";
+    case actRealise:
+        return "Realise";
+    case actCopyPaths:
+        return "CopyPaths";
+    case actBuilds:
+        return "Builds";
+    case actBuild:
+        return "Build";
+    case actOptimiseStore:
+        return "OptimiseStore";
+    case actVerifyPaths:
+        return "VerifyPaths";
+    case actSubstitute:
+        return "Substitute";
+    case actQueryPathInfo:
+        return "QueryPathInfo";
+    case actPostBuildHook:
+        return "PostBuildHook";
+    case actBuildWaiting:
+        return "BuildWaiting";
+    }
+}
+
+static constexpr const std::string_view resultTypeName(ResultType type)
+{
+    switch (type) {
+    case resFileLinked:
+        return "FileLinked";
+    case resBuildLogLine:
+        return "BuildLogLine";
+    case resUntrustedPath:
+        return "UntrustedPath";
+    case resCorruptedPath:
+        return "CorruptedPath";
+    case resSetPhase:
+        return "SetPhase";
+    case resProgress:
+        return "Progress";
+    case resSetExpected:
+        return "SetExpected";
+    case resPostBuildLogLine:
+        return "PostBuildLogLine";
+    }
+}
+
+static std::string formatFields(const Logger::Fields & fields)
+{
+    if (fields.empty()) {
+        return "";
+    }
+
+    std::ostringstream oss;
+    oss << " (";
+    bool first = true;
+    for (const auto & f : fields) {
+        if (!first) {
+            oss << ", ";
+        }
+        first = false;
+
+        switch (f.type) {
+        case Logger::Field::tInt:
+            oss << f.i;
+            continue;
+        case Logger::Field::tString:
+            oss << f.s;
+            continue;
+        }
+    }
+    oss << ")";
+    return oss.str();
+}
+
+void TraceLogger::startActivity(
+    ActivityId act,
+    Verbosity level,
+    ActivityType type,
+    const std::string & s,
+    const Fields & fields,
+    ActivityId parent
+)
+{
+    // Each activity is another track, since we have no real guarantee of what
+    // thread they will end on.
+    bool inserted = false;
+    {
+        std::lock_guard _g{impl_->lock_};
+
+        auto track = impl_->mainTrack_.child("");
+        inserted = impl_->activityToTrack_.insert(std::make_pair(act, track)).second;
+        track.begin(s + formatFields(fields), activityTypeName(type), tracing::Timestamp::now());
+    }
+    if (!inserted) {
+        printError("Duplicated activity ID: %d, this is a bug in Lix", act);
+    }
+}
+
+void TraceLogger::stopActivity(ActivityId act)
+{
+    std::lock_guard _g{impl_->lock_};
+
+    if (auto it = impl_->activityToTrack_.find(act); it != impl_->activityToTrack_.end()) {
+        it->second.end(tracing::Timestamp::now());
+        impl_->activityToTrack_.erase(it);
+    }
+}
+
+void TraceLogger::result(ActivityId act, ResultType type, const Fields & fields)
+{
+    // There are an incredibly unreasonable number of these and they are of very little value
+    if (type == resProgress) {
+        return;
+    }
+    if (auto it = impl_->activityToTrack_.find(act); it != impl_->activityToTrack_.end()) {
+        it->second.logMessage(
+            std::string(resultTypeName(type)) + formatFields(fields),
+            resultTypeName(type),
+            tracing::Timestamp::now(),
+            tracing::LogLevel::INFO
+        );
+    }
+}
+
+}

src/libutil/logging/trace-logger.hh

@@ -0,0 +1,36 @@
+#pragma once
+///@file
+
+#include "error.hh"
+#include "logging.hh"
+#include "types.hh"
+
+namespace nix {
+
+/** Logger that logs to perfetto traces */
+class TraceLogger : public Logger
+{
+    struct Impl;
+
+    std::unique_ptr<Impl> impl_;
+
+public:
+    TraceLogger(const nix::Path outputPath);
+
+    virtual void log(Verbosity level, std::string_view s) override;
+    virtual void logEI(const ErrorInfo &ei) override;
+    virtual void startActivity(
+        ActivityId act,
+        Verbosity level,
+        ActivityType type,
+        const std::string & s,
+        const Fields & fields,
+        ActivityId parent
+    ) override;
+    virtual void stopActivity(ActivityId act) override;
+    virtual void result(ActivityId act, ResultType type, const Fields & fields) override;
+
+    virtual ~TraceLogger();
+};
+
+}

src/libutil/meson.build

@@ -21,6 +21,8 @@ libutil_sources = files(
   'hilite.cc',
   'json-utils.cc',
   'logging.cc',
+  'logging/chain-logger.cc',
+  'logging/trace-logger.cc',
   'namespaces.cc',
   'position.cc',
   'print-elided.cc',
@@ -78,8 +80,10 @@ libutil_headers = files(
   'input-accessor.hh',
   'json-impls.hh',
   'json-utils.hh',
-  'logging.hh',
   'logging-json.hh',
+  'logging.hh',
+  'logging/chain-logger.hh',
+  'logging/trace-logger.hh',
   'lru-cache.hh',
   'monitor-fd.hh',
   'namespaces.hh',
@@ -128,6 +132,7 @@ libutil = library(
     brotli,
     openssl,
     nlohmann_json,
+    liblixtracing,
   ],
   cpp_pch : cpp_pch,
   implicit_include_directories : true,

src/meson.build

@@ -1,12 +1,13 @@
 # Subcomponents: these link into artifacts themselves, and have interdependencies.
 
+# libtracing is self-contained
+subdir('libtracing')
+# libutil depends on libtracing
 subdir('libutil')
 # Load-bearing order. libstore depends on libutil.
 subdir('libstore')
 # libfetchers depends on libstore
 subdir('libfetchers')
-# libtracing is self-contained
-subdir('libtracing')
 # libexpr depends on all of the above
 subdir('libexpr')
 # libmain depends on libutil and libstore