runtime: Performance regression: System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8

Repro

git clone https://github.com/dotnet/performance.git
py .\performance\scripts\benchmarks_ci.py -f netcoreapp3.1 netcoreapp5.0 --filter System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: UnsafeRelaxed,no <escaping /> required,512)

Conclusion	Base	Diff	Base/Diff	Modality	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	1809.34	3014.46	0.60		Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Slower	1076.94	1540.30	0.70		Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	950.47	1186.75	0.80		Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	1142.73	1765.04	0.65	several?	Windows 10.0.18363.959	X86	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20420.2
Slower	1348.91	2244.69	0.60		Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: JavaScript,no escaping required,512)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	1805.25	2974.82	0.61	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Slower	1074.65	1529.30	0.70	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	943.09	1184.95	0.80	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	1146.45	1769.32	0.65	Windows 10.0.18363.959	X86	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20420.2
Slower	1330.70	2227.21	0.60	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: UnsafeRelaxed,hello “there”,512)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	1783.16	2957.33	0.60	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Slower	1111.22	1524.46	0.73	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	939.13	1176.89	0.80	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	1344.53	2224.69	0.60	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: JavaScript,&Hello+<World>!,512)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	1872.80	3055.42	0.61	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Slower	1092.13	1545.38	0.71	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	955.69	1194.21	0.80	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	1385.56	2252.29	0.62	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: Url,c2020,512)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	1798.51	3055.97	0.59	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Slower	1130.74	1516.15	0.75	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	936.81	1176.26	0.80	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	1350.33	2216.17	0.61	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: Url,&lorem ipsum=dolor sit amet,512)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	2112.16	3117.17	0.68	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Slower	1162.38	1610.63	0.72	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	979.94	1247.30	0.79	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	1251.98	1856.24	0.67	Windows 10.0.18363.959	X86	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20420.2
Slower	1448.69	2325.45	0.62	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: UnsafeRelaxed,no <escaping /> required,16)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	177.61	246.68	0.72	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Slower	104.77	131.53	0.80	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	92.71	102.98	0.90	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	104.18	142.99	0.73	Windows 10.0.18363.959	X86	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20420.2
Slower	122.05	171.79	0.71	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: JavaScript,no escaping required,16)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	146.39	224.46	0.65	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Slower	97.42	116.05	0.84	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	86.18	93.76	0.92	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	95.23	130.77	0.73	Windows 10.0.18363.959	X86	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20420.2
Slower	111.51	152.55	0.73	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: UnsafeRelaxed,hello “there”,16)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	151.00	207.48	0.73	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Slower	101.15	114.62	0.88	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	77.07	93.02	0.83	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	121.72	152.87	0.80	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: Url,&lorem ipsum=dolor sit amet,16)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	281.09	347.81	0.81	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Slower	156.06	189.22	0.82	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	118.21	151.30	0.78	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	186.27	223.79	0.83	Windows 10.0.18363.959	X86	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20420.2
Slower	226.76	262.86	0.86	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: JavaScript,&Hello+<World>!,16)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	178.36	264.02	0.68	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Same	120.66	123.62	0.98	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	92.38	99.48	0.93	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Slower	157.38	178.95	0.88	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8(arguments: Url,c2020,16)

Conclusion	Base	Diff	Base/Diff	Operating System	Bit	Processor Name	Base Runtime	Diff Runtime
Slower	162.02	204.71	0.79	Windows 10.0.18363.1016	Arm	Microsoft SQ1 3.0 GHz	.NET Core 3.1.6	5.0.100-rc.1.20413.9
Same	105.67	100.29	1.05	Windows 10.0.18363.959	X64	Intel Xeon CPU E5-1650 v4 3.60GHz	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Same	81.69	85.48	0.96	Windows 10.0.19042	X64	Intel Core i7-7700 CPU 3.60GHz (Kaby Lake)	.NET Core 3.1.6	5.0.100-rc.1.20418.3
Same	129.29	133.32	0.97	Windows 10.0.19041.450	X86	Intel Core i7-5557U CPU 3.10GHz (Broadwell)	.NET Core 3.1.6	5.0.100-rc.1.20419.5

Docs

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

@eiriktsarpalis @GrabYourPitchforks I am setting 5.0 milestone to make sure that it gets ~~tagged~~ triaged within the next few weeks.

@DrewScoggins this regression did not get detected by the bot because benchmark was added just a few days ago, so everything is 👍

category:performance theme:needs-triage skill-level:expert cost:large

About this issue

Original URL
State: closed
Created 4 years ago
Comments: 15 (15 by maintainers)

Most upvoted comments

I am currently working on a workshop about identifying regressions and decided to use this particular regression as an example. I was hoping that it’s going to be a simple one 😉

Initially, I’ve used PerfView, which was not very useful as it has just shown that all CPU time is spent in one big method: system.text.encodings.web.il!TextEncoder.EncodeUtf8

So to get CPU % per C# source line I’ve switched to VS Profiler. After hitting and reporting two bugs, I was finally able to find a workaround (attaching the profiler to an already running process using a local build of 5.0 and 3.1 with Tiered JIT disabled) to get the desired effect: CPU time per code line.

And then surprisingly I realized that the profiler is more or less reporting exact CPU usage:

obraz

This has reminded me of an old issue where the regression was caused by Tier 1 codegen being worse than the precompiled Tier 0 codegen.

So I’ve re-run the benchmarks and using benchmarks_ci.py --dotnet-compilation-mode and confirmed that it’s a codegen problem. You can see the full results in the details below.

@layomia I am going to unassign you and set the area to codegen (cc @JulieLeeMSFT )

Defaults

benchmarks_ci.py --dotnet-compilation-mode Default -f netcoreapp3.1 netcoreapp5.0 --filter System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8

no env vars set

Method	arguments	3.1 Mean	5.0 Mean
EncodeUtf8	JavaScript,&Hello+<World>!,16	124.9 ns	130.1 ns
EncodeUtf8	JavaScript,&Hello+<World>!,512	1,124.9 ns	1,590.8 ns
EncodeUtf8	JavaScript,no escaping required,16	102.3 ns	127.4 ns
EncodeUtf8	JavaScript,no escaping required,512	1,099.6 ns	1,719.4 ns
EncodeUtf8	UnsafeRelaxed,hello “there”,16	103.3 ns	126.3 ns
EncodeUtf8	UnsafeRelaxed,hello “there”,512	1,137.1 ns	1,572.3 ns
EncodeUtf8	UnsafeRelaxed(…)> required,16 [41]	108.2 ns	136.2 ns
EncodeUtf8	UnsafeRelaxed(…) required,512 [42]	1,109.5 ns	1,596.9 ns
EncodeUtf8	Url,&lorem ipsum=dolor sit amet,16	150.3 ns	192.5 ns
EncodeUtf8	Url,&lorem ipsum=dolor sit amet,512	1,163.7 ns	1,656.4 ns
EncodeUtf8	Url,c2020,16	110.8 ns	107.5 ns
EncodeUtf8	Url,c2020,512	1,115.2 ns	1,560.2 ns

NoTiering

benchmarks_ci.py --dotnet-compilation-mode NoTiering -f netcoreapp3.1 netcoreapp5.0 --filter System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8

"COMPLUS_TIEREDCOMPILATION=0"

Method	arguments	3.1 Mean	5.0 Mean
EncodeUtf8	JavaScript,&Hello+<World>!,16	207.2 ns	125.1 ns
EncodeUtf8	JavaScript,&Hello+<World>!,512	1,611.5 ns	1,666.1 ns
EncodeUtf8	JavaScript,no escaping required,16	141.4 ns	122.6 ns
EncodeUtf8	JavaScript,no escaping required,512	1,543.7 ns	1,596.7 ns
EncodeUtf8	UnsafeRelaxed,hello “there”,16	159.0 ns	118.6 ns
EncodeUtf8	UnsafeRelaxed,hello “there”,512	1,589.0 ns	1,591.0 ns
EncodeUtf8	UnsafeRelaxed(…)> required,16 [41]	155.3 ns	132.0 ns
EncodeUtf8	UnsafeRelaxed(…) required,512 [42]	1,576.2 ns	1,578.7 ns
EncodeUtf8	Url,&lorem ipsum=dolor sit amet,16	255.5 ns	181.2 ns
EncodeUtf8	Url,&lorem ipsum=dolor sit amet,512	1,698.3 ns	1,675.7 ns
EncodeUtf8	Url,c2020,16	130.6 ns	100.8 ns
EncodeUtf8	Url,c2020,512	1,644.7 ns	1,550.7 ns

FullyJittedNoTiering

benchmarks_ci.py --dotnet-compilation-mode FullyJittedNoTiering -f netcoreapp3.1 netcoreapp5.0 --filter System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8

 "COMPLUS_READYTORUN=0"
 "COMPLUS_TIEREDCOMPILATION=0"
 "COMPLUS_ZAPDISABLE=1"

Method	arguments	3.1 Mean	5.0 Mean
EncodeUtf8	JavaScript,&Hello+<World>!,16	150.7 ns	126.0 ns
EncodeUtf8	JavaScript,&Hello+<World>!,512	1,602.0 ns	1,593.3 ns
EncodeUtf8	JavaScript,no escaping required,16	130.6 ns	118.8 ns
EncodeUtf8	JavaScript,no escaping required,512	1,580.7 ns	1,564.3 ns
EncodeUtf8	UnsafeRelaxed,hello “there”,16	129.7 ns	118.0 ns
EncodeUtf8	UnsafeRelaxed,hello “there”,512	1,572.0 ns	1,553.7 ns
EncodeUtf8	UnsafeRelaxed(…)> required,16 [41]	141.3 ns	131.1 ns
EncodeUtf8	UnsafeRelaxed(…) required,512 [42]	1,589.5 ns	1,569.7 ns
EncodeUtf8	Url,&lorem ipsum=dolor sit amet,16	204.7 ns	182.4 ns
EncodeUtf8	Url,&lorem ipsum=dolor sit amet,512	1,647.7 ns	1,641.4 ns
EncodeUtf8	Url,c2020,16	108.8 ns	108.1 ns
EncodeUtf8	Url,c2020,512	1,568.1 ns	1,559.3 ns

MinOpt

benchmarks_ci.py --dotnet-compilation-mode MinOpt -f netcoreapp3.1 netcoreapp5.0 --filter System.Text.Encodings.Web.Tests.Perf_Encoders.EncodeUtf8

 "COMPLUS_JITMINOPTS=1"
 "COMPLUS_TIEREDCOMPILATION=0"

Method	arguments	3.1 Mean	5.0 Mean
EncodeUtf8	JavaScript,&Hello+<World>!,16	187.1 ns	496.7 ns
EncodeUtf8	JavaScript,&Hello+<World>!,512	1,687.2 ns	5,784.3 ns
EncodeUtf8	JavaScript,no escaping required,16	157.0 ns	423.1 ns
EncodeUtf8	JavaScript,no escaping required,512	1,609.0 ns	5,667.8 ns
EncodeUtf8	UnsafeRelaxed,hello “there”,16	164.1 ns	419.0 ns
EncodeUtf8	UnsafeRelaxed,hello “there”,512	1,622.9 ns	5,797.9 ns
EncodeUtf8	UnsafeRelaxed(…)> required,16 [41]	172.0 ns	471.3 ns
EncodeUtf8	UnsafeRelaxed(…) required,512 [42]	1,594.0 ns	5,733.4 ns
EncodeUtf8	Url,&lorem ipsum=dolor sit amet,16	283.6 ns	675.3 ns
EncodeUtf8	Url,&lorem ipsum=dolor sit amet,512	1,709.0 ns	5,983.6 ns
EncodeUtf8	Url,c2020,16	162.9 ns	350.0 ns
EncodeUtf8	Url,c2020,512	1,569.8 ns	5,591.1 ns

adamsitnik on Sep 22, 2020