seltene Lastspitze analysieren

Programmiersprachen, APIs, Bibliotheken, Open Source Engines, Debugging, Quellcode Fehler und alles was mit praktischer Programmierung zu tun hat.
Antworten
Benutzeravatar
Krishty
Establishment
Beiträge: 8229
Registriert: 26.02.2009, 11:18
Benutzertext: state is the enemy
Kontaktdaten:

seltene Lastspitze analysieren

Beitrag von Krishty »

Heyho,

manchmal hängt mein Flugsimulator beim Start für ein paar Sekunden das System auf. Genauer:
  • Mein Spiel startet und zeigt den Ladebildschirm (Win32).
  • DirectX 9 wird im Haupt-Thread initialisiert. XAudio 2, Windows’ USB-HID-API, und mehr Kram werden im Win32-Thread-Pool initialisiert.
Jetzt wird’s heikel. Ich weiß nicht genau, ob während des Ladens oder nach Abschluss aller Threads (ich glaube, danach!), aber:
  • Das Spiel bleibt für einige Sekunden stehen.
  • Die Anzeige friert komplett ein; nicht einmal der Maus-Cursor lässt sich noch bewegen. Hintergrundanwendungen bewegen sich nicht. Alt+Tab reagiert nicht.
  • Nach einigen Sekunden holt das System auf und läuft weiter als wäre nichts gewesen.
Bonus: Es passiert nur selten. Oft, wenn der Computer lange geschlafen hat; ganz selten aber auch direkt im aktiven Workflow. Eben habe ich es in 59 Starts nicht triggern können.

Bonus-Bonus: Ich beobachte das Problem auf einem 64-Bit-Windows-10-System, aber auf einem 32-Bit-Windows-7-System habe ich es auch schon einmal gesehen.

Bonus-Bonus-Bonus: Es scheint nichts auszumachen, ob ein Debugger angehängt ist oder nicht. Debug- und Release-Version sind beide betroffen.

Wie finde ich heraus, was da hängt? Hatte schonmal jemand von euch so ein Problem?

Die normalen Performance-Tools von Visual Studio scheinen für solche Probleme nutzlos zu sein. Falls es sich um einen Life Lock handelt, könnte ich da tatsächlich eine Spitze sehen, aber normalerweise nur in „External Code“. Falls alles an einem Mutex hängt, wären da schlicht null Samples und kein Call Stack. (Außerdem habe ich es bisher noch nie geschafft, den Fehler mit den Performance Tools zu reproduzieren.)

Application Verifier gibt keine Warnungen aus; Stack und Heap scheinen laut AppVerif sauber zu sein.

Klingt nach einem Fall für ETW. Ich werde mich schlau machen, was ich konfigurieren muss, damit mein Spiel bei jedem Start getracet wird.
seziert Ace Combat, Driver, und S.T.A.L.K.E.R.   —   rendert Sterne
Benutzeravatar
Tiles
Establishment
Beiträge: 1990
Registriert: 11.01.2003, 13:21
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Tiles »

Schon in die Windows Ereignisanzeige geschaut? Vielleicht rennt da ja ein anderes Programm amok. Mit hat der Defender immer mal wieder mein Mailprogramm blockiert. Aber den hast du ja aus.
Free Gamegraphics, Freeware Games https://www.reinerstilesets.de
Die deutsche 3D Community: https://www.3d-ring.de
Benutzeravatar
marcgfx
Establishment
Beiträge: 2050
Registriert: 18.10.2010, 23:26

Re: seltene Lastspitze analysieren

Beitrag von marcgfx »

Ist vielleicht nicht die optimale Idee, aber du könntest Logs mit ms Zeitangaben ausgeben lassen. Dann weisst du zwischen welchen Logs es hängt, da dort ein grösserer Abstand ist als erwartet. Wenn du das herausfindest, aber es nicht genau genug ist, kannst du zwischen den logs weitere logs einbauen. Divide and Conquer sozusagen. (aber evtl meinst du genau das mit tracen lassen beim start)
Benutzeravatar
Schrompf
Moderator
Beiträge: 4838
Registriert: 25.02.2009, 23:44
Benutzertext: Lernt nur selten dazu
Echter Name: Thomas Ziegenhagen
Wohnort: Dresden
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Schrompf »

Ich hatte das auch einmal vor einigen Jahren, also noch vor Win10. Da war's eine rotierende Platte, die ausgestiegen ist. Bei Lesefehlern ist das komplette System für einige Sekunden eingefroren, inklusive Mauszeiger.
Früher mal Dreamworlds. Früher mal Open Asset Import Library. Heutzutage nur noch so rumwursteln.
Benutzeravatar
Krishty
Establishment
Beiträge: 8229
Registriert: 26.02.2009, 11:18
Benutzertext: state is the enemy
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Krishty »

Tiles hat geschrieben: 17.10.2020, 08:57Schon in die Windows Ereignisanzeige geschaut? Vielleicht rennt da ja ein anderes Programm amok. Mit hat der Defender immer mal wieder mein Mailprogramm blockiert. Aber den hast du ja aus.
Stimmt; da werde ich nächstes Mal nachschauen!
marcgfx hat geschrieben: 17.10.2020, 09:50Ist vielleicht nicht die optimale Idee, aber du könntest Logs mit ms Zeitangaben ausgeben lassen. Dann weisst du zwischen welchen Logs es hängt, da dort ein grösserer Abstand ist als erwartet. Wenn du das herausfindest, aber es nicht genau genug ist, kannst du zwischen den logs weitere logs einbauen. Divide and Conquer sozusagen.
Problematisch ist, dass das Problem mitunter tagelang nicht auftritt. Ich möchte meine Chancen verbessern, es beim nächsten Mal auf Anhieb zu verstehen, damit ich nicht wieder eine Woche auf die nächste Gelegenheit warten muss. (Aber Log-Ausgaben sind nun drin; hast schon recht.)
Schrompf hat geschrieben: 17.10.2020, 11:17Ich hatte das auch einmal vor einigen Jahren, also noch vor Win10. Da war's eine rotierende Platte, die ausgestiegen ist. Bei Lesefehlern ist das komplette System für einige Sekunden eingefroren, inklusive Mauszeiger.
Ich dachte auch erst an einen Windows- oder Hardware-Verschlucker, aber dieses Jahr habe ich’s ein Dutzend Mal auf zwei verschiedenen Computern beobachtet – und zwar immer an der selben Stelle nach dem Start meines Spiels, und niemals sonst. Die Ursache muss in der Nähe meines Codes liegen.
seziert Ace Combat, Driver, und S.T.A.L.K.E.R.   —   rendert Sterne
Benutzeravatar
Krishty
Establishment
Beiträge: 8229
Registriert: 26.02.2009, 11:18
Benutzertext: state is the enemy
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Krishty »

Es ist gerade zum ersten Mal seit einer Woche aufgetreten. Der Bildschirm fror nach dem Laden für gefühlt drei bis fünf Sekunden ein.

Leider haben die Log-Ausgaben während der Initialisierung nichts bewirkt. Gemäß ihnen lief die Initialisierung völlig reibungslos in 720ms ab – ein unterdurchschnittlicher Wert, aber unvereinbar mit dem für 3–5 s eingefrorenen Bildschirm.

Ich werde die Log-Ausgaben nun in meine Menü-Animationen verlagern, denn die folgen auf die Initialisierung und wurden komplett übersprungen.

Mein Auge fällt auf den Aufruf DwmFlush(), den ich nutze, um meine Animationen mit der Bildwiederholrate des Monitors zu synchronisieren. Das ist der einzige Aufruf weit und breit, der intuitiv vielleicht mit eingefrorenen Bildschirmen zu tun haben könnte.

————

Edit: Oh shit shit shit! Ich wollte gerade schreiben, dass Chrome ebenfalls DwmFlush() nutzt um seine Animationen zu synchronisieren, und da fiel es mir wie Schuppen von den Augen: Ich kenne diese Hänger doch aus einer anderen Situation! Nämlich:
  • Ganz exakt so viele Threads mit harter Berechnung starten, wie die CPU logische Kerne hat. In meinem Fall gebe ich meinem Optimizer zwölf PNG-Bilder zu optimieren, bei niedriger Priorität.
  • In Chrome herumsurfen.
Ein, zwei Mal pro Minute wird nun der Bildschirm für ein paar Sekunden einfrieren, mitsamt Mauszeiger. Besonders häufig beim Schließen von Tabs.

Das Problem tritt bei mir seit drei oder vier Jahren mit zwei verschiedenen PCs derart häufig auf (ich nutze meine CPU halt gern intensiv), dass ich mich schon total dran gewöhnt habe und bei allen möglichen Aufgaben einen CPU-Kern frei lasse oder doppelt belege! Beim alten PC habe ich alles immer in 7 oder 9 Threads berechnen lassen, aktuell immer mit 11 oder 13. Denn sonst bringt Chrome ständig meinen Bildschirm zum Einfrieren.

Ich ging bisher immer davon aus, dass es ein Bug im Nvidia-Treiber sei. Dass der Treiber irgendwo von einem Thread mit niedriger Priorität abhinge, der halt von Zeit zu Zeit verhungert, wenn alle Kerne ausgelastet sind. Konnte mir aber nie erklären, warum es dann bei einem doppelt belegten Kern besser wird.

Bitte jetzt nicht noch ein Bug im DWM! :( :( :(

Andererseits hat mein Netbook hat Intel Integrated Graphics, und da hakt mein Flugsimulator ebenfalls. Und mein Flugsimulator lastet nicht alle Kerne voll aus, die Situation ist also anders. Erstmal alle Animationen loggen und schauen, was passiert …

————

Nachtrag 2: Nein, da kann ich wohl Entwarnung geben. Habe meine Optimierung auf exakt einen Thread pro logischer CPU gestellt und nach Chrome gewechselt. Chrome wurde komplett unbedienbar; ist alle fünf Sekunden für fünf Sekunden eingefroren – allerdings nur dieses Fenster. Der Rest von Windows und der Mauszeiger ließen sich problemlos weiterbedienen. Auch in meinem Flugsimulator gab es nicht das kleinste Stottern.
seziert Ace Combat, Driver, und S.T.A.L.K.E.R.   —   rendert Sterne
Benutzeravatar
Tiles
Establishment
Beiträge: 1990
Registriert: 11.01.2003, 13:21
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Tiles »

Und immer noch nichts in der Ereignisanzeige?
Free Gamegraphics, Freeware Games https://www.reinerstilesets.de
Die deutsche 3D Community: https://www.3d-ring.de
Benutzeravatar
Krishty
Establishment
Beiträge: 8229
Registriert: 26.02.2009, 11:18
Benutzertext: state is the enemy
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Krishty »

Stimmt! Da gibt es tatsächlich einen Eintrag, der zur Uhrzeit passt:
Fault bucket , type 0
Event Name: LiveKernelEvent
Response: Not available
Cab Id: 0

Problem signature:
P1: 190
P2: 1
P3: fffff9564061b010
P4: fffff9564b2e5b00
P5: fffff95646d48130
P6: 10_0_18363
P7: 0_0
P8: 768_1
P9:
P10:

Attached files:
\\?\C:\WINDOWS\LiveKernelReports\win32k.sys\win32k.sys-20201024-0203.dmp
\\?\C:\WINDOWS\TEMP\WER-822660625-0.sysdata.xml
\\?\C:\WINDOWS\LiveKernelReports\win32k.sys-20201024-0203.dmp
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERE07F.tmp.WERInternalMetadata.xml
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERE090.tmp.xml
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERE08F.tmp.csv
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WERE0BF.tmp.txt

These files may be available here:
\\?\C:\ProgramData\Microsoft\Windows\WER\ReportQueue\Kernel_<ID entfernt>

Analysis symbol:
Rechecking for solution: 0
Report Id: 85bec804-8066-40bf-96fb-04667db0b0d8
Report Status: 4
Hashed bucket:
Cab Guid: 0
Das sieht nach einem Crash von Win32k aus, der Windows-Komponente für Fenstermanagement. Leider möchte mir Windows aktuell keinen Zugriff auf den Dump gewähren; ich schaue mal, wie ich die Rechte verbiegen kann.
seziert Ace Combat, Driver, und S.T.A.L.K.E.R.   —   rendert Sterne
Benutzeravatar
Krishty
Establishment
Beiträge: 8229
Registriert: 26.02.2009, 11:18
Benutzertext: state is the enemy
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Krishty »

Tiles, das war ein Volltreffer. Laut Dump (2.5 GiB, lol) hat mein Flugsimulator Win32k.sys genuket – beim Einscrollen meines Hauptmenüs.

Ich spreche mal nicht über konkrete Funktionsaufrufe bis ich ausschließen kann, dass das Sicherheitsauswirkungen hat.
seziert Ace Combat, Driver, und S.T.A.L.K.E.R.   —   rendert Sterne
Benutzeravatar
Tiles
Establishment
Beiträge: 1990
Registriert: 11.01.2003, 13:21
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Tiles »

\o/
Free Gamegraphics, Freeware Games https://www.reinerstilesets.de
Die deutsche 3D Community: https://www.3d-ring.de
Benutzeravatar
Krishty
Establishment
Beiträge: 8229
Registriert: 26.02.2009, 11:18
Benutzertext: state is the enemy
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Krishty »

(Switching to English because searching for the error code yields no results. International readers will likely find this thread.)

I’m stuck with my investigation. Maybe someone else can help.

What happened so far

Once in a few weeks, my game freezes the system upon completing the splash screen. Happens on Windows 10 1909 x64 as well as Windows 7 x86. The screen freezes and I cannot move the cursor. A few seconds later, the system comes back to life and acts as if nothing happened.

Windows Error Reporting writes an Event Log entry like the following:
Fault bucket , type 0
Event Name: LiveKernelEvent
Response: Not available
Cab Id: 0

Problem signature:
P1: 190
P2: 1
P3: ███████████████
P4: ███████████████
P5: ███████████████
P6: 10_0_18363
P7: 0_0
P8: 768_1
P9:
P10:

Attached files:
\\?\C:\WINDOWS\LiveKernelReports\win32k.sys\win32k.sys-████████-████.dmp
\\?\C:\WINDOWS\TEMP\WER-██████████-0.sysdata.xml
\\?\C:\WINDOWS\LiveKernelReports\win32k.sys-████████-████.dmp
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER████.tmp.WERInternalMetadata.xml
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER████.tmp.xml
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER████.tmp.csv
\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER████.tmp.txt

These files may be available here:
\\?\C:\ProgramData\Microsoft\Windows\WER\ReportQueue\Kernel_██_█████████████████████████████████████████████████████████████████████████████████████

Analysis symbol:
Rechecking for solution: 0
Report Id: ████████-████-████-████-████████████
Report Status: 4
Hashed bucket:
Cab Guid: 0
I saved both crash dumps I could find (one 2.5 GiB, one 3.0). I won’t upload them because they contain personal data like encryption keys.

I open the first dump in windbg and type !analyze -v. The result is:

Code: Alles auswählen

*******************************************************************************
*                                                                             *
*                        Bugcheck Analysis                                    *
*                                                                             *
*******************************************************************************

WIN32K_CRITICAL_FAILURE_LIVEDUMP (190)
Win32k has encountered a critical failure.
Live dump is captured to collect the debug information.
Arguments:
Arg1: 0000000000000001, REGION_VALIDATION_FAILURE
	Region is out of surface bounds.
Arg2: fffff9564061b010, Pointer to DC
Arg3: fffff9564b2e5b00, Pointer to SURFACE
Arg4: fffff95646d48130, Pointer to REGION

Debugging Details:
------------------


KEY_VALUES_STRING: 1

    Key  : Analysis.CPU.Sec
    Value: 9

    Key  : Analysis.DebugAnalysisProvider.CPP
    Value: Create: 8007007e on ████████

    Key  : Analysis.DebugData
    Value: CreateObject

    Key  : Analysis.DebugModel
    Value: CreateObject

    Key  : Analysis.Elapsed.Sec
    Value: 29

    Key  : Analysis.Memory.CommitPeak.Mb
    Value: 75

    Key  : Analysis.System
    Value: CreateObject


DUMP_FILE_ATTRIBUTES: 0x10
  Live Generated Dump

BUGCHECK_CODE:  190

BUGCHECK_P1: 1

BUGCHECK_P2: fffff9564061b010

BUGCHECK_P3: fffff9564b2e5b00

BUGCHECK_P4: fffff95646d48130

PROCESS_NAME:  TFXplorer x64.exe

STACK_TEXT:  
ffff820d`29faa1b0 fffff807`5939c167 : ffffffff`ffffffff 00000000`00000211 00000000`00000211 00000000`00000008 : nt!IopLiveDumpEndMirroringCallback+0x7e
ffff820d`29faa200 fffff807`593a8405 : 00000000`00000000 fffff807`00000000 ffffa802`00000001 00000000`00000001 : nt!MmDuplicateMemory+0x3cb
ffff820d`29faa2a0 fffff807`5965923b : ffffa802`e47e9c30 ffffa802`e47e9c30 ffff820d`29faa578 ffff820d`29faa578 : nt!IopLiveDumpCaptureMemoryPages+0x79
ffff820d`29faa360 fffff807`5964c29f : 00000000`00000000 ffff930e`29ff0450 ffff930e`3677adb0 ffff930e`29ff0450 : nt!IoCaptureLiveDump+0x2e7
ffff820d`29faa510 fffff807`5964c9c8 : ffffffff`80002080 00000000`00000000 00000000`00000000 00000000`00000190 : nt!DbgkpWerCaptureLiveFullDump+0x137
ffff820d`29faa570 fffff807`5964c0f1 : 00000000`00000002 00000000`00000000 fffff914`10aab830 fffff914`00000000 : nt!DbgkpWerProcessPolicyResult+0x30
ffff820d`29faa5a0 fffff914`1098be9d : 00000000`00000315 fffff956`46d48130 fffff956`4061b010 00000000`00000000 : nt!DbgkWerCaptureLiveKernelDump+0x1a1
ffff820d`29faa5f0 fffff914`108d72bb : 00000000`00000000 ffff820d`29faa6e0 00000000`00000000 ffff820d`29faa730 : win32kbase!GrepValidateVisRgn+0xb150d
ffff820d`29faa690 fffff914`108d7070 : ffff820d`29faa850 fffff956`4061b010 00000000`00040064 ffffa802`de7f91f0 : win32kbase!GreSelectVisRgnInternal+0x9f
ffff820d`29faa710 fffff914`0fcecc1f : 00000000`00040064 ffffffff`94052614 00000000`00040064 ffffffe6`ffffffa8 : win32kbase!GreSelectVisRgn+0x40
ffff820d`29faa750 fffff914`0fcd66ee : 00000000`00040064 fffff956`467d2d20 00000000`00040062 00000000`00000000 : win32kfull!UpdateSpriteArea+0x13f
ffff820d`29faa8b0 fffff914`0fcd7f15 : fffff956`474ea0d0 00000000`00000001 fffff956`478eb460 fffff956`477f3550 : win32kfull!zzzBltValidBits+0x7a2
ffff820d`29faa9d0 fffff914`0fc2c877 : 00000000`00000001 00000000`00000000 00000000`00000001 00000000`00000001 : win32kfull!xxxEndDeferWindowPosEx+0x445
ffff820d`29faaab0 fffff807`58fd4558 : ffffa802`e55ba080 00000000`00000742 00000000`00000742 ffffa802`e6af5820 : win32kfull!NtUserEndDeferWindowPosEx+0x97
ffff820d`29faab00 00007ff8`05eb1564 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : nt!KiSystemServiceCopyEnd+0x28
00000000`0057bcb8 00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : 0x00007ff8`05eb1564


SYMBOL_NAME:  win32kbase!GrepValidateVisRgn+b150d

MODULE_NAME: win32kbase

IMAGE_NAME:  win32kbase.sys

STACK_COMMAND:  .thread ; .cxr ; kb

BUCKET_ID_FUNC_OFFSET:  b150d

FAILURE_BUCKET_ID:  LKD_0x190_win32kbase!GrepValidateVisRgn

OS_VERSION:  10.0.18362.1

BUILDLAB_STR:  19h1_release

OSPLATFORM_TYPE:  x64

OSNAME:  Windows 10

FAILURE_ID_HASH:  {████████-████-████-████-████████████}

Followup:     MachineOwner
---------
This gives us, indeed, the most important information:
  1. PROCESS_NAME: TFXplorer x64.exe
    That’s my game!
     
  2. Win32k has encountered a critical failure. Win32k is the graphics subsystem of the kernel. It renders windows and menus, delegates work to the graphics driver, etc. We hit a critical failure there.
     
  3. Call Stack:
      nt!DbgkWerCaptureLiveKernelDump+0x1a1
      win32kbase!GrepValidateVisRgn+0xb150d
      win32kbase!GreSelectVisRgnInternal+0x9f
      win32kbase!GreSelectVisRgn+0x40
      win32kfull!UpdateSpriteArea+0x13f
      win32kfull!zzzBltValidBits+0x7a2
      win32kfull!xxxEndDeferWindowPosEx+0x445


    xxxEndDeferWindowPosEx() is the kernel-mode call to EndDeferWindowPos(), which moves a number of windows to a new position. As we can see, this call identified the visible region of a window and tries to copy its pixels to the new position (so that the window doesn’t have to be redrawn entirely).
     
  4. Bugcheck:
      Arg1: 0000000000000001, REGION_VALIDATION_FAILURE
        Region is out of surface bounds.
      Arg2: fffff9564061b010, Pointer to DC
      Arg3: fffff9564b2e5b00, Pointer to SURFACE
      Arg4: fffff95646d48130, Pointer to REGION


    Before copying pixels, the kernel does some sanity checking – are the pixels there in the first place? Here, they are not. The visible region determined by zzzBltValidBits() cannot be found on the surface and rather than copying garbage, it dumps core.
In short, I made the kernel copy pixels which aren’t there. How could this happen?

The obvious first step is reducing my program to a minimal reproducable sample. But this isn’t possible here: I collected the first crash dump on 2020-10-24. Then I ran the program about a thousand times(!) and nothing happened. The second dump was written a week later, on 2020-10-31.

I tried to find out what exactly was causing the error, but the dump does not include user-mode information, as can be seen by Kernel Bitmap Dump File: Kernel address space is available, User address space may not be available. when windbg opens the dump.

I wanted to make DbgkWerCaptureLiveKernelDump() collect user-mode information, but instead I found the following culprit:
Clearly the code is trying to avoid generating too many Live Kernel Reports and thus has put some arbitrary deadline in the future for the next time a dump may be written. I searched but could not find a way to bypass this (i.e. a, “no, please do wear out my SSD and fill my drive, I don’t care!” flag) but alas did not find one. This dashed any and all hopes I had for using this as a testing mechanism in the lab.
The sample in the article uses a time span of four days. So I could be hitting this bug all the time but only once every few weeks the kernel would actually dump core. So much for reducing the problem.

Instead, let’s have a look at the invalid region/surface and try to recognize them in my game.

Here’s a recording of my game without it hanging:

Bild
(enable non-https content in your browser if you can’t see anything)

First comes the splash screen and checks whether Direct3D and XAudio are available, etc. The splash screen is then scrolled out to the left and the main page is scrolled in from the right. The bugcheck occurs when the page transition starts; i.e. the splash screen remains frozen. When the system comes back a few seconds later, the transition is already over.


Finding the surface

Let’s find out which surface is garbage.

  Arg3: fffff9564b2e5b00, Pointer to SURFACE

Unfortunately, there is no type for this address. I tried a number of explicit types (via dt) but they didn’t work either. Looks like the surface structure is just not included in the Win32k debug symbols.

I googled quite a bit and eventually found definitions here: https://blog.quarkslab.com/reverse-engi ... ation.html

Code: Alles auswählen

typedef struct _BASEOBJECT {
    HANDLE hHmgr;
    ULONG  ulShareCount;
    USHORT cExclusiveLock;
    USHORT BaseFlags;
    PVOID  Tid;
} BASEOBJECT, *PBASEOBJECT;

typedef struct _SURFOBJ {
    DHSURF dhsurf;
    HSURF  hsurf;
    DHPDEV dhpdev;
    HDEV   hdev;
    SIZEL  sizlBitmap;
    ULONG  cjBits;
    PVOID  pvBits;
    PVOID  pvScan0;
    LONG   lDelta;
    ULONG  iUniq;
    ULONG  iBitmapFormat;
    USHORT iType;
    USHORT fjBitmap;
} SURFOBJ, *PSURFOBJ;
These match quite well:

Code: Alles auswählen

fffff956`4b2e5b00 14 26 05 94 ff ff ff ff 03 00 00 00 00 00 00 40  .&.............@ _BASEOBJECT.handle         	14 26 05 94 ff ff ff ff
                                                                                    _BASEOBJECT.ulShareCount   	03 00 00 00
                                                                                    _BASEOBJECT.cExclusiveLock 	00 00
                                                                                    _BASEOBJECT.BaseFlags      	00 40
fffff956`4b2e5b10 80 a0 5b e5 02 a8 ff ff 90 da 3b 47 56 f9 ff ff  ..[.......;GV... _BASEOBJECT.Tid            	80 a0 5b e5 02 a8 ff ff
                                                                                    _SURFOBJ.dhsurf             90 da 3b 47 56 f9 ff ff
fffff956`4b2e5b20 14 26 05 94 ff ff ff ff 20 e0 31 47 56 f9 ff ff  .&...... .1GV... _SURFOBJ.hsurf              14 26 05 94 ff ff ff ff
                                                                                    _SURFOBJ.dhpdev             14 26 05 94 ff ff ff ff
fffff956`4b2e5b30 00 10 91 40 56 f9 ff ff 52 07 00 00 15 03 00 00  ...@V...R....... _SURFOBJ.hdev               00 10 91 40 56 f9 ff ff
                                                                                    _SURFOBJ.sizlBitmap.x       == 1874
                                                                                    _SURFOBJ.sizlBitmap.y       == 789 – 1874×789 ~ size of main window (a little larger even)
fffff956`4b2e5b40 e8 3e 5a 00 00 00 00 00 00 00 00 00 00 00 00 00  .>Z............. _SURFOBJ.cjBits             e8 3e 5a 00 == 4 * width * height (32-bit color depth)
                                                                                    _SURFOBJ.pvBits             nullptr
                                                                                    _SURFOBJ.pvScan0            nullptr
fffff956`4b2e5b50 00 00 00 00 00 00 00 00 00 00 00 00 be b7 27 01  ..............'. _SURFOBJ.lDelta             00 00 00 00
                                                                                    _SURFOBJ.iUniq              00 00 00 00
                                                                                    _SURFOBJ.iBitmapFormat      00 00 00 00
                                                                                    _SURFOBJ.iType              be b7
                                                                                    _SURFOBJ.fjBitmap           27 01
The symbols do seem to fall apart at iType. I’d be glad if someone could provide me with the actual symbols …

But anyway, we see a bitmap of 1874×789 pixels and 32-bit color depth. That matches the main window pretty well. (A few extra pixels for Aero’s shadow effects, maybe?)

We also see that _SURFOBJ.pvBits and _SURFOBJ.pvScan0 are both zero. That’s not good, I guess, because MSDN says one of them should always be set.

I interpret the data as: “The kernel tries to copy pixels from the main window, but the main window doesn’t have a bitmap allocated”. Which is very strange, because we do see that window on-screen. But we know we are in a strange place, because the kernel wouldn’t panic otherwise.


Finding the region

I had even less luck looking for a definition of REGION. Instead, I just interpreted the stuff as 4-B numbers:

Code: Alles auswählen

fffff956`46d48130 64 00 04 00 00 00 00 00 00 00 00 00 01 00 00 80  d...............
fffff956`46d48140 80 a0 5b e5 02 a8 ff ff d8 00 00 00 00 00 00 00  ..[.............
fffff956`46d48150 00 00 00 00 00 00 00 00 08 82 d4 46 56 f9 ff ff  ...........FV...
fffff956`46d48160 60 81 d4 46 56 f9 ff ff 60 81 d4 46 56 f9 ff ff  `..FV...`..FV...
fffff956`46d48170 30 81 d4 46 56 f9 ff ff e0 4c 9e 10 14 f9 ff ff  0..FV....L......
fffff956`46d48180 d8 00 00 00 05 00 00 00 ea ff ff ff 4f 00 00 00  ............O... |  216 |   5 |  -22 |  79  |   << d8 = 216; 4f 00 00 00 == 0x0000004f == 79
fffff956`46d48190 2c 07 00 00 0d 03 00 00 00 00 00 00 00 00 00 80  ,............... | 1836 | 781 |    0 |INTMIN|
fffff956`46d481a0 4f 00 00 00 00 00 00 00 02 00 00 00 4f 00 00 00  O...........O... |   79 |   0 |    2 |  79  |
fffff956`46d481b0 fe 01 00 00 ea ff ff ff 2c 07 00 00 02 00 00 00  ........,....... |  510 | -22 | 1836 |   2  |
fffff956`46d481c0 04 00 00 00 fe 01 00 00 46 02 00 00 ea ff ff ff  ........F....... |    4 | 510 |  582 | -22  |   << fe 01 == 0x01fe == 510; 46 02 == 0x0246 == 582; ea ff ff ff == 0xffffffea == -22;
fffff956`46d481d0 db 02 00 00 1b 05 00 00 2c 07 00 00 04 00 00 00  ........,....... |  731 | 1307| 1836 |    4 |   << 2c 07 == 0x72c == 1836
fffff956`46d481e0 02 00 00 00 46 02 00 00 0d 03 00 00 ea ff ff ff  ....F........... |    2 | 582 |  781 |  -22 |
fffff956`46d481f0 2c 07 00 00 02 00 00 00 00 00 00 00 0d 03 00 00  ,............... | 1836 |   2 |    0 |  781 |
fffff956`46d48200 ff ff ff 7f 00 00 00 00 ff ff ff 7f 00 00 00 00  ................ |INTMAX|   0 |INTMAX|    0 |
fffff956`46d48210 00 00 0f 23 47 6c 61 34 00 00 00 00 00 00 00 00  ...#Gla4........
#Gla at the end marks the beginning of a new kernel object (global lookaside table). The numbers 1836 and 781 appear quite often. 781 is exactly the height of my main window (no shadows or anything). 1836 is smaller by 24 pixels, and the other common number is -22.

If you draw it over my screenshot, you can see that the coordinates (-22, 79) and (1836, 781) correspond exactly to the old page after scrolling out a few pixels to the left.

FWIW, the coordinates in both crash dumps are almost identical. This is suspicious – the amount of scrolling in the animation depends on the timing of the next monitor refresh.


What exactly happened?

I can now reconstruct pretty accurately what happened in my game, I just cannot explain the error. Sorry for just presenting this “as is” and not explaining a lot, but I encounter this problem in a pre-existing program and we just have to take it the way it is.


1. My game starts.

It creates a dialog of 1860×782 pixels. (These dimensions were chosen by Windows as a default based on my monitor resolution.)

It creates five children for the dialog:
  1. The “Back” button.
  2. The title label.
  3. The “Info” button.
  4. The splash page (a dialog itself with children, e.g. for text labels).
  5. The main page (a dialog itself with children).
  6. (More pages for other UI stuff in my game, but this never activates before the bugcheck.)
All these children are created in the top-left corner of their parent’s client area. They are all 0×0 or 1×1 pixels small. The main window is invisible because I don’t want the user to see it building up.

Bild
(enable non-https content in your browser if you can’t see anything)


2. The main window is shown. This triggers a resize message to compute the layout.

All children go to the final coordinates you see – except the main page. (The main page is not visible yet, and so I don’t invest time in its layout and it just sticks around invisibly at (0, 0) with size 1×1 or so.)

The window is drawn for the first time.

Bild


3. I put a little twist on the splash screen: It normally starts a transition to the main menu automatically, except if there is an error during initialization. (E.g. the XAudio debug library missing in debug builds.) In this case, it’ll show the according text and you must click “Accept” in the bottom-right corner to proceed anyway (e.g. without sound).

I got one dump with a release version, no game errors and automatic transition to main menu. I got the other dump with a debug version, one error and manual clicking “Accept”.

This tells us that the window is fully functional and interactive at this point.


4. Transition to the main menu starts.

The sub-dialog for the main menu is positioned at the right edge of the main window (via the trinity of the DeferWindowPos() API. This is a resizing, so its layout gets re-computed. No pixels are visible (the sub-dialog is outside of its parent’s client area), but it now lurks just off the right edge of the window.

Bild


5. First animation frame.

The sub-dialog for the splash screen is moved 20–30 pixels to the left, and so is the sub-dialog. Both happens atomically via the trinity of the DeferWindowPos() API.

The call to EndDeferWindowPos() hits the bugcheck and the system freezes until the core dump is written to disk. According to our analysis above, the kernel fails to copy the pixels of the old splash screen to its new position after scrolling 24 pixels or so.

Bild


What now?

So here we are. Anyone having a suggestion on what to do to find the cause *or* create a minimal example that could be sent to Microsoft for investigation?

Please keep in mind, I have about one shot per week.
seziert Ace Combat, Driver, und S.T.A.L.K.E.R.   —   rendert Sterne
Benutzeravatar
Tiles
Establishment
Beiträge: 1990
Registriert: 11.01.2003, 13:21
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Tiles »

Maybe that's too obvius, but what about an example that is just reduced to the scrolling and is permanently looping?
Free Gamegraphics, Freeware Games https://www.reinerstilesets.de
Die deutsche 3D Community: https://www.3d-ring.de
Benutzeravatar
Krishty
Establishment
Beiträge: 8229
Registriert: 26.02.2009, 11:18
Benutzertext: state is the enemy
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Krishty »

Yes, that’ll be my next step!

For now, I have a few news:

1. DbgkWerCaptureLiveKernelDump() is limited to one dump a week. I indeed got a hang eight days after the previous one, but not 6.5 days after. Had no time to try it on the 7th day, but close enough.

2. It is indeed the exact DeferWindowPos() call I suspected.
I printed all parameters as well as the old and new coordinates before calling EndDeferWindowPos(). The hang occurs exactly as described previously, when the transition animation starts:

Code: Alles auswählen

  BeginDeferWindowPos() ...
  moving window 00000000028E0DCC from (0, 48, +1858, +702) to (-30, 48, +1858, +702) ...
  moving window 0000000000C708DA from (1858, 48, +1858, +702) to (1828, 48, +1858, +702) ...
  before EndDeferWindowPos(), 0 ms passed ...
  after EndDeferWindowPos() 3172 ms passed ...
The two windows are the pages, and they are moved left 30 pixels, in the first frame of the animation.

3. The hang is independent of Direct3D and XAudio. I disabled Direct3D and XAudio completely, and the hang occurred anyway.

4. This time (and only this time), it corrupted my graphics driver. The screen started freezing in intervals of a few seconds, and it got worse the more windows were visible. I had to restart the machine. Upon reboot, my GPU did a fan noise I had never heard before. The event log says
The description for Event ID 14 from source nvlddmkm cannot be found. Either the component that raises this event is not installed on your local computer or the installation is corrupted. You can install or repair the component on the local computer.

If the event originated on another computer, the display information had to be saved with the event.

The following information was included with the event:

\Device\000005aa
0c83(17dc) 00000000 00000000

The message resource is present but the message was not found in the message table
nvlddmkm is the Kernel-mode Nvidia driver. This did not happen any time before, so I suspect it’s a side-effect.

I still have to test my other machines, and I’ll create a minimal scrolling program for next week, as Tiles suggested.
seziert Ace Combat, Driver, und S.T.A.L.K.E.R.   —   rendert Sterne
Benutzeravatar
Krishty
Establishment
Beiträge: 8229
Registriert: 26.02.2009, 11:18
Benutzertext: state is the enemy
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Krishty »

FWIW, I did create a minimal scrolling program, but I was unable to reproduce the error before I gave up.

I upgraded to Windows 20H2 on March 27. It’s been more than two weeks (the refresh interval for Kernel bug checks), and the crashes are gone. The event log is clean.

I have installed the exact same drivers after the upgrade, including the graphics driver (I always back up my drivers), so a Kernel bug in Windows <=1909 is the only explanation.
seziert Ace Combat, Driver, und S.T.A.L.K.E.R.   —   rendert Sterne
Benutzeravatar
Krishty
Establishment
Beiträge: 8229
Registriert: 26.02.2009, 11:18
Benutzertext: state is the enemy
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Krishty »

Problem is back on Windows Server 2019 after
  • installing the December 2019 security updates for Windows
  • updating Nvidia’s GeForce Game Ready Driver for Windows 10 to version 474.04
I should roll back the Nvidia driver and observe system state for two weeks, but the release notes list 29 nightmarish security issues being fixed and TBH I don’t want to have those back.
seziert Ace Combat, Driver, und S.T.A.L.K.E.R.   —   rendert Sterne
Benutzeravatar
Krishty
Establishment
Beiträge: 8229
Registriert: 26.02.2009, 11:18
Benutzertext: state is the enemy
Kontaktdaten:

Re: seltene Lastspitze analysieren

Beitrag von Krishty »

Funny: This afternoon, Windows started saving crash dumps every time I ran the program. After amounting to ca. 20 of them, Windows seems to have returned to the one-per-two-weeks cycle from before 🤷

Maybe someone in Redmond finally noticed my crash dumps and asked for more information.
seziert Ace Combat, Driver, und S.T.A.L.K.E.R.   —   rendert Sterne
Antworten