Skip to content
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

add abstract base tracer class #3152

Merged
merged 1 commit into from
Nov 22, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
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
Loading