Kontynuujemy zabawę, tym razem spróbuję rzucić nieco światła na drugą część pierwszego pytania:
1. Mając do dyspozycji pełny memory.dmp można wygenerować zrzuty ekranu dla wszystkich aktywnych sesji z momentu padu systemu, a także co się działo w systemie w ostatnich sekundach przed padem.
W ramach pakietu z WinDbg dostajemy zestaw rozszerzeń pozwalających na analizę zdarzeń ETW, które zapisywane są w buforach pamięci zrzucanych do memory dumpa.
!wmitrace
W zasadzie wszystko sprowadza się do zabawy z poleceniami rozszerzenia wmitrace.
kd> !wmitrace.help
ETW Tracing Kernel Debugger Extensions
strdump - List running loggers
logger <LoggerId> - Dump the logger information
logdump <LoggerId> [-t n] [-tmf GUIDFile] [-man Man1 Man2 ... ManN] [-xml] [-of file]
- Dump the in-memory portion of a log file.
[-t n]: Dump the last n events, sorted by timestamp.
[-tmf GUIDFile]: Specify the tmf file for WPP events.
[-man Man1 Man2 ... ManN]: Specify a list of manifest files for ETW events.
[-xml]: Dump the events in xml format.
[-of file]: Dump the events in file, instead of the debugger console.
logsave <LoggerId> <Save file name> - Save the in-memory portion of a log to an .etl file
searchpath [+] <Path> - Set the trace format search path
manpath <Path> - Set the manifest search path
tmffile <filename> - Set the TMF file name (default is 'default.tmf')
setprefix [+] <TraceFormatPrefix> - Set the prefix format.
(default for WPP events: [%9!d!]%8!04X!.%3!04X!::%4!s! [%1!s!])
(default for ETW events: [%9!d!]%8!04X!.%3!04X!::%4!s! [EventId=%2!s!])
start LoggerName [-cir n] [-seq n] [-f file] [-b n] [-max n] [-min n] [-kd] [-ft n] [-singlestream [0|1]]
- Start the logger. For circular and sequential file maximum file size
can be provided. Default is buffered mode. Other arguments: filename,
buffer size, max and min buffers, flush timer, KdFilter.
enable LoggerId GUID [-level n] [-matchallkw n] [-matchanykw n] [-enableproperty n] [-flag n]
- Enable provider. Level, keywords, flags and enableproperty can be provided
stop <LoggerId> - Stop the logger.
disable LoggerId GUID - Disable provider.
dynamicprint <0|1> - Turn live tracing messages on (1) or off (0). Default is on.
traceoperation <0|1|2> - Verbose output. Default is OFF (debugging feature).
dumpmini - Dump the system trace fragment stored in a minidump (Vista and later).
dumpminievent - Dump the system event log trace fragment from a minidump (Vista SP1 and later).
eventlogdump <LoggerId> - Dump a logger using eventlog formatting.
bufdump [<LoggerId>] - Dump the Wmi Trace Loggers Buffers
In all commands logger name can be used instead of logger id.
Przy zabawie z dumpem odpadają wszystkie polecenia uruchamiające, aktywujące, etc. logger, czyli zaczynamy od zrzutu aktywnych loggerów:
kd> !wmitrace.strdump
(WmiTracing)StrDump Generic
LoggerContext Array @ 0xFFFFF80002A72880 [64 Elements]
Logger Id 0x02 @ 0xFFFFFA8001D83C80 Named 'Circular Kernel Context Logger'
Logger Id 0x03 @ 0xFFFFFA8001939040 Named 'Eventlog-Security'
Logger Id 0x04 @ 0xFFFFFA800191C040 Named 'Audio'
Logger Id 0x05 @ 0xFFFFFA800191C8C0 Named 'DiagLog'
Logger Id 0x06 @ 0xFFFFFA800191C500 Named 'EventLog-Application'
Logger Id 0x07 @ 0xFFFFFA8001939780 Named 'EventLog-System'
Logger Id 0x08 @ 0xFFFFFA8001943AC0 Named 'Microsoft Security Client'
Logger Id 0x09 @ 0xFFFFFA8002D3B440 Named 'MpWppTracing-04192013-191832-00000003-ffffffff'
Logger Id 0x0a @ 0xFFFFFA8001947780 Named 'NtfsLog'
Logger Id 0x0b @ 0xFFFFFA800194D040 Named 'UBPM'
Logger Id 0x0c @ 0xFFFFFA8001950040 Named 'WdiContextLog'
Logger Id 0x0d @ 0xFFFFFA80035EE2C0 Named 'MSDTC_TRACE_SESSION'
Logger Id 0x0e @ 0xFFFFFA80023DF280 Named 'WFP-IPsec Diagnostics'
Jak widać, lista zaczyna się od Id=0x02, przy aktywnym loggerze ‘NT Kernel Logger’ mielibyśmy go na pozycji 0x00 (z tego loggera korzysta np. procmon)
Na początek interesuje nas logger CKCL, czyli Circular Kernel Context Logger, bo w nim możemy znaleźć troszkę informacji o tym, co się działo w systemie przed jego padem. Zazwyczaj zaczynamy od zapisania logu do pliku .etl
kd> !wmitrace.logsave 2 c:\dumps\CKCL.etl
i następnie przejrzeniu go przy użyciu xperfview, WPA, lub - w ostateczności - zrzucie wszystkiego z poziomu samego xperf.
>xperf -i ckcl.etl -o ckcl.txt -a dumper
Oczywiście log możemy zapisać dla każdego z wypisanych wyżej loggerów - polecam to jako ćwiczenie i rozejrzenie się w rodzaju informacji, które można wyciągnąć.
Przeglądanie logu związanego z loggerem eventlogowym nie jest zbyt przyjazne (wszystko trafia do generic events i oglądanie tego w tabelce jest po prostu uciążliwe), dlatego też w kolejnym kroku możemy zrobić zrzut eventloga:
kd> !wmitrace.eventlogdump 5
WMI Trace Save: Debugger Extension. LoggerId = 5, Save File = 'c:\temp\wmiE890.tmp'
Logger Id 0x05 @ 0xFFFFFA800191C8C0 Named 'DiagLog'
CollectionOn = 1
LoggerMode = 0x10000180 ( secure rt single-str )
BufferSize = 16 KB
BuffersAvailable = 2
MinimumBuffers = 2
NumberOfBuffers = 2
MaximumBuffers = 22
EventsLost = 0
LogBuffersLost = 0
RealTimeBuffersLost = 0
LastFlushedBuffer = 0
MaximumFileSize = 100
FlushTimer = 1 sec
LoggerThread = 0xfffffa8001926040 <359>
PoolType = NonPaged
SequenceNumber = 66
ClockType = PerfCounter
EventsLogged = 0
Consumer @ 0xfffffa8003267f70 'dt nt!_ETW_REALTIME_CONSUMER 0xfffffa8003267f70'
Buffer Address Cpu RefCnt State
-----------------------------------------------------------------------------------------
Buffer 1: fffffa80022ab000 , 0: 0 Free List , Offset: 152 , 0% Used
Buffer 2: fffffa80022e3000 , 0: 0 Free List , Offset: 696 , 4% Used
Saved 2 Buffers
Querying c:\temp\wmiE890.tmp for all events...
Event 0 :
============
<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'>
<System>
<Provider Name='Microsoft-Windows-Kernel-PnP' Guid='{9c205a39-1250-487d-abd7-e831c6290539}'/>
<EventID> 212 </EventID>
<Version> 0 </Version>
<Level> 4 </Level>
<Task> 212 </Task>
<Opcode> 1 </Opcode>
<Keywords> 0x4000000000002020 </Keywords>
<TimeCreated SystemTime='2013-04-19T17:26:56.946394300Z'/>
<EventRecordID> 0 </EventRecordID>
<Correlation/>
<Execution ProcessID='4' ThreadID='48' ProcessorID='0' KernelTime='20' UserTime='0'/>
<Channel> </Channel>
<Computer> VM7 </Computer>
<Security/>
</System>
<EventData>
<Data Name='DriverNameLength'> 7 </Data>
<Data Name='DriverName'> win64dd </Data>
</EventData>
</Event>
TimeCreated SystemTime='2013-04-19T17:26:56.946394300Z'
Publisher name: Microsoft-Windows-Kernel-PnP
Failed to get event format size. Error = 3AB4
Event 1 :
============
<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'>
<System>
<Provider Name='Microsoft-Windows-Kernel-PnP' Guid='{9c205a39-1250-487d-abd7-e831c6290539}'/>
<EventID> 226 </EventID>
<Version> 0 </Version>
<Level> 4 </Level>
<Task> 226 </Task>
<Opcode> 1 </Opcode>
<Keywords> 0x4000000000020020 </Keywords>
<TimeCreated SystemTime='2013-04-19T17:26:56.960558900Z'/>
<EventRecordID> 1 </EventRecordID>
<Correlation/>
<Execution ProcessID='4' ThreadID='48' ProcessorID='0' KernelTime='20' UserTime='0'/>
<Channel> </Channel>
<Computer> VM7 </Computer>
<Security/>
</System>
<EventData>
<Data Name='DriverNameLength'> 55 </Data>
<Data Name='DriverName'> \REGISTRY\MACHINE\SYSTEM\ControlSet001\services\win64dd </Data>
</EventData>
</Event>
TimeCreated SystemTime='2013-04-19T17:26:56.960558900Z'
Publisher name: Microsoft-Windows-Kernel-PnP
Failed to get event format size. Error = 3AB4
Event 2 :
============
<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'>
<System>
<Provider Name='Microsoft-Windows-Kernel-PnP' Guid='{9c205a39-1250-487d-abd7-e831c6290539}'/>
<EventID> 227 </EventID>
<Version> 0 </Version>
<Level> 4 </Level>
<Task> 226 </Task>
<Opcode> 2 </Opcode>
<Keywords> 0x4000000000020020 </Keywords>
<TimeCreated SystemTime='2013-04-19T17:26:56.961033000Z'/>
<EventRecordID> 2 </EventRecordID>
<Correlation/>
<Execution ProcessID='4' ThreadID='48' ProcessorID='0' KernelTime='20' UserTime='0'/>
<Channel> </Channel>
<Computer> VM7 </Computer>
<Security/>
</System>
<EventData>
<Data Name='DriverNameLength'> 55 </Data>
<Data Name='DriverName'> \REGISTRY\MACHINE\SYSTEM\ControlSet001\services\win64dd </Data>
<Data Name='Status'> 0 </Data>
</EventData>
</Event>
TimeCreated SystemTime='2013-04-19T17:26:56.961033000Z'
Publisher name: Microsoft-Windows-Kernel-PnP
Failed to get event format size. Error = 3AB4
Event 3 :
============
<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'>
<System>
<Provider Name='Microsoft-Windows-Kernel-PnP' Guid='{9c205a39-1250-487d-abd7-e831c6290539}'/>
<EventID> 213 </EventID>
<Version> 0 </Version>
<Level> 4 </Level>
<Task> 212 </Task>
<Opcode> 2 </Opcode>
<Keywords> 0x4000000000002020 </Keywords>
<TimeCreated SystemTime='2013-04-19T17:26:56.961046400Z'/>
<EventRecordID> 3 </EventRecordID>
<Correlation/>
<Execution ProcessID='4' ThreadID='48' ProcessorID='0' KernelTime='20' UserTime='0'/>
<Channel> </Channel>
<Computer> VM7 </Computer>
<Security/>
</System>
<EventData>
<Data Name='ServiceNameLength'> 7 </Data>
<Data Name='ServiceName'> win64dd </Data>
<Data Name='Status'> 0 </Data>
<Data Name='DriverNameLength'> 15 </Data>
<Data Name='DriverName'> \Driver\win64dd </Data>
<Data Name='Version'> 393217 </Data>
</EventData>
</Event>
TimeCreated SystemTime='2013-04-19T17:26:56.961046400Z'
Publisher name: Microsoft-Windows-Kernel-PnP
Failed to get event format size. Error = 3AB4
Event 4 :
============
<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'>
<System>
<Provider Name='Microsoft-Windows-Diagnosis-DPS' Guid='{6bba3851-2c7e-4dea-8f54-31e5afd029e3}'/>
<EventID> 1 </EventID>
<Version> 0 </Version>
<Level> 5 </Level>
<Task> 3 </Task>
<Opcode> 10 </Opcode>
<Keywords> 0x2000000200000000 </Keywords>
<TimeCreated SystemTime='2013-04-19T17:28:33.032663600Z'/>
<EventRecordID> 4 </EventRecordID>
<Correlation/>
<Execution ProcessID='1200' ThreadID='1400' ProcessorID='0' KernelTime='0' UserTime='0'/>
<Channel> </Channel>
<Computer> VM7 </Computer>
<Security/>
</System>
<EventData> </EventData>
</Event>
TimeCreated SystemTime='2013-04-19T17:28:33.032663600Z'
Publisher name: Microsoft-Windows-Diagnosis-DPS
Event message:
Usługa Zasady diagnostyki została uruchomiona. To zdarzenie sygnalizuje modułom diagnostycznym opóźnione przetwarzanie po zainicjowaniu usługi.
==========
Success all items processed!
Zauważmy, że zrzucone zdarzenia są w formacie xml eventloga, co nieco ułatwia ich interpretację. W powyższym przypadku mamy zapisane zdarzenia związane ze sterownikiem win64dd, co może sugerować bezpośredni związek z padem systemu.
Dla niektórych loggerów i mniej obciążonego systemu można wyciągnąć nawet setki sekund zdarzeń (vide przykłady z linku #2 z przypisów). W przypadku loggera CKCL (i oczywiście innych, +własne) można czasem przed padem systemu dorzucić do niego zdarzenia związane z innymi, niż podstawowe providerami i w ten sposób dopisać sporo interesujących informacji do dumpa (też link #2).
Jako lekturę obowiązkową dla zainteresowanych, podaję:
1. Defrag Tools: #29 - WinDbg - ETW Logging
2. Part 3: ETW Methods of Tracing (z cyklu tekstów o ETW na blogu ntdebugging)