IDbProfiler not adding to _inProgress if timing is null

[michal-ciechan]

We are getting the following null reference exceptions:

System.NullReferenceException
HResult=0x80004003
Message=Object reference not set to an instance of an object.
Source=MiniProfiler.Shared
StackTrace:
at StackExchange.Profiling.MiniProfiler.StackExchange.Profiling.Data.IDbProfiler.ExecuteFinish(IDbCommand profiledDbCommand, SqlExecuteType executeType, DbDataReader reader) in C:\projects\dotnet\src\MiniProfiler.Shared\MiniProfiler.IDbProfiler.cs:line 75
at StackExchange.Profiling.Data.ProfiledDbCommand.ExecuteNonQuery() in C:\projects\dotnet\src\MiniProfiler.Shared\Data\ProfiledDbCommand.cs:line 297
at Dapper.SqlMapper.ExecuteCommand(IDbConnection cnn, CommandDefinition& command, Action`2 paramReader) in /_/Dapper/SqlMapper.cs:line 2813
at Dapper.SqlMapper.ExecuteImpl(IDbConnection cnn, CommandDefinition& command) in /_/Dapper/SqlMapper.cs:line 572
at Dapper.SqlMapper.Execute(IDbConnection cnn, String sql, Object param, IDbTransaction transaction, Nullable`1 commandTimeout, Nullable`1 commandType) in /_/Dapper/SqlMapper.cs:line 443

From the looks of things, looks like profiledDbCommand.GetTiming(executeType.ToString(), this); can return null, which we then add. Later on we use this CustomTiming inside IDbProfiler.ExecuteFinish without null checking.

It doesn't make sense adding a null to that collection imho?

[NickCraver]

I'm not 100% sure on what combination leads to a null profiler but still calling these methods, so I'm still curious there if you could share your profiled connection setup, but no problems at all adding protection for the case. Thanks for the addition!

[michal-ciechan]

Thanks for merging, I will try to replicate this, but in short it is probably partly because a parent profile span is being killed before and child one as we kick off a task from an AspNetCore request which carries on running.

I have tried resetting the "Head" to null, so that it generates a new "tree root" but we still noticed this issue occasionally, albeit so far only while debugging locally not in production. (Sorry for wrong naming)

This rarely happens and seems to be some sort of race condition, where I would guess, only happens if you have timings that continue where parent has finished. And seems to always happen when finishing a Dapper call.

I will try to get a minimum repro at some point (probably next weekend), see if I get any luck. Unfortunately can't share company code where we were seeing this.