caddyserver
Add `spanID` field to access logs and `http.vars.span_id` placeholder when tracing is enabled
In PR #5507, the traceid was added to the logs. To further align with the OpenTelemetry Log Correlation specification and achieve complete log correlation using trace context, we have now included the spanid alongside the traceid.
Benchmark Comparison
I conducted benchmarks to assess the performance impact of adding the spanid. Since traceid and spanid are always used together, I modified the existing benchmarks for traceid to include spanid. Below is the performance comparison before and after adding the spanid:
Before:
$ go test -benchtime=3s -count=10 -benchmem -run=^$ -bench ^BenchmarkServer ./modules/caddyhttp | tee before.txt
goos: linux
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: AMD EPYC 9754 128-Core Processor
BenchmarkServer_LogRequest-64 3140806 1174 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3026678 1161 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3103068 1156 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3121268 1152 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3098882 1163 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3171706 1147 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3098536 1128 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3198552 1143 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3118201 1159 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3211209 1151 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 27751924 127.9 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28101333 125.2 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28519773 124.9 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 27652406 126.6 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28332801 124.6 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28507286 125.0 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28651822 126.3 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28575466 130.1 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28702560 128.1 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28392454 125.5 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2870023 1248 ns/op 484 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2934045 1239 ns/op 484 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2897414 1240 ns/op 484 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2886142 1240 ns/op 484 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2973252 1241 ns/op 484 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2958910 1214 ns/op 484 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2922925 1219 ns/op 484 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2962358 1230 ns/op 484 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2883412 1225 ns/op 484 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 3014709 1151 ns/op 484 B/op 4 allocs/op
PASS
ok github.com/caddyserver/caddy/v2/modules/caddyhttp 133.403s
After:
$ go test -benchtime=3s -count=10 -benchmem -run=^$ -bench ^BenchmarkServer ./modules/caddyhttp | tee after.txt
goos: linux
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: AMD EPYC 9754 128-Core Processor
BenchmarkServer_LogRequest-64 3152115 1158 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3094155 1143 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3174631 1132 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3161185 1133 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3190516 1136 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3090571 1154 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3119666 1153 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3145326 1144 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3134314 1135 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest-64 3138734 1136 ns/op 419 B/op 4 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28379570 133.5 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28388329 134.3 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28012402 124.0 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28187100 126.3 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28356514 125.5 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 26432298 125.4 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 27307333 124.9 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 27985292 133.6 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28657483 132.7 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_NopLogger-64 28491796 124.5 ns/op 8 B/op 1 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2783799 1273 ns/op 548 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2767974 1324 ns/op 548 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2786803 1295 ns/op 548 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2805546 1269 ns/op 548 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2816472 1287 ns/op 548 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2801752 1299 ns/op 548 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2732166 1316 ns/op 548 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2740275 1316 ns/op 548 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2766216 1293 ns/op 548 B/op 4 allocs/op
BenchmarkServer_LogRequest_WithTrace-64 2706841 1348 ns/op 548 B/op 4 allocs/op
PASS
ok github.com/caddyserver/caddy/v2/modules/caddyhttp 134.236s
Diff:
$ benchstat before.txt after.txt
goos: linux
goarch: amd64
pkg: github.com/caddyserver/caddy/v2/modules/caddyhttp
cpu: AMD EPYC 9754 128-Core Processor
│ before.txt │ after.txt │
│ sec/op │ sec/op vs base │
Server_LogRequest-64 1.154µ ± 1% 1.140µ ± 1% ~ (p=0.055 n=10)
Server_LogRequest_NopLogger-64 125.9n ± 2% 125.9n ± 6% ~ (p=0.698 n=10)
Server_LogRequest_WithTrace-64 1.235µ ± 2% 1.297µ ± 2% +5.06% (p=0.000 n=10)
geomean 564.0n 570.9n +1.23%
│ before.txt │ after.txt │
│ B/op │ B/op vs base │
Server_LogRequest-64 419.0 ± 0% 419.0 ± 0% ~ (p=1.000 n=10) ¹
Server_LogRequest_NopLogger-64 8.000 ± 0% 8.000 ± 0% ~ (p=1.000 n=10) ¹
Server_LogRequest_WithTrace-64 484.0 ± 0% 548.0 ± 0% +13.22% (p=0.000 n=10)
geomean 117.5 122.5 +4.23%
¹ all samples are equal
│ before.txt │ after.txt │
│ allocs/op │ allocs/op vs base │
Server_LogRequest-64 4.000 ± 0% 4.000 ± 0% ~ (p=1.000 n=10) ¹
Server_LogRequest_NopLogger-64 1.000 ± 0% 1.000 ± 0% ~ (p=1.000 n=10) ¹
Server_LogRequest_WithTrace-64 4.000 ± 0% 4.000 ± 0% ~ (p=1.000 n=10) ¹
geomean 2.520 2.520 +0.00%
¹ all samples are equal
The addition of spanid to the logs led to a slight increase (~5%) in processing time. Memory usage increased in ~13%, as expected.
I also added the http.vars.span_id placeholder, similar to what was done in PR #6308 for the http.vars.trace_id placeholder.
Thanks for the PR!
Just so I'm clear on this, the performance is only impacted if metrics are enabled, right?
Thanks for the PR!
Just so I'm clear on this, the performance is only impacted if metrics are enabled, right?
That's correct. The performance impact occurs only when tracing is enabled, as both traceid and spanid are added to the logs only in that scenario.
However, it seemed that my previous benchmarks showed some impact even when tracing wasn't enabled. I reran the benchmarks several times, and the new results confirm that the performance is affected only when spanid is being added. The slight (~3%) increase in runtime observed earlier was likely just measurement noise.
I've also updated the previous benchmark results.
Just so I'm clear on this, the performance is only impacted if metrics are enabled, right?
yes if you mean s/metrics/tracing/ - this is (or, should be) orthogonal to metrics
No docs for that... I want to use custom tags, any idea how i can send via caddy custom tags to the tracing?
For example i am using this:
route {
@traceable {
not path /build/* /images/* /favicon-32x32.png
}
handle @traceable {
tracing {
span "[{http.request.method}] {http.request.uri.path}"
##here i want add custom tags for sending to the tracing tool jaeger
}
}
push
php_fastcgi php:9000
encode zstd gzip
file_server
}
```
I want add tags(); for the tracing any idea how i can do it?
All this does is add the span ID to the logs automatically, when tracing is enabled. That's it. There's not really anything to document.
Tagging is a totally different topic, it's not currently a supported feature.
