Direct log submission PoC#1846
Closed
andrewlock wants to merge 14 commits into
Closed
Conversation
Member
Author
Benchmarks Report 🐌Benchmarks for #1846 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️Raw results
|
This comment has been minimized.
This comment has been minimized.
3843418 to
5f11b3a
Compare
Member
Author
Benchmarks Report 🐌Benchmarks for #1846 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.GraphQLBenchmark - Faster 🎉 Same allocations ✔️
|
| 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 |
ca4fb7d to
19c18a8
Compare
Member
Author
Benchmarks Report 🐌Benchmarks for #1846 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️Raw results
|
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
19c18a8 to
4c053fa
Compare
Member
Author
Benchmarks Report 🐌Benchmarks for #1846 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AspNetCoreBenchmark - Unknown 🤷 Same allocations ✔️Raw results
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️Raw results
|
Member
Author
|
Superseded by #1945 |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
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. TheLogsApitype takes care of the transport (similar to theApiclass 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/SerilogSinkas required, which then farms off the logs to the singleton Serilog Sink.Current limitations
Questions
Evidence it works 🎉
@DataDog/apm-dotnet