perfview icon indicating copy to clipboard operation
perfview copied to clipboard

Log shows that Provider's Level is Critical (expected: Verbose)

Open lpnam0201 opened this issue 1 year ago • 1 comments

I'm trying out PerfView to see events of *Microsoft-System-Net-Http and *Microsoft-System-Net.Security I have an ASP.NET application running in the machine, and I used the following config image

The result .etl file looks like this (it doesn't have any events of Microsoft-System-Net-Http, Microsoft-System-Net.Security that I'm expecting) image

Here is the log of PerfView Could it be because it uses Level:Critical for my ETW Providers so I don't see any other events ? How do I force it to use Level:Verbose ?

Collection Dialog open.
Started: Collecting data D:\users\nlp\PerfViewData.etl
[Kernel Log: D:\users\nlp\PerfViewData.kernel.etl]
Kernel keywords enabled: None
[User mode Log: D:\users\nlp\PerfViewData.etl]
Enabling Provider:PerfViewLogger Level:Verbose Keywords:0xffffffffffffffff Stacks:0 Values: Guid:a8a71ac1-040f-54a2-07ca-00a89b5ab761
Enabling Providers specified by the user.
Parsing ETW Provider Spec: *Microsoft-System-Net-Http
Parsing ETW Provider Spec: *Microsoft-System-Net.Security
Enabling Provider:*Microsoft-System-Net-Http Level:Verbose Keywords:0xffffffffffffffff Stacks:0 Values: Guid:bdd9a83e-1929-5482-0d73-2fe5e1c0e16d
Enabling Provider:*Microsoft-System-Net.Security Level:Verbose Keywords:0xffffffffffffffff Stacks:0 Values: Guid:6f8297ee-33c3-5151-4352-7233647873dd
[Starting collection at 04.07.2024 05:59:18][Collecting   10 sec: Size=  0.1 MB.]
[Collecting   20 sec: Size=  0.1 MB.]
[Collecting   30 sec: Size=  0.1 MB.]
[Manually Stopped (Gui)]
Stopping tracing for sessions 'NT Kernel Logger' and 'PerfViewSession'.
No Heap events were active for this trace.
[Sending rundown command to CLR providers...]
Enabling Provider:PerfViewLogger Level:Verbose Keywords:0xffffffffffffffff Stacks:0 Values: Guid:a8a71ac1-040f-54a2-07ca-00a89b5ab761
Parsing ETW Provider Spec: *Microsoft-System-Net-Http
Parsing ETW Provider Spec: *Microsoft-System-Net.Security
Enabling Provider:*Microsoft-System-Net-Http Level:Critical Keywords:0x80000000000 Stacks:0 Values: Guid:bdd9a83e-1929-5482-0d73-2fe5e1c0e16d
Enabling Provider:*Microsoft-System-Net.Security Level:Critical Keywords:0x80000000000 Stacks:0 Values: Guid:6f8297ee-33c3-5151-4352-7233647873dd
Waiting up to 120 sec for rundown events.  Use /RundownTimeout to change.
Maximum rundown file size is -1MB.  Use /RundownMaxMB to change.
If you know your process has exited, use /noRundown qualifer to skip this step.
Rundown File Length: 0.1MB delta: 0.1MB
Rundown File Length: 0.1MB delta: 0.0MB
Rundown file has stopped growing, assuming rundown complete.
CLR Rundown took 2.178 sec.
Done stopping sessions.

lpnam0201 avatar Jul 04 '24 04:07 lpnam0201

If you look earlier in the log, you'll see the following:

Parsing ETW Provider Spec: *Microsoft-System-Net-Http
Parsing ETW Provider Spec: *Microsoft-System-Net.Security
Enabling Provider:*Microsoft-System-Net-Http Level:Verbose Keywords:0xffffffffffffffff Stacks:0 Values: Guid:bdd9a83e-1929-5482-0d73-2fe5e1c0e16d
Enabling Provider:*Microsoft-System-Net.Security Level:Verbose Keywords:0xffffffffffffffff Stacks:0 Values: Guid:6f8297ee-33c3-5151-4352-7233647873dd

This is where the providers are being enabled with all keywords enabled at verbose level. Later in the trace after you stop collection, rundown is performed, and these providers are re-enabled in the rundown session with the following configuration:

Parsing ETW Provider Spec: *Microsoft-System-Net-Http
Parsing ETW Provider Spec: *Microsoft-System-Net.Security
Enabling Provider:*Microsoft-System-Net-Http Level:Critical Keywords:0x80000000000 Stacks:0 Values: Guid:bdd9a83e-1929-5482-0d73-2fe5e1c0e16d
Enabling Provider:*Microsoft-System-Net.Security Level:Critical Keywords:0x80000000000 Stacks:0 Values: Guid:6f8297ee-33c3-5151-4352-7233647873dd

This rundown step is asking the providers to dump their manifests into the event stream to ensure that they were captured. The manifest is what is used by PerfView to decode the events from these providers.

I suspect that there is something else happening here. Either the provider names are incorrect, which results in the wrong ETW provider GUIDs, or the processes of interest are not actually running during trace capture. Can you confirm that the provider names are correct and that they are event sources? If you are trying to enable the System.Net events, I suspect that the security provider is incorrect: https://github.com/dotnet/runtime/blob/e56ebd16a77992f9fea8e919960cec74955a6714/docs/workflow/debugging/libraries/windows-instructions.md?plain=1#L164

brianrob avatar Jul 12 '24 22:07 brianrob