Skip to content

Debugging Tips

Jordan Rhee edited this page Mar 10, 2016 · 13 revisions

Viewing trace logs from the kernel mode driver (roskmd)

During development and debugging it is often useful to view log output from a software component. The kernel mode driver is instrumented with WPP logging and has the WPP in-flight recorder enabled. The in-flight recorder saves up to one page of the most recent tracing calls, which can be dumped from the debugger with the following command:

!rcdrkd.rcdrlogdump roskmd

You should see output similar to the following:

Trying to extract TMF information from - C:\debuggers\sym\roskmd.pdb\50607DB595DB494D985FEF3D0B1B6AA61\roskmd.pdb
--- start of log ---
1: RosKmdGlobal::DriverEntry -  [RosKmdGlobal.cpp @ 84] INFO :(pDriverObject=8AA97A10, pRegistryPath=8AACB000)
---- end of log ----

Note that the debugger must have access to the symbols to format the log output. Trace messages can also be sent to the kernel debugger in real time with the following command:

tracelog -start ros -rt -kd -guid #B5B486C1-F57B-4993-8ED7-E3C2F5E4E65A -flags 0xffff -level 5

To stop sending traces, run the following command

tracelog -stop ros

More information about WPP and ETW is available on MSDN.

The dxgkrnl logs can be dumped with the following command:

!dxgkdx.dxglog

Trace Macros

The following table describes the purpose of each trace macro and on which build flavors (debug/release) it is enabled.

Macro Name Description Enabled in Debug Builds Enabled in Release Builds
ROS_LOG_CRITICAL_ERROR Will cause bugcheck in release build. Yes Yes
ROS_LOG_ASSERTION Will cause debug break if debugger is attached. Yes No
ROS_LOG_ERROR Use to log all errors, e.g. before returning failure NTSTATUS. Yes Yes
ROS_LOG_LOW_MEMORY Use before returning STATUS_NO_MEMORY and STATUS_INSUFFICIENT_RESOURCES Yes Yes
ROS_LOG_WARNING Use to log things that are less severe than errors but more severe than information. Yes Yes
ROS_LOG_INFORMATION Use to log interesting events. Yes Yes
ROS_LOG_TRACE Use to log debugging information. Yes No
ROS_CRITICAL_ASSERT Will cause a bugcheck if the assertion expression evaluates to false. Yes Yes
ROS_ASSERT Will cause bugcheck if assertion expression evaluates to false. Yes No

Assorted Debugging Tips

Breaking in at driver entry

You can break in to the driver at the earliest possible point (DriverEntry) by using one of these techniques.

Hit Ctrl+Alt+K in windbg anytime before boot. This will break at kernel load. Run

sxe ld:roskmd.sys

This will cause the debugger to break in when the roskmd.sys module is loaded, but before any code is run. You can now load symbols and set a breakpoint on DriverEntry:

bp roskmd!DriverEntry

Assuming your symbol path is set up correctly, a breakpoint should be set.

You could also skip the 'sxe' step above by running the following command any time. This command does not require symbols to be loaded.

bu roskmd!DriverEntry

This sets a deferred breakpoint, which won't try to resolve the symbol to an address until the image is loaded.

Tell roskmd not to load

ed roskmd!RosKmdGlobal::s_bDoNotInstall 1

Skip loading of SiHost

reg add "HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon" /v ShellInfrastructure /t REG_SZ /d cmd.exe
reg add "HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Winlogon" /v Headless /t REG_DWORD  /d 1

Configure driver in render-only mode

reg add "HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\RenderOnlySample" /v RenderOnly /t REG_DWORD /d 1
reg add "HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\GraphicsDrivers" /v DisableAutoAcpiPostDeivce /t REG_DWORD /d 1
reg add HKLM\SOFTWARE\Microsoft\XAML /v ForceWARP /t REG_DWORD /d 1

Determining if DirectFlip is active

DirectFlip is a feature that allows full-screen applications to bypass the normal DWM composition process and flip application back buffers directly to the screen. During composition a rendering pass is performed that copies the entire frame buffer, so avoiding composition is necessary to achieve decent framerates. When DirectFlip is active, you should not see any calls to dxkgnl!DxgkPresent from the DWM, and roskmd!RosKmContext::Present should not get called. To determine if Present calls are coming from the app or from the DWM, set a breakpoint on dxkgnl!DxgkPresent,

bp dxgkrnl!DxgkPresent

When it gets hit, print out the current process:

!process -1 0

If the process is dwm.exe, DirectFlip is not being used. If the process is always the app, DirectFlip is being used.

Stop the kernel debugger from breaking on debugbreaks

If there are too many debugbreaks getting hit it can make it impossible to make forward progress. To prevent the debugger from breaking in when debugbreaks are hit, run

sxd bpe

To reenable debug breaks,

sxe bpe

Update the default app without rebooting

The app needs to not be running so that you can update the app's EXE. By default, SiHost will restart an app as soon as it crashes. We need to configure SiHost to wait 10 seconds before restarting the app. Add the following reg keys and reboot:

reg add "HKLM\Software\Microsoft\Windows NT\CurrentVersion\Winlogon\IoTShellExtension\ForegroundAppConfig" /v FailureResetIntervalMs /t REG_QWORD /d 1 /f
reg add "HKLM\Software\Microsoft\Windows NT\CurrentVersion\Winlogon\IoTShellExtension\ForegroundAppConfig" /v BaseRetryDelayMs /t REG_QWORD /d 10000 /f
reg add "HKLM\Software\Microsoft\Windows NT\CurrentVersion\Winlogon\IoTShellExtension\ForegroundAppConfig" /v MaxFailureCount /t REG_DWORD /d 0xffffffff /f
reg add "HKLM\Software\Microsoft\Windows NT\CurrentVersion\Winlogon\IoTShellExtension\ForegroundAppConfig" /v FallbackExponentNumerator /t REG_DWORD /d 1 /f
reg add "HKLM\Software\Microsoft\Windows NT\CurrentVersion\Winlogon\IoTShellExtension\ForegroundAppConfig" /v FallbackExponentDenominator /t REG_DWORD /d 1 /f

When you want to update the app, kill the app

tlist
kill CubeTestUwp

Then copy in the new files, for example

net use \\mycomputer /user:mycomputer\myusername
copy \\mycomputer\c$\git\graphics-driver-samples\render-only-sample\demos\arm\Debug\CubeTestUwp\* C:\Data\Programs\WindowsApps\83D8282E-44EC-430F-9A46-BB7C9C256D48_1.0.0.0_arm__t8h25trp4pa7y /y

Breaking in to DWM at boot

There are other ways to break in at process creation, but in my opinion this is the easiest way to break into DWM at an early stage.

Enable break on load of dxgkrnl and reboot

sxe ld:dxgkrnl.sys

When it breaks in at load of dxgkrnl, set a breakpoint on DxgkCreateDevice, which is called by every application that uses DirectX.

bp dxgkrnl!DxgkCreateDevice

When this breakpoint gets hit, check the current process to see if it's DWM. DWM is usually the first process to hit DxgkCreateDevice.

Breakpoint 0 hit
dxgkrnl!DxgkCreateDevice:
92525634 b403     push        {r0,r1}
2: kd> !process -1 0
PROCESS aa42eb80  SessionId: 0  Cid: 0294    Peb: 0057f000  ParentCid: 01dc
    DirBase: 02164000  ObjectTable: 95537a00  HandleCount: 142.
    Image: dwm.exe
2: kd> .reload /user
Loading User Symbols
.................................
Cannot read PEB32 from WOW64 TEB32 ffffffff - Win32 error 0n30
2: kd> k
 # Child-SP RetAddr  Call Site
00 91d19cf8 a88b48e8 dxgkrnl!DxgkCreateDevice [d:\rs1\onecoreuap\windows\core\dxkernel\dxgkrnl\core\device.cxx @ 1661]
01 91d19cf8 8107cb20 win32kbase!NtGdiDdDDICreateDevice+0xc [d:\rs1\onecoreuap\windows\core\ntgdi\gre\base\ddsup.cxx @ 1859]
02 91d19d00 8107c884 nt!KiSystemService+0x100 [d:\rs1\minkernel\ntos\ke\arm\trap.asm @ 2386]
03 91d19d40 76931ef6 nt!KiSWIException+0x104 [d:\rs1\minkernel\ntos\ke\arm\trap.asm @ 2134]
04 00dee760 754ab28c win32u!ZwGdiDdDDICreateDevice+0x6 [d:\rs1.obj.armfre\onecoreuap\windows\core\umode\moderncore\objfre\arm\usrstubs.asm @ 1099]
05 00dee760 754c5352 d3d11!NDXGI::CDevice::CreateDriverInstance+0x7c [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\dxgidevice.cpp @ 1111]
06 (Inline) -------- d3d11!CDevice::CreateDriverInstance+0x5e [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\device.cpp @ 9317]
07 00dee848 754f177e d3d11!CContext::LUCCompleteLayerConstruction+0xee [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\device.cpp @ 9065]
08 00dee918 754f200c d3d11!NOutermost::CDeviceChild::LUCCompleteLayerConstruction+0x26 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\outermost.cpp @ 371]
09 00dee950 754f1e84 d3d11!NOutermost::CDeviceChild::FinalConstruct+0x54 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\inc\outermost.inl @ 808]
0a 00dee998 754f1406 d3d11!CUseCountedObject<NOutermost::CDeviceChild>::CUseCountedObject<NOutermost::CDeviceChild>+0x60 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\inc\outermost.inl @ 247]
0b (Inline) -------- d3d11!CUseCountedObject<NOutermost::CDeviceChild>::CreateInstance+0x48 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\inc\outermost.inl @ 524]
0c 00dee9e8 754c42be d3d11!NOutermost::CDevice::CreateLayeredChild+0x136 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\outermost.cpp @ 160]
0d 00deeae0 754a88dc d3d11!CDevice::LLOCompleteLayerConstruction+0x852 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\device.cpp @ 8437]
0e 00def028 754f125a d3d11!NDXGI::CDevice::LLOCompleteLayerConstruction+0xb4 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\inc\dxgidevice.inl @ 305]
0f 00def3b8 754a4984 d3d11!NOutermost::CDevice::LLOCompleteLayerConstruction+0x1a [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\outermost.cpp @ 72]
10 (Inline) -------- d3d11!NOutermost::CDevice::FinalConstruct+0x58 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\inc\outermost.inl @ 171]
11 00def3c8 7549f024 d3d11!TComObject<NOutermost::CDevice>::TComObject<NOutermost::CDevice>+0xf8 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\inc\outermost.inl @ 34]
12 (Inline) -------- d3d11!TComObject<NOutermost::CDevice>::CreateInstance+0x3a [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\inc\outermost.inl @ 113]
13 00def458 7549f41e d3d11!D3D11CreateLayeredDevice+0xe4 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\main.cpp @ 534]
14 00def538 754a125a d3d11!D3D11CoreCreateLayeredDevice+0xce [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\main.cpp @ 813]
15 00def5e0 754a1984 d3d11!D3D11RegisterLayersAndCreateDevice+0x7ea [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\main.cpp @ 2548]
16 00def760 754a2c4a d3d11!D3D11CoreCreateDevice+0x634 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\main.cpp @ 2891]
17 00defab8 754a1c06 d3d11!D3D11CreateDeviceAndSwapChainImpl+0x39a [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\main.cpp @ 3985]
18 (Inline) -------- d3d11!D3D11CreateDeviceAndSwapChain+0x34 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\main.cpp @ 4066]
19 00defca0 754a1c50 d3d11!D3D11CreateDeviceImpl+0x46 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\main.cpp @ 3017]
1a 00defce0 74af727a d3d11!D3D11CreateDevice+0x40 [d:\rs1\onecoreuap\windows\directx\dxg\d3d11\d3dcore\lowfreq\main.cpp @ 3054]
1b 00defd18 74af7592 ism!DWMCursorBroker::Initialize+0xde [d:\rs1\onecoreuap\windows\moderncore\inputv2\systeminputrouters\dwm\components\cursor\lib\dwmcursorbroker.cpp @ 73]
1c 00defd78 74aeb346 ism!DWMCursorBroker::Create+0xca [d:\rs1\onecoreuap\windows\moderncore\inputv2\systeminputrouters\dwm\components\cursor\lib\dwmcursorbroker.cpp @ 150]
1d 00defda0 74adbc6c ism!DWMInputRouter::Initialize+0x4ce [d:\rs1\onecoreuap\windows\moderncore\inputv2\systeminputrouters\dwm\lib\dwminputrouter.cpp @ 298]
1e (Inline) -------- ism!DWMInputRouter::Create+0x70 [d:\rs1\onecoreuap\windows\moderncore\inputv2\systeminputrouters\dwm\lib\dwminputrouter.cpp @ 346]
1f 00defe08 74adb7c8 ism!OneCoreUAPInputHost::Initialize+0xfc [d:\rs1\onecoreuap\windows\moderncore\inputv2\systeminputhosts\onecoreuap\dll\onecoreuapinputhost.cpp @ 87]
20 (Inline) -------- ism!OneCoreUAPInputHost::Create+0x5e [d:\rs1\onecoreuap\windows\moderncore\inputv2\systeminputhosts\onecoreuap\dll\onecoreuapinputhost.cpp @ 146]
21 00defe48 75ca6a48 ism!CreateSystemInputHost+0x68 [d:\rs1\onecoreuap\windows\moderncore\inputv2\systeminputhosts\onecoreuap\dll\onecoreuapinputhost.cpp @ 43]
22 00defe70 76fce7b2 dwmcore!CISMInputThread::Run+0x58 [d:\rs1\onecoreuap\windows\dwm\dwmcore\input\isminputthread.cpp @ 129]
23 00defea0 00000000 ntdll!RtlUserThreadStart+0x22 [d:\rs1\minkernel\ntdll\rtlstrt.c @ 996]