Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
lpnam0201 opened this issue Jul 4, 2024 · 1 comment
Open

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

lpnam0201 opened this issue Jul 4, 2024 · 1 comment

Comments

@lpnam0201
Copy link

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.
@brianrob
Copy link
Member

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants