Skip to content

Commit

Permalink
add abstract base tracer class
Browse files Browse the repository at this point in the history
  • Loading branch information
anonrig committed Nov 21, 2024
1 parent 66ec290 commit 63535c4
Show file tree
Hide file tree
Showing 4 changed files with 47 additions and 43 deletions.
16 changes: 5 additions & 11 deletions src/workerd/io/trace.c++
Original file line number Diff line number Diff line change
Expand Up @@ -820,7 +820,7 @@ WorkerTracer::WorkerTracer(PipelineLogLevel pipelineLogLevel, ExecutionModel exe
kj::none, kj::none, kj::none, kj::none, kj::none, nullptr, kj::none, executionModel)),
self(kj::refcounted<WeakRef<WorkerTracer>>(kj::Badge<WorkerTracer>{}, *this)) {}

void WorkerTracer::log(kj::Date timestamp, LogLevel logLevel, kj::String message, bool isSpan) {
void WorkerTracer::addLog(kj::Date timestamp, LogLevel logLevel, kj::String message, bool isSpan) {
if (trace->exceededLogLimit) {
return;
}
Expand Down Expand Up @@ -854,14 +854,14 @@ void WorkerTracer::addSpan(const Span& span, kj::String spanContext) {
}
if (isPredictableModeForTest()) {
// Do not emit span duration information in predictable mode.
log(span.endTime, LogLevel::LOG, kj::str("[\"span: ", span.operationName, "\"]"), true);
addLog(span.endTime, LogLevel::LOG, kj::str("[\"span: ", span.operationName, "\"]"), true);
} else {
// Time since Unix epoch in seconds, with millisecond precision
double epochSecondsStart = (span.startTime - kj::UNIX_EPOCH) / kj::MILLISECONDS / 1000.0;
double epochSecondsEnd = (span.endTime - kj::UNIX_EPOCH) / kj::MILLISECONDS / 1000.0;
auto message = kj::str("[\"span: ", span.operationName, " ", kj::mv(spanContext), " ",
epochSecondsStart, " ", epochSecondsEnd, "\"]");
log(span.endTime, LogLevel::LOG, kj::mv(message), true);
addLog(span.endTime, LogLevel::LOG, kj::mv(message), true);
}

// TODO(cleanup): Create a function in kj::OneOf to automatically convert to a given type (i.e
Expand All @@ -885,7 +885,7 @@ void WorkerTracer::addSpan(const Span& span, kj::String spanContext) {
KJ_UNREACHABLE;
}();
kj::String message = kj::str("[\"tag: "_kj, tag.key, " => "_kj, value, "\"]");
log(span.endTime, LogLevel::LOG, kj::mv(message), true);
addLog(span.endTime, LogLevel::LOG, kj::mv(message), true);
}
}

Expand Down Expand Up @@ -972,15 +972,9 @@ void WorkerTracer::setEventInfo(kj::Date timestamp, tracing::EventInfo&& info) {
trace->eventInfo = kj::mv(info);
}

void WorkerTracer::setOutcome(EventOutcome outcome) {
void WorkerTracer::setOutcome(EventOutcome outcome, kj::Duration cpuTime, kj::Duration wallTime) {
trace->outcome = outcome;
}

void WorkerTracer::setCPUTime(kj::Duration cpuTime) {
trace->cpuTime = cpuTime;
}

void WorkerTracer::setWallTime(kj::Duration wallTime) {
trace->wallTime = wallTime;
}

Expand Down
67 changes: 39 additions & 28 deletions src/workerd/io/trace.h
Original file line number Diff line number Diff line change
Expand Up @@ -586,49 +586,60 @@ class PipelineTracer final: public kj::Refcounted, public kj::EnableAddRefToThis
friend class WorkerTracer;
};

// Records a worker stage's trace information into a Trace object. When all references to the
// Tracer are released, its Trace is considered complete and ready for submission. If the Trace to
// write to isn't provided (that already exists in a PipelineTracer), the trace must by extracted
// via extractTrace.
class WorkerTracer final: public kj::Refcounted {
// An abstract class that defines shares functionality for tracers
// that have different characteristics.
class BaseTracer {
public:
explicit WorkerTracer(kj::Rc<PipelineTracer> parentPipeline,
kj::Own<Trace> trace,
PipelineLogLevel pipelineLogLevel);
explicit WorkerTracer(PipelineLogLevel pipelineLogLevel, ExecutionModel executionModel);
~WorkerTracer() {
self->invalidate();
}
KJ_DISALLOW_COPY_AND_MOVE(WorkerTracer);

// Adds log line to trace. For Spectre, timestamp should only be as accurate as JS Date.now().
// The isSpan parameter allows for logging spans, which will be emitted after regular logs. There
// can be at most MAX_USER_SPANS spans in a trace.
void log(kj::Date timestamp, LogLevel logLevel, kj::String message, bool isSpan = false);
virtual void addLog(kj::Date timestamp, LogLevel logLevel, kj::String message, bool isSpan) = 0;
// Add a span, which will be represented as a log.
void addSpan(const Span& span, kj::String spanContext);

// TODO(soon): Eventually:
//void setMetrics(...) // Or get from MetricsCollector::Request directly?
virtual void addSpan(const Span& span, kj::String spanContext) = 0;

void addException(
kj::Date timestamp, kj::String name, kj::String message, kj::Maybe<kj::String> stack);
virtual void addException(
kj::Date timestamp, kj::String name, kj::String message, kj::Maybe<kj::String> stack) = 0;

void addDiagnosticChannelEvent(
kj::Date timestamp, kj::String channel, kj::Array<kj::byte> message);
virtual void addDiagnosticChannelEvent(
kj::Date timestamp, kj::String channel, kj::Array<kj::byte> message) = 0;

// Adds info about the event that triggered the trace. Must not be called more than once.
void setEventInfo(kj::Date timestamp, tracing::EventInfo&&);
virtual void setEventInfo(kj::Date timestamp, tracing::EventInfo&&) = 0;

// Adds info about the response. Must not be called more than once, and only
// after passing a FetchEventInfo to setEventInfo().
void setFetchResponseInfo(tracing::FetchResponseInfo&&);
virtual void setFetchResponseInfo(tracing::FetchResponseInfo&&) = 0;

void setOutcome(EventOutcome outcome);
virtual void setOutcome(EventOutcome outcome, kj::Duration cpuTime, kj::Duration wallTime) = 0;
};

void setCPUTime(kj::Duration cpuTime);
// Records a worker stage's trace information into a Trace object. When all references to the
// Tracer are released, its Trace is considered complete and ready for submission. If the Trace to
// write to isn't provided (that already exists in a PipelineTracer), the trace must by extracted
// via extractTrace.
class WorkerTracer final: public kj::Refcounted, public BaseTracer {
public:
explicit WorkerTracer(kj::Rc<PipelineTracer> parentPipeline,
kj::Own<Trace> trace,
PipelineLogLevel pipelineLogLevel);
explicit WorkerTracer(PipelineLogLevel pipelineLogLevel, ExecutionModel executionModel);
~WorkerTracer() {
self->invalidate();
}
KJ_DISALLOW_COPY_AND_MOVE(WorkerTracer);

void setWallTime(kj::Duration wallTime);
void addLog(
kj::Date timestamp, LogLevel logLevel, kj::String message, bool isSpan = false) override;
void addSpan(const Span& span, kj::String spanContext) override;
void addException(kj::Date timestamp,
kj::String name,
kj::String message,
kj::Maybe<kj::String> stack) override;
void addDiagnosticChannelEvent(
kj::Date timestamp, kj::String channel, kj::Array<kj::byte> message) override;
void setEventInfo(kj::Date timestamp, tracing::EventInfo&&) override;
void setFetchResponseInfo(tracing::FetchResponseInfo&&) override;
void setOutcome(EventOutcome outcome, kj::Duration cpuTime, kj::Duration wallTime) override;

// Used only for a Trace in a process sandbox. Copies the content of this tracer's trace to the
// builder.
Expand Down
2 changes: 1 addition & 1 deletion src/workerd/io/worker.c++
Original file line number Diff line number Diff line change
Expand Up @@ -1842,7 +1842,7 @@ void Worker::handleLog(jsg::Lock& js,
auto& ioContext = IoContext::current();
KJ_IF_SOME(tracer, ioContext.getWorkerTracer()) {
auto timestamp = ioContext.now();
tracer.log(timestamp, level, message());
tracer.addLog(timestamp, level, message(), false);
}
}

Expand Down
5 changes: 2 additions & 3 deletions src/workerd/server/server.c++
Original file line number Diff line number Diff line change
Expand Up @@ -1455,9 +1455,8 @@ class RequestObserverWithTracer final: public RequestObserver, public WorkerInte
if (fetchStatus != 0) {
t->setFetchResponseInfo(tracing::FetchResponseInfo(fetchStatus));
}
t->setCPUTime(0 * kj::MILLISECONDS);
t->setWallTime(0 * kj::MILLISECONDS);
t->setOutcome(outcome);
t->setOutcome(
outcome, 0 * kj::MILLISECONDS /* cpu time */, 0 * kj::MILLISECONDS /* wall time */);
}
}

Expand Down

0 comments on commit 63535c4

Please sign in to comment.