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:

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:

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?

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:

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?

Marhára oda kell figyelni, hogy mindig csak a főszálból nyúljunk a GUI-hoz.
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.

Could you hire me? Contact me if you like what I’ve done in this article and think I can create value for your company with my skills.

LEAVE A COMMENT

1 COMMENTS