-
Notifications
You must be signed in to change notification settings - Fork 141
Debugging Tips
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 usermode driver is also instrumented with WPP tracing, and there are a variety of ways in which traces can be viewed.
To send trace output from the usermode driver to the kernel debugger in real time, run the following command and reboot:
tracelog -addautologger rosumd -sessionguid #D124564D-F51F-402D-A86E-7E2247D30AF3 -guid #D124564D-F51F-402D-A86E-7E2247D30AF3 -rt -kd -flags 0xffffff -level 5
After the reboot you should see output in the kernel debugger similar to the following:
[1]0764.0760::03/19/2016-13:35:18.658 [rosumd] [RosUmd.cpp @ 30] TRACE :RosUmd was loaded. (hmod = 0x754C0000)
To stop the trace logging session, run
tracelog -stop rosumd
You can use tracelog.exe to capture traces to an ETL file in a way that impacts performance minimally, then decode and view the log on your PC.
Run the following command to start capturing traces immediately:
tracelog -start rosumd -guid #D124564D-F51F-402D-A86E-7E2247D30AF3 -flags 0xffffff -level 5 -f c:\data\rosumd.etl
You could also use the -addautologger option shown above if you want to start capturing traces from boot. Use the -level parameter to control verbosity. Use a level of 4 to include only errors, warnings, and information. The highest verbosity level is 5 which will include debugging messages.
To stop capture messages, run
tracelog -stop rosumd
Copy rosumd.etl to your desktop and run the following command. rosumd.pdb must be present in the same directory as rosumd.dll.
"C:\Program Files (x86)\Windows Kits\10\bin\x64\tracefmt.exe" rosumd.etl -i path\to\rosumd.dll
For example,
set path=C:\Program Files (x86)\Windows Kits\10\bin\x64;%path%
tracefmt rosumd.etl -i D:\workspace\graphics-driver-samples\render-only-sample\arm\debug\rosumd.dll
The output will be decoded into a file named FmtFile.txt in the directory where the command was run. You can also print output to the console by passing the -displayonly option:
tracefmt rosumd.etl -i D:\workspace\graphics-driver-samples\render-only-sample\arm\debug\rosumd.dll -displayonly
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 |
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