Skip to content

Commit

Permalink
More cleanups and refinements on revised trace api
Browse files Browse the repository at this point in the history
  • Loading branch information
@jasnell
jasnell committed Oct 7, 2024
1 parent e2f05a2 commit 2dcbac7
Show file tree
Hide file tree
Showing 13 changed files with 293 additions and 231 deletions.
4 changes: 2 additions & 2 deletions src/workerd/api/trace.c++
View file
Original file line number Diff line number Diff line change
Expand Up @@ -206,8 +206,8 @@ TraceItem::TraceItem(jsg::Lock& js, const Trace& trace)
trace.onsetInfo.dispatchNamespace.map([](auto& ns) { return kj::str(ns); })),
scriptTags(getTraceScriptTags(trace)),
outcome(getTraceOutcome(trace)),
cpuTime(trace.outcomeInfo.cpuTime / kj::MILLISECONDS),
wallTime(trace.outcomeInfo.wallTime / kj::MILLISECONDS),
cpuTime(trace.cpuTime / kj::MILLISECONDS),
wallTime(trace.wallTime / kj::MILLISECONDS),
truncated(trace.truncated) {}

kj::Maybe<TraceItem::EventInfo> TraceItem::getEvent(jsg::Lock& js) {
Expand Down
117 changes: 57 additions & 60 deletions src/workerd/io/trace-common-test.c++
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,11 +10,11 @@ namespace {

KJ_TEST("Tags work") {
{
trace::Tag tag(kj::str("a"), 1UL);
trace::Tag tag(kj::str("a"), (uint64_t)1);
auto& key = KJ_ASSERT_NONNULL(tag.key.tryGet<kj::String>());
auto& value = KJ_ASSERT_NONNULL(tag.value.tryGet<uint64_t>());
KJ_EXPECT(key == "a");
KJ_EXPECT(value == 1UL);
KJ_EXPECT(value == (uint64_t)1);
KJ_EXPECT(tag.keyMatches("a"_kj));

capnp::MallocMessageBuilder message;
Expand All @@ -35,25 +35,25 @@ KJ_TEST("Tags work") {

{
// The key can be a uint32_t
trace::Tag tag(1U, 2.0);
trace::Tag tag((uint32_t)1, 2.0);
auto key = KJ_ASSERT_NONNULL(tag.key.tryGet<uint32_t>());
KJ_EXPECT(key == 1U);
KJ_EXPECT(tag.keyMatches(1U));
KJ_EXPECT(key == (uint32_t)1);
KJ_EXPECT(tag.keyMatches((uint32_t)1));
}
}

KJ_TEST("Onset works") {
auto tags = kj::arr(trace::Tag(kj::str("a"), 1UL));
trace::Onset onset(1U, kj::str("foo"), kj::str("bar"), kj::none, kj::str("baz"), kj::str("qux"),
kj::arr(kj::str("quux")), kj::str("corge"), kj::mv(tags));
auto tags = kj::arr(trace::Tag(kj::str("a"), (uint64_t)1));
trace::Onset onset((uint32_t)1, kj::str("foo"), kj::str("bar"), kj::none, kj::str("baz"),
kj::str("qux"), kj::arr(kj::str("quux")), kj::str("corge"), kj::mv(tags));

capnp::MallocMessageBuilder message;
auto builder = message.initRoot<rpc::Trace::Onset>();
onset.copyTo(builder);

auto reader = builder.asReader();
trace::Onset onset2(reader);
KJ_EXPECT(onset.accountId == 1U);
KJ_EXPECT(onset.accountId == (uint32_t)1);
KJ_EXPECT(KJ_ASSERT_NONNULL(onset.stableId) == "foo"_kj);
KJ_EXPECT(KJ_ASSERT_NONNULL(onset.scriptName) == "bar"_kj);
KJ_EXPECT(KJ_ASSERT_NONNULL(onset.dispatchNamespace) == "baz"_kj);
Expand All @@ -79,7 +79,7 @@ KJ_TEST("Onset works") {
KJ_EXPECT(encoded == check);

auto onset3 = onset.clone();
KJ_EXPECT(onset3.accountId == 1U);
KJ_EXPECT(onset3.accountId == (uint32_t)1);
KJ_EXPECT(KJ_ASSERT_NONNULL(onset3.stableId) == "foo"_kj);
KJ_EXPECT(KJ_ASSERT_NONNULL(onset3.scriptName) == "bar"_kj);
KJ_EXPECT(KJ_ASSERT_NONNULL(onset3.dispatchNamespace) == "baz"_kj);
Expand Down Expand Up @@ -122,7 +122,7 @@ KJ_TEST("FetchEventInfo works") {
}

KJ_TEST("ActorFlushInfo works") {
auto tags = kj::arr(trace::Tag(trace::ActorFlushInfo::CommonTags::REASON, 1UL),
auto tags = kj::arr(trace::Tag(trace::ActorFlushInfo::CommonTags::REASON, (uint64_t)1),
trace::Tag(trace::ActorFlushInfo::CommonTags::BROKEN, true));
trace::ActorFlushInfo info(kj::mv(tags));

Expand Down Expand Up @@ -216,9 +216,9 @@ KJ_TEST("AlarmEventInfo works") {
}

KJ_TEST("QueueEventInfo works") {
trace::QueueEventInfo info(kj::str("foo"), 1U);
trace::QueueEventInfo info(kj::str("foo"), (uint32_t)1);
KJ_EXPECT(info.queueName == "foo"_kj);
KJ_EXPECT(info.batchSize == 1U);
KJ_EXPECT(info.batchSize == (uint32_t)1);

capnp::MallocMessageBuilder message;
auto builder = message.initRoot<rpc::Trace::QueueEventInfo>();
Expand All @@ -227,18 +227,18 @@ KJ_TEST("QueueEventInfo works") {
auto reader = builder.asReader();
trace::QueueEventInfo info2(reader);
KJ_EXPECT(info2.queueName == "foo"_kj);
KJ_EXPECT(info2.batchSize == 1U);
KJ_EXPECT(info2.batchSize == (uint32_t)1);

auto info3 = info.clone();
KJ_EXPECT(info3.queueName == "foo"_kj);
KJ_EXPECT(info3.batchSize == 1U);
KJ_EXPECT(info3.batchSize == (uint32_t)1);
}

KJ_TEST("EmailEventInfo works") {
trace::EmailEventInfo info(kj::str("foo"), kj::str("bar"), 1U);
trace::EmailEventInfo info(kj::str("foo"), kj::str("bar"), (uint32_t)1);
KJ_EXPECT(info.mailFrom == "foo"_kj);
KJ_EXPECT(info.rcptTo == "bar"_kj);
KJ_EXPECT(info.rawSize == 1U);
KJ_EXPECT(info.rawSize == (uint32_t)1);

capnp::MallocMessageBuilder message;
auto builder = message.initRoot<rpc::Trace::EmailEventInfo>();
Expand All @@ -248,12 +248,12 @@ KJ_TEST("EmailEventInfo works") {
trace::EmailEventInfo info2(reader);
KJ_EXPECT(info2.mailFrom == "foo"_kj);
KJ_EXPECT(info2.rcptTo == "bar"_kj);
KJ_EXPECT(info2.rawSize == 1U);
KJ_EXPECT(info2.rawSize == (uint32_t)1);

auto info3 = info.clone();
KJ_EXPECT(info3.mailFrom == "foo"_kj);
KJ_EXPECT(info3.rcptTo == "bar"_kj);
KJ_EXPECT(info3.rawSize == 1U);
KJ_EXPECT(info3.rawSize == (uint32_t)1);
}

KJ_TEST("HibernatableWebSocketEventInfo works") {
Expand Down Expand Up @@ -292,10 +292,8 @@ KJ_TEST("TraceEventInfo works") {
}

KJ_TEST("Outcome works") {
trace::Outcome outcome(EventOutcome::OK, 1 * kj::MILLISECONDS, 2 * kj::MILLISECONDS);
trace::Outcome outcome(EventOutcome::OK);
KJ_EXPECT(outcome.outcome == EventOutcome::OK);
KJ_EXPECT(outcome.cpuTime == 1 * kj::MILLISECONDS);
KJ_EXPECT(outcome.wallTime == 2 * kj::MILLISECONDS);

capnp::MallocMessageBuilder message;
auto builder = message.initRoot<rpc::Trace::Outcome>();
Expand All @@ -304,13 +302,9 @@ KJ_TEST("Outcome works") {
auto reader = builder.asReader();
trace::Outcome outcome2(reader);
KJ_EXPECT(outcome2.outcome == EventOutcome::OK);
KJ_EXPECT(outcome2.cpuTime == 1 * kj::MILLISECONDS);
KJ_EXPECT(outcome2.wallTime == 2 * kj::MILLISECONDS);

auto outcome3 = outcome.clone();
KJ_EXPECT(outcome3.outcome == EventOutcome::OK);
KJ_EXPECT(outcome3.cpuTime == 1 * kj::MILLISECONDS);
KJ_EXPECT(outcome3.wallTime == 2 * kj::MILLISECONDS);
}

KJ_TEST("DiagnosticChannelEvent works") {
Expand Down Expand Up @@ -359,12 +353,13 @@ KJ_TEST("Log works") {
KJ_EXPECT(log3.message == "foo"_kj);
}

KJ_TEST("LogV2 workers") {
KJ_TEST("LogV2 works") {
kj::Date date = 0 * kj::MILLISECONDS + kj::UNIX_EPOCH;
trace::LogV2 log(date, LogLevel::INFO, kj::heapArray<kj::byte>(1));
KJ_EXPECT(log.timestamp == date);
KJ_EXPECT(log.logLevel == LogLevel::INFO);
KJ_EXPECT(log.data.size() == 1);
KJ_EXPECT(KJ_ASSERT_NONNULL(log.message.tryGet<kj::Array<kj::byte>>()).size() == 1);
KJ_EXPECT(!log.truncated);

capnp::MallocMessageBuilder message;
auto builder = message.initRoot<rpc::Trace::LogV2>();
Expand All @@ -374,12 +369,14 @@ KJ_TEST("LogV2 workers") {
trace::LogV2 log2(reader);
KJ_EXPECT(log2.timestamp == date);
KJ_EXPECT(log2.logLevel == LogLevel::INFO);
KJ_EXPECT(log2.data.size() == 1);
KJ_EXPECT(KJ_ASSERT_NONNULL(log2.message.tryGet<kj::Array<kj::byte>>()).size() == 1);
KJ_EXPECT(!log2.truncated);

auto log3 = log.clone();
KJ_EXPECT(log3.timestamp == date);
KJ_EXPECT(log3.logLevel == LogLevel::INFO);
KJ_EXPECT(log3.data.size() == 1);
KJ_EXPECT(KJ_ASSERT_NONNULL(log3.message.tryGet<kj::Array<kj::byte>>()).size() == 1);
KJ_EXPECT(!log3.truncated);
}

KJ_TEST("Exception works") {
Expand Down Expand Up @@ -409,10 +406,10 @@ KJ_TEST("Exception works") {
}

KJ_TEST("Subrequest works") {
trace::Subrequest subrequest(1U,
trace::Subrequest subrequest((uint32_t)1,
trace::Subrequest::Info(trace::FetchEventInfo(
kj::HttpMethod::GET, kj::str("http://example.org"), kj::String(), nullptr)));
KJ_EXPECT(subrequest.id == 1U);
KJ_EXPECT(subrequest.id == (uint32_t)1);
KJ_EXPECT(KJ_ASSERT_NONNULL(subrequest.info).is<trace::FetchEventInfo>());

capnp::MallocMessageBuilder message;
Expand All @@ -421,38 +418,38 @@ KJ_TEST("Subrequest works") {

auto reader = builder.asReader();
trace::Subrequest subrequest2(reader);
KJ_EXPECT(subrequest2.id == 1U);
KJ_EXPECT(subrequest2.id == (uint32_t)1);
KJ_EXPECT(KJ_ASSERT_NONNULL(subrequest.info).is<trace::FetchEventInfo>());

auto subrequest3 = subrequest.clone();
KJ_EXPECT(subrequest3.id == 1U);
KJ_EXPECT(subrequest3.id == (uint32_t)1);
KJ_EXPECT(KJ_ASSERT_NONNULL(subrequest.info).is<trace::FetchEventInfo>());
}

KJ_TEST("SubrequestOutcome works") {
trace::SubrequestOutcome outcome(1U, kj::none, trace::SpanEvent::Outcome::OK);
KJ_EXPECT(outcome.id == 1U);
KJ_EXPECT(outcome.outcome == trace::SpanEvent::Outcome::OK);
trace::SubrequestOutcome outcome((uint32_t)1, kj::none, trace::Span::Outcome::OK);
KJ_EXPECT(outcome.id == (uint32_t)1);
KJ_EXPECT(outcome.outcome == trace::Span::Outcome::OK);

capnp::MallocMessageBuilder message;
auto builder = message.initRoot<rpc::Trace::SubrequestOutcome>();
outcome.copyTo(builder);

auto reader = builder.asReader();
trace::SubrequestOutcome outcome2(reader);
KJ_EXPECT(outcome2.id == 1U);
KJ_EXPECT(outcome2.outcome == trace::SpanEvent::Outcome::OK);
KJ_EXPECT(outcome2.id == (uint32_t)1);
KJ_EXPECT(outcome2.outcome == trace::Span::Outcome::OK);

auto outcome3 = outcome.clone();
KJ_EXPECT(outcome3.id == 1U);
KJ_EXPECT(outcome3.outcome == trace::SpanEvent::Outcome::OK);
KJ_EXPECT(outcome3.id == (uint32_t)1);
KJ_EXPECT(outcome3.outcome == trace::Span::Outcome::OK);
}

KJ_TEST("SpanEvent works") {
trace::SpanEvent event(1U, 0U, trace::SpanEvent::Outcome::OK, false, kj::none, nullptr);
KJ_EXPECT(event.id == 1U);
KJ_EXPECT(event.parent == 0U);
KJ_EXPECT(event.outcome == trace::SpanEvent::Outcome::OK);
KJ_TEST("Span works") {
trace::Span event((uint32_t)1, (uint32_t)0, trace::Span::Outcome::OK, false, kj::none, nullptr);
KJ_EXPECT(event.id == (uint32_t)1);
KJ_EXPECT(event.parent == (uint32_t)0);
KJ_EXPECT(event.outcome == trace::Span::Outcome::OK);
KJ_EXPECT(event.transactional == false);
KJ_EXPECT(event.info == kj::none);
KJ_EXPECT(event.tags.size() == 0);
Expand All @@ -462,18 +459,18 @@ KJ_TEST("SpanEvent works") {
event.copyTo(builder);

auto reader = builder.asReader();
trace::SpanEvent event2(reader);
KJ_EXPECT(event2.id == 1U);
KJ_EXPECT(event2.parent == 0U);
KJ_EXPECT(event2.outcome == trace::SpanEvent::Outcome::OK);
trace::Span event2(reader);
KJ_EXPECT(event2.id == (uint32_t)1);
KJ_EXPECT(event2.parent == (uint32_t)0);
KJ_EXPECT(event2.outcome == trace::Span::Outcome::OK);
KJ_EXPECT(event2.transactional == false);
KJ_EXPECT(event2.info == kj::none);
KJ_EXPECT(event2.tags.size() == 0);

auto event3 = event.clone();
KJ_EXPECT(event3.id == 1U);
KJ_EXPECT(event3.parent == 0U);
KJ_EXPECT(event3.outcome == trace::SpanEvent::Outcome::OK);
KJ_EXPECT(event3.id == (uint32_t)1);
KJ_EXPECT(event3.parent == (uint32_t)0);
KJ_EXPECT(event3.outcome == trace::Span::Outcome::OK);
KJ_EXPECT(event3.transactional == false);
KJ_EXPECT(event3.info == kj::none);
KJ_EXPECT(event3.tags.size() == 0);
Expand Down Expand Up @@ -522,22 +519,22 @@ KJ_TEST("Metric works") {
}

KJ_TEST("Dropped works") {
trace::Dropped dropped(1U, 2U);
KJ_EXPECT(dropped.start == 1U);
KJ_EXPECT(dropped.end == 2U);
trace::Dropped dropped((uint32_t)1, (uint32_t)2);
KJ_EXPECT(dropped.start == (uint32_t)1);
KJ_EXPECT(dropped.end == (uint32_t)2);

capnp::MallocMessageBuilder message;
auto builder = message.initRoot<rpc::Trace::Dropped>();
dropped.copyTo(builder);

auto reader = builder.asReader();
trace::Dropped dropped2(reader);
KJ_EXPECT(dropped2.start == 1U);
KJ_EXPECT(dropped2.end == 2U);
KJ_EXPECT(dropped2.start == (uint32_t)1);
KJ_EXPECT(dropped2.end == (uint32_t)2);

auto dropped3 = dropped.clone();
KJ_EXPECT(dropped3.start == 1U);
KJ_EXPECT(dropped3.end == 2U);
KJ_EXPECT(dropped3.start == (uint32_t)1);
KJ_EXPECT(dropped3.end == (uint32_t)2);
}

} // namespace
Expand Down
Loading

0 comments on commit 2dcbac7

Please sign in to comment.