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.

Sign up for GitHub

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

Jump to bottom

[Perf] Regression in Perf_FileStream #49156

Closed
DrewScoggins opened this issue Mar 4, 2021 · 8 comments
Closed

[Perf] Regression in Perf_FileStream #49156

DrewScoggins opened this issue Mar 4, 2021 · 8 comments
Assignees
@adamsitnik
Labels
arch-x64 area-System.IO os-linux Linux OS (any supported distro) tenet-performance Performance related issue tenet-performance-benchmarks Issue from performance benchmark
Milestone
6.0.0

Comments

@DrewScoggins
Copy link
Member

Run Information

Architecture x64
OS ubuntu 18.04
Baseline d5ab93c4a8e45da2dab8924c2165000bf78f84e6
Compare cbb5b905d67a91ecf293c8807414b7791713b02d

Regressions in System.IO.Tests.Perf_FileStream

Benchmark Baseline Test Test/Base Baseline IR Compare IR IR Ratio Baseline ETL Compare ETL
ReadByte 7.15 μs 8.49 μs 1.19
ReadAsync 7.87 μs 8.35 μs 1.06
OpenClose 2.87 μs 3.28 μs 1.15
Read 4.44 μs 4.86 μs 1.10
ReadAsync 5.92 μs 6.30 μs 1.06
ReadAsync 6.52 μs 7.88 μs 1.21
ReadByte 6.96 μs 8.79 μs 1.26

graph
graph
graph
graph
graph
graph
graph
Historical Data in Reporting System

Repro

git clone https://github.com/dotnet/performance.git
python3 .\performance\scripts\benchmarks_ci.py -f netcoreapp5.0 --filter 'System.IO.Tests.Perf_FileStream*'

.

Payloads

Baseline
Compare

Histogram

System.IO.Tests.Perf_FileStream.ReadByte(fileSize: 1024, options: None)

[6826.607 ; 7055.656) | @@@@@@@@@@@@@@@@@@@@
[7055.656 ; 7272.377) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[7272.377 ; 7544.007) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[7544.007 ; 7788.644) | @@@@@@@@@@@@@@@@@@@@@@@@
[7788.644 ; 7956.825) | @@@@
[7956.825 ; 8115.204) | 
[8115.204 ; 8369.989) | @@@@@@@@@
[8369.989 ; 8586.710) | @@@@@@@@@@@@
[8586.710 ; 8835.881) | @@@

System.IO.Tests.Perf_FileStream.ReadAsync(fileSize: 1024, userBufferSize: 512, options: None)

[7063.669 ; 7262.293) | @@@@@@@@
[7262.293 ; 7474.602) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[7474.602 ; 7804.894) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[7804.894 ; 7976.427) | @
[7976.427 ; 8188.736) | 
[8188.736 ; 8470.922) | @@@@@
[8470.922 ; 8683.231) | @@@@@@@@@@@@@@@@@
[8683.231 ; 8915.446) | @@@@

System.IO.Tests.Perf_FileStream.OpenClose(fileSize: 1024, options: None)

[2783.082 ; 2841.874) | @@@@@
[2841.874 ; 2907.343) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[2907.343 ; 2977.449) | @@@@@@@@@@@@@@
[2977.449 ; 3085.689) | @@@@@@@@@@@@@
[3085.689 ; 3151.158) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[3151.158 ; 3225.832) | @@@@@@@
[3225.832 ; 3374.205) | @@@@@@@@@

System.IO.Tests.Perf_FileStream.Read(fileSize: 1024, userBufferSize: 512, options: None)

[3971.800 ; 4074.625) | @@
[4074.625 ; 4222.991) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[4222.991 ; 4382.773) | @@@@@@@
[4382.773 ; 4531.139) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[4531.139 ; 4635.424) | @@
[4635.424 ; 4795.866) | @
[4795.866 ; 4944.232) | @@@@@@@@@@@@@@@
[4944.232 ; 5087.227) | @
[5087.227 ; 5235.593) | @@@@@@@
[5235.593 ; 5343.453) | @

System.IO.Tests.Perf_FileStream.ReadAsync(fileSize: 1024, userBufferSize: 4096, options: None)

[5706.751 ; 5865.598) | @@@@@@@@@@@
[5865.598 ; 6071.241) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[6071.241 ; 6200.468) | @@@@@
[6200.468 ; 6434.972) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[6434.972 ; 6698.726) | @@@@@@

System.IO.Tests.Perf_FileStream.ReadAsync(fileSize: 1024, userBufferSize: 512, options: Asynchronous)

[6223.449 ; 6426.159) | @@@@
[6426.159 ; 6638.275) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[6638.275 ; 6788.627) | @@@@
[6788.627 ; 7000.743) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[7000.743 ; 7144.171) | @@@
[7144.171 ; 7356.287) | 
[7356.287 ; 7530.518) | 
[7530.518 ; 7742.634) | @@@@@@@@@@@@@@
[7742.634 ; 8046.329) | @@@@@@@@@@@

System.IO.Tests.Perf_FileStream.ReadByte(fileSize: 1024, options: Asynchronous)

[6899.512 ; 7152.184) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[7152.184 ; 7436.475) | @@@@@@@@@@@@@@@@
[7436.475 ; 7689.147) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[7689.147 ; 7955.746) | @@@@@@@@@@@@@@@@@@@@@@@
[7955.746 ; 8330.840) | @
[8330.840 ; 8583.512) | @@@@@@@@@@@@@@@@
[8583.512 ; 8833.601) | @@@@@@@@
[8833.601 ; 9057.500) | @@

Docs

Profiling workflow for dotnet/runtime repository
Benchmarking workflow for dotnet/runtime repository
@DrewScoggins DrewScoggins added os-linux Linux OS (any supported distro) tenet-performance Performance related issue tenet-performance-benchmarks Issue from performance benchmark arch-x64 labels Mar 4, 2021
@dotnet-issue-labeler dotnet-issue-labeler bot added the untriaged New issue has not been triaged by the area owner label Mar 4, 2021
@dotnet-issue-labeler
Copy link

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

@DrewScoggins
Copy link
Member Author

Probably related to #47128

@stephentoub
Copy link
Member

cc: @adamsitnik

@DrewScoggins
Copy link
Member Author

We are also seeing some wins from this change in BinaryWriter.

Run Information

Architecture x64
OS ubuntu 18.04
Baseline d5ab93c4a8e45da2dab8924c2165000bf78f84e6
Compare cbb5b905d67a91ecf293c8807414b7791713b02d

Improvemnts in System.IO.Tests.BinaryWriterTests

Benchmark Baseline Test Test/Base Baseline IR Compare IR IR Ratio Baseline ETL Compare ETL
WriteUInt32 25.92 ns 1.75 ns 0.07
WriteUInt16 26.78 ns 1.76 ns 0.07
WriteSingle 26.01 ns 2.04 ns 0.08
WriteNonAsciiChar 28.94 ns 4.61 ns 0.16
WriteUInt64 25.80 ns 1.76 ns 0.07
WriteAsciiChar 28.47 ns 4.33 ns 0.15
WriteDouble 25.52 ns 2.04 ns 0.08

graph
graph
graph
graph
graph
graph
graph
Historical Data in Reporting System

Repro

git clone https://github.com/dotnet/performance.git
python3 .\performance\scripts\benchmarks_ci.py -f netcoreapp5.0 --filter 'System.IO.Tests.BinaryWriterTests*'

.

Payloads

Baseline
Compare

Histogram

System.IO.Tests.BinaryWriterTests.WriteUInt32

[-0.377 ;  3.990) | @@@@@@@@@@@@@@@@@@@@@@@@
[ 3.990 ;  8.244) | 
[ 8.244 ; 12.499) | 
[12.499 ; 16.753) | 
[16.753 ; 21.008) | 
[21.008 ; 25.465) | 
[25.465 ; 29.720) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@

System.IO.Tests.BinaryWriterTests.WriteUInt16

[-0.459 ;  3.953) | @@@@@@@@@@@@@@@@@@@@@@@@@
[ 3.953 ;  8.347) | 
[ 8.347 ; 12.742) | 
[12.742 ; 17.136) | 
[17.136 ; 21.530) | 
[21.530 ; 25.742) | 
[25.742 ; 30.136) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[30.136 ; 32.757) | @@

System.IO.Tests.BinaryWriterTests.WriteSingle

[-0.317 ;  4.107) | @@@@@@@@@@@@@@@@@@@@@@@@@
[ 4.107 ;  8.384) | 
[ 8.384 ; 12.660) | 
[12.660 ; 16.937) | 
[16.937 ; 21.213) | 
[21.213 ; 25.404) | 
[25.404 ; 29.681) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[29.681 ; 31.910) | @

System.IO.Tests.BinaryWriterTests.WriteNonAsciiChar

[ 2.406 ;  6.934) | @@@@@@@@@@@@@@@@@@@@@@@@
[ 6.934 ; 11.229) | 
[11.229 ; 15.524) | 
[15.524 ; 19.819) | 
[19.819 ; 24.114) | 
[24.114 ; 28.112) | 
[28.112 ; 32.407) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[32.407 ; 36.890) | @@@

System.IO.Tests.BinaryWriterTests.WriteUInt64

[-0.364 ;  4.011) | @@@@@@@@@@@@@@@@@@@@@@@@@
[ 4.011 ;  8.253) | 
[ 8.253 ; 12.495) | 
[12.495 ; 16.737) | 
[16.737 ; 20.980) | 
[20.980 ; 25.146) | 
[25.146 ; 29.388) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[29.388 ; 32.433) | @@

System.IO.Tests.BinaryWriterTests.WriteAsciiChar

[ 2.079 ;  6.435) | @@@@@@@@@@@@@@@@@@@@@@@@@
[ 6.435 ; 10.706) | 
[10.706 ; 14.976) | 
[14.976 ; 19.247) | 
[19.247 ; 23.518) | 
[23.518 ; 27.696) | 
[27.696 ; 31.967) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@

System.IO.Tests.BinaryWriterTests.WriteDouble

[-0.114 ;  4.203) | @@@@@@@@@@@@@@@@@@@@@@@@@@
[ 4.203 ;  8.498) | 
[ 8.498 ; 12.793) | 
[12.793 ; 17.088) | 
[17.088 ; 21.383) | 
[21.383 ; 24.924) | 
[24.924 ; 29.219) | @@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
[29.219 ; 33.601) | @@@@@

Docs

Profiling workflow for dotnet/runtime repository
Benchmarking workflow for dotnet/runtime repository

@adamsitnik
Copy link
Member

This is very interesting as it seems to be Unix specific regression as Windows charts seem to no be affected:

https://pvscmdupload.blob.core.windows.net/reports/allTestHistory/refs/heads/master_x64_Windows%2010.0.18362/System.IO.Tests.Perf_FileStream.ReadAsync(fileSize%3a%201024%2c%20userBufferSize%3a%20512%2c%20options%3a%20None).html
https://pvscmdupload.blob.core.windows.net/reports/allTestHistory/refs/heads/master_x64_Windows%2010.0.18362/System.IO.Tests.Perf_FileStream.OpenClose(fileSize%3a%201024%2c%20options%3a%20None).html
https://pvscmdupload.blob.core.windows.net/reports/allTestHistory/refs/heads/master_x64_Windows%2010.0.18362/System.IO.Tests.Perf_FileStream.OpenClose(fileSize%3a%201024%2c%20options%3a%20None).html

obraz

obraz

obraz

@AndyAyersMS In #47128 I've basically introduced a new abstraction layer, so all the FileStream method calls are now including the overhead of an additional virtual method call (class, not interface). Is it possible that it's more expensive on Unix compared to Windows?

@adamsitnik
Copy link
Member

We are also seeing some wins from this change in BinaryWriter.

@GrabYourPitchforks

@AndyAyersMS
Copy link
Member

Is it possible that it's more expensive on Unix compared to Windows

The virtual call sequence is the same on both.

There might be some other sources of call overhead. For instance if you are just forwarding struct args, there might be some extra shuffling about on Linux as the jit may not smoothly handle the way the Linux ABI requires structs to be passed in registers.

Would be good to look at some of the actual codegen.

@carlossanlop carlossanlop removed the untriaged New issue has not been triaged by the area owner label Mar 11, 2021
@carlossanlop carlossanlop added this to the 6.0.0 milestone Mar 11, 2021
@adamsitnik adamsitnik self-assigned this Jul 22, 2021
@adamsitnik
Copy link
Member

Overall we were able to solve most of the regressions and even turn most of them into improvements.

Method Runtime fileSize userBufferSize options Mean Ratio Allocated
Read .NET 5.0 1024 1024 None 5.176 μs 1.00 4,280 B
Read .NET 6.0 1024 1024 None 5.903 μs 1.14 4,336 B
ReadAsync .NET 5.0 1024 1024 None 9.314 μs 1.00 4,665 B
ReadAsync .NET 6.0 1024 1024 None 9.257 μs 0.99 4,952 B
Read .NET 5.0 1024 1024 Asynchronous 7.987 μs 1.00 4,520 B
Read .NET 6.0 1024 1024 Asynchronous 5.884 μs 0.74 4,336 B
ReadAsync .NET 5.0 1024 1024 Asynchronous 9.196 μs 1.00 4,706 B
ReadAsync .NET 6.0 1024 1024 Asynchronous 9.374 μs 1.02 4,952 B
OpenClose .NET 5.0 1024 ? None 3.395 μs 1.00 160 B
OpenClose .NET 6.0 1024 ? None 3.679 μs 1.08 216 B
ReadByte .NET 5.0 1024 ? None 9.223 μs 1.00 4,280 B
ReadByte .NET 6.0 1024 ? None 8.729 μs 0.95 4,336 B
OpenClose .NET 5.0 1024 ? Asynchronous 3.505 μs 1.00 280 B
OpenClose .NET 6.0 1024 ? Asynchronous 3.669 μs 1.05 216 B
ReadByte .NET 5.0 1024 ? Asynchronous 9.302 μs 1.00 4,400 B
ReadByte .NET 6.0 1024 ? Asynchronous 8.628 μs 0.93 4,336 B
Read .NET 5.0 1048576 512 None 247.484 μs 1.00 4,280 B
Read .NET 6.0 1048576 512 None 250.115 μs 1.01 4,337 B
ReadAsync .NET 5.0 1048576 512 None 3,550.898 μs 1.00 233,997 B
ReadAsync .NET 6.0 1048576 512 None 674.037 μs 0.19 5,019 B
Read .NET 5.0 1048576 512 Asynchronous 935.502 μs 1.00 35,194 B
Read .NET 6.0 1048576 512 Asynchronous 247.268 μs 0.26 4,337 B
ReadAsync .NET 5.0 1048576 512 Asynchronous 744.525 μs 1.00 35,369 B
ReadAsync .NET 6.0 1048576 512 Asynchronous 663.037 μs 0.91 5,019 B
Read .NET 5.0 1048576 4096 None 199.518 μs 1.00 160 B
Read .NET 6.0 1048576 4096 None 193.003 μs 0.97 217 B
ReadAsync .NET 5.0 1048576 4096 None 537.004 μs 1.00 29,169 B
ReadAsync .NET 6.0 1048576 4096 None 375.843 μs 0.72 706 B
Read .NET 5.0 1048576 4096 Asynchronous 698.735 μs 1.00 31,007 B
Read .NET 6.0 1048576 4096 Asynchronous 197.665 μs 0.28 217 B
ReadAsync .NET 5.0 1048576 4096 Asynchronous 499.676 μs 1.00 31,249 B
ReadAsync .NET 6.0 1048576 4096 Asynchronous 398.217 μs 0.81 706 B
Read_NoBuffering .NET 5.0 1048576 16384 None 97.330 μs 1.00 160 B
Read_NoBuffering .NET 6.0 1048576 16384 None 94.391 μs 0.97 152 B
ReadAsync_NoBuffering .NET 5.0 1048576 16384 None 187.578 μs 1.00 7,664 B
ReadAsync_NoBuffering .NET 6.0 1048576 16384 None 154.951 μs 0.83 553 B
Read_NoBuffering .NET 5.0 1048576 16384 Asynchronous 242.897 μs 1.00 7,963 B
Read_NoBuffering .NET 6.0 1048576 16384 Asynchronous 94.803 μs 0.39 152 B
ReadAsync_NoBuffering .NET 5.0 1048576 16384 Asynchronous 189.687 μs 1.00 8,208 B
ReadAsync_NoBuffering .NET 6.0 1048576 16384 Asynchronous 158.541 μs 0.84 553 B
Read .NET 5.0 104857600 4096 None 25,135.499 μs 1.00 192 B
Read .NET 6.0 104857600 4096 None 24,536.448 μs 0.98 307 B
ReadAsync .NET 5.0 104857600 4096 None 49,196.600 μs 1.00 2,867,768 B
ReadAsync .NET 6.0 104857600 4096 None 41,890.758 μs 0.85 1,124 B
Read .NET 5.0 104857600 4096 Asynchronous 73,430.245 μs 1.00 3,072,558 B
Read .NET 6.0 104857600 4096 Asynchronous 24,432.030 μs 0.33 307 B
ReadAsync .NET 5.0 104857600 4096 Asynchronous 48,793.215 μs 1.00 3,072,600 B
ReadAsync .NET 6.0 104857600 4096 Asynchronous 42,725.572 μs 0.88 1,124 B
Read_NoBuffering .NET 5.0 104857600 16384 None 14,831.359 μs 1.00 178 B
Read_NoBuffering .NET 6.0 104857600 16384 None 14,530.633 μs 0.98 203 B
ReadAsync_NoBuffering .NET 5.0 104857600 16384 None 23,819.030 μs 1.00 717,354 B
ReadAsync_NoBuffering .NET 6.0 104857600 16384 None 18,961.480 μs 0.80 644 B
Read_NoBuffering .NET 5.0 104857600 16384 Asynchronous 29,551.924 μs 1.00 769,481 B
Read_NoBuffering .NET 6.0 104857600 16384 Asynchronous 14,482.452 μs 0.49 203 B
ReadAsync_NoBuffering .NET 5.0 104857600 16384 Asynchronous 21,595.085 μs 1.00 768,557 B
ReadAsync_NoBuffering .NET 6.0 104857600 16384 Asynchronous 18,861.580 μs 0.87 668 B

@ghost ghost locked as resolved and limited conversation to collaborators Sep 12, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@adamsitnik adamsitnik

Labels
arch-x64 area-System.IO os-linux Linux OS (any supported distro) tenet-performance Performance related issue tenet-performance-benchmarks Issue from performance benchmark
Projects
None yet
Milestone
6.0.0
Development

No branches or pull requests
6 participants
@carlossanlop @stephentoub @adamsitnik @DrewScoggins @jeffschwMSFT @AndyAyersMS