Author Archives: Soczó Zsolt

Windows Atom szivárgás nyomozása II.

Az első részben odáig jutottunk el, hogy valószínűleg egy RegisterWindowMessage API hívás helyezi el az Atomot a Windows Atom tárolójában.

A google segített rámutatni, hogy (többek között) a HwndWrapper típus hívja. A forrásban itt az idevágó rész:

HwndWrapper konstruktor

Szinte biztos, hogy megérkeztünk a hibát okozó részhez, mert ilyen atomokkal van tele az atomtároló:

DA13 = HwndWrapper[Trader;;0def0780-e17c-49d0-a243-149008a6b29e]

Eljött az ideje, hogy bepiszkoljuk a kezünket. A cél debuggerben elkapni a HwndWrapper konstruktorát hívó kódot. Ha a stack trace-ben felismerjük a saját kódunkat, akkor tudjuk, melyik sorunk váltotta ki a hibát.

Elővesszük a WinDebugot, és hozzáattacsolunk a szivárogtató processzhez.

A HwndWrapper konstuktorát hívó kódot akarjuk megfogni. De ez a metódus már rég le van jittelve, ezért elő kell keresni a memóriabeli címét.

Lekérjük az osztály metódus tábláját:

Kidumpoltatjuk a metódusokat leíró táblázatot:

Lekérjük a kívánt metódus (konstruktor) részletes adatait:

Most, hogy már tudjuk, hogy lakik a memóriában, beállítunk rá egy töréspontot:

Várunk pár másodpercet, és beáll a debugger a töréspontba. !ClrStack paranccsal (ez már sos managed parancs, nem natív, mint az eddigiek) megnézzük a szálakat. A mi kérdéses szálunk stack trace-e így néz ki:

A problémát okozó stack trace

Mit látunk itt? (Lehet semmit, mert összenyomja a képet a wordpress. Kirakom szövegként is.)

Current frame: (MethodDesc 00007ffaddf27698 + 0 MS.Win32.HwndWrapper..ctor(Int32, Int32, Int32, Int32, Int32, Int32, Int32, System.String, IntPtr, MS.Win32.HwndWrapperHook[]))
Child-SP         RetAddr          Caller, Callee
00000044D153C8A0 00007ffae15d6bb6 (MethodDesc 00007ffaddf0ce98 + 0x266 System.Windows.Threading.Dispatcher..ctor()), calling (MethodDesc 00007ffaddf27698 + 0 MS.Win32.HwndWrapper..ctor(Int32, Int32, Int32, Int32, Int32, Int32, Int32, System.String, IntPtr, MS.Win32.HwndWrapperHook[]))
00000044D153C8C0 00007ffae02cecf9 (MethodDesc 00007ffae00679c0 + 0x59 ATS.Core.Utils.NumberExtensions.LoseEqual(Double, Double)), calling coreclr!JIT_GetSharedNonGCStaticBase_SingleAppDomain [D:\workspace\_work\1\s\src\coreclr\src\vm\amd64\JitHelpers_SingleAppDomain.asm:25]
00000044D153C940 00007ffadf88eafe (MethodDesc 00007ffaddf0c720 + 0x4e System.Windows.Threading.Dispatcher.get_CurrentDispatcher()), calling (MethodDesc 00007ffaddf0ce98 + 0 System.Windows.Threading.Dispatcher..ctor())
00000044D153C960 00007ffae151201e (MethodDesc 00007ffadef6a9b0 + 0x3e System.Windows.Input.CommandManager.get_Current()), calling coreclr!JIT_WriteBarrier [D:\workspace\_work\1\s\src\coreclr\src\vm\amd64\JitHelpers_Fast.asm:97]
00000044D153C970 00007ffae1512056 (MethodDesc 00007ffadef6ab28 + 0x16 System.Windows.Input.CommandManager.RaiseRequerySuggested()), calling (MethodDesc 00007ffaddf0c720 + 0 System.Windows.Threading.Dispatcher.get_CurrentDispatcher())
00000044D153C990 00007ffae15121c9 (MethodDesc 00007ffadef6a998 + 0x9 System.Windows.Input.CommandManager.InvalidateRequerySuggested()), calling (MethodDesc 00007ffadef6a9b0 + 0 System.Windows.Input.CommandManager.get_Current())
00000044D153C9C0 00007ffadf9223c8 (MethodDesc 00007ffadf00a448 + 0x28 ATS.RelayCommand.RaiseCanExecuteChanged()), calling (MethodDesc 00007ffadef6a998 + 0 System.Windows.Input.CommandManager.InvalidateRequerySuggested())
00000044D153C9F0 00007ffae150c44e (MethodDesc 00007ffae1760db0 + 0xee ATS.TaInfo+<OneMinuteUpdates>d__197.MoveNext()), calling (MethodDesc 00007ffadf00a448 + 0 ATS.RelayCommand.RaiseCanExecuteChanged())
00000044D153CA00 00007ffae150d4a4 (MethodDesc 00007ffae0564348 + 0x234 ATS.CommonConcepts.TaBase`1[[System.__Canon, System.Private.CoreLib]].TryToEnter(ATS.BarEx))
00000044D153CBC0 00007ffae0edc2ab (MethodDesc 00007ffadfc50b60 + 0x6b System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[System.__Canon, System.Private.CoreLib]](System.__Canon ByRef))
00000044D153CBF0 00007ffae150c33b (MethodDesc 00007ffae1760da0 + 0x2b ATS.TaInfo+<OneMinuteUpdates>d__197..ctor()), calling (MethodDesc 00007ffaddac0be8 + 0 System.Object..ctor())
00000044D153CC20 00007ffae150c2cb (MethodDesc 00007ffadfbe0cc8 + 0x10b ATS.TaInfo.OneMinuteUpdates(ATS.ITradingAlgorithm, ATS.BarCollection, ATS.BarCollection, ATS.BarEx)), calling (MethodDesc 00007ffadfc50938 + 0 System.Runtime.CompilerServices.AsyncTaskMethodBuilder.Start[[System.__Canon, System.Private.CoreLib]](System.__Canon ByRef))
00000044D153CC40 00007ffae150a6af (MethodDesc 00007ffae0562f80 + 0x12f ATS.TA`1[[System.__Canon, System.Private.CoreLib]].StepOne(ATS.BarEx, Boolean, ATS.BarProperty))
00000044D153CC90 00007ffae150c19b (MethodDesc 00007ffae11827a8 + 0x5b ATS.TaInfo+<>c__DisplayClass196_0.<WhenBarsReady>b__4(ATS.BarEx)), calling (MethodDesc 00007ffadfbe0cc8 + 0 ATS.TaInfo.OneMinuteUpdates(ATS.ITradingAlgorithm, ATS.BarCollection, ATS.BarCollection, ATS.BarEx))
00000044D153CCD0 00007ffae0f432b1 (MethodDesc 00007ffae1183ac0 + 0x71 ILStubClass.IL_STUB_MulticastDelegate_Invoke(ATS.BarEx))
00000044D153CD10 00007ffae150a4e7 (MethodDesc 00007ffade4d81f0 + 0x87 ATS.BarCollection.RaiseDelayedOnBarAdded())
00000044D153CD60 00007ffae150a441 (MethodDesc 00007ffade4cef70 + 0x41 ATS.BarFromTickFactory.RaiseDelayedOnBarAdded()), calling (MethodDesc 00007ffade4d81f0 + 0 ATS.BarCollection.RaiseDelayedOnBarAdded())
00000044D153CDA0 00007ffae150a394 (MethodDesc 00007ffae0562f30 + 0xa4 ATS.TA`1[[System.__Canon, System.Private.CoreLib]].TsOnTickArrivedPost(ATS.Core.TickData.TickOhlc)), calling (MethodDesc 00007ffade4cef70 + 0 ATS.BarFromTickFactory.RaiseDelayedOnBarAdded())
00000044D153CDB0 00007ffadfede055 (MethodDesc 00007ffade3ee688 + 0x45 log4net.Repository.Hierarchy.Logger.IsEnabledFor(log4net.Core.Level))
00000044D153CE00 00007ffae14fceba (MethodDesc 00007ffade4d7118 + 0x9a ATS.SteamingTickSourceBase.OnTickArrivedPost(ATS.Core.TickData.TickOhlc))
00000044D153CE70 00007ffae1599853 (MethodDesc 00007ffade608348 + 0x103 ATS.Basics.LiveTrading.CombinedBackFilledTickDataSource.OnTickArrivedFilteredForRealtimeTicks(ATS.Core.TickData.TickOhlc)), calling (MethodDesc 00007ffade4d7118 + 0 ATS.SteamingTickSourceBase.OnTickArrivedPost(ATS.Core.TickData.TickOhlc))
00000044D153CF50 00007ffae14fcac8 (MethodDesc 00007ffade6082e8 + 0x568 ATS.Basics.LiveTrading.CombinedBackFilledTickDataSource.RealTimeDataSourceTickArrived(ATS.Core.TickData.TickOhlc)), calling (MethodDesc 00007ffade608348 + 0 ATS.Basics.LiveTrading.CombinedBackFilledTickDataSource.OnTickArrivedFilteredForRealtimeTicks(ATS.Core.TickData.TickOhlc))
00000044D153D180 00007ffae1027f8a (MethodDesc 00007ffade4d7100 + 0x9a ATS.SteamingTickSourceBase.OnTickArrived(ATS.Core.TickData.TickOhlc))
00000044D153D1F0 00007ffae10280bd (MethodDesc 00007ffade526628 + 0x10d ATS.TimeAggregatingStreamingTickSourceDecorator.TickSourceOnTickArrived(ATS.Core.TickData.TickOhlc)), calling (MethodDesc 00007ffade4d7100 + 0 ATS.SteamingTickSourceBase.OnTickArrived(ATS.Core.TickData.TickOhlc))
00000044D153D2F0 00007ffae10475a7 (MethodDesc 00007ffae14583f0 + 0x97 ILStubClass.IL_STUB_MulticastDelegate_Invoke(ATS.Core.TickData.TickOhlc))
00000044D153D360 00007ffae1027f8a (MethodDesc 00007ffade4d7100 + 0x9a ATS.SteamingTickSourceBase.OnTickArrived(ATS.Core.TickData.TickOhlc))
00000044D153D3D0 00007ffae102710e (MethodDesc 00007ffade54dff8 + 0x14e ATS.Basics.TradeStationApi.TradeStationSingleTickerRealtimeTickSource.BarStreamerOnBarArrived(ATS.Basics.TradeStationApi.TradeStationSteamingBar)), calling (MethodDesc 00007ffade4d7100 + 0 ATS.SteamingTickSourceBase.OnTickArrived(ATS.Core.TickData.TickOhlc))
00000044D153D490 00007ffae1026fa2 (MethodDesc 00007ffade54b400 + 0x72 ATS.Basics.TradeStationApi.BarStreamerRealtime.OnBarArrived(ATS.Basics.TradeStationApi.TradeStationSteamingBar))
00000044D153D4E0 00007ffae1009534 (MethodDesc 00007ffade54b3c0 + 0x9b4 ATS.Basics.TradeStationApi.BarStreamerRealtime.ProcessBar())
00000044D153D7F0 00007ffae0fee1e1 (MethodDesc 00007ffae13f1b20 + 0x1021 ATS.Basics.TradeStationApi.BarStreamer+<>c__DisplayClass55_0+<<StartStreamingAsync>b__0>d.MoveNext())
00000044D153DE10 00007ffadf8ec8ac (MethodDesc 00007ffade0f31d0 + 0x8c System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object))

A HwndWrapper konstruktora hívja a RegisterWindowMessage-t. A HwndWrappert a Dispatcher konstruktora hívja. A Dispatchert egy hosszabb hívási láncon keresztül a saját TaInfo.OneMinuteUpdates metódusom hívja meg. Ennek az a célja, hogy percenként frissítsen bizonyos elemeket a GUI-n. Még tovább visszafelé haladva a TradeStationApi.BarStreamer metódusaiból jön a hívás.

Ezek viszont háttérszálon működnek!

Ami jó hír, hogy láttuk, a hiba csak akkor indul be, amikor jön adat, ezért még erősebb a gyanú, hogy megvan a probléma kiváltó része. Ez pedig az adatforrásunk!

Az előző rész végén mutattam, hogy van egy gyanús változtatás, ami ezt a hibát behozta:

Ártatlannak tűnő sync-async refactoring

Így néz ki a gyanúsított kódrészlet:

Látszik, hogy a kód elve egy Task.Run-ban van, egy háttérszálon (threadpool szálon) fut. Az eredeti kódban itt egy szinkron ReadLine() volt. Ezután a sor után van a bejövő adat feldolgozása, majd a kód felemel egy eseményt, az fut be a korábban látott OneMinuteUpdates metódusba, ami aztán kiváltja a leakes kód futását.

De a szinkron kód is háttérszálon hívott át, mégse volt belőle leak. Miért? Először is fontos leszögezni, hogy az a tény, hogy a háttérszál GUI-t piszkál, az bug. Csak épp nem esett szét tőle semmi, ezért észrevétlen maradt.

Hogy határozottan lássuk, mi történik, idézzük elő a hibát újra, de most Visual Studio debuggerben. Most már csak managed kódot kell debugolnunk, az érdekel minket, milyen szálon érkezik be a hívás a OneMinuteUpdates metódusba, mivel ez volt a legközelebb a tűzhöz.

Ez a kis kód az, ami belehív a WPF-be, hogy kérje meg a GUI-n levő gombot, hogy az kérdezze meg tőlünk, hogy aktív lehet-e?

Interakció a WPF-fel

A stack trace-ben világosan látszik, hogy ezen keresztül indul el a baj. De nem ez a kód a bűnös, hanem az, aki hívja.

Egy hívás lenyomata:

A 14308-as szál hív be, NEM gui thread.

A következő hívás már másik szálon esik be:

Minden egyes percben egy random threadpool szál visszahív egy olyan kódot, amit csak a főszálból szabadna hívni. De miért nem volt hiba a szinkron kód esetén?

Visszaírtam a kódot szinkronra:

Beesik újra az event:

Azonban van egy nagyon fontos különbség az async kódhoz képest: minden egyes visszahívás ugyanazon a szálon jön be! Nem GUI szál, bugos, de akkor is egyetlen, fix szál. Ha nincs egy szálhoz Dispatcher, akkor a WPF létrehoz hozzá egyet. De, ha mi megvicceljük, és állandóan új szálról kényszerítjük ezt ki, akkor sorban jönnek létre a Dispatcherek, és így az atom leak.

Miért megy egy szálon a szinkron kód, és többön az aszinkron? Azért, mert async esetén a continuation, azaz az await utáni kód egy threadpool szálon kerül visszahívásra. Ha a hívó GUI szál lett volna, akkor vissza dispatch-elték volna a hívást a főszálra, de itt már eleve az async hívó is háttérszálú volt, ezért a continuation threadpool szálról hívódott vissza.

Mi a megoldás? Visszatérjünk a szinkron verzióra? Semmiképpen, ez csak tüneti kezelés lenne. Ki kell javítani az eredeti bugot, azaz, ne nyúljunk a WPF-hez háttérszálból. Ehhez át kell dobni a hívást a főszálra. Én az alábbi kód kódot szoktam erre használni:

Feladat beküldése a főszálra

Amikor elindul a program, és már van GUI, akkor letárolom a főszál szinkronizációs contextjét egy statikus propertyben. Ha át kell dobni egy hívást, akkor ennek a Post metódusával teszem meg.

Így átírva a kódot a GUI-t elérő kód már helyesen a főszálon fut le:

Mi a tanulság az egész nyomozásból?

  1. Marhára oda kell figyelni, hogy mindig csak a főszálból nyúljunk a GUI-hoz.
  2. Egy apró async átírás kilométerekkel arrébb komoly károkat okozhat.

Utószó

A munkám során nagyon sokat nyomozok az ügyfeleimnek hasonló, és még sokkal aljasabb problémákat is, de sajnos ezeket nincs jogom leírni. De gondolkodom rajta, hogy legalább a tanulságokat mégis valahogy megörökítsem.

Windows Atom szivárgás nyomozása I.

Egy nem hétköznapi hibát mutatok most be.

Ez az első része a cikknek, a második itt olvasható.

A managed memory leakeket elég könnyű megfogni allocation profilerekkel, mint pl. a DotMemory. Általában a nehézséget (nekem) az okozza, hogy megértsem az ügyfél kódját annyira, hogy legyen fogalmam róla, mit tekintünk károsan soknak, vagy minek szabad tartósan benn lenne memóriában, és minek nem.

A normál memory leak tüneti kezeléssel gyógyítható, csak meg kell szüntetni a szivárgó processzt, és máris visszakaptuk a feleslegesen lefoglalt memóriát.

A mostani szivárgás viszont egy sokkal aljasabb fajta. Hiába lövöd ki az inkontinens processzt, a lefoglalt erőforrások továbbra is beragadnak, ki kell lépetni a felhasználót és vissza, csak akkor kapjuk vissza az erőforrásokat.

A hiba egy saját WPF programomban jött elő, ami mindig vasárnap éjféltől péntek éjfélig fut. Van tehát ideje szivárogtani, ha akar. A hibajelenség az volt, hogy csütörtök táján elkezdett megdögleni a Windows. Nem indult el az Explorer, nem jött be a Task Manager se. Minden program a “Not enough storage available to process this command” hibával szállt el. Logoff-logon megoldotta.

A processek handle countja normális. A memória felhasználásuk normális. Ezért normál eszközökkel nem utal semmi a hiba forrására.

A “Not enough storage available to process this command” szövegre keresve az Atom táblákra terelődik a gyanú. Ez egy név-érték tároló, ami 16 bites kulcsokat használ. Ez már rögtön gyanús a mai világban, sokan nem is éltek még az olvasók közöl, amikor 16 bites rendszerek voltak. :) DDE és egyes Windowing függvények használják. Nagyon hasonló, mint a .NET CLR String Intern táblája.

Az atom táblák monitorozása nem olyan egyszerű, nincs rá performance counter, debuggerből nem látszik nyilvánvalóan.

Szerencsére egy kolléga írt hozzá egy kis céleszközt. Ez a GetClipboardFormatName API függvény sokféle paraméterrel történő hívásával végigkeresteti a 16 bites teljes tartományt, így láthatóvá válnak, mely címek vannak elfoglalva.

A képen bal oldalán láthatók a bugos program által lefoglalt atomok. Lehet regexekkel színezni a képet, a róaszín az én kis bugos drágaszágom.

Atomszivárgás

Egy nap múlva már durvább a helyzet:

Egy nappal később

A képeken a local atom table látszik, a global atom table nem hízott.

A leírások alapján a RegisterWindowMessage hívások pakolnak be ide tételeket. Maguk a problémás, szaporodó atomokat ezt a szöveget tartalmazzák:

DA13 = HwndWrapper[Trader;;0def0780-e17c-49d0-a243-149008a6b29e] –RWM

Managed kód esetén simán debuggerben megállnánk, amikor be akar szúrni a program egy atomot. De az Atom API csak kernel módban debugolható, egy szerveren ilyet nem fogok csinálni.

Azonban a RegisterWindowMessage-et esetleg el tudom kapni. Igaz, ez se managed funkció, de azért managed programból is ki lehet debugolni a nem managed, de user módú hívásokat.

De előtte azért szét szoktunk nézni, mentális debuggingot alkalmazunk. A WPF forráskódjában ezeken a helyeken van RegisterWindowMessage hivatkozás.

Ami az első ábrán érdekes, hogy vasárnap 18 óráig (EST) nem volt leak, csak utána indul meg a jobb oldali chart felfelé. Akkor indul ugyanis a kereskedés, onnantól érkeznek adatok, amiket a program feldolgoz. Az adatok feldolgozása másodpercenként egyszer történik, mert így adja az adatokat az adatforrás. Mivel az adatokat háttérszálon érkeznek, ezért a GUI részére át kell dispatch-elni a hívásokat a főszálra. Valószínűleg ehhez a WPF valamilyen Windows Window mechanizmust használ, tehát érzésre ezen a környéken lesz a probléma forrása.

Logikus lenne a forráskód változásait visszanézni a múltban, és megnézni, mi változott benne, ami kiváltotta a hibát. A nehézség az, hogy a beteg program általában egy példányban fut csak, és akkor kiírja egy hétig a Windows, nem telik be az atom tábla. De mostanában két példányban futtatom, ezért jött elő a hiba. Így viszont nem tudom, melyik verzióval jött be. (Visszaállni meg üzleti okok miatt nem lehet).

Azon az úton azonban el lehet indulni, hogy vagy a GUI részen történt valami módosítás, ahol a háttérszálas adatokat veszem ki, vagy az adatforrásnál.

Az adatforrásban egy ilyen kis változtatás volt szeptember végén:

Ha már úgyis async volt a külső metódus, akkor egy szinkron hívást is kicseréltem asyncre, hogy szép legyen. Lehet hogy ez okozza a problémát? Hamarosan kiderül.

Architektúra dilemma

Tegyük fel hogy van egy klasszikus, többrétegű alkalmazásunk. Van benne egy service layer, ami hív valamiféle alkalmazás logikát. A logika direktben hivatkozik Entity Framework DbContextre, abból olvas fel adatokat, módosítja őket, illetve direkt EF Context és DBSet hívásokkal menti őket.

Szeretnénk ezt az architektúrát egy kicsit jobban szétdarabolni, hogy átláthatóbb és tesztelhetőbb legyen. Ezért először az EF adatlekérő részeket kiszedjük Extract Method refactoringgal, majd utána átmozgatjuk őket saját osztályokba (Extract Class a vége). Ezeket az osztályokat elnevezhetjük repositoryknak. Ezek ugyan nem olyan szép, idealizált repository-k, mint amiket Martin Fowlerék álmodtak meg, de lényeg, hogy az adatelérő kódokat szeretnénk valamennyire elszigetelni a logikától. 

Miért? Mert így elszigetelve jobban meg lehet érteni őket, könnyebb optimalizálni a benne lévő adaterlését, és könnyebb az adateléréshez integrációs teszteket írni (például perf okokból).  A hívó, üzleti logika oldalon élesen szétválik az adatelérő kód és a logika, így az üzleti logikába könnyen tudunk fake adatokat bevinni, ami addig nem volt egyszerűen megoldható, amíg az entity frameworköt direktbe hivatkozva kért le adatokat a logika. Tehát a cél egy jobban kezelhető (SOLID) és jobban tesztelhető kód előállítása.

A dilemma a következő. Nyilván egy nagy osztályba nem lehet kimozgatni az összes helyen szétszórt eddigi adatelérő kódot, mert akkor kapunk egy több ezer soros monstrumot.  Valamilyen módon szét kell szedni az adatelérő metódusokat különböző osztályokba, ezeket hívtam az előbb repositoryknak. Ezek nem feltétlen 1-1 entitáshoz kapcsolódó repositoryk, hanem lehet, hogy valami üzleti területet foglalnak egybe. Például a SzámlázásRepo lehet, hogy 5-20 entitáshoz kapcsolódó adatelérést is csinál, hisz gyakori, hogy egy teljes gráfot kell letölteni (mint a Domain Aggregate a DDD-ben). De nincs jelentősége most a repó felbontásának.

Tételezzük fel, hogy itt tényleg entitás példányok jönnek vissza a repókból, tehát nem rakunk be egyelőre semmi mapping réteget, amivel DTO-k vagy Domin Objecteket alakítanánk ki. Egy ilyen refactoring során nem lehet ekkorát harapni egyszerre.

Tehát direktben entitásokat, persistent entityket adunk vissza. Minden repó mögött ugyanaz az EF DBContext példány van, ez könnyű elérni valamilyen Dependency Injection Framework Scope-olt lifetime fogalmával, általában a szerviz hívást mint scope-ot felhasználva. Ez azért fontos, mert ha letöltök egy entitást, majd letöltöm annak egy gyerekét, akkor belül az EF összekapcsolja a kettőt, azaz a szülő gyerek kollekciójába belekerül a gyerek, a gyerek szülő referenciája pedig a szülőre fog mutatni. Ez a közös Context egy kritikus koncepció az eddigi kódban, ugyanis bár lehet nem tudatos azokban, akik írták a kódot, de az EF Context révén implicit kapcsolatba kerül sok sornyi adatelérő kód, és csak azért működött helyesen az adatelérés, mert az EF így van megírva.

A get műveletek szépen és elegánsan becsomagolhatók repó műveletekbe. Ha van pl. egy GetInvoicesByCustomer metódus, akkor az visszaad Invoice entitásokat, ami mögé tetszőleges szintig betöltünk minden egyéb gyermek vagy szülő objektumokat. Igaz, ez a részlet nem látszik a metódus szignatúrából, de ezzel együtt élünk. A logikát könnyű tesztelni fake adatokkal, hisz csak ki kell cserélni a teljes repó metódust valami fix adatot visszaadó stubbal.

A módosítások repók felé történő kommunikációja már nehezebb. Az insert még elmegy, hisz pl. az InvoceRepository.AddInvoice vagy AddInvoceWithDetails vagy hasonló leírja, mit várunk a művelettől. A háttérben egyszerűen hívunk egy DbSet.Add-ot.

A Delete hasonlóan egyszerű, ha top level objektumról van szó, DeleteInvoice(Invoice).

Az egész viszont sokkal macerásabbá kezd válni, amikor például egy szülő objektum alá kell berakni egy gyerek objektumot.

Például, a repóból lekérek egy számlát, majd ehhez kellene tételeket hozzáadni.

Az InvoiceItems kollekció a visszakapott Invoice entitás része. Ha ehhez egyszerűen hozzáadunk egy új InvoceItemet, akkor az EF erről tudni fog, hisz neki végig van referenciája a gyökér Invoice objektumra, így a SaveChanges csak úgy el fogja menteni a gyerek sort, beállítva az FK-ját a szülő Invoice-ra.

A gondom az, hogy ez teljesen implicit. Nem tudok értelmes metódust felrakni a repóra, ami kommunikálná a logika azon szándékát, hogy ő itt most egy gyerek objektumot akar hozzáadni a szülőhöz. Emiatt tesztelni se tudom rendesen.

Ugyanez a probléma a módosításokkal. Lehozok a repó.GetValami metódussal egy entitást. Ezt direktben módosíthatja a logika, majd a SaveChanges-re az EF csak úgy tudja, hogy erre update SQL parancsot kell kiadni.

Megint, nem fogható meg jól tesztből, hogy a logika szándéka az volt, hogy módosít egy entitást.

Tehát, az átalakított kód úgy néz ki, hogy betölt mindenféle adatot mindenféle repo.Get hívásokkal. Ezek nem elszigetelt adatok, hanem “össze vannak ragadva”. Az EF mindet követi. A logika tetszőleges módon megbabrálja ezt a több darabból összerakott gráfot, majd az EF ezt elmenti “okosba”. De rém utálom az ilyen okosba megoldásokat.

Hogyan lehet erre tesztet írni, ami azt vizsgálja meg, hogy a logika a lehozott Invoce-hoz hozzáadott egy új tételt? Hogy lehet megfogni tesztből, hogy milyen entitás milyen property-jét mire állította be a logika? Azt feltételezem, hogy fake repók vannak a logika mögött. Ahogy megbeszéltük, a Getekben adatbázis helyett könnyű kamu adatokat behazudni memóriából, azaz visszaadhatunk teljesen feltöltött gráfokat. Például visszajön egy Invoice, benne két InvoiceItem, és referencia egy Customerre. Az logika legyen az, hogy ha a Customer neve Mari, akkor berak egy új tételt, InvoiceItemet, “Talp és egyéb masszázs” tartalommal.

A logika egyszerűen hozzáad egy new InvoiceItemet a Getben visszakapott Invoice objektumhoz, majd a repó mögötti EF DbContext.SaveChanges csak úgy el fogja menteni.

Hogyan lehet tesztből detektálni, hogy a logika tényleg hozzáadta a számlatételt?

Azt lehet tenni, hogy eltérítjük a SaveChanges hívást (mock scenario), és abban átnézzük a mit? Itt nincs igazi EF DbContext, nincs semmi state a kezünkben, amit meg vizsgálni.

Ha a repón lenne valami explicit metódus, akkor könnyebben lehetne tesztelni. Ha például lenne egy InvoceRepo.AddInvoiceItem(Invoice, InvoiceItem) metódus, akkor ezen keresztül explicit látszik a logika szándéka, hogy egy gyerekelemet akkor hozzáadni. Ez könnyen tesztelhető.

De mit csináljon az igazi AddInvoiceItem implementáció? Adja ő hozzá az itemet az átpasszolt Invoice-hoz? Ok, megteheti. De az EF kialakítása miatt a logika ezt minden további nélkül megteheti a visszakapott Invoice entitáson is, mindenféle repó hívás nélkül, mégis működni fog az igazi implementáció, míg a teszt hibát jelezne.

A probléma fő oka szerintem az, hogy a két réteg között csak úgy átmennek az entitások, így a logic layerben történt módosítások csak úgy átlátszanak a repó (data access) rétegbe.

Ez nyilvánvalóan egy nem elegáns, nem elég tiszta modell. 

De térjünk vissza az elejére. Van egy spagetti kódunk, amiben egymás után vannak logika és adatelérő kódok. Ez akarjuk elkezdeni kis kockázatú refactoringokkal darabolni tesztelés és kezelhetőség miatt. Mivel az eddigi kód erősen épített az EF-re mint change trackerre, ezt nem lehet egyszerű refactoringgal kiszedni belőle. Az átláthatóbb szerkezet érdekében kirakjuk saját osztályokba, repókba, de tudjuk, hogy erősen kilátszik az EF a repó mögül (google: Leaky Abstraction). Ezt tudjuk, elfogadjuk, mert nem lehet egy nagyon sok sorból álló kódot csak úgy átalakítani. A kérdés tehát az, hogyan lehet ilyen kötöttségek mellett úgy kialakítani egy értelmes repó interfészt és értelmes együttműködést a két réteg között, ami elfogadható szintű logika tesztelést tesz lehetővé?

RDP Brute Force Protection with PowerShell and Windows Firewall Rules

Az ötlet innen jött. Kicsit átírtam a kódot, mert az eredeti minden egyes kitiltott IP-t egyesével appendelte a log fájlhoz, ami nagyon lassúvá tette, valamint nem kezelte a duplikát bejegyzéseket.

Íme az átírt verzió:

$Last_n_Hours = [DateTime]::Now.AddHours(-24)
$badRDPlogons = Get-EventLog -LogName 'Security' -after $Last_n_Hours -InstanceId 4625 | ?{$_.Message -match 'logon type:\s+(3)\s'} | Select-Object @{n='IpAddress';e={$_.ReplacementStrings[-2]} }
$getip = $badRDPlogons | group-object -property IpAddress | where {$_.Count -gt 10} | Select -property Name

$uniqueIps = @{}

$current_ips = (Get-NetFirewallRule -DisplayName "BlockRDPBruteForce" | Get-NetFirewallAddressFilter ).RemoteAddress

foreach ($ip in $current_ips)
{
    $uniqueIps[$ip] = $true
}

foreach ($ip in $getip)
{
    $uniqueIps[$ip.Name] = $true
}

$finalBlockedIps = $uniqueIps.Keys | Sort-Object

Set-NetFirewallRule -DisplayName "BlockRDPBruteForce" -RemoteAddress $finalBlockedIps

Write-Output "Blocked addresses:"
$finalBlockedIps 

Write-Output "Blocked address count:"
$finalBlockedIps.Count

$log = "C:\ware\secu\rdp_blocked_ip.txt"
$finalBlockedIps | Select-Object {(Get-Date).ToString() + ' ' + $_} | Out-File $log

Itt látható, hogy 1 nap után már 260 címet tiltott ki.

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

DDD Bounded Contextek egy hosting processzben?

Tegyük fel van egy nagy alkalmazás, amely többé-kevésbé DDD mentén van elkészítve.
Minden terület saját bounded contextben (BC) van, a BC-ek egymás felé csak az apijaikon keresztül kommunikálnak.

A fő cél az lenne, hogy a csapatok/emberek tisztán egy BC-en tudjanak dolgozni, ne kelljen a többit is mindig lefordítani, a méretek miatt. Ezért mondjuk minden BC-ből csak az API komponensét publikáljuk ki, nugetbe csomagoljuk, és így binárisan tudnak egymással kommunikálni a BC-ek. Ez eddig szerintem rendben van, bár a verziózás kérdése itt sem egyszerű, hiába próbáljuk a csatolást az API-kon és az Anti Corruption Layeren (ACL) keresztül lazítani.

A nagy kérdés számomra a közös komponensek használata. “A” BC használ mondjuk 10.1-es NewtonSoft.Json-t, “B” BC pedig 9.0-t. Amikor minden bounded contextet bemásolunk egy website bin könyvtárába, akkor esetleges lesz, hogy melyik verziójú külső komponens lesz bemásolva, illetve a verziókhoz passzoló assembly redirectek is kellenek a web.config-ba.

Hogy szoktak ebben rendet tenni? Vagy megfordítva a kérdést, jó ötlet egy processben hosztolni a BC-eket, vagy ha ennyire laza csatolást akarunk, akkor külön processzbe kell őket rakni, és elkezdeni elmenni a microservices irányba?

Ötletek, linkek, könyvek, bármi érdekel a témában.

Ha valaki játszani akar a választási adatokkal

using System;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using System.Text.RegularExpressions;
using System.Xml;

namespace ConsoleApp1
{
    class Program
    {
        static void Main()
        {
            new Program().Run();
        }

        private void Run()
        {
            Regex r = new Regex(@".+\\(\w+)\\(\w+).evkjkv.html", RegexOptions.Compiled | RegexOptions.IgnoreCase);

            List<string> parties = new List<string>()
            {
                "FIDESZ",
                "JOBBIK",
                "MSZP",
                "LMP",
                "EGYÜTT",
                "DK",
            };

            foreach (var file in Directory.GetFiles(
                @"C:\temp\valasztas\valasztas.hu\dyn\pv18\szavossz\hu\", "evkjkv.html", SearchOption.AllDirectories))
            {
                var d = FromHtml(file);

                IEnumerable<string> cols = parties.Select(p =>
                {
                    var part = GetVotes(d, file, p);
                    return $"{p},{part}";
                });
                string res = string.Join(",", cols);
                var m = r.Match(file);
                Console.WriteLine($"{m.Groups[1]},{m.Groups[2]},{res}");
            }
        }

        private static string GetVotes(XmlDocument d, string file, string party)
        {
            var n = d.SelectSingleNode($"//tr[td[starts-with(text(), '{party}')]]");
            if (n == null)
            {
                return "0";
                //Console.WriteLine($"Skipping {file} because there is no data for {party}");
            }

            //Console.WriteLine(n.InnerXml);
            return n.SelectSingleNode("td[4]").InnerText.Replace("&amp;", "").Replace("&nbsp;", "");
        }

        XmlDocument FromHtml(string path)
        {
            using (TextReader reader = File.OpenText(path))
            {
                XmlDocument doc;
                using (var sgmlReader = new Sgml.SgmlReader
                {
                    DocType = "HTML",
                    WhitespaceHandling = WhitespaceHandling.All,
                    CaseFolding = Sgml.CaseFolding.ToLower,
                    InputStream = reader
                })
                {
                    doc = new XmlDocument
                    {
                        PreserveWhitespace = true,
                        XmlResolver = null
                    };
                    doc.Load(sgmlReader);
                }

                return doc;
            }
        }
    }
}

.NET Rocks letöltése kocsiban hallgatáshoz

Másold be egy ps1 fájlba, és hagyd úgy éjszakára, reggelre ott lesz az egész.

function GetFeedPageCount ($url) {
  $feed=(New-Object System.Net.WebClient).DownloadString($url)
  $pageCount = $feed.rss.channel.pageCount
  return $pageCount;
}

function DownloadFeed ($url) {
  $feed=(New-Object System.Net.WebClient).DownloadString($url)
  foreach($i in $feed.rss.channel.item) {
    $url = New-Object System.Uri($i.enclosure.url)
    $url.ToString()
    $url.Segments[-1]
    $localFile = $url.Segments[-1]
    if (Test-Path($localFile)) {
      Write-Host "Skipping file, already downloaded"
    }
    else
    {
      Invoke-WebRequest $url -OutFile $url.Segments[-1]
    }
  }
}

# Related blog post here: http://blogs.msdn.com/b/cdndevs/archive/2014/11/18/azure-fridays-a-powershell-script-to-download-rss-videos.aspx

$feedUrl = "http://www.pwop.com/feed.aspx?show=dotnetrocks&filetype=master"
DownloadFeed($feedUrl)

Windows 10 system process high cpu usage: solution

Recently my laptop started to become sluggish and the ventilators was constantly on. In task manager it was clear the system process (pid 4) ate 1 cpu core.
Process explorer did not bring any interesting results.
Then I started an investigation using xperf.exe, a Windows Performance Toolkit utility. It is very similar to the profilers you might use for .NET, so I encourage my developer mates to use it when you have a native code performance problem.

Here is what I saw:

Process Explorer did not show more than the ExpWorkerThread level. Ok, I did not configure debug symbols for it, it might have shown stacks correctly, but it is just a snapshot, a sample of the state of the threads in opposite to xperf which profile processes in sampling mode.

However, xperf clearly shows us that volsnap.sys constantly uses the disk. I suppose it stuck into some infinite loop or some.
Volsnap is the volume snapshot service, which supports backup and recovery. So, at first I stopped Volume Shadow Copy service. It did not help.
Then, I deleted system restore points for my drives.
It took several minutes to finish deleting old restore points. After a reset system process is now behave correctly.
System restore points are very important for certain scenarios, so be careful to turn it off. This is just a workaround, to clean up bogus system restore points.
After deletion and restart you should have to reenable it!
I re-enabled it, and the problem did not manifest again. So, I think deleting and recreating restore points solve this kind of weird problem.

CIG visszatekintés – avagy miért nagyon sok a 2% alapkezelési díj a semmiért

Annak idején írtam a nem etikus (szépen fogalmaztam) CIG-ról, a befektetésről programozóknak sorozatban.
Azóta eltelt két év, és a pénz a leírtaknak megfelelően már nem a rablóknál van, hanem direktben vettem BRK-B részvényeket, ami a CIG-nál Warren Buffett Részvény Eszközalap néven fut.
A nevetséges, eszement költségekről, amikből többek között a brokernetes ügynököket fizetik most nem írok újra, korábban már leírtam.

Most a csekélynek tűnő 2%-os alapkezelési költség hatását akarom bemutatni. Ez fel se merül a legtöbb emberben, hisz csak jönnek-mennek a vonalak, nem látszik, hogy milyen manipuláció történik a háttérben. Milyen értéket ad hozzá az alapkezelő ahhoz képest, mintha direktben fektetnék be egy részvénybe? Magyarországról nézve egy dolgot, hedge-eli az USD/HUF mozgásokat. Azaz, mint a példában, ha erős dollár esetén váltottam forintot dollárra, és abból vettem amerikai részvényt, majd most a gyenge dollár esetén hiába hoz sokat egy részvény, ha visszaváltanám, akkor kevesebbet kapnék Ft-ban, mivel közben sokat gyengült a dollár. Más esetben ez fordítva lenne. Azaz, ha én csakis forintban gondolkodok, és külföldi részvényt veszek, akkor nem csak a részvény árfolyama befolyásolja a nyereségemet, hanem a dollár-forint árfolyam is. Ezt ki lehet ütni, másodlagos ügyletekkel (forex vagy opciós ügyletekkel).
Nekem ez nem érték, én egy alapkezelőtől az várnám, hogy ügyesen trade-elve generáljon a benchmark fölött profitot. Nem tudok egyetlen magyar befektetési intézetről sem, ami hosszútávon (de akár rövidtávon is) ezt meg tudná lépni. Mondhatnám tehetségtelen kutyaütők, de nem mondom, mert nagyon is okosok. Bevágják a pénzt valami ETF-be vagy részvénypakkba, beizzítják a hedge-elést, ami nem nagy művészet, majd hátradőlnek, és beszedik minden évben a TELJES BENN LEVŐ PÉNZ 2%-át!
Azaz olyan, mintha minden évben beszoroznák a meglévő pénzt 0,98-cal. Tegyük fel én egy kis-közepes magyar intézet vagyok, és kapok 100 milliárd forintot befektetésre. Minden évben 2 milliárd forintot kapok a semmiért. Hát nem jó biznisz az alapkezelés?
Még egyszer, nincs semmi bajom a 2%-kal, ha ezért kapok valamit, dolgoznak a pénzemen. De lófaszt nem kapok.
Ez nyilván akkor is így van, ha a bankokban fektetsz be alapokba, csak ott legalább nincs a különös feltételekben leírt extra rablás, ami 1-3 év befizetését égeti el.
Csak érdekességképpen belenéztem, a CIB-nél (nem CIG) az első két alapjukban (10. oldal) 300 milliárd forint van. Ennek 2%-a 6 millárd forint. A semmiért, és mégis veszteséges a bank. Eh.

Na, akkor a lényeg. Az évi 2% folyamatosan szívja le a pénzed, akkor ha, ha minden felfele megy, és akkor is, ha lefele.
Így:

Eltelt idő	2% hatása	Mi marad?
1 év	0.98	4,900,000 Ft
2 év	0.9604	4,802,000 Ft
3 év	0.941192	4,705,960 Ft
4 év	0.92236816	4,611,841 Ft
5 év	0.903920797	4,519,604 Ft
6 év	0.885842381	4,429,212 Ft
7 év	0.868125533	4,340,628 Ft
8 év	0.850763023	4,253,815 Ft
9 év	0.833747762	4,168,739 Ft
10 év	0.817072807	4,085,364 Ft

Tíz év alatt elégetnek 19%-ot. 5 millió induló tőkéből lenyesnek 1 millót, neked marad 4. Hosszabb távon nyilván még durvább a hatás az exponenciális jelleg miatt. Csak engem zavar ez? Biztos.

Vissza a CIG-re. Két éve elhoztam a pénzt a rablóktól, és azonnal átraktam a KBC-nél a CIG alap által is viszonteladott BRK-B részvénybe. A mellékelt excelben CIGLopas pontosan meg lehet nézni az eredményeket (csak 10M-ra módosítottam a számot, hogy könnyebb legyen vele számolni).
A CIG-nél 10M két év alatt 13.15M-ra menne fel, csak az alapkezelőből kieső pénzt számolva (durva bull van még). Persze, ha évente 1M-et fizettem volna be, akkor az első 3 év 8.5%-át is elviszik 10 éven keresztül, ami kb. 250000 évente (kicsit kevesebb, mert fogy a pénz, amiből a 8,5-et vonják).
Direkben befektetve, Ft hedge nélkül 13,94M lenne. Ha most kellene forintra visszaváltani pont szopó a hedge hiánya, mivel valójában a részvény felment 58%-kal, de ebből csak 39 marad, annyit gyengült a dollár. Ha pl. 2010 körül fektettem volna be, amikor még 1.5-szer erősebb volt a forint, akkor meg lenne egy 50%-os extra hozamom (mint ahogy a CIG-nél így volt, de persze ezt is lenyelték).
Tehát annak ellenére, hogy a dollár 8%-ot gyengült még mindig 7.81%-kal több pénzem van, mint a CIG-nél (és még több, mivel a különös lopótényezőt (8.5% első 3 évből) bele se raktam). 780000 különbség csak két év alatt. Ez szerintem durva.

Ha az UDF/HUF nem mozgott volna, akkor a 10M most két évvel később 15,8M lenne (és a portfóliómban dollárban kifejezve tényleg ez látszik, 60,8%-ban áll).
Ha hosszútávú befektetésről van szó, én nem félek attól, hogy a forint majd olyan brutál erős lesz 10-20 év múlva, hogy megszívom a visszaváltást, így engem nem érdekel a hedge-elés.

Összegezve, igen sok milliót veszítesz az alapkezelők 2%-án. Ha nem farhátat akarsz enni nyugdíjas korodban, míg a pénzeden szingapúri kuplerájba viszik a “befektetési tanácsadókat” és autókat sorsolnak ki nekik karácsonyra, akkor tanulj, és fektess be direktben, hagyd ki a vámpírokat a pipeline-ból.

Python pandas lassú io.parsers.read_csv metódus

Elkezdtem pythonozni, mivel machine learninget tanulok, és ahhoz vagy python vagy R javasolt. Legjobb mindkettőhöz érteni, most a pyhon van soron.

Akit érdekel bátran vágjon bele, a nyelv nem nagy szám (nekem ronda ez a kettőspontos mindenség, de majd megszokom), a tanulást a libek megismerése viszi el (kb. mint a legtöbb nyelvnél).

Mivel van sok tőzsdei adatom ezeken futtatom az ML libeket. A legtöbb példában napos adatokat használnak, de én intraday akarok keresgélni, ami sokkal több adatot jelent. Valószínűleg bajban leszek, pl. a Support Vector Machine o(n^4)-es alg, quadratikus, így nem tolhatok rá túl sok adatot.
De már az elején elakadtam, mert 1-2M CSV betöltése is 10mp volt.

Mindenféléket írtak a stackoverflown, csak a megoldást nem.

sym1 = pd.io.parsers.read_csv(os.path.join(datadir, '%s.txt' % symbol),
header=None, index_col=0, nrows = rows, parse_dates=[['Date', 'Time']],
infer_datetime_format=True,
names=['Date', 'Time','Open','High','Low','Close', 'Up', 'Down'], usecols=['Date', 'Time','Close'])

Az infer_datetime_format=True hozott megoldást, valamiért a dátum parsolása csapnivaló, ezen flag nélkül. A read_csv doksija írta, onnan jött az ötlet:
“infer_datetime_format : boolean, default False

If True and parse_dates is enabled, pandas will attempt to infer the format of the datetime strings in the columns, and if it can be inferred, switch to a faster method of parsing them. In some cases this can increase the parsing speed by 5-10x.”

IIS lassulás probléma – megoldás

Annak idején írtam róla, hogy egy cégnél a web szerverek és a mögöttük levő webszervizek közötti kommunikációban jelen van egy 200ms-os plusz késleltetés, amire nem találtunk racionális magyarázatot.
Semmilyen eddig bevált eszköz, profilerek, WinDebug, Dynatrace, logok elemézése nem adott magyarázatot a jelenségre.
A Google a Nagle és a Delayed Ack irányába tolta a vizsgálódást.
Végül wiresharkkal alaposan kielemezve a forgalmat kiderült, hogy a protokoll leírással szemben csak 200ms késleltetéssel küldtek Acknowledge-et egymásnak a felek, ez adott késleltetést minden híváshoz. Miután a delayed ackot kikapcsoltuk mindkét oldalon, a jelenség megoldódott. A megoldás szerintem csak workaround, mivel a tcp protokol rfcje alapján nem így kellene működni a hálózatnak, vagy a Windows vagy a VMWare network card driver a bugos.

Röviden, mi zajlik itt le. A kliens (web app) TCP kommunikációt kezdeményez a webszerviz felé. A TCP protokollban minden csomag vételét meg kell erősíteni a másik oldalnak. Esetünkben olyan kicsi kérések mentek a szerviz felé, hogy belefértek egy hálózati csomagba. A Nagle algoritmus már eleve bufferelhetné a hívó oldalon a csomag kiküldését, de ezt úgy néz ki a generált webszerviz proxy kikapcsolja a Naglét, így ez nem okozott problémát.
Átmegy a kérés a szervizbe. Onnan egy acknowledgenek kell visszamenni a kliensre, jelezve, hogy a szerviz megkapta a csomagot. Ezt nem akarja visszaküldeni a szerviz azon mód, pár bájt miatt nem akar egy teljes csomagot visszaküldeni. A protokol alapján vár arra, amíg amúgy is küldene valamit vissza a kliensnek, és annak a hátára rakná rá az acknowledget (piggybacking).
Esetünkben volt sok kérés, lett volna alkalma visszaküldeni gyorsan a megerősítést, de nem tette. A protokollban van egy másik elem is. Ha eltelik 200ms, akkor ha eddig nem volt alkalmunk visszaküldeni a választ, legalább 200ms múlva meg kell tenni. Ez a delayed ack. Meg is tette a szerver, de ezzel minden egyes kérésre az ackot 200ms múlva küldte csak vissza. A kikapcsolással pazarló módon minden egyes csomagot azonnal visszajelez a szerver, azaz kikapcsoltuk ezt az optimalizálást, de cserébe a bugos késleltetés kiesett.
Összegezve, a válasznak vissza kellett volna menni más kérésekre adott válaszok hátán, de nem mentek vissza, ezért állítom, hogy ez bug, a delayed ack kikapcsolás csak workaround, de legalább megoldotta a késleltetést.
Két kép, ami szemlélteti a hibát.
Az első egy csatornán a kommunikáció lépéseit mutatja meg (a http keepalive miatt sok kérés meg át egy tcp csatornán). Látható, hogy nagyon sok kérésre csak 200ms múlva jön meg a válasz.

A második képen sok kérés ackjának maximuma látható. Jól megfigyelhető a “fék” hatása.

Sajnos nincs kéznél képem, de a delayed ack kikapcsolása után lemegy pár száz mikro!secre a válasz, mivel ilyenkor buzgó módon azonnal megy vissza az ack.

IIS lassulás probléma – help needed

Kivételesen nem megoldást írok le, hanem kérdést teszek fel.

Egyik ügyfelemnél vagy egy eset, amit egyelőre nem sikerült visszafejteni. Adott 3 IIS publikus web láb NLBS-sel összenyalábolva, és 3 belső IIS alatt futó WS szintén NLBS mögött, ezeket hívják a külső webappok. A Windowsok VmWare alatt vannak virtualizálva.

A hiba az, hogy random időpontban belassulnak a webszerverek webszervizek irányába mutató hívásai. Normál esetben egy gyors ws metódus hívása 2-5ms, amikor beáll ez az állapotváltás a webszerver worker process belsejében, akkor felmegy kb. 200 ms-re.

Azért írok állapotváltást, mert nem azért lassulnak be a dolgok, mert nap közben nagyobb a terhelés, hanem egyszer csak “elborul” a webapp, és belassul. Dynatrace alapján a ws hívások mélyén a recv windows hívás válaszol lassan. Ilyenkor a ws iis logjában is lassú a hívás, vélhetően mert a webapp mint kliens lassan viszi el az adatot.
Hamarosan lesz DotTrace lenyomat és FREB log is, illetve System.NET trace is (csak ez nagyon sok adatot termel).

IIS App reset megoldja a problémát egy ideig. Ha egy app beteg, akkor egy console appból ugyanaz a ws hívás ugyanezen a gépről a wsek felé gyors, tehát nem valószínű, hogy a wsek lassulnak be.

Nehézkes megfogni az estet, mert pl. egy config módosítás a trace-ek kedvéért azonnal appol resetet csinál, így elillan a hiba, aztán lehet megint egy napot várni rá.

A .NET perf counterek nem mutatnak kiugró értékeket, minden normálisnak tűnik. A web processben kb. 500 szál fut 1-3 kérés/sec esetén, ez mondjuk kicsit soknak tűnik, de a procmon nem mutatta meg a managed stacket (debug symbolokkal se), majd csak dottrace-ből látszik, mit csinálnak. A procik 10%-ig vannak kiterhelve. A diszk terhelés minimális, paging nincs, van 0.5G szabad memória, más proceszek nem eszik el az erőforrásokat. A resource monitorban a wsek irányába futó kérések jelentős része 200ms körüli latency-t mutat, ez egybevág más megfigyelésekkel.

Látott már ilyet valaki? Mit lehetne még mérni, amire nem gondoltam?

Forceseek delete-hez

Volt egy delete-em, ami nem akart rendesen index mentén lefutni. A delete-et kicserélve select-re ugyanez volt a helyzet, de select esetén egy oszlopokkal kikényszerített forceseek segített.
Viszont delete-et nem lehet hintelni. A megoldás CTE volt, így indirekten mégiscsak lehet hintelni. A lekérdezés pár százszor gyorsabb lett. :)

Érdemes megjegyezni három trükköt tanulságul:
1. CTE kimenetén lehet futtatni DDL-eket
2. Így indirekten lehet hintelni
3. Néha jó index esetén se seekel a szerver, ilyenkor csakis az oszlopokkal megsegített forceseek segít.

;with B
as
(
select * from dbo.Bar with(forceseek(IX_Natural_Key(TickerId, BDT)))
where TickerId = @tickerId and BDT in 
    (select DATEADD(day, DATEDIFF(day,'19000101',DATEADD(DAY, 1, cast(StartDate as datetime))), CAST(ClosingTime AS DATETIME2(7)))
    from TradingHours where TickerId = @timeTemplateTickerId and StartDate is not null and EndDate is null and IsEnabled = 1 and Priority > 10)
)
delete from B;