diff --git a/meson.build b/meson.build index 7a6283ca2..77c8a1477 100644 --- a/meson.build +++ b/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', diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc index c72b69af2..b9beff48e 100644 --- a/src/libexpr/eval.cc +++ b/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 #include #include +#include #include #include #include @@ -394,6 +396,7 @@ EvalState::EvalState( , debugStop(false) , trylevel(0) , regexCache(makeRegexCache()) + , tracer(nullptr) #if HAVE_BOEHMGC , valueAllocCache(std::allocate_shared(traceable_allocator(), nullptr)) , env1AllocCache(std::allocate_shared(traceable_allocator(), 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(*this, *traceFunctionsEnv); + } } @@ -1542,6 +1550,9 @@ void EvalState::callFunction(Value & fun, size_t nrArgs, Value * * args, Value & auto trace = evalSettings.traceFunctionCalls ? std::make_unique(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 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(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(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(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) { + // TODO: turning these into symbols is kind of unfortunate because it leaks memory + // TODO: This API loses the category of the things! + std::optional _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); diff --git a/src/libexpr/eval.hh b/src/libexpr/eval.hh index 411364d9f..ce4017746 100644 --- a/src/libexpr/eval.hh +++ b/src/libexpr/eval.hh @@ -14,6 +14,7 @@ #include "repl-exit-status.hh" #include +#include #include #include #include @@ -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; + /** + * A function tracer. May be null! + */ + std::unique_ptr tracer; + #if HAVE_BOEHMGC /** * Allocation cache for GC'd Value objects. diff --git a/src/libexpr/fast-function-tracer.cc b/src/libexpr/fast-function-tracer.cc new file mode 100644 index 000000000..8ae6ef6f0 --- /dev/null +++ b/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 +#include + +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(evalState)} + , outputPath_{outputFile} + , rootTrack_{writer_.trackByTid(getpid(), gettid(), "Functions")} + { + } +}; + +FastFunctionTracer::FastFunctionTracer(EvalState & evalState, Path outputFile) + : impl_{std::make_unique(evalState, std::move(outputFile))} +{ +} + +FastFunctionTracer::~FastFunctionTracer() +{ + try { + std::ofstream ofs(impl_->outputPath_); + auto buf = impl_->writer_.splat(); + ofs.write(reinterpret_cast(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, + }; +} + +} diff --git a/src/libexpr/fast-function-tracer.hh b/src/libexpr/fast-function-tracer.hh new file mode 100644 index 000000000..34d7e3bb4 --- /dev/null +++ b/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 + +namespace nix { + +class Symbol; +class PosIdx; +class EvalState; + +class FastFunctionTracer { + class Impl; + + std::unique_ptr 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(); +}; +} diff --git a/src/libexpr/meson.build b/src/libexpr/meson.build index 080fdb443..10a5e70e7 100644 --- a/src/libexpr/meson.build +++ b/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, diff --git a/src/libexpr/pos-idx.hh b/src/libexpr/pos-idx.hh index 406fc1b36..3769801d8 100644 --- a/src/libexpr/pos-idx.hh +++ b/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; diff --git a/src/libexpr/symbol-table.hh b/src/libexpr/symbol-table.hh index 967a186dd..99a75187a 100644 --- a/src/libexpr/symbol-table.hh +++ b/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; diff --git a/src/libmain/loggers.cc b/src/libmain/loggers.cc index fd3a773fb..602ac4084 100644 --- a/src/libmain/loggers.cc +++ b/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 namespace nix { @@ -21,22 +24,34 @@ LogFormat parseLogFormat(const std::string & logFormatStr) { } std::shared_ptr makeDefaultLogger() { - switch (defaultLogFormat) { - case LogFormat::raw: - return makeSimpleLogger(false); - case LogFormat::rawWithLogs: - return makeSimpleLogger(true); - case LogFormat::internalJSON: - return makeJSONLogger(*makeSimpleLogger(true)); - case LogFormat::bar: - return makeProgressBar(); - case LogFormat::barWithLogs: { - auto logger = makeProgressBar(); - logger->setPrintBuildLogs(true); - return logger; - } - default: - abort(); + auto pickMainLogger = []() { + switch (defaultLogFormat) { + case LogFormat::raw: + return makeSimpleLogger(false); + case LogFormat::rawWithLogs: + return makeSimpleLogger(true); + case LogFormat::internalJSON: + return makeJSONLogger(*makeSimpleLogger(true)); + case LogFormat::bar: + return makeProgressBar(); + case LogFormat::barWithLogs: { + auto logger = makeProgressBar(); + logger->setPrintBuildLogs(true); + return logger; + } + 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(std::make_shared(std::vector{mainLogger, std::shared_ptr(std::make_shared(*traceFile))})); + } else { + return mainLogger; } } diff --git a/src/libtracing/main.cc b/src/libtracing/main.cc index d2e59fd64..f53571927 100644 --- a/src/libtracing/main.cc +++ b/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()}; - tw.begin(InternedPos{1}, InternedName{3}, Timestamp{250}); - tw.end(Timestamp{1235}); + auto track = tw.trackByTid(1, 2, "track"); + + track.begin(InternedPos{1}, InternedName{3}, Timestamp{250}); + track.end(Timestamp{1235}); std::ofstream ofs(argv[1]); auto buf = tw.splat(); diff --git a/src/libtracing/meson.build b/src/libtracing/meson.build index 946c504c9..213eaaf0c 100644 --- a/src/libtracing/meson.build +++ b/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( diff --git a/src/libtracing/trace-writer.cc b/src/libtracing/trace-writer.cc index aefda13ae..591b36602 100644 --- a/src/libtracing/trace-writer.cc +++ b/src/libtracing/trace-writer.cc @@ -1,12 +1,17 @@ +#include +#include +#include +#include +#include +#include +#include + #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 -#include -#include template<> struct std::hash @@ -56,15 +61,27 @@ struct TraceWriter::Impl Trace trace_; protozero::MessageHandle traceHandle_; - std::unordered_map posMap_; + std::unordered_map posMap_{}; uint64_t posIid_ = 1; - std::unordered_map nameMap_; + std::unordered_map nameMap_{}; uint64_t nameIid_ = 1; - auto getName(InternedName name, std::optional &outName) -> ProtoInternedName; + uint64_t logMessageIid_ = 1; - auto getPos(InternedPos pos, InternedName funcName, std::optional &outPos) -> ProtoInternedPos; + /** Mapping between TID and track */ + std::unordered_map 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 & outName) -> ProtoInternedName; + + auto getPos(InternedPos pos, InternedName funcName, std::optional & outPos) + -> ProtoInternedPos; Impl(std::unique_ptr 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(trace_.add_packet()); - auto td = protozero::MessageHandle(p->set_track_descriptor()); - td->set_name("track"); - td->set_uuid(1); + std::random_device rd; + rand_ = std::mt19937_64(rd()); - p->set_trusted_packet_sequence_id(1337); - 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); + trustedSequenceId_ = rand_(); } }; -auto TraceWriter::Impl::getName(InternedName name, std::optional &outName) -> ProtoInternedName +auto Timestamp::now() -> Timestamp +{ + auto point = std::chrono::steady_clock::now(); + return tracing::Timestamp{ + .monotonic_nanos = static_cast( + std::chrono::duration_cast(point.time_since_epoch()).count() + ) + }; +} + +auto TraceWriter::Impl::getName(InternedName name, std::optional & 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 &o } } -auto TraceWriter::Impl::getPos(InternedPos pos, InternedName funcName, std::optional &outPos) -> ProtoInternedPos +auto TraceWriter::Impl::getPos( + InternedPos pos, InternedName funcName, std::optional & 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 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 pid, + std::optional tid, + const std::string_view name, + std::optional parentUuid, + bool initial +) + : w_(w) +{ + auto p = protozero::MessageHandle(w_.impl_->trace_.add_packet()); + + { + auto td = protozero::MessageHandle(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(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 nameToIntern; std::optional posToIntern; - auto nameIid = impl_->getName(name, nameToIntern); - auto posIid = impl_->getPos(pos, name, posToIntern); + auto nameIid = w_.impl_->getName(name, nameToIntern); + auto posIid = w_.impl_->getPos(pos, name, posToIntern); - auto packet = protozero::MessageHandle(impl_->trace_.add_packet()); + auto packet = protozero::MessageHandle(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(internedData->add_source_locations()); + auto sourceLoc = + protozero::MessageHandle(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); - auto te = protozero::MessageHandle(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); + packet->set_trusted_packet_sequence_id(w_.impl_->trustedSequenceId_); - // TODO: make a real value - te->set_track_uuid(1); + { + auto te = protozero::MessageHandle(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_name("meow"); - // TODO: te->set_source_location_iid(); + te->set_track_uuid(uuid_); + } } -void TraceWriter::end(Timestamp ts) +void TraceWriter::Track::begin( + std::string_view const name, std::optional category, Timestamp ts +) { - protozero::MessageHandle tp(impl_->trace_.add_packet()); + auto packet = protozero::MessageHandle(w_.impl_->trace_.add_packet()); + + packet->set_timestamp(ts.monotonic_nanos); + packet->set_trusted_packet_sequence_id(w_.impl_->trustedSequenceId_); + auto te = protozero::MessageHandle(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 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 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 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 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{te->set_log_message()}; + logMessage->set_body_iid(iid); + logMessage->set_prio(mapLogLevel(level)); + } + } } auto TraceWriter::splat() const -> std::vector diff --git a/src/libtracing/trace-writer.hh b/src/libtracing/trace-writer.hh index e864d0052..e72679c56 100644 --- a/src/libtracing/trace-writer.hh +++ b/src/libtracing/trace-writer.hh @@ -1,15 +1,23 @@ #pragma once ///@file -#include #include +#include #include #include -#include #include 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_; public: + class Track + { + TraceWriter & w_; + uint64_t uuid_; + + explicit Track( + TraceWriter & w, + std::optional pid, + std::optional tid, + std::string_view const name, + std::optional 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 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 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 retriever); - void begin(InternedPos pos, InternedName name, Timestamp ts); - void end(Timestamp ts); + Track trackByTid(uint64_t pid, uint64_t tid, std::string_view const name); /** Splats the trace out into a buffer */ auto splat() const -> std::vector; diff --git a/src/libutil/logging/chain-logger.cc b/src/libutil/logging/chain-logger.cc new file mode 100644 index 000000000..d7f0f6ef2 --- /dev/null +++ b/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); + } +} + +} diff --git a/src/libutil/logging/chain-logger.hh b/src/libutil/logging/chain-logger.hh new file mode 100644 index 000000000..c890f5b40 --- /dev/null +++ b/src/libutil/logging/chain-logger.hh @@ -0,0 +1,40 @@ +#pragma once +///@file + +#include +#include + +#include "logging.hh" + +namespace nix { + +/** Logs to a chain of other loggers */ +class ChainLogger : public Logger +{ + std::vector> children_; + +public: + ChainLogger(std::vector> 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() {} +}; +} diff --git a/src/libutil/logging/trace-logger.cc b/src/libutil/logging/trace-logger.cc new file mode 100644 index 000000000..7624d22e3 --- /dev/null +++ b/src/libutil/logging/trace-logger.cc @@ -0,0 +1,232 @@ +#include +#include +#include +#include +#include +#include +#include + +#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 activityToTrack_; + + tracing::TraceWriter::Track mainTrack_; + + Impl(nix::Path outputPath) + : outputPath_(outputPath) + , writer_(std::make_unique()) + , mainTrack_(writer_.trackByTid(getpid(), gettid(), "Lix")) + { + } +}; + +TraceLogger::TraceLogger(const nix::Path outputPath) + : impl_{std::make_unique(outputPath)} +{ + std::cerr << "TraceLogger!!\n"; +} + +TraceLogger::~TraceLogger() +{ + try { + std::ofstream ofs(impl_->outputPath_); + auto buf = impl_->writer_.splat(); + ofs.write(reinterpret_cast(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 + ); + } +} + +} diff --git a/src/libutil/logging/trace-logger.hh b/src/libutil/logging/trace-logger.hh new file mode 100644 index 000000000..0586120b5 --- /dev/null +++ b/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_; + +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(); +}; + +} diff --git a/src/libutil/meson.build b/src/libutil/meson.build index f6d14a11b..b3c85c3ca 100644 --- a/src/libutil/meson.build +++ b/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, diff --git a/src/meson.build b/src/meson.build index bc5ad44dd..8dd312614 100644 --- a/src/meson.build +++ b/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