Skip to content

Commit b6452a3

Browse files
fhanaufhanau
committed
[o11y] Report SpanOpen event earlier
1 parent ddd10b0 commit b6452a3

File tree

10 files changed

+145
-89
lines changed

10 files changed

+145
-89
lines changed

‎src/cloudflare/internal/test/d1/d1-api-instrumentation-test.js‎

Lines changed: 31 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -31,18 +31,6 @@ export const test = {
3131
};
3232

3333
const expectedSpans = [
34-
{
35-
name: 'fetch',
36-
'network.protocol.name': 'http',
37-
'network.protocol.version': 'HTTP/1.1',
38-
'http.request.method': 'POST',
39-
'url.full': 'http://d1/execute?resultsFormat=NONE',
40-
'http.request.header.content-type': 'application/json',
41-
'http.request.body.size': 231n,
42-
'http.response.status_code': 200n,
43-
'http.response.body.size': 0n,
44-
closed: true,
45-
},
4634
{
4735
name: 'd1_run',
4836
'db.system.name': 'cloudflare-d1',
@@ -70,9 +58,9 @@ const expectedSpans = [
7058
'network.protocol.name': 'http',
7159
'network.protocol.version': 'HTTP/1.1',
7260
'http.request.method': 'POST',
73-
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
61+
'url.full': 'http://d1/execute?resultsFormat=NONE',
7462
'http.request.header.content-type': 'application/json',
75-
'http.request.body.size': 42n,
63+
'http.request.body.size': 231n,
7664
'http.response.status_code': 200n,
7765
'http.response.body.size': 0n,
7866
closed: true,
@@ -96,7 +84,7 @@ const expectedSpans = [
9684
'network.protocol.name': 'http',
9785
'network.protocol.version': 'HTTP/1.1',
9886
'http.request.method': 'POST',
99-
'url.full': 'http://d1/execute?resultsFormat=NONE',
87+
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
10088
'http.request.header.content-type': 'application/json',
10189
'http.request.body.size': 42n,
10290
'http.response.status_code': 200n,
@@ -124,7 +112,7 @@ const expectedSpans = [
124112
'http.request.method': 'POST',
125113
'url.full': 'http://d1/execute?resultsFormat=NONE',
126114
'http.request.header.content-type': 'application/json',
127-
'http.request.body.size': 40n,
115+
'http.request.body.size': 42n,
128116
'http.response.status_code': 200n,
129117
'http.response.body.size': 0n,
130118
closed: true,
@@ -148,9 +136,9 @@ const expectedSpans = [
148136
'network.protocol.name': 'http',
149137
'network.protocol.version': 'HTTP/1.1',
150138
'http.request.method': 'POST',
151-
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
139+
'url.full': 'http://d1/execute?resultsFormat=NONE',
152140
'http.request.header.content-type': 'application/json',
153-
'http.request.body.size': 223n,
141+
'http.request.body.size': 40n,
154142
'http.response.status_code': 200n,
155143
'http.response.body.size': 0n,
156144
closed: true,
@@ -180,9 +168,9 @@ const expectedSpans = [
180168
'network.protocol.name': 'http',
181169
'network.protocol.version': 'HTTP/1.1',
182170
'http.request.method': 'POST',
183-
'url.full': 'http://d1/execute?resultsFormat=NONE',
171+
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
184172
'http.request.header.content-type': 'application/json',
185-
'http.request.body.size': 40n,
173+
'http.request.body.size': 223n,
186174
'http.response.status_code': 200n,
187175
'http.response.body.size': 0n,
188176
closed: true,
@@ -208,7 +196,7 @@ const expectedSpans = [
208196
'http.request.method': 'POST',
209197
'url.full': 'http://d1/execute?resultsFormat=NONE',
210198
'http.request.header.content-type': 'application/json',
211-
'http.request.body.size': 223n,
199+
'http.request.body.size': 40n,
212200
'http.response.status_code': 200n,
213201
'http.response.body.size': 0n,
214202
closed: true,
@@ -238,9 +226,9 @@ const expectedSpans = [
238226
'network.protocol.name': 'http',
239227
'network.protocol.version': 'HTTP/1.1',
240228
'http.request.method': 'POST',
241-
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
229+
'url.full': 'http://d1/execute?resultsFormat=NONE',
242230
'http.request.header.content-type': 'application/json',
243-
'http.request.body.size': 31n,
231+
'http.request.body.size': 223n,
244232
'http.response.status_code': 200n,
245233
'http.response.body.size': 0n,
246234
closed: true,
@@ -344,7 +332,7 @@ const expectedSpans = [
344332
'http.request.method': 'POST',
345333
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
346334
'http.request.header.content-type': 'application/json',
347-
'http.request.body.size': 42n,
335+
'http.request.body.size': 31n,
348336
'http.response.status_code': 200n,
349337
'http.response.body.size': 0n,
350338
closed: true,
@@ -448,7 +436,7 @@ const expectedSpans = [
448436
'http.request.method': 'POST',
449437
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
450438
'http.request.header.content-type': 'application/json',
451-
'http.request.body.size': 61n,
439+
'http.request.body.size': 42n,
452440
'http.response.status_code': 200n,
453441
'http.response.body.size': 0n,
454442
closed: true,
@@ -656,7 +644,7 @@ const expectedSpans = [
656644
'http.request.method': 'POST',
657645
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
658646
'http.request.header.content-type': 'application/json',
659-
'http.request.body.size': 125n,
647+
'http.request.body.size': 61n,
660648
'http.response.status_code': 200n,
661649
'http.response.body.size': 0n,
662650
closed: true,
@@ -685,7 +673,7 @@ const expectedSpans = [
685673
'http.request.method': 'POST',
686674
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
687675
'http.request.header.content-type': 'application/json',
688-
'http.request.body.size': 79n,
676+
'http.request.body.size': 125n,
689677
'http.response.status_code': 200n,
690678
'http.response.body.size': 0n,
691679
closed: true,
@@ -815,7 +803,7 @@ const expectedSpans = [
815803
'http.request.method': 'POST',
816804
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
817805
'http.request.header.content-type': 'application/json',
818-
'http.request.body.size': 298n,
806+
'http.request.body.size': 79n,
819807
'http.response.status_code': 200n,
820808
'http.response.body.size': 0n,
821809
closed: true,
@@ -846,7 +834,7 @@ const expectedSpans = [
846834
'http.request.method': 'POST',
847835
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
848836
'http.request.header.content-type': 'application/json',
849-
'http.request.body.size': 45n,
837+
'http.request.body.size': 298n,
850838
'http.response.status_code': 200n,
851839
'http.response.body.size': 0n,
852840
closed: true,
@@ -950,7 +938,7 @@ const expectedSpans = [
950938
'http.request.method': 'POST',
951939
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
952940
'http.request.header.content-type': 'application/json',
953-
'http.request.body.size': 76n,
941+
'http.request.body.size': 45n,
954942
'http.response.status_code': 200n,
955943
'http.response.body.size': 0n,
956944
closed: true,
@@ -976,7 +964,7 @@ const expectedSpans = [
976964
'http.request.method': 'POST',
977965
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
978966
'http.request.header.content-type': 'application/json',
979-
'http.request.body.size': 117n,
967+
'http.request.body.size': 76n,
980968
'http.response.status_code': 200n,
981969
'http.response.body.size': 0n,
982970
closed: true,
@@ -996,4 +984,16 @@ const expectedSpans = [
996984
'cloudflare.d1.response.changes': 0,
997985
closed: true,
998986
},
987+
{
988+
name: 'fetch',
989+
'network.protocol.name': 'http',
990+
'network.protocol.version': 'HTTP/1.1',
991+
'http.request.method': 'POST',
992+
'url.full': 'http://d1/query?resultsFormat=ROWS_AND_COLUMNS',
993+
'http.request.header.content-type': 'application/json',
994+
'http.request.body.size': 117n,
995+
'http.response.status_code': 200n,
996+
'http.response.body.size': 0n,
997+
closed: true,
998+
},
999999
];

‎src/workerd/api/actor-kv-test-tail.js‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,7 @@ export default testTailHandler;
1111
export const test = {
1212
async test(ctrl, env, ctx) {
1313
const expected = [
14+
{ name: 'durable_object_subrequest', closed: true },
1415
{ name: 'durable_object_storage_put', closed: true },
1516
{ name: 'durable_object_storage_put', closed: true },
1617
{ name: 'durable_object_storage_get', closed: true },
@@ -23,7 +24,6 @@ export const test = {
2324
{ name: 'durable_object_storage_deleteAlarm', closed: true },
2425
{ name: 'durable_object_storage_transaction', closed: true },
2526
{ name: 'durable_object_storage_sync', closed: true },
26-
{ name: 'durable_object_subrequest', closed: true },
2727
];
2828

2929
await Promise.allSettled(invocationPromises);

‎src/workerd/api/r2-instrumentation-test.js‎

Lines changed: 13 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -192,12 +192,19 @@ export const test = {
192192
closed: true,
193193
},
194194
{
195-
name: 'r2_put',
195+
name: 'r2_get',
196196
'cloudflare.binding.type': 'r2',
197197
'cloudflare.binding.name': 'BUCKET',
198-
'cloudflare.r2.operation': 'PutObject',
198+
'cloudflare.r2.operation': 'GetObject',
199199
'cloudflare.r2.bucket': 'r2-test',
200-
'cloudflare.r2.request.key': 'throwOnInvalidEtag',
200+
'cloudflare.r2.request.key': 'rangeSuff',
201+
'cloudflare.r2.request.range.suffix': 2n,
202+
'cloudflare.r2.response.success': true,
203+
'cloudflare.r2.response.etag': 'objectEtag',
204+
'cloudflare.r2.response.size': 123,
205+
'cloudflare.r2.response.uploaded': '2024-08-27T14:00:57.918Z',
206+
'cloudflare.r2.response.storage_class': 'Standard',
207+
'cloudflare.r2.response.custom_metadata': true,
201208
closed: true,
202209
},
203210
{
@@ -210,19 +217,12 @@ export const test = {
210217
closed: true,
211218
},
212219
{
213-
name: 'r2_get',
220+
name: 'r2_put',
214221
'cloudflare.binding.type': 'r2',
215222
'cloudflare.binding.name': 'BUCKET',
216-
'cloudflare.r2.operation': 'GetObject',
223+
'cloudflare.r2.operation': 'PutObject',
217224
'cloudflare.r2.bucket': 'r2-test',
218-
'cloudflare.r2.request.key': 'rangeSuff',
219-
'cloudflare.r2.request.range.suffix': 2n,
220-
'cloudflare.r2.response.success': true,
221-
'cloudflare.r2.response.etag': 'objectEtag',
222-
'cloudflare.r2.response.size': 123,
223-
'cloudflare.r2.response.uploaded': '2024-08-27T14:00:57.918Z',
224-
'cloudflare.r2.response.storage_class': 'Standard',
225-
'cloudflare.r2.response.custom_metadata': true,
225+
'cloudflare.r2.request.key': 'throwOnInvalidEtag',
226226
closed: true,
227227
},
228228
{

‎src/workerd/api/tail-worker-test.js‎

Lines changed: 1 addition & 1 deletion
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

‎src/workerd/io/trace.c++‎

Lines changed: 15 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -1469,7 +1469,10 @@ SpanBuilder::SpanBuilder(kj::Maybe<kj::Own<SpanObserver>> observer,
14691469
KJ_IF_SOME(obs, observer) {
14701470
// TODO(o11y): Once we report the user tracing spanOpen event as soon as a span is created, we
14711471
// should be able to fold this virtual call and just get the timestamp directly.
1472-
span.emplace(kj::mv(operationName), startTime.orDefault(obs->getTime()));
1472+
kj::Date time = startTime.orDefault([&]() { return obs->getTime(); });
1473+
// Report spanOpen event for user tracing spans
1474+
obs->reportStart(operationName, time);
1475+
span.emplace(kj::mv(operationName), time);
14731476
this->observer = kj::mv(obs);
14741477
}
14751478
}
@@ -1612,7 +1615,6 @@ void CompleteSpan::copyTo(rpc::UserSpanData::Builder builder) const {
16121615
builder.setStartTimeNs((startTime - kj::UNIX_EPOCH) / kj::NANOSECONDS);
16131616
builder.setEndTimeNs((endTime - kj::UNIX_EPOCH) / kj::NANOSECONDS);
16141617
builder.setSpanId(spanId);
1615-
builder.setParentSpanId(parentSpanId);
16161618

16171619
auto tagsParam = builder.initTags(tags.size());
16181620
auto i = 0;
@@ -1622,10 +1624,15 @@ void CompleteSpan::copyTo(rpc::UserSpanData::Builder builder) const {
16221624
serializeTagValue(tagParam.initValue(), tag.value);
16231625
}
16241626
}
1627+
void SpanOpenData::copyTo(rpc::SpanOpenData::Builder builder) const {
1628+
builder.setOperationName(operationName.asPtr());
1629+
builder.setStartTimeNs((startTime - kj::UNIX_EPOCH) / kj::NANOSECONDS);
1630+
builder.setSpanId(spanId);
1631+
builder.setParentSpanId(parentSpanId);
1632+
}
16251633

16261634
CompleteSpan::CompleteSpan(rpc::UserSpanData::Reader reader)
16271635
: spanId(reader.getSpanId()),
1628-
parentSpanId(reader.getParentSpanId()),
16291636
operationName(kj::str(reader.getOperationName())),
16301637
startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS),
16311638
endTime(kj::UNIX_EPOCH + reader.getEndTimeNs() * kj::NANOSECONDS) {
@@ -1636,22 +1643,11 @@ CompleteSpan::CompleteSpan(rpc::UserSpanData::Reader reader)
16361643
deserializeTagValue(tagParam.getValue()));
16371644
}
16381645
}
1639-
1640-
CompleteSpan CompleteSpan::clone() const {
1641-
CompleteSpan copy(
1642-
spanId, parentSpanId, kj::ConstString(kj::str(operationName)), startTime, endTime);
1643-
copy.tags.reserve(tags.size());
1644-
for (auto& tag: tags) {
1645-
copy.tags.insert(kj::ConstString(kj::str(tag.key)), spanTagClone(tag.value));
1646-
}
1647-
return copy;
1648-
}
1649-
1650-
kj::String CompleteSpan::toString() const {
1651-
return kj::str("CompleteSpan: ", operationName,
1652-
kj::strArray(
1653-
KJ_MAP(tag, tags) { return kj::str("(", tag.key, ", ", tag.value, ")"); }, ", "));
1654-
}
1646+
SpanOpenData::SpanOpenData(rpc::SpanOpenData::Reader reader)
1647+
: spanId(reader.getSpanId()),
1648+
parentSpanId(reader.getParentSpanId()),
1649+
operationName(kj::str(reader.getOperationName())),
1650+
startTime(kj::UNIX_EPOCH + reader.getStartTimeNs() * kj::NANOSECONDS) {}
16551651

16561652
ScopedDurationTagger::ScopedDurationTagger(
16571653
SpanBuilder& span, kj::ConstString key, const kj::MonotonicClock& timer)

‎src/workerd/io/trace.capnp‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -42,3 +42,14 @@ struct UserSpanData {
4242
parentSpanId @5 :UInt64;
4343
}
4444

45+
struct SpanOpenData {
46+
# Representation of a SpanOpen event
47+
operationName @0 :Text;
48+
49+
startTimeNs @1 :Int64;
50+
# Nanoseconds since Unix epoch
51+
52+
spanId @2 :UInt64;
53+
parentSpanId @3 :UInt64;
54+
}
55+

‎src/workerd/io/trace.h‎

Lines changed: 24 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -611,8 +611,10 @@ kj::String KJ_STRINGIFY(const CustomInfo& customInfo);
611611
struct CompleteSpan {
612612
// Represents a completed span within user tracing.
613613
tracing::SpanId spanId;
614-
tracing::SpanId parentSpanId;
615614

615+
// TODO(cleanup): operationName and startTime are not used in the spanClose event, but still used
616+
// for diagnostics and a fallback timestamp in the implementation. Get rid of them once that is no
617+
// longer needed.
616618
kj::ConstString operationName;
617619
kj::Date startTime;
618620
kj::Date endTime;
@@ -621,21 +623,37 @@ struct CompleteSpan {
621623

622624
CompleteSpan(rpc::UserSpanData::Reader reader);
623625
void copyTo(rpc::UserSpanData::Builder builder) const;
624-
CompleteSpan clone() const;
625626
explicit CompleteSpan(tracing::SpanId spanId,
626-
tracing::SpanId parentSpanId,
627627
kj::ConstString operationName,
628628
kj::Date startTime,
629629
kj::Date endTime,
630630
kj::HashMap<kj::ConstString, tracing::Attribute::Value> tags =
631631
kj::HashMap<kj::ConstString, tracing::Attribute::Value>())
632632
: spanId(spanId),
633-
parentSpanId(parentSpanId),
634633
operationName(kj::mv(operationName)),
635634
startTime(startTime),
636635
endTime(endTime),
637636
tags(kj::mv(tags)) {}
638-
kj::String toString() const;
637+
};
638+
639+
struct SpanOpenData {
640+
// Represents the data needed for a SpanOpen event
641+
tracing::SpanId spanId;
642+
tracing::SpanId parentSpanId;
643+
644+
kj::ConstString operationName;
645+
kj::Date startTime;
646+
647+
SpanOpenData(rpc::SpanOpenData::Reader reader);
648+
void copyTo(rpc::SpanOpenData::Builder builder) const;
649+
explicit SpanOpenData(tracing::SpanId spanId,
650+
tracing::SpanId parentSpanId,
651+
kj::ConstString operationName,
652+
kj::Date startTime)
653+
: spanId(spanId),
654+
parentSpanId(parentSpanId),
655+
operationName(kj::mv(operationName)),
656+
startTime(startTime) {}
639657
};
640658

641659
namespace tracing {
@@ -1099,6 +1117,7 @@ class SpanObserver: public kj::Refcounted {
10991117
//
11001118
// This should always be called exactly once per observer.
11011119
virtual void report(const Span& span) = 0;
1120+
virtual void reportStart(kj::ConstString& operationName, kj::Date startTime) = 0;
11021121

11031122
// The current time to be provided for the span. For user tracing, we will override this to
11041123
// provide I/O time. This *requires* that spans are only created when an IOContext is available

0 commit comments

Comments
 (0)