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

Linux performance problem #18465

Open
Extred opened this Issue Jun 14, 2018 · 18 comments

Comments

Projects
None yet
6 participants
@Extred

Extred commented Jun 14, 2018

Hello.

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

Flame graphs:
image

Debian PerfView view:
deb.perfView.xml.zip

It looks like locale/encoding problem, but changing system locale settings (as suggested in #5612) helps not.

Tried on .NET Core runtimes 2.0.7 and 2.1.0.

@danmosemsft

This comment has been minimized.

Show comment
Hide comment
@danmosemsft

danmosemsft Jun 15, 2018

Member

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

Member

danmosemsft commented Jun 15, 2018

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

@danmosemsft

This comment has been minimized.

Show comment
Hide comment
@danmosemsft

danmosemsft Jun 15, 2018

Member

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

Member

danmosemsft commented Jun 15, 2018

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

@Extred

This comment has been minimized.

Show comment
Hide comment
@Extred

Extred Jun 15, 2018

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.

Extred commented Jun 15, 2018

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

This comment has been minimized.

Show comment
Hide comment
@mikem8361

mikem8361 Jun 15, 2018

Member

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

Member

mikem8361 commented Jun 15, 2018

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

@vancem

This comment has been minimized.

Show comment
Hide comment
@vancem

vancem Jun 19, 2018

Member

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

Member

vancem commented Jun 19, 2018

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

This comment has been minimized.

Show comment
Hide comment
@mikem8361

mikem8361 Jun 19, 2018

Member
Member

mikem8361 commented Jun 19, 2018

@Extred

This comment has been minimized.

Show comment
Hide comment
@Extred

Extred Jun 20, 2018

@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.

Extred commented Jun 20, 2018

@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

This comment has been minimized.

Show comment
Hide comment
@vancem

vancem Jun 20, 2018

Member

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.

Member

vancem commented Jun 20, 2018

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

This comment has been minimized.

Show comment
Hide comment
@brianrob

brianrob Jun 20, 2018

Member

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.

Member

brianrob commented Jun 20, 2018

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

This comment has been minimized.

Show comment
Hide comment
@Extred

Extred Jun 20, 2018

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.

Extred commented Jun 20, 2018

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

This comment has been minimized.

Show comment
Hide comment
@vancem

vancem Jun 20, 2018

Member

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.

Member

vancem commented Jun 20, 2018

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

This comment has been minimized.

Show comment
Hide comment
@vancem

vancem Jun 20, 2018

Member

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.

Member

vancem commented Jun 20, 2018

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

This comment has been minimized.

Show comment
Hide comment
@vancem

vancem Jun 20, 2018

Member

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.

Member

vancem commented Jun 20, 2018

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

This comment has been minimized.

Show comment
Hide comment
@vancem

vancem Jun 20, 2018

Member

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.

Member

vancem commented Jun 20, 2018

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

This comment has been minimized.

Show comment
Hide comment
@Extred

Extred Jun 20, 2018

@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

Extred commented Jun 20, 2018

@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

@brianrob

This comment has been minimized.

Show comment
Hide comment
@brianrob

brianrob Jun 20, 2018

Member

@vancem, the difference in EventSource events coming to EventPipe is expected for .NET Core 2.1 as the fix to enable these for Windows was made in a post 2.1 change. You are also correct that EventPipe should not cause anything to go down the EventListener path - it goes down the platform logger (ETW) path.

Member

brianrob commented Jun 20, 2018

@vancem, the difference in EventSource events coming to EventPipe is expected for .NET Core 2.1 as the fix to enable these for Windows was made in a post 2.1 change. You are also correct that EventPipe should not cause anything to go down the EventListener path - it goes down the platform logger (ETW) path.

@brianrob

This comment has been minimized.

Show comment
Hide comment
@brianrob

brianrob Jun 20, 2018

Member

It sounds like there is an EventListener being turned on somewhere, as that would explain the time spent in System.Diagnostics.Tracing.EventSource.DispatchToAllListener.

Member

brianrob commented Jun 20, 2018

It sounds like there is an EventListener being turned on somewhere, as that would explain the time spent in System.Diagnostics.Tracing.EventSource.DispatchToAllListener.

@Extred

This comment has been minimized.

Show comment
Hide comment
@Extred

Extred Jun 21, 2018

Found the cause: it's related to locale settings AND specific symbols in target strings.

Here is the repro: https://gist.github.com/Extred/9a7c827d3538b2bbc1bd2be50e4ecbee

windows:

ru-RU; CompareInfo - ru-RU
GOOD: 00:00:00.1328909
BAD: 00:00:00.1115774

linux:

root@s4:~/js# dotnet wx-test.dll
en-US; CompareInfo - en-US
GOOD: 00:00:00.0706630
BAD: 00:00:10.5655465

root@s4:~/js# export LANG=ru_RU.UTF-8
root@s4:~/js# dotnet wx-test.dll
ru-RU; CompareInfo - ru-RU
GOOD: 00:00:09.6179485
BAD: 00:00:10.1025412

StringComparison.OrdinalIgnoreCase removes the problem.
Seems like heavily related to #5612

Extred commented Jun 21, 2018

Found the cause: it's related to locale settings AND specific symbols in target strings.

Here is the repro: https://gist.github.com/Extred/9a7c827d3538b2bbc1bd2be50e4ecbee

windows:

ru-RU; CompareInfo - ru-RU
GOOD: 00:00:00.1328909
BAD: 00:00:00.1115774

linux:

root@s4:~/js# dotnet wx-test.dll
en-US; CompareInfo - en-US
GOOD: 00:00:00.0706630
BAD: 00:00:10.5655465

root@s4:~/js# export LANG=ru_RU.UTF-8
root@s4:~/js# dotnet wx-test.dll
ru-RU; CompareInfo - ru-RU
GOOD: 00:00:09.6179485
BAD: 00:00:10.1025412

StringComparison.OrdinalIgnoreCase removes the problem.
Seems like heavily related to #5612

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment