Category Archives: .NET Core

.NET Core performance nyomozás II.

Újra nekiálltam mérni. Előző alkalommal azért voltak rosszabbak a .NET Core számai, mert szándékaim ellenére elsőre nem optimalizált kódot mértem. A régi projectről SDK projectre konverzió során valami összezagyválódott az optimalizálás beállítások körül a release configonál. Kézzel kitakarítottam a csprojokat, így már azt fordít, amit én akarok (egyébként optimize+ a default).

Mivel a mérés során láttuk, hogy a GC-nek nagy hatása van a mért teljesítményre, ezért, hogy reálisabb képet kapjunk, hogy olyan sokszor kell megismételni a mérést, hogy biztos elinduljon párszor a GC. Hisz lehet azért szépek egyes méréseknél a számok, mert nem volt elég nagy a használt memória mérete, hogy a GC elinduljon, így nincs alkalma rontani a számokat.
.NET 4.8 alatt app.configból szabályzom a GC működését:

<gcServer enabled="true|false"/>
<gcConcurrent enabled="true|false"/>

.NET 5 alatt a runtimeconfig.template.jsonből a legyegyszerűbb szabályozni a GC-t:

{
  "runtimeOptions": {
  "configProperties": {
  "System.GC.Concurrent": false
  "System.GC.Server": false }
  }
}

De nekem egyelőre erre nem hallgatott, de az csprojban beállítottra igen:

<PropertyGroup>
	<ServerGarbageCollection>true</ServerGarbageCollection>
	<ConcurrentGarbageCollection>false</ConcurrentGarbageCollection>
</PropertyGroup>

Az első futások nincsenek benne az aggregált statiszikákban, de a listákban látszanak.

Jöjjenek a 4.8-as .NET Frameworks számok.

A mérések tetején ott a konfig, a GC számok azt mutatják, addig az adott generációban hányszor történt takarítás.


Először két mérés Workstation GC-vel:

Server: False, LatencyMode: Batch
1849ms, GC0: 13, GC1: 8, GC2: 4
1565ms, GC0: 17, GC1: 11, GC2: 5
1958ms, GC0: 23, GC1: 14, GC2: 6
1072ms, GC0: 26, GC1: 16, GC2: 6
1696ms, GC0: 31, GC1: 19, GC2: 7
1371ms, GC0: 36, GC1: 21, GC2: 8
1411ms, GC0: 41, GC1: 24, GC2: 9
1270ms, GC0: 45, GC1: 26, GC2: 10
1446ms, GC0: 50, GC1: 29, GC2: 11
1264ms, GC0: 54, GC1: 31, GC2: 12
1455ms, GC0: 59, GC1: 34, GC2: 13
1294ms, GC0: 63, GC1: 36, GC2: 14
1433ms, GC0: 68, GC1: 39, GC2: 15
1246ms, GC0: 72, GC1: 41, GC2: 16
1431ms, GC0: 77, GC1: 44, GC2: 17
1318ms, GC0: 81, GC1: 46, GC2: 18
1460ms, GC0: 86, GC1: 49, GC2: 19
1258ms, GC0: 90, GC1: 51, GC2: 20
1434ms, GC0: 95, GC1: 54, GC2: 21
1251ms, GC0: 99, GC1: 56, GC2: 22
Min: 1072, Avg: 1402

Server: False, LatencyMode: Interactive
1193ms, GC0: 137, GC1: 49, GC2: 7
1381ms, GC0: 209, GC1: 74, GC2: 8
1619ms, GC0: 282, GC1: 100, GC2: 10
1540ms, GC0: 355, GC1: 125, GC2: 12
1601ms, GC0: 429, GC1: 151, GC2: 14
1314ms, GC0: 500, GC1: 176, GC2: 14
1549ms, GC0: 573, GC1: 202, GC2: 16
1404ms, GC0: 645, GC1: 226, GC2: 16
1620ms, GC0: 718, GC1: 252, GC2: 18
1531ms, GC0: 791, GC1: 278, GC2: 20
1450ms, GC0: 864, GC1: 303, GC2: 21
1542ms, GC0: 937, GC1: 328, GC2: 23
1390ms, GC0: 1009, GC1: 353, GC2: 24
1353ms, GC0: 1081, GC1: 377, GC2: 24
1523ms, GC0: 1154, GC1: 403, GC2: 26
1313ms, GC0: 1225, GC1: 427, GC2: 26
1529ms, GC0: 1299, GC1: 454, GC2: 28
1435ms, GC0: 1371, GC1: 479, GC2: 29
1275ms, GC0: 1443, GC1: 503, GC2: 29
1500ms, GC0: 1516, GC1: 536, GC2: 31
Min: 1275, Avg: 1467

Érdekes látni, az interakív 15x annyi 0 generációs takarítást indított, mert igyekszik sokszor, de kicsit takarítani, hogy ha animációk vagy más időérzékeny kódok futnának, akkor ne szaggasson bele. De cserébe a futási idők kissé megnyúlnak.

Jöjjenek a server GC-k.


Server: True, LatencyMode: Batch
852ms, GC0: 2, GC1: 2, GC2: 2
683ms, GC0: 2, GC1: 2, GC2: 2
859ms, GC0: 3, GC1: 3, GC2: 3
509ms, GC0: 3, GC1: 3, GC2: 3
1061ms, GC0: 4, GC1: 4, GC2: 4
523ms, GC0: 4, GC1: 4, GC2: 4
539ms, GC0: 4, GC1: 4, GC2: 4
1084ms, GC0: 5, GC1: 5, GC2: 5
498ms, GC0: 5, GC1: 5, GC2: 5
505ms, GC0: 5, GC1: 5, GC2: 5
530ms, GC0: 5, GC1: 5, GC2: 5
894ms, GC0: 6, GC1: 6, GC2: 6
503ms, GC0: 6, GC1: 6, GC2: 6
1021ms, GC0: 7, GC1: 7, GC2: 7
495ms, GC0: 7, GC1: 7, GC2: 7
537ms, GC0: 7, GC1: 7, GC2: 7
1136ms, GC0: 8, GC1: 8, GC2: 8
498ms, GC0: 8, GC1: 8, GC2: 8
490ms, GC0: 8, GC1: 8, GC2: 8
514ms, GC0: 8, GC1: 8, GC2: 8
Min: 490, Avg: 678

Meghökkentő különbség a workstationhöz képest. Sokkal gyorsabban fut le a kód (pontosabban kevesebb időt vesz el a GC), sokkal kevesebb a takarítás minden generációban, ezért az áteresztőképesség több mint a duplája lett. Érdekes látni, mindig akkor nagyobbak a mért idők, amikor a GC0 is ugrik egyet (dőlttel megjelöltem).
Hozzáteszem, többszálú kódnál ez valószínűleg még harsányabban kijönne, mivel Server GC esetén processzoronkét 1 heap van, így kisebb a torlódás.

Server: True, LatencyMode: Interactive
868ms, GC0: 5, GC1: 3, GC2: 2
616ms, GC0: 5, GC1: 3, GC2: 2
1308ms, GC0: 7, GC1: 5, GC2: 3
613ms, GC0: 7, GC1: 5, GC2: 3
604ms, GC0: 7, GC1: 5, GC2: 3
1259ms, GC0: 8, GC1: 5, GC2: 3
538ms, GC0: 8, GC1: 5, GC2: 3
607ms, GC0: 8, GC1: 5, GC2: 3
1056ms, GC0: 9, GC1: 6, GC2: 4
487ms, GC0: 9, GC1: 6, GC2: 4
475ms, GC0: 9, GC1: 6, GC2: 4
883ms, GC0: 11, GC1: 8, GC2: 5
471ms, GC0: 11, GC1: 8, GC2: 5
489ms, GC0: 11, GC1: 8, GC2: 5
1110ms, GC0: 13, GC1: 9, GC2: 6
606ms, GC0: 13, GC1: 9, GC2: 6
599ms, GC0: 13, GC1: 9, GC2: 6
596ms, GC0: 14, GC1: 10, GC2: 7
1227ms, GC0: 15, GC1: 11, GC2: 7
477ms, GC0: 15, GC1: 11, GC2: 7
Min: 471, Avg: 738

Itt is szépek a számok, de jobban szórnak. Mindenesetre tisztán látszik, ha a nyers teljesítmény kell, a server GC sokat számít. Ezt főleg azoknak mondom, akik például Windows Service-ben futtatnak feldolgozó kódokat, még inkább, ha ezt több szálon teszik. Nagyon sokat lehet nyerni ezzel az egyszerű átkonfigurálással. Egyről már írtam 2009-ben is.

Még egy érdekes eset. Ha minden mérés között futtatom a GC-t (ezt nem belemérve az időkbe), így a mérés során kisebb a valószínűsége, hogy elinduljon (az első mérést megismételve)
Server: False, LatencyMode: Batch
1869ms, GC0: 13, GC1: 8, GC2: 4
1018ms, GC0: 17, GC1: 11, GC2: 5
1300ms, GC0: 23, GC1: 14, GC2: 6
1368ms, GC0: 27, GC1: 17, GC2: 8
1071ms, GC0: 32, GC1: 19, GC2: 9
1050ms, GC0: 36, GC1: 22, GC2: 10
1059ms, GC0: 41, GC1: 24, GC2: 11
1053ms, GC0: 45, GC1: 27, GC2: 12
986ms, GC0: 49, GC1: 30, GC2: 13
1076ms, GC0: 55, GC1: 33, GC2: 14
1049ms, GC0: 59, GC1: 36, GC2: 15
982ms, GC0: 63, GC1: 39, GC2: 16
1074ms, GC0: 69, GC1: 42, GC2: 17
1044ms, GC0: 73, GC1: 45, GC2: 18
980ms, GC0: 77, GC1: 48, GC2: 19
1072ms, GC0: 83, GC1: 51, GC2: 20
1056ms, GC0: 87, GC1: 54, GC2: 21
972ms, GC0: 91, GC1: 57, GC2: 22
1117ms, GC0: 97, GC1: 59, GC2: 23
1045ms, GC0: 101, GC1: 62, GC2: 24
Min: 972, Avg: 1072


Látható, hogy az átlag sokkal közelebb van a minimumhoz, mivel kevésbé szórnak a mért értékek, mert kevesebbszer szakadt meg a futás a GC miatt.

Mi eddig a tanulság? A GC erősen beleszól egy .NET app teljesítményébe, nem csoda, hogy az utóbbi években igen sokat tesznek a kevesebb heap szemetelés érdekében. ref return, structok erőltetett használata, stackalloc, Span, stb.

De az eredeti cél a .NET 4.8 és a .NET 5 közötti teljesítménykülönbség vizsgálata. Ezért lássuk az előző 4 esetet, de most .NET 5 alatt.

GC Server: False, GC LatencyMode: Interactive, .NETCoreApp,Version=v5.0
1098ms, GC0: 136, GC1: 50, GC2: 8
1287ms, GC0: 210, GC1: 77, GC2: 10
1122ms, GC0: 282, GC1: 102, GC2: 11
1457ms, GC0: 356, GC1: 129, GC2: 14
1188ms, GC0: 429, GC1: 154, GC2: 15
1009ms, GC0: 500, GC1: 178, GC2: 15
1345ms, GC0: 573, GC1: 203, GC2: 17
1321ms, GC0: 647, GC1: 229, GC2: 19
1059ms, GC0: 718, GC1: 253, GC2: 19
1381ms, GC0: 792, GC1: 287, GC2: 22
1154ms, GC0: 863, GC1: 323, GC2: 22
1235ms, GC0: 937, GC1: 353, GC2: 24
1179ms, GC0: 1008, GC1: 377, GC2: 24
1303ms, GC0: 1081, GC1: 403, GC2: 26
1419ms, GC0: 1154, GC1: 428, GC2: 27
1302ms, GC0: 1227, GC1: 453, GC2: 29
1310ms, GC0: 1299, GC1: 478, GC2: 30
1067ms, GC0: 1371, GC1: 502, GC2: 30
1499ms, GC0: 1445, GC1: 529, GC2: 33
1305ms, GC0: 1516, GC1: 553, GC2: 33
Min: 1009, Avg: 1260

GC Server: False, GC LatencyMode: Batch, .NETCoreApp,Version=v5.0
1536ms, GC0: 11, GC1: 8, GC2: 4
1552ms, GC0: 14, GC1: 11, GC2: 5
1729ms, GC0: 18, GC1: 15, GC2: 6
1293ms, GC0: 22, GC1: 17, GC2: 7
1691ms, GC0: 27, GC1: 20, GC2: 8
1205ms, GC0: 32, GC1: 22, GC2: 8
1368ms, GC0: 36, GC1: 24, GC2: 9
1213ms, GC0: 40, GC1: 26, GC2: 10
1262ms, GC0: 44, GC1: 29, GC2: 11
1226ms, GC0: 48, GC1: 31, GC2: 12
1366ms, GC0: 53, GC1: 34, GC2: 13
1231ms, GC0: 57, GC1: 36, GC2: 14
1373ms, GC0: 62, GC1: 39, GC2: 15
1219ms, GC0: 66, GC1: 41, GC2: 16
1364ms, GC0: 71, GC1: 44, GC2: 17
1243ms, GC0: 75, GC1: 46, GC2: 18
1392ms, GC0: 80, GC1: 49, GC2: 19
1284ms, GC0: 84, GC1: 51, GC2: 20
1379ms, GC0: 89, GC1: 54, GC2: 21
1265ms, GC0: 93, GC1: 56, GC2: 22
Min: 1205, Avg: 1350

GC Server: True, GC LatencyMode: Interactive, .NETCoreApp,Version=v5.0
792ms, GC0: 5, GC1: 3, GC2: 2
561ms, GC0: 5, GC1: 3, GC2: 2
1003ms, GC0: 6, GC1: 4, GC2: 2
563ms, GC0: 6, GC1: 4, GC2: 2
558ms, GC0: 6, GC1: 4, GC2: 2
907ms, GC0: 7, GC1: 4, GC2: 2
555ms, GC0: 7, GC1: 4, GC2: 2
550ms, GC0: 7, GC1: 4, GC2: 2
1182ms, GC0: 9, GC1: 5, GC2: 3
579ms, GC0: 9, GC1: 5, GC2: 3
551ms, GC0: 9, GC1: 5, GC2: 3
874ms, GC0: 10, GC1: 6, GC2: 4
400ms, GC0: 10, GC1: 6, GC2: 4
414ms, GC0: 11, GC1: 7, GC2: 5
536ms, GC0: 11, GC1: 7, GC2: 5
888ms, GC0: 12, GC1: 8, GC2: 5
402ms, GC0: 12, GC1: 8, GC2: 5
414ms, GC0: 12, GC1: 8, GC2: 5
799ms, GC0: 14, GC1: 9, GC2: 6
693ms, GC0: 14, GC1: 9, GC2: 6
Min: 400, Avg: 654

GC Server: True, GC LatencyMode: Batch, .NETCoreApp,Version=v5.0
804ms, GC0: 4, GC1: 2, GC2: 2
543ms, GC0: 4, GC1: 2, GC2: 2
544ms, GC0: 4, GC1: 2, GC2: 2
694ms, GC0: 5, GC1: 3, GC2: 3
672ms, GC0: 6, GC1: 4, GC2: 4
402ms, GC0: 6, GC1: 4, GC2: 4
734ms, GC0: 7, GC1: 5, GC2: 5
395ms, GC0: 7, GC1: 5, GC2: 5
419ms, GC0: 7, GC1: 5, GC2: 5
722ms, GC0: 8, GC1: 6, GC2: 6
401ms, GC0: 8, GC1: 6, GC2: 6
394ms, GC0: 8, GC1: 6, GC2: 6
626ms, GC0: 9, GC1: 7, GC2: 7
402ms, GC0: 9, GC1: 7, GC2: 7
670ms, GC0: 10, GC1: 8, GC2: 8
405ms, GC0: 10, GC1: 8, GC2: 8
408ms, GC0: 10, GC1: 8, GC2: 8
638ms, GC0: 11, GC1: 9, GC2: 9
408ms, GC0: 11, GC1: 9, GC2: 9
637ms, GC0: 12, GC1: 10, GC2: 10
Min: 394, Avg: 532

Na, azért ezek a számok már durvák! .NET 4.8 alatt a legjobb átlag 678ms volt Server: True, LatencyMode: Batch beállítások mellett.

.NET 5.0 (RC2) alatt GC Server: True, GC LatencyMode: Batch mellett 532 az átlag. Ez 21% teljesítménynövekedés, egy egyszerű újrafordítással.

Érdekes, hogy minkét esetben a server és a batch volt a nyertes.

A minimum is 471-ről leesett 394-re. Ez is 16%. Miért fontos nekem a minimum? Mert, ha tudom csökkenteni a felesleges heap allokálások számát, akkor az átlagot közel tudom húzni ehhez a számhoz. A teszt alatt gigabájtokat szemetelek, lesz mit faragni belőle.

.NET Core performance nyomozás

Sok szépet lehet olvasni, milyen durva optimalizálások csináltak a .NET Core-ban. Annyira élni akartam ezekkel, hogy a tradinghez írt backtesteremet átportoltam Core 3.1-re. A WCF és a WPF részek igényeltek némi googlizást, de nem vészes a migráció.
Van egy nagyon CPU intenzív kód a backtesterben, ez több millió tömb műveletet és dátum összehasonlítást végez. Erre voltam kíváncsi, mennyit gyorsul az új .NET assembly-ket használva.
.NET 4.8:
00:00:00.6295321
00:00:01.2317440
00:00:00.6597345
00:00:01.2434665
Min: 629.5321

.NET Core 3.1:
00:00:01.4422192
00:00:01.3073163
00:00:01.6955676
00:00:01.2051358
Min: 1205.1358

Ez siralmas. Először azt hittem azért, mert debug, nem optimalizált kódban futtattam a core-os részt, de nem, abban 2.5mp a futásidő.

Ha lúd legyen kövér, felraktam a .NET 5 RC2-t, Visual Studio Previewt, és leforgattam .NET 5 alá is ugyanazt a kódot:

00:00:01.2580593
00:00:01.3729454
00:00:01.2055221
00:00:01.5244462
Min: 1205.5221

Véletlen, de msre ugyanaz jött ki, mint .NET Core 3.1 alatt (gondolom kb. ugyanaz a kód van a kettő mögött).

Aztán rájöttem, hogy sok desktop appban is Server GC-t használtam, mert többszálú terhelésnél sokkal jobban ki lehet használni a CPU-kat.

Core-ban másképp kell állítani, de itt is lehet. Hozzáteszem azonban, hogy a jó eredmények Workstation GC-vel jöttek ki .NET 4.8 alatt.

Mindenesetre background server GC esetén ezek a számok:

00:00:00.7827110
00:00:00.7870250
00:00:01.3079196
00:00:00.7937517
Min: 782.711

Ez már sokkal közelebb van a kiinduláshoz. Gondoltad volna, hogy ekkora hatása van a GC-nek?

Ha nem background (hanem blocking) server GC-t használok, akkor:

00:00:00.9668477
00:00:00.7707329
00:00:00.8736540
00:00:00.4659059
Min: 465.9059

Na, ez már igen! 630 helyett 466ms.

De akkor ez úgy igazságos, hogy .NET 4.8 alatt is megnézzük a server GC-kel a mérést.

Concurrent (background) GC:

00:00:01.5112052
00:00:01.7877981
00:00:01.7735863
00:00:01.9077548
Min: 1511.2052

Blocking GC:

00:00:01.4676091
00:00:01.7899143
00:00:01.5936619
00:00:02.0141916
Min: 1467.6091

Workstation GC (ezzel ment az eredeti mérés):

00:00:01.4541448
00:00:01.7498414
00:00:01.9155145
00:00:01.7816521
Min: 1454.1448

Na, ez meg mi? Úgy látszik VS Preview alatt a net48-windows moniker .NET 5 kódot fordított be. net48-ra átírva már jönnek a régi számok.

WS, Blocking GC:

00:00:00.9853411
00:00:00.6656316
00:00:01.1928848
00:00:00.7570509
Min: 665.6316

WS, Background GC:

00:00:00.6371798
00:00:01.0235119
00:00:00.6491366
00:00:01.2766926
Min: 637.1798

Server, Blocking GC:

00:00:00.9851811
00:00:00.6396851
00:00:01.4888114
00:00:00.6327586
Min: 632.7586

Server, Background GC:

00:00:00.7241423
00:00:01.0104857
00:00:00.6526001
00:00:01.2343597
Min: 652.6001

Ez a négy eset kb. ugyanaz, zajhatáron belül vannak a számok.

Egyelőre ennyi, majd írok még a témáról, ha bővebben belementem, de a server GC-s Core verzió mindenképpen tetszik: 630 helyett 466ms.