Add instrumentation for `Process.Start` by NachoEchevarria · Pull Request #3146 · DataDog/dd-trace-dotnet

NachoEchevarria · 2022-08-31T15:47:34Z

Summary of changes

It has been implemented a mechanism to trace the launching of a process and generate a span. The parsing of the command line has been left out for this PR.

More details can be found here:
https://docs.google.com/document/d/1WDuvG_4LxgWZaS-X4UJQZd0MjmahPkPtPv23wacAFHE

Reason for change

Implementation details

The non static method process.Start() has been instrumented. The other signatures of process.Start() end up calling this method. The process contains a property named StartInfo that contains the information related to the process execution.

The process class is included in the System assembly for full framework , and in the assembly System.Diagnostics.Process in the case of netcore apps.

Test coverage

A sample console app and two integration tests have been implemented in order to test the funcionality.

Other details

tonyredondo

A few comments for now, I will continue the review later :)

tonyredondo · 2022-09-01T16:51:53Z

        internal const string GrpcMethodName = "grpc.method.name";
        internal const string GrpcStatusCode = "grpc.status.code";

+        internal const string ProcesTruncated = "cmd.truncated";


Truncated has a different meaning here: https://datadoghq.atlassian.net/wiki/spaces/APM/pages/2357395856/Span+attributes#%5BinlineExtension%5DSystem

Because I guess the plan is to have a single integration, I think we should talk to other tracers on this.

We are not processing the command line arguments right now (we left that out), but we are processing the environment variables. It makes sense to truncate the env variables line if it's too big and the documentation talks about truncating the command line with the arguments and the variables. Since we are not processing the arguments, only variables are left. This tag is useful to let the user know that part of the information was truncated. What do you think?

The specifications doc says cmd.truncated should only be set if cmd.exec or cmd.shell was truncated. Where are we including the environment variables? In another tag?

Ahh, I see cmd.environment_variables, but that is not in the specs (neither the google doc or the confluence page). I think it's fine to add this tag but we should probably not change the expected meaning of cmd.truncated.

I think that we can skip the cmd.truncated tag, for now, since we are not processing the full command line with the arguments. Later, when we do that, this tag can be included. I will change that.

andrewlock

Very nice! One request - could you switch to snapshots instead of Asserts for the integration tests 🙂 ping me if you need a hand with them!

andrewlock · 2022-09-02T12:15:33Z

Just FYI, we use the titles of PRs to generate the release notes, so I've updated it to look a bit nicer 🙂

…ssStart/EnvironmentVariablesScrubber.cs Co-authored-by: Zach Montoya <[email protected]>

…ssStart/ProcessStartIntegration.cs Co-authored-by: Zach Montoya <[email protected]>

…ss/ProcessStartCommon.cs Co-authored-by: Lucas Pimentel-Ordyna <[email protected]>

andrewlock · 2022-09-09T14:20:26Z

Benchmarks Report 🐌

Benchmarks for #3146 compared to master:

2 benchmarks are faster, with geometric mean 1.185
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	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net472	719μs	332ns	1.24μs	0.359	3.18 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	462μs	347ns	1.34μs	0	2.59 KB
#3146	`WriteAndFlushEnrichedTraces`	net472	725μs	181ns	678ns	0.361	3.18 KB
#3146	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	465μs	256ns	957ns	0	2.58 KB

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

Faster 🎉 in #3146

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.AppSecBodyBenchmark.AllCycleMoreComplexBody‑net472	1.254	231.33	184.47
Benchmarks.Trace.AppSecBodyBenchmark.AllCycleSimpleBody‑net472	1.120	208.19	185.87

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`AllCycleSimpleBody`	net472	208ns	0.125ns	0.467ns	0.0676	0	425 B
master	`AllCycleSimpleBody`	netcoreapp3.1	236ns	0.279ns	1.08ns	0.00588	0	424 B
master	`AllCycleMoreComplexBody`	net472	231ns	0.0804ns	0.279ns	0.0637	0	401 B
master	`AllCycleMoreComplexBody`	netcoreapp3.1	233ns	0.45ns	1.62ns	0.00546	0	400 B
master	`BodyExtractorSimpleBody`	net472	259ns	0.307ns	1.15ns	0.0573	0	361 B
master	`BodyExtractorSimpleBody`	netcoreapp3.1	226ns	0.286ns	1.07ns	0.00365	0	272 B
master	`BodyExtractorMoreComplexBody`	net472	14.6μs	10.4ns	40.3ns	1.21	0.0218	7.62 KB
master	`BodyExtractorMoreComplexBody`	netcoreapp3.1	11.8μs	16.8ns	65.1ns	0.0879	0	6.75 KB
#3146	`AllCycleSimpleBody`	net472	186ns	0.182ns	0.705ns	0.0675	0	425 B
#3146	`AllCycleSimpleBody`	netcoreapp3.1	236ns	0.543ns	2.03ns	0.00578	0	424 B
#3146	`AllCycleMoreComplexBody`	net472	185ns	0.143ns	0.534ns	0.0637	0	401 B
#3146	`AllCycleMoreComplexBody`	netcoreapp3.1	233ns	0.402ns	1.56ns	0.00547	0	400 B
#3146	`BodyExtractorSimpleBody`	net472	260ns	0.234ns	0.875ns	0.0573	0	361 B
#3146	`BodyExtractorSimpleBody`	netcoreapp3.1	236ns	0.25ns	0.935ns	0.00374	0	272 B
#3146	`BodyExtractorMoreComplexBody`	net472	14.6μs	16.1ns	60.1ns	1.21	0.0219	7.62 KB
#3146	`BodyExtractorMoreComplexBody`	netcoreapp3.1	12.3μs	16.8ns	65ns	0.0921	0	6.75 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendRequest`	net472	0ns	0ns	0ns	0	0 b
master	`SendRequest`	netcoreapp3.1	181μs	212ns	823ns	0.271	20.57 KB
#3146	`SendRequest`	net472	0ns	0ns	0ns	0	0 b
#3146	`SendRequest`	netcoreapp3.1	184μs	313ns	1.21μs	0.182	20.58 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`ExecuteNonQuery`	net472	1.87μs	1.21ns	4.53ns	0.15	0	947 B
master	`ExecuteNonQuery`	netcoreapp3.1	1.43μs	0.472ns	1.83ns	0.0122	0	936 B
#3146	`ExecuteNonQuery`	net472	1.88μs	0.91ns	3.52ns	0.15	0.00094	947 B
#3146	`ExecuteNonQuery`	netcoreapp3.1	1.4μs	0.579ns	2.24ns	0.0127	0	936 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`CallElasticsearch`	net472	2.75μs	2.06ns	7.99ns	0.184	1.16 KB
master	`CallElasticsearch`	netcoreapp3.1	1.51μs	0.644ns	2.41ns	0.0151	1.1 KB
master	`CallElasticsearchAsync`	net472	2.78μs	1.87ns	7.23ns	0.205	1.29 KB
master	`CallElasticsearchAsync`	netcoreapp3.1	1.61μs	0.578ns	2.24ns	0.0162	1.22 KB
#3146	`CallElasticsearch`	net472	2.67μs	1.87ns	7.23ns	0.183	1.16 KB
#3146	`CallElasticsearch`	netcoreapp3.1	1.57μs	1.35ns	5.25ns	0.0142	1.1 KB
#3146	`CallElasticsearchAsync`	net472	2.74μs	1.87ns	7.24ns	0.205	1.29 KB
#3146	`CallElasticsearchAsync`	netcoreapp3.1	1.57μs	0.828ns	3.1ns	0.0166	1.22 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteAsync`	net472	2.75μs	7.66ns	29.7ns	0.225	1.42 KB
master	`ExecuteAsync`	netcoreapp3.1	1.74μs	3.15ns	11.8ns	0.0184	1.34 KB
#3146	`ExecuteAsync`	net472	2.7μs	5.14ns	19.9ns	0.225	1.42 KB
#3146	`ExecuteAsync`	netcoreapp3.1	1.73μs	4.25ns	16.5ns	0.018	1.34 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`SendAsync`	net472	5.71μs	9.27ns	35.9ns	0.437	0.00284	2.77 KB
master	`SendAsync`	netcoreapp3.1	3.64μs	7.29ns	26.3ns	0.0345	0	2.6 KB
#3146	`SendAsync`	net472	5.66μs	13.5ns	52.4ns	0.439	0	2.77 KB
#3146	`SendAsync`	netcoreapp3.1	3.61μs	6.69ns	25ns	0.0357	0	2.6 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	3.16μs	2.93ns	11.3ns	0.288	1.81 KB
master	`EnrichedLog`	netcoreapp3.1	2.52μs	4.98ns	19.3ns	0.0252	1.85 KB
#3146	`EnrichedLog`	net472	3.32μs	3.38ns	12.7ns	0.288	1.81 KB
#3146	`EnrichedLog`	netcoreapp3.1	2.52μs	2.83ns	11ns	0.0254	1.85 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net472	155μs	428ns	1.66μs	0.683	0.228	4.66 KB
master	`EnrichedLog`	netcoreapp3.1	116μs	73.8ns	266ns	0.0579	0	4.5 KB
#3146	`EnrichedLog`	net472	152μs	243ns	940ns	0.674	0.225	4.66 KB
#3146	`EnrichedLog`	netcoreapp3.1	118μs	155ns	602ns	0.0589	0	4.49 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net472	5.51μs	10.4ns	40.3ns	0.57	0.00277	3.59 KB
master	`EnrichedLog`	netcoreapp3.1	4.43μs	7.27ns	28.1ns	0.0527	0	3.91 KB
#3146	`EnrichedLog`	net472	5.67μs	12.2ns	47.3ns	0.569	0.00279	3.59 KB
#3146	`EnrichedLog`	netcoreapp3.1	4.26μs	12.8ns	49.6ns	0.0546	0	3.91 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendReceive`	net472	2.43μs	3.48ns	13.5ns	0.218	1.37 KB
master	`SendReceive`	netcoreapp3.1	1.83μs	1.07ns	4.13ns	0.0183	1.32 KB
#3146	`SendReceive`	net472	2.35μs	4.39ns	17ns	0.218	1.37 KB
#3146	`SendReceive`	netcoreapp3.1	1.86μs	2.69ns	10ns	0.0176	1.32 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	5.06μs	3.28ns	12.7ns	0.354	2.23 KB
master	`EnrichedLog`	netcoreapp3.1	4.23μs	1.7ns	6.6ns	0.0231	1.8 KB
#3146	`EnrichedLog`	net472	5.09μs	2.23ns	8.64ns	0.353	2.23 KB
#3146	`EnrichedLog`	netcoreapp3.1	4.37μs	0.994ns	3.59ns	0.0241	1.8 KB

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`StartFinishSpan`	net472	1.15μs	0.508ns	1.9ns	0.129	0	810 B
master	`StartFinishSpan`	netcoreapp3.1	952ns	0.424ns	1.53ns	0.0105	0	760 B
master	`StartFinishScope`	net472	1.42μs	0.99ns	3.83ns	0.141	0	891 B
master	`StartFinishScope`	netcoreapp3.1	1.13μs	0.344ns	1.33ns	0.0124	0	880 B
#3146	`StartFinishSpan`	net472	1.11μs	0.333ns	1.25ns	0.128	0.000554	810 B
#3146	`StartFinishSpan`	netcoreapp3.1	940ns	1.67ns	6.48ns	0.0103	0	760 B
#3146	`StartFinishScope`	net472	1.42μs	1.39ns	5.37ns	0.141	0	891 B
#3146	`StartFinishScope`	netcoreapp3.1	1.08μs	0.286ns	1.11ns	0.0119	0	880 B

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

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net472	1.5μs	0.438ns	1.58ns	0.141	891 B
master	`RunOnMethodBegin`	netcoreapp3.1	1.2μs	0.47ns	1.76ns	0.0118	880 B
#3146	`RunOnMethodBegin`	net472	1.48μs	0.662ns	2.56ns	0.141	891 B
#3146	`RunOnMethodBegin`	netcoreapp3.1	1.18μs	3.08ns	11.1ns	0.0118	880 B

andrewlock · 2022-09-09T16:01:58Z

Code Coverage Report 📊

✔️ Merging #3146 into master will not change line coverage
✔️ Merging #3146 into master will not change branch coverage
⛔ Merging #3146 into master will will increase complexity by 94

	master	#3146	Change
Lines	`17831` / `24369`	`18004` / `24521`
Lines %	`73%`	`73%`	`0%` ✔️
Branches	`10488` / `14968`	`10605` / `15054`
Branches %	`70%`	`70%`	`0%` ✔️
Complexity	`16169`	`16263`	`94` ⛔

View the full report for further details:

Datadog.Trace Breakdown ✔️

	master	#3146	Change
Lines %	`73%`	`73%`	`0%` ✔️
Branches %	`70%`	`70%`	`0%` ✔️
Complexity	`16169`	`16263`	`94` ⛔

The following classes have significant coverage changes.

File	Line coverage change	Branch coverage change	Complexity change
Datadog.Trace.Debugger.Sink.AgentBatchUploadApi	`-8%` ⛔	`0%` ✔️	`2` ⛔
Datadog.Trace.Ci.CIVisibility	`5%` ✔️	`6%` ✔️	`0` ✔️
Datadog.Trace.Activity.DiagnosticSourceEventListener	`6%` ✔️	`0%` ✔️	`0` ✔️
Datadog.Trace.Agent.Transports.HttpStreamRequestFactory	`12%` ✔️	`0%` ✔️	`0` ✔️
Datadog.Trace.Agent.DiscoveryService.DiscoveryService	`15%` ✔️	`46%` ✔️	`29` ⛔

The following classes were added in #3146:

File	Line coverage	Branch coverage	Complexity
Datadog.Trace.Agent.DiscoveryService.AgentConfiguration	`100%`	`100%`	`1`
Datadog.Trace.ClrProfiler.AutoInstrumentation.Process.EnvironmentVariablesScrubber	`100%`	`100%`	`11`
Datadog.Trace.ClrProfiler.AutoInstrumentation.Process.ProcessStartCommon	`85%`	`80%`	`11`
Datadog.Trace.ClrProfiler.AutoInstrumentation.Process.ProcessStartIntegration	`80%`	`50%`	`3`
Datadog.Trace.Tagging.ProcessCommandStartTags	`100%`	`100%`	`1`
...And 1 more

View the full reports for further details:

NachoEchevarria · 2022-09-12T07:42:45Z

An implementation of the instrumentation of the process.start() method. When this method is called, an span is generated.

NachoEchevarria requested review from a team as code owners August 31, 2022 15:47