Linux performance problem

[Extred]

Hello.

I've spotted a performance drop on "Linux s4-srv 4.9.0-6-amd64 dotnet/coreclr#1 SMP Debian 4.9.88-1+deb9u1 (2018-05-07) x86_64 GNU/Linux" compared to Windows/MacOS.

Flame graphs:

Debian PerfView view:
deb.perfView.xml.zip

It looks like locale/encoding problem, but changing system locale settings (as suggested in https://github.com/dotnet/coreclr/issues/5612) helps not.

Tried on .NET Core runtimes 2.0.7 and 2.1.0.

[danmoseley]

Is it possible to resolve CLR symbols? Generally they should be on the public symbol server.

[danmoseley]

@mikem8361 can remind us how to do that for Linux.

[Extred]

If you mean that part then it's done already.
Perfcollect log:
Collection started. Press CTRL+C to stop.
^C
...STOPPED.
Starting post-processing. This may take some time.
Generating native image symbol files
...FINISHED
Saving native symbols
...FINISHED
Exporting perf.data file
...FINISHED
Compressing trace files
...FINISHED
Cleaning up artifacts
...FINISHED

Clicking 'resolve symbols' in PerfView does not make any effect.

[mikem8361]

@vancem might know more about this if this is perfview related.

[vancem]

The lack of symbols reduces the value of the deb.PerfView.xml.zip file that was attached. From the look of things, the instructions for getting the framework symbols did not work (all of the System.Private.Corelib file are not present.

The symbols for libcoreclr.so for V2.1 can be fetched from here, but the process is pretty painful (you have to unpack a zip and then unpack a nuget package …)

@mikem8361 was working on an application that made this easy. He may be willing to comment. We might be able to get away without the symbols for libcoreclr.so but it does look like they would be helpful.

Something that is pretty easy which is likely to be helpful is to collect using the new V2.1 'EventPipe' feature. For this you need to set the variables

export COMPlus_EnableEventPipe=1
export COMPlus_EventPipeConfig=Microsoft-DotNETCore-SampleProfiler:1:5

And run the program (on a V2.1 runtime) until it exits (you have to let it die cleanly) it will create a Process*.netperf file that can also be opened in PerfView (or put here). If you did that on both Linux and Windows, that would likely be very helpful.

Finally if you can easily 'package' up a repro and simply send us the files needed to run it (e.g. you can reduce it to a simple app and send us a ZIP of the unbuilt project directory (or put it on github somewhere) we could investigate it properly.

@brianrob

[mikem8361]

I’ll you know when this symbol downloader is ready. It should soon 😊.

[Extred]

@vancem I've tried EventPipe feature, but it does not create any .netperf files both on my project and helloworld sample.

Host (useful for support):
Version: 2.1.0
Commit: caa7b7e2ba
.NET Core SDKs installed:
2.1.300 [/usr/share/dotnet/sdk]

As for repro project: I'm trying to make one, but it's still unclear what's the cause of performance drop, so I can't reproduce it with simple app yet.

[vancem]

Hmm, I tried those instructions (setting the two environment variables (be careful with capitalization, it matters!) locally on what seems to be the same version Here is the complete output of 'dotnet --info'

.NET Core SDK (reflecting any global.json):
 Version:   2.1.300
 Commit:    adab45bf0c

Runtime Environment:
 OS Name:     ubuntu
 OS Version:  18.04
 OS Platform: Linux
 RID:         ubuntu.18.04-x64
 Base Path:   /usr/share/dotnet/sdk/2.1.300/

Host (useful for support):
  Version: 2.1.0
  Commit:  caa7b7e2ba

.NET Core SDKs installed:
  2.1.300 [/usr/share/dotnet/sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.0 [/usr/share/dotnet/shared/Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.0 [/usr/share/dotnet/shared/Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.0 [/usr/share/dotnet/shared/Microsoft.NETCore.App]

The important part is the 2.1.0 version of Microsoft.NETCore.App because that is the part that has the new EventPipe code.

I would start with the simplest case. Create a hello-world app and do

export COMPlus_EnableEventPipe=1
dotnet run 

And look for a *.netperf file.

Note that I corrected my entried above and here from

export COMPlus_EventPipeEnable=1

to

export COMPlus_EnableEventPipe=1

I was sloppy when transcribing it (I did the right thing when testing it, but not when writing up the instructions. Brian points this out below. COMPlus_EnableEventPipe is the correct variable.

[brianrob]

I missed this in my first read - the first environment variable is close, but not quite correct. You should use:

export COMPlus_EnableEventPipe=1
export COMPlus_EventPipeConfig=Microsoft-DotNETCore-SampleProfiler:1:5

The first environment variable is corrected to EnableEventPipe from EventPipeEnable.

Note that dotnet run is likely to give you at least two netperf files because it will run multiple dotnet processes - one for the SDK to ensure that the built app is up-to-date and one for your app. If compilation is required, I believe you may get more. If you want to guarantee that you only get one, you can build your app first and then run dotnet path/to/dll.

[Extred]

That worked!

netperfs.zip

Both perfs are for 3-minute app worktime.
There is a heavy startup in that app so first 30s can be ignored.

[vancem]

OK I have decoded the files. Brian for you information they re in my public clrmain area under users\vancem\issue18465. There is a linux.netperf and a win.netperf

One big difference I see right away is that the Linux trace has a bunch of EventSource logging overhead that is coming from the network and task library instrumentation. This is not present in the windows trace. There is alot of overhead in System.Diagnostics.Tracing.EventSource.DispatchToAllListener which is the path to send things to an EventListener. We should not be going down this path for EventPipe correct?

@Extred : another possibility is something has turned on more logging (e.g. some monitoring system). Are there any monitoring systems that you know about on your Linux run?

I need to look at this trace a bit and do some experiments myself. Right now the problem is clearly excessive logging (I have conformed that the netperf file does NOT have any events but the Thread Sampling, so it does not seem to be EventPipe itself that is causing the additional events.

[vancem]

In the Linux trace I also see System.IO.FileSystem.Watcher running in the Linux trace but not in the Windows trace at all. @Extred it would be useful to see what is going on in a debugger with this (set a breakpoint on its constructors). My guess is that again there is a code difference on Linux.

[vancem]

I have confirmed that in a sample MVC app that when you turn on EventPipe

1. There is NOT alot of EventSource overhead. Thus it is NOT something inherent in ASP.NET or EventPipe but something specific to @Extred scenario.

2. There IS however a bunch of FileSystem.Watcher overhead. Thus this seems to be something built into ASP.NET. Investigating...

To dig into (1) above you can place a breakpoint at System.Diagnostics.Tracing.EventSource.DoCommand. This routine is called any time a EventSource provider is enabled or disabled (or other commands sent to it). We need to find out who is turning on EventSources.

[vancem]

Ignore the issue with FileSystem.Watcher I am forgetting that this is thread time, not CPU time. You expect alot of blocked time just waiting around for a file system change.

[Extred]

@vancem

Are there any monitoring systems that you know about on your Linux run?

No, that's a fresh linux installation

To dig into (1) above you can place a breakpoint at System.Diagnostics.Tracing.EventSource.DoCommand

How do I do that?

My guess is that again there is a code difference on Linux

Code is the same, I've copied the publish directory to Windows from Linux