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

Add benchmark for SuppressInstrumentation #1049

Closed

Conversation

alanwest
Copy link
Member

@alanwest alanwest commented Aug 12, 2020

Related to #1079 and #1098.

Method Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
SuppressInstrumentationFalse 1,349.4 ns 24.13 ns 22.58 ns 0.0267 - - 744 B
SuppressInstrumentationTrue 303.2 ns 6.01 ns 6.44 ns 0.0091 - - 240 B
SuppressInstrumentationTrueNested 425.1 ns 8.52 ns 9.12 ns 0.0172 - - 456 B
NoneListener 147.7 ns 2.26 ns 1.89 ns 0.0007 - - 24 B
AllDataAndRecordedListener1 1,236.0 ns 23.93 ns 27.55 ns 0.0248 - - 656 B
AllDataAndRecordedListener2 1,315.1 ns 25.98 ns 31.91 ns 0.0267 - - 744 B

@reyang

@alanwest alanwest requested a review from a team August 12, 2020 01:04
{
BenchmarkSwitcher.FromAssembly(typeof(Program).Assembly).Run(args);
Copy link
Member Author

Choose a reason for hiding this comment

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

Changed this so you can run like:

dotnet run --configuration Release --filter SuppressInstrumentationBenchmarks

or

dotnet run --configuration Release --filter TraceBenchmarks

Copy link
Member

Choose a reason for hiding this comment

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

@alanwest FYI the benchmark project in /test/ is already set up for that. We should combine these two benchmark projects at some point.

Copy link
Member Author

Choose a reason for hiding this comment

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

Yep noticed that, that's where I copied the pattern. Put these next to @reyang's other benchmarks for now since they are similar, but we can discuss a better place once we're through with analysis.

Copy link
Member

Choose a reason for hiding this comment

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

Ping back from #1039 (comment).

@codecov
Copy link

codecov bot commented Aug 12, 2020

Codecov Report

Merging #1049 into master will increase coverage by 0.01%.
The diff coverage is n/a.

Impacted file tree graph

@@            Coverage Diff             @@
##           master    #1049      +/-   ##
==========================================
+ Coverage   75.83%   75.85%   +0.01%     
==========================================
  Files         225      225              
  Lines        6225     6225              
==========================================
+ Hits         4721     4722       +1     
+ Misses       1504     1503       -1     
Impacted Files Coverage Δ
...us/Implementation/PrometheusExporterEventSource.cs 72.72% <0.00%> (+9.09%) ⬆️

@reyang
Copy link
Member

reyang commented Aug 12, 2020

Looks like the memory allocation increased from 656B to 744B. We probably need to analyze where the tax is coming from using https://docs.microsoft.com/visualstudio/profiling/dotnet-alloc-tool.

FYI @cijothomas @rajkumar-rangaraj @ThomsonTan in case you might be interested.

@reyang reyang added the question Further information is requested label Aug 12, 2020
@rajkumar-rangaraj
Copy link
Contributor

@reyang I will investigate an increase in allocation.

@alanwest
Copy link
Member Author

So I'm fairly certain the increase is simply the AsyncLocal allocation. Ran a simple console app:

public static void Main(string[] args)
{
    using var sourceWithSuppressInstrumentation = new ActivitySource("Benchmark.SuppressInstrumentation");

    Activity.DefaultIdFormat = ActivityIdFormat.W3C;

    ActivitySource.AddActivityListener(new ActivityListener
    {
        ActivityStarted = null,
        ActivityStopped = null,
        ShouldListenTo = (activitySource) => activitySource.Name == sourceWithSuppressInstrumentation.Name,
        GetRequestedDataUsingParentId = (ref ActivityCreationOptions<string> options) => { return Sdk.SuppressInstrumentation ? ActivityDataRequest.None : ActivityDataRequest.AllDataAndRecorded; },
        GetRequestedDataUsingContext = (ref ActivityCreationOptions<ActivityContext> options) => { return Sdk.SuppressInstrumentation ? ActivityDataRequest.None : ActivityDataRequest.AllDataAndRecorded; },
    });

    for (var i = 0; i < 5000; ++i)
    {
        using (var activity = sourceWithSuppressInstrumentation.StartActivity("Benchmark"))
        {
            // this activity will be created and feed into an ActivityListener that simply drops everything on the floor
        }
    }
}

The allocations per iteration for OneElementAsyncLocalMap + TwoElementAsyncLocalMap is about 80 bytes.

Screen Shot 2020-08-11 at 9 48 44 PM

Screen Shot 2020-08-11 at 9 48 58 PM

@alanwest
Copy link
Member Author

I left a comment declaring no more increase in allocations after cherry-picking #1067 into this PR. I lied 😬. Comment deleted. Here are the real results after cherry-picking:

Method Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
SuppressInstrumentationFalse 1,272.5 ns 24.75 ns 33.87 ns 0.0248 - - 656 B
SuppressInstrumentationTrue 298.1 ns 5.83 ns 11.65 ns 0.0091 - - 240 B
SuppressInstrumentationTrueNested 425.2 ns 8.44 ns 15.64 ns 0.0172 - - 456 B
NoneListener 145.5 ns 2.95 ns 4.93 ns 0.0007 - - 24 B
AllDataAndRecordedListener1 1,280.8 ns 25.26 ns 45.56 ns 0.0248 - - 656 B
AllDataAndRecordedListener2 1,769.9 ns 34.42 ns 58.44 ns 0.0324 - - 864 B

SuppressInstrumentationFalse case is better but the AllDataAndRecordedListener2 case is worse.

@alanwest alanwest force-pushed the alanwest/suppress-benchmarks branch from eff2abb to f3e3c3a Compare August 17, 2020 17:44
@alanwest
Copy link
Member Author

@reyang Here are the latest results. My interpretation is that the check (i.e., Sdk.SuppressInstrumentation) no longer results in additional memory allocation. Prior to #1067, we were seeing that even the check resulted in additional allocations (as seen between the AllDataAndRecordedListener1 and AllDataAndRecordedListener2 cases).

My question now is that since the "check" seems free of additional allocations do we want to move forward with #1079 or instead explore the "alternatives" I've referenced in the description of that PR?

Method Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
SuppressInstrumentationFalse 1,565.7 ns 30.56 ns 33.97 ns 0.0248 - - 656 B
SuppressInstrumentationTrue 354.2 ns 7.05 ns 8.65 ns 0.0091 - - 240 B
SuppressInstrumentationTrueNested 551.6 ns 11.06 ns 28.54 ns 0.0172 - - 456 B
NoneListener 163.2 ns 3.25 ns 4.22 ns 0.0007 - - 24 B
AllDataAndRecordedListener1 1,539.6 ns 30.27 ns 44.37 ns 0.0248 - - 656 B
AllDataAndRecordedListener2 1,521.8 ns 30.37 ns 26.92 ns 0.0248 - - 656 B

@reyang
Copy link
Member

reyang commented Aug 17, 2020

My question now is that since the "check" seems free of additional allocations do we want to move forward with #1079 or instead explore the "alternatives" I've referenced in the description of that PR?

I think if there is no additional memory allocation cost, and the extra CPU cost is less than 3%, it makes good sense to add it to the hotpath.

@alanwest
Copy link
Member Author

alanwest commented Aug 17, 2020

When Sdk.SuppressInstrumentation == false I think these are the relevant benchmarks to compare:

Method Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
SuppressInstrumentationFalse 1,565.7 ns 30.56 ns 33.97 ns 0.0248 - - 656 B
AllDataAndRecordedListener1 1,539.6 ns 30.27 ns 44.37 ns 0.0248 - - 656 B
  • SuppressInstrumentationFalse has the the Sdk.SuppressInstrumentation check which returns false.
  • AllDataAndRecordedListner1 does not have the check. That is, it always returns ActivityDataRequest.AllDataAndRecorded.

Memory allocation is the same. CPU is actually slightly lower w/ the check. Seems like a bit of a wash.


When Sdk.SuppressInstrumentation == true I think it's a bit harder to find a point of comparison here, but if we compare the following:

Method Mean Error StdDev Gen 0 Gen 1 Gen 2 Allocated
SuppressInstrumentationTrue 354.2 ns 7.05 ns 8.65 ns 0.0091 - - 240 B
NoneListener 163.2 ns 3.25 ns 4.22 ns 0.0007 - - 24 B
  • SuppressInstrumentationTrue has the the Sdk.SuppressInstrumentation check which returns true resulting in ActivityDataRequest.None.
  • NoneListener does not have the check. That is, it always returns ActivityDataRequest.None.

Memory allocation is naturally different between these cases. SuppressInstrumentationTrue allocates to AsyncLocal. Not a surprise that CPU is different here too. The differences look dramatic, though Sdk.SuppressInstrumentation == true will be the less common scenario. From the standpoint of suppressing things prior to invoking an exporter, any additional overhead will be incurred by operations performed by the exporter that are instrumented under normal circumstances (e.g., an HTTP call).

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

Successfully merging this pull request may close these issues.

4 participants