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

Fixes issue when monitoring a process launched via the same command line #76965

Merged
merged 3 commits into from
Oct 20, 2022

Conversation

dramos020
Copy link
Contributor

@dramos020 dramos020 commented Oct 12, 2022

Fixes dotnet/diagnostics#3366. A NullReferenceException was being thrown and caught because the CommandHandler in MetricsEventSource was being referenced before being initialized. Now custom metrics are displayed when trying to monitor a process in the same command line. Here is example output for a simple application with a custom meter that displays random values:

  • Running dotnet-counters monitor --counters System.Runtime,demo_meter -- countersbug.exe will now output:

    Press p to pause, r to resume, q to quit.
        Status: Running
    
    [System.Runtime]
        % Time in GC since last GC (%)                                 0
        Allocation Rate (B / 1 sec)                               16,072
        CPU Usage (%)                                                  0
        Exception Count (Count / 1 sec)                                0
        GC Committed Bytes (MB)                                        0
        GC Fragmentation (%)                                           0
        GC Heap Size (MB)                                              0.462
        Gen 0 GC Count (Count / 1 sec)                                 0
        Gen 0 Size (B)                                                 0
        Gen 1 GC Count (Count / 1 sec)                                 0
        Gen 1 Size (B)                                                 0
        Gen 2 GC Count (Count / 1 sec)                                 0
        Gen 2 Size (B)                                                 0
        IL Bytes Jitted (B)                                       47,239
        LOH Size (B)                                                   0
        Monitor Lock Contention Count (Count / 1 sec)                  0
        Number of Active Timers                                        0
        Number of Assemblies Loaded                                   13
        Number of Methods Jitted                                     438
        POH (Pinned Object Heap) Size (B)                              0
        ThreadPool Completed Work Item Count (Count / 1 sec)           0
        ThreadPool Queue Length                                        0
        ThreadPool Thread Count                                        0
        Time spent in JIT (ms / 1 sec)                                10.01
        Working Set (MB)                                              25.793
    [demo_meter]
        random (Count / 1 sec)
            instance=app                                            -793.95
    
  • Running dotnet-counters monitor --counters demo_meter -- countersbug.exe will now output:

    Press p to pause, r to resume, q to quit.
        Status: Running
    
    [demo_meter]
        random (Count / 1 sec)
            instance=app                                 799.513
    

@ghost
Copy link

ghost commented Oct 12, 2022

Tagging subscribers to this area: @tarekgh, @tommcdon, @pjanotti
See info in area-owners.md if you want to be subscribed.

Issue Details

Fixes dotnet/diagnostics#3366. A NullReferenceException was being thrown and caught because the CommandHandler in MetricsEventSource was being referenced before being initialized. Now custom metrics are displayed when trying to monitor a process in the same command line. Here is example output for a simple application with a custom meter that displays random values:

  • Running dotnet-counters monitor --counters System.Runtime,demo_meter -- countersbug.exe will output:

    Press p to pause, r to resume, q to quit.
        Status: Running
    
    [System.Runtime]
        % Time in GC since last GC (%)                                 0
        Allocation Rate (B / 1 sec)                               16,072
        CPU Usage (%)                                                  0
        Exception Count (Count / 1 sec)                                0
        GC Committed Bytes (MB)                                        0
        GC Fragmentation (%)                                           0
        GC Heap Size (MB)                                              0.462
        Gen 0 GC Count (Count / 1 sec)                                 0
        Gen 0 Size (B)                                                 0
        Gen 1 GC Count (Count / 1 sec)                                 0
        Gen 1 Size (B)                                                 0
        Gen 2 GC Count (Count / 1 sec)                                 0
        Gen 2 Size (B)                                                 0
        IL Bytes Jitted (B)                                       47,239
        LOH Size (B)                                                   0
        Monitor Lock Contention Count (Count / 1 sec)                  0
        Number of Active Timers                                        0
        Number of Assemblies Loaded                                   13
        Number of Methods Jitted                                     438
        POH (Pinned Object Heap) Size (B)                              0
        ThreadPool Completed Work Item Count (Count / 1 sec)           0
        ThreadPool Queue Length                                        0
        ThreadPool Thread Count                                        0
        Time spent in JIT (ms / 1 sec)                                10.01
        Working Set (MB)                                              25.793
    [demo_meter]
        random (Count / 1 sec)
            instance=app                                            -793.95
    
  • Running dotnet-counters monitor --counters demo_meter -- countersbug.exe will output:

    Press p to pause, r to resume, q to quit.
        Status: Running
    
    [demo_meter]
        random (Count / 1 sec)
            instance=app                                 799.513
    
Author: dramos020
Assignees: -
Labels:

area-System.Diagnostics.Tracing

Milestone: -

@noahfalk
Copy link
Member

Can you include the callstack where the NullReferenceException occurs? A lot of the changes were swapping the Log property to a local parent field so does that also mean the static Log property was not initialized at that point? I want to understand what constraints we are working within :)

@davmason
Copy link
Member

davmason commented Oct 13, 2022

@noahfalk we're trying to grab the original exception but running in to technical difficulties.

The reason it fails is if you start a session before the runtime starts, you see the following scenario

  • MetricsEventSource static construct runs to initialize the Log object
  • It calls the base EventSource constructor, which sees a session is open and calls the OnEventCommand for MetricsEventSource from inside the EventSource constructor
  • Now we are calling in to MetricsEventSource before the static constructor has fully run and Log is assigned to so any call to Log will have a null reference

@noahfalk
Copy link
Member

Got it. What if we did something like this?

  1. When MetricsEventSource needs to access the command handler it can use a property and implement the property like this:
private CommandHandler Handler {
    get {
        if(_handler == null) {
            Interlocked.CompareExchange(ref _handler, new CommandHandler(this), null);
        }
        return handler;
    }
  1. When CommandHandler needs to access the MetricsEventSource it can do that through a property that was initialized in the CommandHandler constructor:
public CommandHandler(MetricsEventSource parent) {
    Parent = parent;
}
public MetricsEventSource Parent { get; }

// some code that needs to use parent
Parent.Error("Something bad happened");

@davmason
Copy link
Member

Works for me

@dramos020
Copy link
Contributor Author

dramos020 commented Oct 14, 2022

Just made the changes that were suggested. @noahfalk @davmason

@dramos020 dramos020 marked this pull request as ready for review October 14, 2022 21:16
Copy link
Member

@davmason davmason left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

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

Successfully merging this pull request may close these issues.

dotnet-counters issue when monitoring a process launched via the same command-line
3 participants