I can't understand how it works inside

[verdysh]

Hi!

I'm trying to understand how open telemetry works.
I have this configuration of open telemetry

builder.Services.AddOpenTelemetryTracing(builder =>
{
	builder.AddConsoleExporter();	
	builder.AddSqlClientInstrumentation(opt =>
	{
		opt.SetDbStatementForText = true;
	});
});

And I have controller with this action:

[HttpGet("sqlDelay")]
public async Task SqlDelay()
{
	var db1 = new TracingDemoDbContext(_options);
	var t1 = db1.Database.ExecuteSqlRawAsync("exec Delay");

	await Task.Delay(1500);

	var db2 = new TracingDemoDbContext(_options);
	var t2 = db2.Database.ExecuteSqlRawAsync("exec Delay");

	await Task.WhenAll(t1, t2);
}

"exec Delay" - it's a call to stored procedure which is executed 3 seconds.
As a result I see correct activities in console:

Activity.TraceId:          1eef473d4ae1dd45ccd61b3a468c28a6
Activity.SpanId:           b3338719ba9e9498
Activity.TraceFlags:           Recorded
Activity.ParentSpanId:    389ba8ba705e5944
Activity.ActivitySourceName: OpenTelemetry.SqlClient
Activity.DisplayName: TracingDemoDb
infoActivity.Kind:        Client
Activity.StartTime:   2022-06-07T18:19:14.0592323Z
Activity.Duration:    00:00:03.0024293

Activity.TraceId:          1eef473d4ae1dd45ccd61b3a468c28a6
Activity.SpanId:           ec886023cfb98782
Activity.TraceFlags:           Recorded
infoActivity.ParentSpanId:    92109c4d7efdc515
Activity.ActivitySourceName: OpenTelemetry.SqlClient
Activity.DisplayName: TracingDemoDb
Activity.Kind:        Client
Activity.StartTime:   2022-06-07T18:19:15.5625225Z
Activity.Duration:    00:00:03.0037277

*with correct duration of each

How it works on my opinion.
In SqlCommand there is SqlDiagnosticListener through which it writes its diagnostic events.
SqlClientDiagnosticListener is listening to these events and calls appropriate handler which is SqlClientDiagnosticListener in current case.

In case of SqlMicrosoftBeforeExecuteCommand/SqlDataBeforeExecuteCommand events it creates new activity (which is set as Current under the hood), in cases when command is finished it stops activity which is passed as Activity.Current from SqlClientDiagnosticListener.

When activity is stopped, ConsoleActivityExporter is notified about that and writes activity data to Console.

Knowing all that, I assumed there can be wrong result in case when we start second query while first isn't finished yet. I imagined something like this will happen:

• var t1 = db1.Database.ExecuteSqlRawAsync("exec Delay");
  this creates new activity (A1) and sets it as Current

• var t2 = db2.Database.ExecuteSqlRawAsync("exec Delay");
  this creates new activity (A2) and sets it as Current; probably, A1 will be parent activity for this one.

• when t1 will be finished it takes A2 activity (as it's current) and stops it

• when t2 will be finished it takes A1 activity (because A2 already is stopped and current is A1) and stops it

I thought it would lead to the fact when A1 will have duration more than 3 seconds, A2 will have duration less than 3 seconds.
But both activities have duration equal 3 seconds as they should.

I've spent a lot of time trying to figure out how it works, but I haven't been able to figure it out.

Could someone explain to me how it works?

[cijothomas]

@rajkumar-rangaraj @vishweshbankwar Could you help?

[vishweshbankwar]

@verdysh Activity.Current is local to your asynchronous flow. So, when you do db2.Database.ExecuteSqlRawAsync("exec Delay"); after
db1.Database.ExecuteSqlRawAsync("exec Delay"); it would not set activity created in db1.Database.ExecuteSqlRawAsync("exec Delay"); as parent to the one being created in db2.Database.ExecuteSqlRawAsync("exec Delay"); . The parent would be whatever operation started these two async operations.

However, in your sample output of console, I see two different parent IDs for the exporter activities. Is that being created inside new TracingDemoDbContext(_options);?

[verdysh]

@vishweshbankwar thanks for the answer!

I thought there is one ExecutionContext during http request. That's why I thought there will be the same instance of ExecutionContext inside both these calls db1.Database.ExecuteSqlRawAsync("exec Delay"), db2.Database.ExecuteSqlRawAsync("exec Delay"). Because of this I thought when activity is set as Current inside db1.Database.ExecuteSqlRawAsync("exec Delay") it becomes Current in db2.Database.ExecuteSqlRawAsync("exec Delay") because the same ExecutionContext will be in both these calls.

From your answer I understood that inside db1.Database.ExecuteSqlRawAsync("exec Delay") and db2.Database.ExecuteSqlRawAsync("exec Delay") there will be different instances of ExecutionContext. If it's so, where exactly these instances are created?

I looked to AsyncTaskMethodBuilder and all I saw is how current ExecutionContext is captured and passed on. I didn't find where new instances of ExecutionContext can be created.

However, in your sample output of console, I see two different parent IDs for the exporter activities. Is that being created inside new TracingDemoDbContext(_options);?

I don't know why it happened so. Maybe I messed something and copied wrong peace of output from console. I have checked few times today and today it seems all is correct:

Activity.TraceId:          83616a2f61af1e3453e81e9d687bd567
Activity.SpanId:           3d2145013d067d36
Activity.TraceFlags:           Recorded
Activity.ParentSpanId:    f6451ba12c921e2e
Activity.ActivitySourceName: OpenTelemetry.SqlClient
Activity.DisplayName: TracingDemoDb
Activity.Kind:        Client
Activity.StartTime:   2022-06-09T08:42:04.7547016Z
Activity.Duration:    00:00:03.0236279
Activity.Tags:
    db.system: mssql
    db.name: TracingDemoDb
    peer.service: 127.0.0.1
    db.statement_type: Text
    db.statement: exec Delay
   StatusCode : UNSET
Resource associated with Activity:
    service.name: unknown_service:dotnet

Activity.TraceId:          83616a2f61af1e3453e81e9d687bd567
Activity.SpanId:           0090cfbe8a9cd09e
Activity.TraceFlags:           Recorded
Activity.ParentSpanId:    f6451ba12c921e2e
Activity.ActivitySourceName: OpenTelemetry.SqlClient
Activity.DisplayName: TracingDemoDb
Activity.Kind:        Client
Activity.StartTime:   2022-06-09T08:42:06.1012368Z
Activity.Duration:    00:00:03.0150139
Activity.Tags:
    db.system: mssql
    db.name: TracingDemoDb
    peer.service: 127.0.0.1
    db.statement_type: Text
    db.statement: exec Delay
   StatusCode : UNSET
Resource associated with Activity:
    service.name: unknown_service:dotnet

Activity.TraceId:          83616a2f61af1e3453e81e9d687bd567
Activity.SpanId:           f6451ba12c921e2e
Activity.TraceFlags:           Recorded
Activity.ActivitySourceName: OpenTelemetry.Instrumentation.AspNetCore
Activity.DisplayName: api/Values/sqlDelay
Activity.Kind:        Server
Activity.StartTime:   2022-06-09T08:42:03.6985584Z
Activity.Duration:    00:00:05.4741324
Activity.Tags:
    http.host: localhost:7172
    http.method: GET
    http.target: /api/values/sqlDelay
    http.url: https://localhost:7172/api/values/sqlDelay
    http.user_agent: PostmanRuntime/7.29.0
    http.route: api/Values/sqlDelay
    http.status_code: 200
   StatusCode : UNSET
Resource associated with Activity:
    service.name: unknown_service:dotnet

[vishweshbankwar]

@verdysh
Take a look at https://docs.microsoft.com/dotnet/api/system.threading.asynclocal-1?view=net-6.0. This is what Activity.Current uses internally.

[verdysh]

@vishweshbankwar if I understood you correct, my question isn't related to Open Telemetry, it's related to AsyncLocal implementation. I will figure out how it works. Thank you for your time!

@cijothomas thank you for participation too!