Zine.net online

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.

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)