Skip to content

Direct log submission PoC#1846

Closed
andrewlock wants to merge 14 commits into
masterfrom
andrew/log-submission/serilog
Closed

Direct log submission PoC#1846
andrewlock wants to merge 14 commits into
masterfrom
andrew/log-submission/serilog

Conversation

@andrewlock

Copy link
Copy Markdown
Member

This PR adds support for directly shipping logs to the Datadog intake, so customers don't have to configure log tailing in the agent etc.

Each of the commits is pretty well self contained, so may be best to review sequentially. (The first commit is #1841 so feel free to skip that one)

Approach

This essentially takes the same approach as the official Datadog Serilog Sink. In various places I deviated from their approach however, as there were various opportunities for performance improvements (not serializing two JSON, then back to Dynamic, and back to JSON etc).

I partially vendored in the Serilog batching sink provider, removed the Serilog-isms, and created an abstraction around that. Similar to other components, we have a singleton DatadogSink, (which implements the vendored batching sink) and is responsible for formatting and sending batches of logs. The LogsApi type takes care of the transport (similar to the Api class for traces).

For serialization, I used a similar formatting to the CompactJsonFormatter, as that's supported in the logs documentation, serializing efficiently where possible. Without System.Text.Json's Utf8Writer, the best I could do to reduce memory impact was to reuse a stringbuilder, and have a persistent buffer for the UTF8 bytes.

We use automatic instrumentation to add the ILoggerProvider/SerilogSink as required, which then farms off the logs to the singleton Serilog Sink.

Current limitations

  • Currently only supports Serilog and ILogger. Wanted to get feedback before implementing the others, but I have PoCs so I think the overall design works
  • Currently only supports the HTTP transport. We could feasibly ship a PoC with that I think, but we may want to add TCP too. Shouldn't be too hard, just requires slightly different formatting etc.

Questions

  • The configuration key environment variable names are quite descriptive (i.e. long). Any preferences for alternative names?
  • There are various TODOs I'll add later

Evidence it works 🎉

image

@DataDog/apm-dotnet

@andrewlock

Copy link
Copy Markdown
Member Author

Benchmarks Report 🐌

Benchmarks for #1846 compared to master:

  • All benchmarks have the same speed
  • All benchmarks have the same allocations

The following thresholds were used for comparing the benchmark speeds:

  • Mann–Whitney U test with statistical test for significance of 5%
  • Only results indicating a difference greater than 10% and 0.3 ns are considered.

Allocation changes below 0.5% are ignored.

Benchmark details

Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net472 938.5 μs 17.55 μs 23.43 μs 0.0000 0.0000 0.0000 3.09 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 740.7 μs 14.72 μs 12.30 μs 0.0000 0.0000 0.0000 2.51 KB
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net472 0.0000 ns 0.0000 ns 0.0000 ns 0.0000 0.0000 0.0000 0 B
master SendRequest netcoreapp3.1 288,449.0783 ns 5,211.7733 ns 4,875.0960 ns 0.1457 0.0000 0.0000 18665 B
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net472 2.000 μs 0.0392 μs 0.0537 μs 0.1081 0.0010 0.0000 682 B
master ExecuteNonQuery netcoreapp3.1 1.945 μs 0.0367 μs 0.0306 μs 0.0097 0.0000 0.0000 712 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net472 2.984 μs 0.0417 μs 0.0349 μs 0.1280 0.0000 0.0000 827 B
master CallElasticsearch netcoreapp3.1 1.581 μs 0.0247 μs 0.0231 μs 0.0103 0.0000 0.0000 768 B
master CallElasticsearchAsync net472 3.231 μs 0.0525 μs 0.0465 μs 0.1503 0.0000 0.0000 963 B
master CallElasticsearchAsync netcoreapp3.1 1.690 μs 0.0320 μs 0.0299 μs 0.0120 0.0000 0.0000 888 B
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net472 3.301 μs 0.0580 μs 0.0569 μs 0.1694 0.0000 0.0000 1083 B
master ExecuteAsync netcoreapp3.1 1.985 μs 0.0394 μs 0.0422 μs 0.0145 0.0000 0.0000 1008 B
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendAsync net472 5.884 μs 0.1177 μs 0.1650 μs 0.3509 0.0000 0.0000 2.19 KB
master SendAsync netcoreapp3.1 4.366 μs 0.0842 μs 0.0787 μs 0.0291 0.0000 0.0000 2.09 KB
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 3.778 μs 0.0522 μs 0.0488 μs 0.2864 0.0000 0.0000 1.79 KB
master EnrichedLog netcoreapp3.1 4.284 μs 0.0596 μs 0.0558 μs 0.0273 0.0000 0.0000 2 KB
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 174.6 μs 2.73 μs 2.55 μs 1.2608 0.2702 0.0000 8.95 KB
master EnrichedLog netcoreapp3.1 150.8 μs 2.17 μs 2.03 μs 0.0755 0.0000 0.0000 9.82 KB
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 11.492 μs 0.2106 μs 0.1970 μs 0.8533 0.0000 0.0000 5.31 KB
master EnrichedLog netcoreapp3.1 9.856 μs 0.1759 μs 0.1559 μs 0.0910 0.0000 0.0000 6.28 KB
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net472 2.115 μs 0.0409 μs 0.0383 μs 0.1545 0.0000 0.0000 987 B
master SendReceive netcoreapp3.1 1.949 μs 0.0359 μs 0.0479 μs 0.0135 0.0000 0.0000 984 B
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 7.942 μs 0.1589 μs 0.1830 μs 0.4473 0.0000 0.0000 2.8 KB
master EnrichedLog netcoreapp3.1 7.030 μs 0.1249 μs 0.1168 μs 0.0360 0.0000 0.0000 2.61 KB
Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net472 885.1 ns 13.65 ns 12.10 ns 0.0682 0.0000 0.0000 433 B
master StartFinishSpan netcoreapp3.1 851.7 ns 16.06 ns 25.00 ns 0.0059 0.0000 0.0000 432 B
master StartFinishScope net472 1,058.6 ns 15.88 ns 14.85 ns 0.0807 0.0000 0.0000 514 B
master StartFinishScope netcoreapp3.1 1,021.8 ns 16.40 ns 15.34 ns 0.0073 0.0000 0.0000 552 B

@andrewlock

This comment has been minimized.

@andrewlock andrewlock force-pushed the andrew/log-submission/serilog branch 3 times, most recently from 3843418 to 5f11b3a Compare October 8, 2021 13:27
@andrewlock

Copy link
Copy Markdown
Member Author

Benchmarks Report 🐌

Benchmarks for #1846 compared to master:

  • 1 benchmarks are faster, with geometric mean 1.203
  • All benchmarks have the same allocations

The following thresholds were used for comparing the benchmark speeds:

  • Mann–Whitney U test with statistical test for significance of 5%
  • Only results indicating a difference greater than 10% and 0.3 ns are considered.

Allocation changes below 0.5% are ignored.

Benchmark details

Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net472 1,031.5 μs 19.69 μs 21.07 μs 0.0000 0.0000 0.0000 3.1 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 783.5 μs 14.98 μs 16.65 μs 0.0000 0.0000 0.0000 2.51 KB
#1846 WriteAndFlushEnrichedTraces net472 988.2 μs 19.73 μs 19.37 μs 0.0000 0.0000 0.0000 3.09 KB
#1846 WriteAndFlushEnrichedTraces netcoreapp3.1 780.1 μs 9.95 μs 11.06 μs 0.0000 0.0000 0.0000 2.51 KB
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net472 0.0000 ns 0.0000 ns 0.0000 ns 0.0000 0.0000 0.0000 0 B
master SendRequest netcoreapp3.1 322,444.2996 ns 3,270.6837 ns 2,899.3759 ns 0.1521 0.0000 0.0000 19778 B
#1846 SendRequest net472 0.0000 ns 0.0000 ns 0.0000 ns 0.0000 0.0000 0.0000 0 B
#1846 SendRequest netcoreapp3.1 314,245.1714 ns 5,418.0734 ns 5,068.0692 ns 0.1539 0.0000 0.0000 19777 B
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net472 2.333 μs 0.0429 μs 0.0728 μs 0.1082 0.0011 0.0000 682 B
master ExecuteNonQuery netcoreapp3.1 2.186 μs 0.0265 μs 0.0221 μs 0.0097 0.0000 0.0000 712 B
#1846 ExecuteNonQuery net472 2.193 μs 0.0418 μs 0.0410 μs 0.1080 0.0011 0.0000 682 B
#1846 ExecuteNonQuery netcoreapp3.1 2.046 μs 0.0351 μs 0.0311 μs 0.0101 0.0000 0.0000 712 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net472 3.466 μs 0.0688 μs 0.0894 μs 0.1281 0.0000 0.0000 827 B
master CallElasticsearch netcoreapp3.1 1.776 μs 0.0237 μs 0.0222 μs 0.0109 0.0000 0.0000 768 B
master CallElasticsearchAsync net472 3.700 μs 0.0712 μs 0.0699 μs 0.1487 0.0000 0.0000 963 B
master CallElasticsearchAsync netcoreapp3.1 1.900 μs 0.0268 μs 0.0237 μs 0.0123 0.0000 0.0000 888 B
#1846 CallElasticsearch net472 3.258 μs 0.0522 μs 0.0488 μs 0.1285 0.0000 0.0000 827 B
#1846 CallElasticsearch netcoreapp3.1 1.784 μs 0.0237 μs 0.0222 μs 0.0108 0.0000 0.0000 768 B
#1846 CallElasticsearchAsync net472 3.500 μs 0.0687 μs 0.0764 μs 0.1496 0.0000 0.0000 963 B
#1846 CallElasticsearchAsync netcoreapp3.1 1.824 μs 0.0337 μs 0.0331 μs 0.0122 0.0000 0.0000 888 B
Benchmarks.Trace.GraphQLBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #1846

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.GraphQLBenchmark.ExecuteAsync‑netcoreapp3.1 1.203 2,355.83 1,958.43

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net472 3.812 μs 0.0676 μs 0.0633 μs 0.1677 0.0000 0.0000 1083 B
master ExecuteAsync netcoreapp3.1 2.381 μs 0.0402 μs 0.0840 μs 0.0135 0.0000 0.0000 1008 B
#1846 ExecuteAsync net472 3.859 μs 0.0757 μs 0.1441 μs 0.1682 0.0000 0.0000 1083 B
#1846 ExecuteAsync netcoreapp3.1 1.969 μs 0.0377 μs 0.0353 μs 0.0139 0.0000 0.0000 1008 B
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendAsync net472 6.545 μs 0.1269 μs 0.1411 μs 0.3483 0.0000 0.0000 2.19 KB
master SendAsync netcoreapp3.1 4.539 μs 0.0474 μs 0.0443 μs 0.0293 0.0000 0.0000 2.09 KB
#1846 SendAsync net472 6.445 μs 0.1267 μs 0.1691 μs 0.3487 0.0000 0.0000 2.19 KB
#1846 SendAsync netcoreapp3.1 4.537 μs 0.0320 μs 0.0300 μs 0.0301 0.0000 0.0000 2.09 KB
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 4.243 μs 0.0707 μs 0.0662 μs 0.2859 0.0000 0.0000 1.79 KB
master EnrichedLog netcoreapp3.1 3.915 μs 0.0758 μs 0.0745 μs 0.0287 0.0000 0.0000 1.94 KB
#1846 EnrichedLog net472 4.150 μs 0.0680 μs 0.0603 μs 0.2874 0.0000 0.0000 1.79 KB
#1846 EnrichedLog netcoreapp3.1 3.908 μs 0.0493 μs 0.0437 μs 0.0279 0.0000 0.0000 1.94 KB
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 183.0 μs 2.63 μs 2.20 μs 0.6415 0.1833 0.0000 5.23 KB
master EnrichedLog netcoreapp3.1 156.2 μs 3.07 μs 3.15 μs 0.0000 0.0000 0.0000 5.05 KB
#1846 EnrichedLog net472 178.8 μs 2.31 μs 2.16 μs 0.7143 0.2679 0.0000 5.23 KB
#1846 EnrichedLog netcoreapp3.1 156.1 μs 3.03 μs 2.69 μs 0.0000 0.0000 0.0000 5.05 KB
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 12.42 μs 0.186 μs 0.174 μs 0.8527 0.0000 0.0000 5.31 KB
master EnrichedLog netcoreapp3.1 10.80 μs 0.212 μs 0.208 μs 0.0903 0.0000 0.0000 6.28 KB
#1846 EnrichedLog net472 12.30 μs 0.235 μs 0.209 μs 0.8492 0.0000 0.0000 5.31 KB
#1846 EnrichedLog netcoreapp3.1 11.62 μs 0.225 μs 0.241 μs 0.0905 0.0000 0.0000 6.28 KB
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net472 2.372 μs 0.0447 μs 0.0515 μs 0.1541 0.0000 0.0000 987 B
master SendReceive netcoreapp3.1 2.256 μs 0.0404 μs 0.0378 μs 0.0136 0.0000 0.0000 984 B
#1846 SendReceive net472 2.219 μs 0.0405 μs 0.0379 μs 0.1542 0.0000 0.0000 987 B
#1846 SendReceive netcoreapp3.1 2.052 μs 0.0355 μs 0.0332 μs 0.0142 0.0000 0.0000 984 B
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 8.462 μs 0.1381 μs 0.1478 μs 0.4477 0.0000 0.0000 2.8 KB
master EnrichedLog netcoreapp3.1 7.273 μs 0.1089 μs 0.0966 μs 0.0358 0.0000 0.0000 2.61 KB
#1846 EnrichedLog net472 8.433 μs 0.1618 μs 0.1863 μs 0.4450 0.0000 0.0000 2.8 KB
#1846 EnrichedLog netcoreapp3.1 7.742 μs 0.0944 μs 0.0837 μs 0.0355 0.0000 0.0000 2.61 KB
Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net472 1,023.0 ns 20.09 ns 24.67 ns 0.0677 0.0000 0.0000 433 B
master StartFinishSpan netcoreapp3.1 927.2 ns 17.85 ns 19.09 ns 0.0063 0.0000 0.0000 432 B
master StartFinishScope net472 1,119.9 ns 18.50 ns 17.31 ns 0.0802 0.0000 0.0000 514 B
master StartFinishScope netcoreapp3.1 1,103.9 ns 18.39 ns 17.21 ns 0.0077 0.0000 0.0000 552 B
#1846 StartFinishSpan net472 1,007.0 ns 19.72 ns 17.48 ns 0.0679 0.0000 0.0000 433 B
#1846 StartFinishSpan netcoreapp3.1 918.3 ns 15.74 ns 14.72 ns 0.0061 0.0000 0.0000 432 B
#1846 StartFinishScope net472 1,176.0 ns 18.74 ns 17.53 ns 0.0806 0.0000 0.0000 514 B
#1846 StartFinishScope netcoreapp3.1 1,121.0 ns 18.63 ns 15.56 ns 0.0074 0.0000 0.0000 552 B

@andrewlock andrewlock force-pushed the andrew/log-submission/serilog branch 3 times, most recently from ca4fb7d to 19c18a8 Compare October 12, 2021 09:17
@andrewlock

Copy link
Copy Markdown
Member Author

Benchmarks Report 🐌

Benchmarks for #1846 compared to master:

  • All benchmarks have the same speed
  • All benchmarks have the same allocations

The following thresholds were used for comparing the benchmark speeds:

  • Mann–Whitney U test with statistical test for significance of 5%
  • Only results indicating a difference greater than 10% and 0.3 ns are considered.

Allocation changes below 0.5% are ignored.

Benchmark details

Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net472 992.9 μs 14.82 μs 13.14 μs 0.0000 0.0000 0.0000 3.09 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 791.9 μs 15.22 μs 18.70 μs 0.0000 0.0000 0.0000 2.51 KB
#1846 WriteAndFlushEnrichedTraces net472 995.3 μs 18.53 μs 16.42 μs 0.0000 0.0000 0.0000 3.09 KB
#1846 WriteAndFlushEnrichedTraces netcoreapp3.1 782.6 μs 4.94 μs 4.13 μs 0.0000 0.0000 0.0000 2.51 KB
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net472 0.0000 ns 0.0000 ns 0.0000 ns 0.0000 0.0000 0.0000 0 B
master SendRequest netcoreapp3.1 319,847.9104 ns 6,086.9593 ns 8,729.7351 ns 0.1603 0.0000 0.0000 19776 B
#1846 SendRequest net472 0.0000 ns 0.0000 ns 0.0000 ns 0.0000 0.0000 0.0000 0 B
#1846 SendRequest netcoreapp3.1 325,216.1510 ns 4,524.6600 ns 4,010.9932 ns 0.1615 0.0000 0.0000 19777 B
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net472 2.255 μs 0.0423 μs 0.0396 μs 0.1083 0.0011 0.0000 682 B
master ExecuteNonQuery netcoreapp3.1 2.004 μs 0.0246 μs 0.0218 μs 0.0090 0.0000 0.0000 712 B
#1846 ExecuteNonQuery net472 2.210 μs 0.0317 μs 0.0281 μs 0.1080 0.0011 0.0000 682 B
#1846 ExecuteNonQuery netcoreapp3.1 2.076 μs 0.0404 μs 0.0525 μs 0.0101 0.0000 0.0000 712 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net472 3.308 μs 0.0405 μs 0.0359 μs 0.1283 0.0000 0.0000 827 B
master CallElasticsearch netcoreapp3.1 1.678 μs 0.0321 μs 0.0316 μs 0.0101 0.0000 0.0000 768 B
master CallElasticsearchAsync net472 3.540 μs 0.0707 μs 0.0695 μs 0.1499 0.0000 0.0000 963 B
master CallElasticsearchAsync netcoreapp3.1 1.886 μs 0.0346 μs 0.0324 μs 0.0127 0.0000 0.0000 888 B
#1846 CallElasticsearch net472 3.338 μs 0.0654 μs 0.0700 μs 0.1287 0.0000 0.0000 827 B
#1846 CallElasticsearch netcoreapp3.1 1.621 μs 0.0204 μs 0.0181 μs 0.0107 0.0000 0.0000 768 B
#1846 CallElasticsearchAsync net472 3.601 μs 0.0666 μs 0.0818 μs 0.1500 0.0000 0.0000 963 B
#1846 CallElasticsearchAsync netcoreapp3.1 1.733 μs 0.0332 μs 0.0326 μs 0.0123 0.0000 0.0000 888 B
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net472 3.792 μs 0.0735 μs 0.0875 μs 0.1692 0.0000 0.0000 1083 B
master ExecuteAsync netcoreapp3.1 2.041 μs 0.0349 μs 0.0326 μs 0.0145 0.0000 0.0000 1008 B
#1846 ExecuteAsync net472 3.711 μs 0.0434 μs 0.0406 μs 0.1687 0.0000 0.0000 1083 B
#1846 ExecuteAsync netcoreapp3.1 1.928 μs 0.0220 μs 0.0206 μs 0.0141 0.0000 0.0000 1008 B
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendAsync net472 6.620 μs 0.1262 μs 0.1180 μs 0.3497 0.0000 0.0000 2.19 KB
master SendAsync netcoreapp3.1 4.612 μs 0.0667 μs 0.0624 μs 0.0302 0.0000 0.0000 2.09 KB
#1846 SendAsync net472 6.757 μs 0.1307 μs 0.1699 μs 0.3484 0.0000 0.0000 2.19 KB
#1846 SendAsync netcoreapp3.1 4.525 μs 0.0376 μs 0.0333 μs 0.0293 0.0000 0.0000 2.09 KB
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 4.335 μs 0.0794 μs 0.1060 μs 0.2870 0.0000 0.0000 1.79 KB
master EnrichedLog netcoreapp3.1 3.952 μs 0.0776 μs 0.0830 μs 0.0280 0.0000 0.0000 1.94 KB
#1846 EnrichedLog net472 4.292 μs 0.0561 μs 0.0525 μs 0.2862 0.0000 0.0000 1.79 KB
#1846 EnrichedLog netcoreapp3.1 3.871 μs 0.0530 μs 0.0470 μs 0.0270 0.0000 0.0000 1.94 KB
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 185.5 μs 2.51 μs 2.35 μs 0.6472 0.1849 0.0000 5.23 KB
master EnrichedLog netcoreapp3.1 159.1 μs 3.02 μs 2.68 μs 0.0000 0.0000 0.0000 5.05 KB
#1846 EnrichedLog net472 181.7 μs 1.23 μs 0.96 μs 0.7082 0.2656 0.0000 5.23 KB
#1846 EnrichedLog netcoreapp3.1 160.0 μs 1.78 μs 1.66 μs 0.0000 0.0000 0.0000 5.05 KB
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 13.08 μs 0.260 μs 0.231 μs 0.8506 0.0000 0.0000 5.31 KB
master EnrichedLog netcoreapp3.1 11.15 μs 0.218 μs 0.259 μs 0.0920 0.0000 0.0000 6.28 KB
#1846 EnrichedLog net472 12.63 μs 0.238 μs 0.199 μs 0.8515 0.0000 0.0000 5.31 KB
#1846 EnrichedLog netcoreapp3.1 10.97 μs 0.155 μs 0.137 μs 0.0867 0.0000 0.0000 6.28 KB
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net472 2.466 μs 0.0480 μs 0.0533 μs 0.1531 0.0000 0.0000 987 B
master SendReceive netcoreapp3.1 2.059 μs 0.0261 μs 0.0218 μs 0.0141 0.0000 0.0000 984 B
#1846 SendReceive net472 2.341 μs 0.0416 μs 0.0389 μs 0.1548 0.0000 0.0000 987 B
#1846 SendReceive netcoreapp3.1 2.055 μs 0.0315 μs 0.0263 μs 0.0133 0.0000 0.0000 984 B
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 8.715 μs 0.1695 μs 0.1665 μs 0.4474 0.0000 0.0000 2.8 KB
master EnrichedLog netcoreapp3.1 8.325 μs 0.1144 μs 0.1014 μs 0.0370 0.0000 0.0000 2.61 KB
#1846 EnrichedLog net472 8.471 μs 0.1658 μs 0.2430 μs 0.4452 0.0000 0.0000 2.8 KB
#1846 EnrichedLog netcoreapp3.1 8.104 μs 0.0943 μs 0.0836 μs 0.0355 0.0000 0.0000 2.61 KB
Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net472 992.2 ns 19.62 ns 20.15 ns 0.0677 0.0000 0.0000 433 B
master StartFinishSpan netcoreapp3.1 934.6 ns 13.44 ns 11.22 ns 0.0060 0.0000 0.0000 432 B
master StartFinishScope net472 1,143.7 ns 22.91 ns 21.43 ns 0.0804 0.0000 0.0000 514 B
master StartFinishScope netcoreapp3.1 1,067.3 ns 17.86 ns 16.71 ns 0.0078 0.0000 0.0000 552 B
#1846 StartFinishSpan net472 983.7 ns 18.15 ns 16.98 ns 0.0677 0.0000 0.0000 433 B
#1846 StartFinishSpan netcoreapp3.1 934.4 ns 16.59 ns 15.52 ns 0.0061 0.0000 0.0000 432 B
#1846 StartFinishScope net472 1,169.5 ns 16.45 ns 13.74 ns 0.0804 0.0000 0.0000 514 B
#1846 StartFinishScope netcoreapp3.1 1,078.3 ns 11.61 ns 10.29 ns 0.0076 0.0000 0.0000 552 B

Not strictly vendored, as make various changes to remove Serilog dependency and update API a little (as we don't need to support as many scenarios).
Previously we were silently setting the content-type to msgpack, now we _explicitly_ set it in the method
Also, we we previously _weren't_ setting the contentType in HttpStreamRequest, now we do
Store logs as `DatadogLogEvent`, so we don't _have_ to serialize on the main thread, and instead can defer to when we send the logs
Also update unit tests to not rely on Thread.Sleep (as makes tests flaky)
* Currently avoids calculating exact size of messages to reduce allocations, that's something we could/should look at later
* Use a shared string builder
* Currently only supports sending as JSON and Http.
* Retries up to 5 times on error, give up after ~7.5s (original sink tries 10 times, for up to 6 minutes!)
* Skip retry on 400 error
* Currently not collecting metrics about the send itself, we can add those if necessary
Accounts for the fact they may have already added the sink directly
This is slightly tricky because:
* ILoggerFactory uses a different "root" constructor in .net 5+
* We can't reverse duck type the ILoggerProvider directly, because we need to implement two interfaces, so have to `DefineType` an interface that implements both, and then duck type that.
Instruments the AppenderCollection.ToArray() method to sneak our own appender in every time a logger is requested
Added a MockLogsIntake to support verifying logs are shipped correctly, and have the expected properties
In the previous version, everything was added to a giant (persistent) StringBuilder, we then call ToString(), and convert the string to a byte array (which is then thrown away). The string and utf8 array are ultimately garbage.

In this version, we keep a smaller persistent StringBuilder (one for each log, instead of all logs), convert that to a string, and write the bytes to a persistent byte array. Only the intermediate string is garbage.

The benefit should be that we have less chance of the string/byte array ending up on the LOH, and we can reuse the UTF8 array
@andrewlock andrewlock force-pushed the andrew/log-submission/serilog branch from 19c18a8 to 4c053fa Compare October 13, 2021 14:47
@andrewlock

Copy link
Copy Markdown
Member Author

Benchmarks Report 🐌

Benchmarks for #1846 compared to master:

  • All benchmarks have the same speed
  • All benchmarks have the same allocations

The following thresholds were used for comparing the benchmark speeds:

  • Mann–Whitney U test with statistical test for significance of 5%
  • Only results indicating a difference greater than 10% and 0.3 ns are considered.

Allocation changes below 0.5% are ignored.

Benchmark details

Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net472 1,041.9 μs 17.04 μs 18.94 μs 0.0000 0.0000 0.0000 3.1 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 827.4 μs 12.19 μs 10.81 μs 0.0000 0.0000 0.0000 2.51 KB
#1846 WriteAndFlushEnrichedTraces net472 1,028.3 μs 15.32 μs 13.58 μs 0.0000 0.0000 0.0000 3.09 KB
#1846 WriteAndFlushEnrichedTraces netcoreapp3.1 797.2 μs 15.74 μs 17.49 μs 0.0000 0.0000 0.0000 2.51 KB
Benchmarks.Trace.AspNetCoreBenchmark - Unknown 🤷 Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net472 0.0000 ns 0.0000 ns 0.0000 ns 0.0000 0.0000 0.0000 0 B
master SendRequest netcoreapp3.1 325,979.7399 ns 6,280.2132 ns 5,874.5153 ns 0.1619 0.0000 0.0000 19778 B
#1846 SendRequest net472 0.0000 ns 0.0000 ns 0.0000 ns 0.0000 0.0000 0.0000 0 B
#1846 SendRequest netcoreapp3.1 314,799.4774 ns 6,162.4822 ns 8,638.9393 ns 0.1611 0.0000 0.0000 19777 B
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net472 2.294 μs 0.0451 μs 0.0537 μs 0.1074 0.0012 0.0000 682 B
master ExecuteNonQuery netcoreapp3.1 2.104 μs 0.0404 μs 0.0397 μs 0.0094 0.0000 0.0000 712 B
#1846 ExecuteNonQuery net472 2.247 μs 0.0360 μs 0.0319 μs 0.1081 0.0011 0.0000 682 B
#1846 ExecuteNonQuery netcoreapp3.1 2.137 μs 0.0416 μs 0.0462 μs 0.0092 0.0000 0.0000 712 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net472 3.489 μs 0.0601 μs 0.0533 μs 0.1279 0.0000 0.0000 827 B
master CallElasticsearch netcoreapp3.1 1.778 μs 0.0212 μs 0.0177 μs 0.0106 0.0000 0.0000 768 B
master CallElasticsearchAsync net472 3.693 μs 0.0637 μs 0.0596 μs 0.1491 0.0000 0.0000 963 B
master CallElasticsearchAsync netcoreapp3.1 1.905 μs 0.0357 μs 0.0317 μs 0.0125 0.0000 0.0000 888 B
#1846 CallElasticsearch net472 3.543 μs 0.0709 μs 0.0728 μs 0.1276 0.0000 0.0000 827 B
#1846 CallElasticsearch netcoreapp3.1 1.704 μs 0.0333 μs 0.0295 μs 0.0110 0.0000 0.0000 768 B
#1846 CallElasticsearchAsync net472 3.679 μs 0.0726 μs 0.0776 μs 0.1486 0.0000 0.0000 963 B
#1846 CallElasticsearchAsync netcoreapp3.1 1.859 μs 0.0278 μs 0.0260 μs 0.0127 0.0000 0.0000 888 B
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net472 3.994 μs 0.0655 μs 0.0581 μs 0.1675 0.0000 0.0000 1083 B
master ExecuteAsync netcoreapp3.1 2.083 μs 0.0259 μs 0.0242 μs 0.0137 0.0000 0.0000 1008 B
#1846 ExecuteAsync net472 4.076 μs 0.0448 μs 0.0397 μs 0.1677 0.0000 0.0000 1083 B
#1846 ExecuteAsync netcoreapp3.1 2.015 μs 0.0295 μs 0.0262 μs 0.0138 0.0000 0.0000 1008 B
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendAsync net472 6.818 μs 0.0931 μs 0.0727 μs 0.3506 0.0000 0.0000 2.19 KB
master SendAsync netcoreapp3.1 4.565 μs 0.0459 μs 0.0383 μs 0.0297 0.0000 0.0000 2.09 KB
#1846 SendAsync net472 6.742 μs 0.1292 μs 0.1079 μs 0.3507 0.0000 0.0000 2.19 KB
#1846 SendAsync netcoreapp3.1 4.701 μs 0.0658 μs 0.0616 μs 0.0298 0.0000 0.0000 2.09 KB
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 4.488 μs 0.0567 μs 0.0757 μs 0.2863 0.0000 0.0000 1.79 KB
master EnrichedLog netcoreapp3.1 4.065 μs 0.0507 μs 0.0450 μs 0.0265 0.0000 0.0000 1.94 KB
#1846 EnrichedLog net472 4.401 μs 0.0839 μs 0.0824 μs 0.2867 0.0000 0.0000 1.79 KB
#1846 EnrichedLog netcoreapp3.1 3.933 μs 0.0639 μs 0.0598 μs 0.0275 0.0000 0.0000 1.94 KB
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 189.8 μs 2.52 μs 2.36 μs 0.6579 0.1880 0.0000 5.23 KB
master EnrichedLog netcoreapp3.1 158.7 μs 2.28 μs 2.13 μs 0.0780 0.0000 0.0000 5.05 KB
#1846 EnrichedLog net472 182.7 μs 2.16 μs 1.80 μs 0.6286 0.1796 0.0000 5.23 KB
#1846 EnrichedLog netcoreapp3.1 159.6 μs 3.05 μs 3.13 μs 0.0000 0.0000 0.0000 5.05 KB
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 12.90 μs 0.212 μs 0.177 μs 0.8542 0.0000 0.0000 5.31 KB
master EnrichedLog netcoreapp3.1 11.09 μs 0.206 μs 0.193 μs 0.0930 0.0000 0.0000 6.28 KB
#1846 EnrichedLog net472 12.97 μs 0.171 μs 0.151 μs 0.8545 0.0000 0.0000 5.31 KB
#1846 EnrichedLog netcoreapp3.1 11.02 μs 0.133 μs 0.118 μs 0.0885 0.0000 0.0000 6.28 KB
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net472 2.335 μs 0.0455 μs 0.0558 μs 0.1540 0.0000 0.0000 987 B
master SendReceive netcoreapp3.1 2.233 μs 0.0215 μs 0.0201 μs 0.0135 0.0000 0.0000 984 B
#1846 SendReceive net472 2.331 μs 0.0353 μs 0.0313 μs 0.1544 0.0000 0.0000 987 B
#1846 SendReceive netcoreapp3.1 2.109 μs 0.0235 μs 0.0220 μs 0.0136 0.0000 0.0000 984 B
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net472 8.700 μs 0.1719 μs 0.1608 μs 0.4476 0.0000 0.0000 2.8 KB
master EnrichedLog netcoreapp3.1 7.725 μs 0.0973 μs 0.0760 μs 0.0383 0.0000 0.0000 2.61 KB
#1846 EnrichedLog net472 8.540 μs 0.1707 μs 0.1597 μs 0.4452 0.0000 0.0000 2.8 KB
#1846 EnrichedLog netcoreapp3.1 7.726 μs 0.1134 μs 0.1005 μs 0.0383 0.0000 0.0000 2.61 KB
Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net472 983.9 ns 15.05 ns 14.08 ns 0.0678 0.0000 0.0000 433 B
master StartFinishSpan netcoreapp3.1 936.6 ns 13.25 ns 12.40 ns 0.0061 0.0000 0.0000 432 B
master StartFinishScope net472 1,157.8 ns 22.95 ns 25.51 ns 0.0807 0.0000 0.0000 514 B
master StartFinishScope netcoreapp3.1 1,130.4 ns 22.66 ns 22.26 ns 0.0079 0.0000 0.0000 552 B
#1846 StartFinishSpan net472 1,065.4 ns 17.97 ns 16.81 ns 0.0680 0.0000 0.0000 433 B
#1846 StartFinishSpan netcoreapp3.1 983.9 ns 14.57 ns 13.63 ns 0.0060 0.0000 0.0000 432 B
#1846 StartFinishScope net472 1,188.1 ns 23.28 ns 23.91 ns 0.0805 0.0000 0.0000 514 B
#1846 StartFinishScope netcoreapp3.1 1,085.9 ns 10.50 ns 9.31 ns 0.0079 0.0000 0.0000 552 B

@andrewlock

Copy link
Copy Markdown
Member Author

Superseded by #1945

@andrewlock andrewlock closed this Oct 27, 2021
@andrewlock andrewlock deleted the andrew/log-submission/serilog branch October 27, 2021 13:34
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant