Wtrace 2.2

On the occasion of releasing wtrace 2.2, I decided to write a short post about new functionalities I added to this tool in the recent months. I hope you will find them interesting. Wtrace is a command line application which collects ETW traces from the system and the selected processes and outputs them to the console. It is very simple to use and runs on Windows 7+. Currently, it supports the collection of File I/O, TCP, ALPC, RPC, ISR, DPC, and PowerShell events.

Driver tracing (ISR/DPC)

If you use the -s switch during your trace, wtrace will also collect events measuring the time drivers spent in Interrupt Service Routines (ISRs) and Deferred Procedure Calls (DPCs). At the end of the trace, they will appear in the summary section, grouped by the driver name. Those should be minimal values compared to the overall time of the trace session. If you experience any lags in your system (nonresponsive desktop, sound stuttering) checking the ISR/DPC times might help diagnose the problem. If a driver spends too much time in either ISR or DPC, the regular user mode threads will not get access to the CPU on which the driver code runs. You may use -s switch alone or while tracing a process in the system. An example session:

PS> wtrace -s
System tracing has started. Press Ctrl + C to stop...
### Stopping NT Kernel Logger session...
### NT Kernel Logger session stopped. Number of lost events: 0

...
--------------------------------
              ISR
--------------------------------
'C:\Windows\system32\hal.dll', total: 30,655ms (6032 event(s))
'C:\Windows\system32\DRIVERS\HDAudBus.sys', total: 7,724ms (652 event(s))
'C:\Windows\system32\drivers\ACPI.sys', total: 0,218ms (12 event(s))

--------------------------------
              DPC
--------------------------------
'C:\Windows\system32\ntoskrnl.exe', total: 8,694ms (1179 event(s))
'C:\Windows\System32\drivers\dxgkrnl.sys', total: 7,295ms (806 event(s))
'C:\Windows\system32\DRIVERS\HDAudBus.sys', total: 3,201ms (652 event(s))
'C:\Windows\System32\drivers\tcpip.sys', total: 1,381ms (51 event(s))
'C:\Windows\system32\drivers\ndis.sys', total: 1,321ms (123 event(s))
'C:\Windows\system32\drivers\iaStorA.sys', total: 1,302ms (85 event(s))
'C:\Windows\system32\drivers\storport.sys', total: 1,178ms (165 event(s))
'C:\Windows\system32\DRIVERS\iusb3xhc.sys', total: 0,718ms (15 event(s))
'C:\Windows\system32\drivers\ACPI.sys', total: 0,557ms (20 event(s))
'C:\Windows\system32\drivers\NETIO.SYS', total: 0,250ms (30 event(s))
'C:\Windows\system32\DRIVERS\rassstp.sys', total: 0,197ms (98 event(s))
'C:\Windows\system32\drivers\Wdf01000.sys', total: 0,195ms (12 event(s))
'C:\Windows\System32\DRIVERS\netbt.sys', total: 0,158ms (3 event(s))
'C:\Windows\system32\DRIVERS\igdkmd64.sys', total: 0,105ms (29 event(s))
'C:\Windows\system32\DRIVERS\SCSIPORT.SYS', total: 0,059ms (6 event(s))
'C:\Windows\system32\drivers\usbccgp.sys', total: 0,050ms (6 event(s))
'C:\Windows\system32\drivers\afd.sys', total: 0,044ms (4 event(s))
'C:\Windows\System32\DRIVERS\srv.sys', total: 0,023ms (9 event(s))
'C:\Windows\system32\DRIVERS\nvlddmkm.sys', total: 0,011ms (6 event(s))
'C:\Windows\System32\Drivers\cng.sys', total: 0,005ms (1 event(s))
'C:\Windows\system32\drivers\HTTP.sys', total: 0,003ms (1 event(s))
'C:\Windows\System32\Drivers\Ntfs.sys', total: 0,003ms (1 event(s))
'C:\Windows\system32\drivers\luafv.sys', total: 0,002ms (1 event(s))
'C:\Windows\system32\DRIVERS\rdbss.sys', total: 0,002ms (1 event(s))

You may perform further DPC/ISR analysis in Windows Performance Analyzer, if necessary.

Basic event name filtering

It is possible to filter the events by their names using the -f switch. The filter value must appear anywhere in the event name (it does not support wildcards, and the search is case insensitive). Example:

PS> wtrace -f "fileio/create" notepad
1084,1959 (4044.7048) FileIO/Create 'C:\' (0xFFFFFA8024ED8820) rw-
1084,4550 (4044.7048) FileIO/Create 'C:\tools\notepad2_x86\Notepad2.exe' (0xFFFFFA802E30BF20) rw-
1084,9201 (4044.7048) FileIO/Create 'C:\' (0xFFFFFA802E30BF20) rw-
1085,0909 (4044.7048) FileIO/Create 'C:\tools\notepad2_x86\Notepad2.exe' (0xFFFFFA8024ED8820) rw-
1092,4074 (4044.7048) FileIO/Create 'C:\Windows\Prefetch\NOTEPAD2.EXE-5DB4E400.pf' (0xFFFFFA8024ED8820) ---
...

Automatic tracing of child processes

When your primary process spawns new processes that you would also like to trace you may start wtrace with the -c switch. In this mode, wtrace will automatically begin to trace every process which is a child of the primary process. An example when I monitored the cmd.exe starting notepad:

PS> .\wtrace.exe --newconsole -c cmd
1085,3112 (9112.4264) FileIO/Create 'C:\Windows\Prefetch\CMD.EXE-4A81B364.pf' (0xFFFFFA8022CF0AA0) ---
1086,0403 (9112.4264) FileIO/Create 'C:\temp' (0xFFFFFA8022CF0AA0) rw-
1087,5141 (9112.4264) ALPC cmd <--(0xA84)--- csrss (820.4712)
1095,6011 (9112.4264) ALPC cmd <--(0xA84)--- csrss (820.4720)
1149,6165 (9112.4264) ALPC cmd <--(0x674)--- conhost (8928.12720)
1167,2738 (9112.4264) ALPC cmd <--(0x674)--- conhost (8928.12720)
...
4779,1104 (14000.6408) FileIO/Create 'C:\' (0xFFFFFA802A66B800) rw-
4779,1312 (9112.4264) ALPC cmd <--(0x670)--- csrss (820.1004)
4779,1708 (9112.4264) ALPC cmd <--(0x670)--- csrss (820.1004)
4779,1881 (14000.6408) FileIO/Create 'C:\tools\notepad2_x86\Notepad2.exe' (0xFFFFFA8026E9D070) rw-
4779,2130 (14000.6408) FileIO/Close 'C:\' (0xFFFFFA802A66B800)
4779,2339 (9112.4264) ALPC cmd <--(0x670)--- csrss (820.1004)
4779,2478 (9112.4264) ALPC cmd <--(0x670)--- csrss (820.1004)
4779,2555 (9112.4264) ALPC cmd <--(0x670)--- csrss (820.1004)
...

Tracing PowerShell commands

The last feature I want to mention is the wtrace’s ability to output PowerShell commands executed in the PowerShell session. By default, ETW events reported by the Microsoft-Windows-PowerShell provider do not contain command parameters (7937 event). But you may enable detailed logging in the Local Group Policy Editor (Administrative Templates – Windows Components – Windows PowerShell). To learn more check this article. The interesting options are Turn on Module Logging and Turn on PowerShell Script Block Logging. After some experimentation, I discovered that the generated events differ between Windows versions. That is a bit surprising, and I do not yet understand why it happens. Also, the manifest produced by PerfView for the Microsoft-Windows-PowerShell provider (perfview /nogui usercommand dumpregisteredmanifest Microsoft-Windows-PowerShell) is quite complicated and convoluted. In the end, I recorded multiple ETW sessions and manually implemented the required events. Below you may find an example PowerShell command and the output that wtrace produces:

PS> get-content -Encoding byte C:\windows\notepad.exe | Select-Object -First 10 | Format-HexPrettyPrint
       0  1  2  3  4  5  6  7  8  9  A  B  C  D  E  F
0000: 4d 5a 90 00 03 00 00 00 04 00                    MZ........

PS> .\wtrace -f powershell 9704
2658,9133 (9704.10280) PowerShell/Script
2658,9454 (9704.10280) PowerShell/Cmdlet Out-Default
2659,1716 (9704.10280) PowerShell/Cmdlet Get-Content
2659,7312 (9704.10280) PowerShell/Cmdlet Select-Object
2659,8044 (9704.10280) PowerShell/Function Format-HexPrettyPrint
2660,0039 (9704.10280) PowerShell/Cmdlet Write-Host
2663,2664 (9704.10280) PowerShell/Function PrintLine
2663,4364 (9704.10280) PowerShell/Cmdlet ForEach-Object
2663,9474 (9704.10280) PowerShell/Cmdlet
~~~~~~~~~~~~~~~~~ BEGIN ~~~~~~~~~~~~~~~~~
CommandInvocation(ForEach-Object): "ForEach-Object"
ParameterBinding(ForEach-Object): name="Process"; value=" '{0:x2}' -f $_ "
ParameterBinding(ForEach-Object): name="InputObject"; value="77"
ParameterBinding(ForEach-Object): name="InputObject"; value="90"
ParameterBinding(ForEach-Object): name="InputObject"; value="144"
ParameterBinding(ForEach-Object): name="InputObject"; value="0"
ParameterBinding(ForEach-Object): name="InputObject"; value="3"
ParameterBinding(ForEach-Object): name="InputObject"; value="0"
ParameterBinding(ForEach-Object): name="InputObject"; value="0"
ParameterBinding(ForEach-Object): name="InputObject"; value="0"
ParameterBinding(ForEach-Object): name="InputObject"; value="4"
ParameterBinding(ForEach-Object): name="InputObject"; value="0"
~~~~~~~~~~~~~~~~~  END  ~~~~~~~~~~~~~~~~~
2664,0567 (9704.10280) PowerShell/Cmdlet ForEach-Object
2664,4949 (9704.10280) PowerShell/Cmdlet
~~~~~~~~~~~~~~~~~ BEGIN ~~~~~~~~~~~~~~~~~
CommandInvocation(ForEach-Object): "ForEach-Object"
ParameterBinding(ForEach-Object): name="Process"; value="
                $Numeric = [Int32]$_
                if ($Numeric -ge 32 -and $Numeric -le 126) {
                    [Char]$_
                } else {
                    [Char]'.'
                }
            "
ParameterBinding(ForEach-Object): name="InputObject"; value="77"
ParameterBinding(ForEach-Object): name="InputObject"; value="90"
ParameterBinding(ForEach-Object): name="InputObject"; value="144"
ParameterBinding(ForEach-Object): name="InputObject"; value="0"
ParameterBinding(ForEach-Object): name="InputObject"; value="3"
ParameterBinding(ForEach-Object): name="InputObject"; value="0"
ParameterBinding(ForEach-Object): name="InputObject"; value="0"
ParameterBinding(ForEach-Object): name="InputObject"; value="0"
ParameterBinding(ForEach-Object): name="InputObject"; value="4"
ParameterBinding(ForEach-Object): name="InputObject"; value="0"
~~~~~~~~~~~~~~~~~  END  ~~~~~~~~~~~~~~~~~
2664,5918 (9704.10280) PowerShell/Cmdlet Write-Host
2667,1845 (9704.10280) PowerShell/Script CommandInvocation(Out-Default): "Out-Default"
2669,4010 (9704.10280) PowerShell/Script
2669,5340 (9704.10280) PowerShell/Function prompt
2669,7160 (9704.10280) PowerShell/Cmdlet Test-Path
2670,0204 (9704.10280) PowerShell/Cmdlet Get-Location
2670,1694 (9704.10280) PowerShell/Cmdlet Split-Path
2671,0039 (9704.10280) PowerShell/Function PSConsoleHostReadline
2671,1895 (9704.10280) PowerShell/Cmdlet Set-StrictMode
2671,5095 (9704.10280) PowerShell/Cmdlet
~~~~~~~~~~~~~~~~~ BEGIN ~~~~~~~~~~~~~~~~~
CommandInvocation(Set-StrictMode): "Set-StrictMode"
ParameterBinding(Set-StrictMode): name="Off"; value="True"
~~~~~~~~~~~~~~~~~  END  ~~~~~~~~~~~~~~~~~