Refactor ModuleMetadata handling to reduce memory allocations by tonyredondo · Pull Request #1906 · DataDog/dd-trace-dotnet

tonyredondo · 2021-10-13T19:53:12Z

Reverts #1904 Applying #1891 again and fixes race condition using std::promise

…ocations. (#1891)" (#1904)" This reverts commit 6ff66db.

…metadata-allocations

gleocadie · 2021-10-14T16:33:18Z

        {
            Logger::Warn("AssemblyLoadFinished failed to get metadata interface for module id ",
-                         assembly_info.manifest_module_id, " from assembly ", assembly_info.name);
+                         assembly_info.manifest_module_id, " from assembly ", assembly_info.name, " HRESULT=0x", HResultStr(hr));


FYI, you can use std::hex, before hr

gleocadie · 2021-10-18T16:44:38Z

-            CallTarget_RequestRejitForModule(moduleItem.first, moduleItem.second, integrationMethods);
+            std::promise<int> promise;
+            std::future<int> future = promise.get_future();
+            rejit_handler->EnqueueProcessModule(module_ids_, integrationMethods, &promise);


Question: EnqueueProcessModule will enqueue the promise, right?
but promise is a local variable. If the processing of the queue occurs after we get out of the promise variable scope, we have a bug.

next line we wait for the future in future.get() :) same scope.

oh ok.... so if we remove the call to the logger (or it's optimized out), we break the application ?
Maybe having the call to .get() on a different line to be more explicit, no?

Why not having EnqueueProcessModule returning a std::future<int> instead ? it will be safer
Or maybe it was to have less changes in EnqueueProcessModule (it would require to keep the promise somewhere)

I'll take a look at this, I want to keep the future as an optional thing.

First I have to fix a deadlock here.

…metadata-allocations

andrewlock · 2021-10-21T09:05:34Z

Code Coverage Report 📊

⚠️ Merging #1906 into master will will decrease line coverage by 1%
⚠️ Merging #1906 into master will will decrease branch coverage by 1%
✔️ Merging #1906 into master will not change complexity

	master	#1906	Change
Lines	`9540` / `15402`	`9415` / `15402`
Lines %	`62%`	`61%`	`-1%` ⚠️
Branches	`4228` / `6712`	`4147` / `6712`
Branches %	`63%`	`62%`	`-1%` ⚠️
Complexity	`8202`	`8202`	`0` ✔️

View the full report for further details:

Datadog.Trace Breakdown ⚠️

	master	#1906	Change
Lines %	`62%`	`61%`	`-1%` ⚠️
Branches %	`63%`	`62%`	`-1%` ⚠️
Complexity	`8202`	`8202`	`0` ✔️

The following classes have significant coverage changes.

File	Line coverage change	Branch coverage change	Complexity change
Datadog.Trace.Agent.StreamFactories.TcpStreamFactory	`-82%` ⛔	`0%` ✔️	`0` ✔️
Datadog.Trace.Agent.Transports.HttpStreamResponse	`-67%` ⛔	`-100%` ⛔	`0` ✔️
Datadog.Trace.Agent.Transports.HttpStreamRequestFactory	`-67%` ⛔	`0%` ✔️	`0` ✔️
Datadog.Trace.Agent.Transports.HttpStreamRequest	`-45%` ⛔	`-17%` ⛔	`0` ✔️
Datadog.Trace.Agent.TransportStrategy	`-29%` ⛔	`-33%` ⛔	`0` ✔️
Datadog.Trace.HttpOverStreams.HttpMessage	`-27%` ⛔	`-12%` ⛔	`0` ✔️
Datadog.Trace.ClrProfiler.Integrations.RabbitMQIntegration	`-14%` ⛔	`-24%` ⛔	`0` ✔️
Datadog.Trace.ClrProfiler.AutoInstrumentation.Kafka.KafkaConsumerConsumeIntegration	`-12%` ⛔	`-31%` ⛔	`0` ✔️
Datadog.Trace.HttpOverStreams.DatadogHttpHeaderHelper	`-11%` ⛔	`0%` ✔️	`0` ✔️
Datadog.Trace.ClrProfiler.AutoInstrumentation.Testing.NUnit.NUnitCompositeWorkItemSkipChildrenIntegration	`-8%` ⛔	`-8%` ⛔	`0` ✔️
...And 3 more

View the full reports for further details:

andrewlock · 2021-10-21T10:24:51Z

Benchmarks Report 🐌

Benchmarks for #1906 compared to master:

1 benchmarks are faster, with geometric mean 1.230
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	Allocated
master	`WriteAndFlushEnrichedTraces`	net472	1,037.2 μs	15.73 μs	12.28 μs	3.09 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	781.9 μs	9.79 μs	8.68 μs	2.51 KB
#1906	`WriteAndFlushEnrichedTraces`	net472	1,024.9 μs	20.26 μs	20.81 μs	3.09 KB
#1906	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	801.1 μs	15.32 μs	15.05 μs	2.51 KB

Benchmarks.Trace.AspNetCoreBenchmark - Unknown 🤷 Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`SendRequest`	net472	0.0000 ns	0.0000 ns	0.0000 ns	0.0000	0 B
master	`SendRequest`	netcoreapp3.1	310,589.0625 ns	5,123.8584 ns	5,032.3141 ns	0.2306	19798 B
#1906	`SendRequest`	net472	0.0000 ns	0.0000 ns	0.0000 ns	0.0000	0 B
#1906	`SendRequest`	netcoreapp3.1	314,434.6045 ns	6,036.7287 ns	5,646.7598 ns	0.1474	19777 B

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Gen 1	Allocated
master	`ExecuteNonQuery`	net472	2.217 μs	0.0443 μs	0.0492 μs	0.1081	0.0011	682 B
master	`ExecuteNonQuery`	netcoreapp3.1	2.038 μs	0.0343 μs	0.0321 μs	0.0093	0.0000	712 B
#1906	`ExecuteNonQuery`	net472	2.203 μs	0.0428 μs	0.0440 μs	0.1076	0.0011	682 B
#1906	`ExecuteNonQuery`	netcoreapp3.1	2.075 μs	0.0287 μs	0.0254 μs	0.0095	0.0000	712 B

Benchmarks.Trace.ElasticsearchBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #1906

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearch‑net472	1.230	4,228.49	3,436.42

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`CallElasticsearch`	net472	4.222 μs	0.0649 μs	0.0607 μs	0.1260	827 B
master	`CallElasticsearch`	netcoreapp3.1	1.749 μs	0.0339 μs	0.0390 μs	0.0104	768 B
master	`CallElasticsearchAsync`	net472	3.606 μs	0.0703 μs	0.0914 μs	0.1495	963 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.859 μs	0.0212 μs	0.0188 μs	0.0120	888 B
#1906	`CallElasticsearch`	net472	3.431 μs	0.0468 μs	0.0438 μs	0.1287	827 B
#1906	`CallElasticsearch`	netcoreapp3.1	1.756 μs	0.0349 μs	0.0441 μs	0.0106	768 B
#1906	`CallElasticsearchAsync`	net472	3.752 μs	0.0722 μs	0.0773 μs	0.1495	963 B
#1906	`CallElasticsearchAsync`	netcoreapp3.1	1.834 μs	0.0349 μs	0.0478 μs	0.0123	888 B

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`ExecuteAsync`	net472	3.941 μs	0.0781 μs	0.1016 μs	0.1690	1083 B
master	`ExecuteAsync`	netcoreapp3.1	2.068 μs	0.0324 μs	0.0303 μs	0.0137	1008 B
#1906	`ExecuteAsync`	net472	3.785 μs	0.0596 μs	0.0557 μs	0.1677	1083 B
#1906	`ExecuteAsync`	netcoreapp3.1	1.992 μs	0.0340 μs	0.0318 μs	0.0136	1008 B

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`SendAsync`	net472	6.536 μs	0.1247 μs	0.1105 μs	0.3482	2.19 KB
master	`SendAsync`	netcoreapp3.1	4.974 μs	0.0977 μs	0.1004 μs	0.0302	2.09 KB
#1906	`SendAsync`	net472	6.725 μs	0.0980 μs	0.0917 μs	0.3496	2.19 KB
#1906	`SendAsync`	netcoreapp3.1	4.719 μs	0.0857 μs	0.0760 μs	0.0310	2.09 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	4.384 μs	0.0877 μs	0.1010 μs	0.2866	1.79 KB
master	`EnrichedLog`	netcoreapp3.1	3.825 μs	0.0396 μs	0.0371 μs	0.0290	1.94 KB
#1906	`EnrichedLog`	net472	4.245 μs	0.0736 μs	0.0788 μs	0.2866	1.79 KB
#1906	`EnrichedLog`	netcoreapp3.1	3.940 μs	0.0698 μs	0.0653 μs	0.0276	1.94 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net472	187.5 μs	2.68 μs	2.51 μs	0.6669	0.1905	5.23 KB
master	`EnrichedLog`	netcoreapp3.1	160.2 μs	1.57 μs	1.39 μs	0.0000	0.0000	5.05 KB
#1906	`EnrichedLog`	net472	190.3 μs	3.69 μs	3.08 μs	0.6731	0.1923	5.23 KB
#1906	`EnrichedLog`	netcoreapp3.1	158.6 μs	2.69 μs	2.52 μs	0.0000	0.0000	5.05 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	12.54 μs	0.235 μs	0.208 μs	0.8543	5.31 KB
master	`EnrichedLog`	netcoreapp3.1	11.02 μs	0.198 μs	0.176 μs	0.0906	6.28 KB
#1906	`EnrichedLog`	net472	12.53 μs	0.224 μs	0.240 μs	0.8513	5.31 KB
#1906	`EnrichedLog`	netcoreapp3.1	11.07 μs	0.201 μs	0.178 μs	0.0930	6.28 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`SendReceive`	net472	2.364 μs	0.0408 μs	0.0419 μs	0.1550	987 B
master	`SendReceive`	netcoreapp3.1	2.172 μs	0.0422 μs	0.0486 μs	0.0138	984 B
#1906	`SendReceive`	net472	2.355 μs	0.0461 μs	0.0616 μs	0.1547	987 B
#1906	`SendReceive`	netcoreapp3.1	2.054 μs	0.0324 μs	0.0287 μs	0.0135	984 B

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	9.354 μs	0.1781 μs	0.2051 μs	0.4471	2.8 KB
master	`EnrichedLog`	netcoreapp3.1	7.634 μs	0.1469 μs	0.1302 μs	0.0379	2.61 KB
#1906	`EnrichedLog`	net472	8.449 μs	0.1641 μs	0.1890 μs	0.4471	2.8 KB
#1906	`EnrichedLog`	netcoreapp3.1	7.689 μs	0.1524 μs	0.1425 μs	0.0379	2.61 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net472	970.9 ns	18.95 ns	27.18 ns	0.0678	433 B
master	`StartFinishSpan`	netcoreapp3.1	950.7 ns	7.60 ns	7.11 ns	0.0063	432 B
master	`StartFinishScope`	net472	1,152.1 ns	14.28 ns	13.36 ns	0.0803	514 B
master	`StartFinishScope`	netcoreapp3.1	1,106.3 ns	21.53 ns	21.14 ns	0.0078	552 B
#1906	`StartFinishSpan`	net472	953.1 ns	15.09 ns	18.54 ns	0.0681	433 B
#1906	`StartFinishSpan`	netcoreapp3.1	930.2 ns	18.52 ns	19.81 ns	0.0060	432 B
#1906	`StartFinishScope`	net472	1,134.7 ns	22.39 ns	32.12 ns	0.0806	514 B
#1906	`StartFinishScope`	netcoreapp3.1	1,101.2 ns	20.88 ns	18.51 ns	0.0075	552 B

tonyredondo · 2021-10-21T13:33:15Z

Superseeded by #1931

Revert "Revert "Refactor ModuleMetadata handling to reduce memory all…

140ce8a

…ocations. (#1891)" (#1904)" This reverts commit 6ff66db.

tonyredondo requested a review from a team as a code owner October 13, 2021 19:53

tonyredondo self-assigned this Oct 13, 2021

tonyredondo added 2 commits October 13, 2021 21:54

Fix race condition with std::promise

3357f0c

Force DEBUG log in the native profiler.

78cb65a

DataDog deleted a comment from andrewlock Oct 14, 2021

tonyredondo added 3 commits October 14, 2021 16:05

Update pipeline.

eb59fd9

Always condition.

787ed87

changes

36ea82a

DataDog deleted a comment from andrewlock Oct 14, 2021

tonyredondo added 5 commits October 14, 2021 23:17

remove promise on ModuleLoadFinished callback

18d1882

Merge branch 'master' into revert-1904-revert-1891-tony/reduce-module…

d1b1f6c

…metadata-allocations

changes

8b3b411

Merge branch 'master' into revert-1904-revert-1891-tony/reduce-module…

ce9d97f

…metadata-allocations

refactor ReJIT

6863a41

gleocadie requested changes Oct 18, 2021

View reviewed changes

Changes.

fb49da9

tonyredondo marked this pull request as draft October 19, 2021 15:33

tonyredondo added 10 commits October 19, 2021 18:01

change

03e93d7

changes

0a6fb4b

changes.

7fe15e9

Changes.

c904c03

change

2cfd993

changes and logs

e1fa299

Change

fc4bd02

fix toolpath

77805e0

change

0bfb5be

Espace quotes.

7787391

tonyredondo added 5 commits October 20, 2021 18:45

dotnet test --blame-hang

5a199ea

Cleanup

7dc4de1

Fix rejit shutdown deadlock issue.

11d8d37

fix

41731d8

Merge branch 'master' into revert-1904-revert-1891-tony/reduce-module…

15cb941

…metadata-allocations

DataDog deleted a comment from andrewlock Oct 21, 2021

tonyredondo mentioned this pull request Oct 21, 2021

Refactor ModuleMetadata handling to reduce memory allocations #1931

Merged

tonyredondo closed this Oct 21, 2021

tonyredondo deleted the revert-1904-revert-1891-tony/reduce-modulemetadata-allocations branch December 28, 2022 19:51

Conversation

tonyredondo commented Oct 13, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

gleocadie Oct 14, 2021

Choose a reason for hiding this comment

Uh oh!

gleocadie Oct 18, 2021

Choose a reason for hiding this comment

Uh oh!

tonyredondo Oct 18, 2021

Choose a reason for hiding this comment

Uh oh!

gleocadie Oct 19, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tonyredondo Oct 19, 2021

Choose a reason for hiding this comment

Uh oh!

andrewlock commented Oct 21, 2021

Code Coverage Report 📊

Datadog.Trace Breakdown ⚠️

Uh oh!

andrewlock commented Oct 21, 2021

Benchmarks Report 🐌

Benchmark details

Raw results

Raw results

Raw results

Faster 🎉 in #1906

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Uh oh!

tonyredondo commented Oct 21, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

tonyredondo commented Oct 13, 2021 •

edited

Loading

gleocadie Oct 19, 2021 •

edited

Loading