Windows 的事件跟踪：OpenTrace/ProcessTrace 未返回任何事件 - 未调用回调

Question

精简版

我正在尝试使用 OpenTrace and ProcessTrace 读取 .etl 文件的事件。

成功调用 OpenTrace returnTRACEHANDLE
调用 ProcessTrace returns ERROR_SUCCESS
但 ProcessTrace 从未调用我的 EVENT_CALLBACK 回调函数

我知道这是一个有效的 .etl 文件，因为我可以在以下位置打开它：

长版

Microsoft 提供 sample code 读取 .etl 文件的事件。基本要点是：

用我们要打开的文件名和回调函数的地址初始化一个EVENT_TRACE_LOGFILE结构。回调函数为文件中的每个事件调用一次：

var 
  filename: UnicodeString;
  trace: EVENT_TRACE_LOGFILEW;

filename := 'C:\test.etl';

//Initialize trace with filename and callback
ZeroMemory(@trace, sizeof(trace));
trace.LogFileName := PWideChar(filename);
trace.EventCallback := ProcessTraceEventCallback; //called once for each event in the file

调用OpenTrace打开指定的.etl文件，得到session的TRACEHANDLE:

//Open the trace
var
  hTrace: TRACEHANDLE;

hTrace := OpenTraceW(trace);
if (hTrace = INVALID_PROCESSTRACE_HANDLE) then
  RaiseLastOSError;

调用ProcessTrace开始从文件中读取事件。我们的回调将针对文件中的每个事件调用一次，并且 ProcessTrace 不会 return 直到所有事件都被读取：
```
var
   res: Cardinal;

res := ProcessTrace(@hTrace, 1, nil, nil);
if (res <> ERROR_SUCCESS) then
   RaiseLastOSError;
```

应该就是这样，除了永远不会调用回调：

procedure ProcessTraceEventCallback(pEvent: PEVENT_TRACE); stdcall;
begin
   //TODO: read the event information out of pEvent
   //pEvent.MofData ==> raw payload information
   //pEvent.MofLength ==> raw payload length (bytes)
   WriteLn('Got an event');
   Winapi.Windows.DebugBreak;
end;

None 的代码 return 是一个错误。

OpenTracereturn一个有效句柄
ProcessTrace 需要一点时间 return（好像它正在处理事件）
和returns ERROR_SUCCESS
但是从未调用用于获取事件信息的回调函数。

我的示例代码和下面的 CRME 都强制使用 W Unicode 版本的函数（只是为了消除混淆）。我确定我的 header 翻译、记录打包、对齐或调用约定有问题 - 但我找不到任何东西。

完整的可重现的最小示例

我知道它看起来并不小。但是我们需要所有 API 函数和结构。

您将需要自己的 C:\test.etl 文件。您可以使用 Windows Performance Recorder 创建一个，或者在您的 PC 中搜索 .etl 文件 - Windows，Microsoft 会创建很多散落在各处的文件。

program Project4;

{$APPTYPE CONSOLE}
{$ALIGN 8} //Windows ABI

{$R *.res}

uses
  System.SysUtils,
  Winapi.Windows;

type
    EVENT_TRACE_HEADER = packed record
        Size: Word;                         // Size of entire record
        FieldTypeFlags: Word;           // Reserved
        EventType: Byte;                    //Type of event. A provider can define their own event types or use the predefined event types (Info, Start,Stop, Suspend, Checkpoint, Resume, etc.)
        EventLevel: Byte;                   //Provider-defined value that defines the severity level used to generate the event. Verbose, Information, Warning, Error, Critical, etc
        EventVersion: Word;             //Which version of MOF class to use to decipher the event data. Specify zero if there is only one version of your event trace class.
        ThreadId: LongWord;                 //On output, identifies the thread that generated the event.
        ProcessId: LongWord;                //On output, identifies the process that generated the event.
        TimeStamp: Int64;                   //The time that the event occurred. On output, contains the time that the event occurred.
        Guid: TGUID;                        //Guid that identifies event. Event trace class GUID. You can use the class GUID to identify a category of events and the Class.Type member to identify an event within the category of events.
        ClientContext: LongWord;        //Reserved
        Flags: LongWord;              //
    end;
    PEVENT_TRACE_HEADER = ^EVENT_TRACE_HEADER;

  EVENT_TRACE = packed record
     Header: EVENT_TRACE_HEADER;    // Event trace header
     InstanceId: Cardinal;          // Instance identifier. Contains valid data when the provider calls the TraceEventInstance function to generate the event. Otherwise, the value is zero.
     ParentInstanceId: Cardinal;    // Instance identifier for a parent event. Contains valid data when the provider calls the TraceEventInstance function to generate the event. Otherwise, the value is zero.
     ParentGuid: TGUID;             // Class GUID of the parent event. Contains valid data when the provider calls the TraceEventInstance function to generate the event. Otherwise, the value is zero.
     MofData: Pointer;              // Pointer to the beginning of the event-specific data for this event.
     MofLength: Cardinal;           // Number of bytes to which MofData points.
     BufferContext: Cardinal;       // Provides information about the event such as the session identifier and processor number of the CPU on which the provider process ran.
  end;
  PEVENT_TRACE = ^EVENT_TRACE;

  TRACE_LOGFILE_HEADER = record
        BufferSize: LongWord;
        MajorVersion: Byte;
        MinorVersion: Byte;
        SubVersion: Byte;
        SubMinorVersion: Byte;

        ProviderVersion: LongWord;    // defaults to NT version
        NumberOfProcessors: LongWord; // Number of Processors
        EndTime: LARGE_INTEGER;       // Time when logger stops
        TimerResolution: LongWord;
        MaximumFileSize: LongWord;    // Maximum in Mbytes
        LogFileMode: LongWord;        // specify logfile mode
        BuffersWritten: LongWord;     // used to file start of Circular File
        StartBuffers: Cardinal;         // Reserved
        PointerSize: Cardinal;          // Size of a Pointer data type, in bytes.
        EventsLost: Cardinal;           // Number of events lost during the event tracing session. Events may be lost due to insufficient memory or a very high rate of incoming events.
        CpuSpeedInMHz: Cardinal;        // CPU speed, in megahertz.
        LoggerName: PWideChar;          // Do not use.
        LogFileName: PWideChar;         // Do not use
        TimeZone: TIME_ZONE_INFORMATION;    // A TIME_ZONE_INFORMATION structure that contains the time zone for the BootTime, EndTime and StartTime members.
        BootTime: Int64;                    // Time at which the system was started, in 100-nanosecond intervals since midnight, January 1, 1601. BootTime is supported only for traces written to the Global Logger session.
        PerfFreq: Int64;                    // Frequency of the high-resolution performance counter, if one exists.
        StartTime: Int64;                   // Time at which the event tracing session started, in 100-nanosecond intervals since midnight, January 1, 1601.
        ReservedFlags: Cardinal;
        BuffersLost: Cardinal;          // Total number of buffers lost during the event tracing session.
    end;
    PTRACE_LOGFILE_HEADER = ^TRACE_LOGFILE_HEADER;

    PEVENT_TRACE_LOGFILEW = ^EVENT_TRACE_LOGFILEW; //forward

    EVENT_TRACE_BUFFER_CALLBACKW = function (Logfile : PEVENT_TRACE_LOGFILEW) : Cardinal; stdcall;
    PEVENT_TRACE_BUFFER_CALLBACKW = EVENT_TRACE_BUFFER_CALLBACKW;

    //Legacy EventCallback callback
    EVENT_CALLBACK = procedure (pEvent: PEVENT_TRACE); stdcall;
    PEVENT_CALLBACK = EVENT_CALLBACK;

    //Newer EventCallback if ProcessTraceMode of PROCESS_TRACE_MODE_EVENT_RECORD is specified
//  EVENT_RECORD_CALLBACK = procedure (EventRecord: PEVENT_RECORD); stdcall;
//  PEVENT_RECORD_CALLBACK = EVENT_RECORD_CALLBACK;

    EVENT_TRACE_LOGFILEW = packed record
        LogFileName: PWideChar;                 // Logfile Name
        LoggerName: PWideChar;                  // LoggerName
        CurrentTime: Int64;                     // timestamp of last event
        BuffersRead: Cardinal;                  // buffers read to date
        ProcessTraceMode: Cardinal;
        CurrentEvent: EVENT_TRACE;              // Current Event from this stream. (84 bytes)
        LogfileHeader: TRACE_LOGFILE_HEADER;            // logfile header structure (272 bytes)
        BufferCallback: PEVENT_TRACE_BUFFER_CALLBACKW;  // callback before each buffer is read

        // following variables are filled for BufferCallback.
        BufferSize: Cardinal;       //On output, contains the size of each buffer, in bytes
        Filled: Cardinal;               //On output, contains the number of bytes in the buffer that contain valid information
        EventsLost: Cardinal;       //Not used

        // following needs to be propaged to each buffer
        EventCallback: PEVENT_CALLBACK; //or EventRecordCallback: PEvent_Record_Callback if flag is on
        IsKernelTrace: Cardinal;    // TRUE for kernel logfile
        Context: Pointer;          // reserved for internal use
    end;

    TRACEHANDLE  = UInt64;
    PTRACEHANDLE = ^TRACEHANDLE;

function OpenTraceW(var Logfile : EVENT_TRACE_LOGFILEW): Cardinal; stdcall; external advapi32 name 'OpenTraceW';
function ProcessTrace(HandleArray: PTRACEHANDLE; HandleCount: Cardinal; StartTime: PFileTime; EndTime: PFileTime): Cardinal; stdcall; external advapi32 name 'ProcessTrace';
function CloseTrace(ATraceHandle: TRACEHANDLE): Cardinal; stdcall; external advapi32 name 'CloseTrace';

const
    INVALID_PROCESSTRACE_HANDLE: TRACEHANDLE = INVALID_HANDLE_VALUE; //i.e. TRACEHANDLE([=16=]000000FFFFFFFF);

procedure ProcessTraceEventCallback(pEvent: PEVENT_TRACE); stdcall;
begin
{
    Our callback, called once for each event in the file
}
    WriteLn('Got an event');
    Winapi.Windows.DebugBreak;
end;

function BufferCallback(logFile: PEVENT_TRACE_LOGFILEW): LongWord; stdcall;
begin
    WriteLn('Finished processing a buffer-full of events. Buffercallback says '+IntToStr(logfile.EventsLost)+' events lost');

    Result := 1; // Return TRUE to continue processing more events. Otherwise FALSE
end;

procedure Main;
var
    trace: EVENT_TRACE_LOGFILEW;
    th: TRACEHANDLE;
    filename: UnicodeString;
    res: Cardinal;
begin
    filename := 'C:\test.etl';
    WriteLn('Filename: '+filename);

    {
      Example code of how to read from a .etl file:

      Using TdhFormatProperty to Consume Event Data
      https://docs.microsoft.com/en-us/windows/win32/etw/using-tdhformatproperty-to-consume-event-data
    }

    //Initialize EVENT_TRACE_LOGFILE with filename to open, and our callback function
    WriteLn('Initializing EVENT_TRACE_LOGFILE');
    ZeroMemory(@trace, sizeof(trace)); // 408 bytes
    trace.LogFileName := PWideChar(filename);
    trace.EventCallback := ProcessTraceEventCallback; //called once for each event in the file
//  trace.ProcessTraceMode := PROCESS_TRACE_MODE_EVENT_RECORD; //we wanted new style events through the "EventRecordCallback"
//  trace.BufferCallback := BufferCallback; //optional callback for inforamtion after processing a buffer-full of events

    WriteLn('Opening trace file "'+filename+'"');
    th := OpenTraceW(trace);
    if (th = INVALID_PROCESSTRACE_HANDLE) or (th = -1) then
    begin
        WriteLn('Error opening trace file: '+SysErrorMessage(GetLastError));
        Exit;
    end;
    WriteLn('Successfully opened trace session. TraceHandle: 0x'+IntToHex(th, 8));

    WriteLn('Processing trace file');
    res := ProcessTrace(@th, 1, nil, nil);
    if (res <> ERROR_SUCCESS) then // and (hr <> ERROR_CANCELLED) then
        RaiseLastOSError;
    WriteLn('Successfully processed trace file');

    WriteLn('Closing trace handle');
    CloseTrace(th);

    WriteLn('Finished processing '+filename);
end;

begin
  try
        Main;
        WriteLn('Execution complete. Press enter to close...');
        ReadLn;
  except
    on E: Exception do
        Writeln(E.ClassName, ': ', E.Message);
  end;
end.

我的输出是：

Filename: C:\test.etl
Initializing EVENT_TRACE_LOGFILE
Opening trace file "C:\test.etl"
Successfully opened trace session. TraceHandle: 0x00000041
Processing trace file
Successfully processed trace file
Closing trace handle
Finished processing C:\test.etl
Execution complete. Press enter to close...

谁能看出我做错了什么？

Answer 1

答案正是我所知道的。

我从 headers 开始，由 Franck Soranio
其中一些定义是 packed records
当这不起作用时，我尝试添加 $ALIGN 8 - Windows
当这不起作用时，我尝试将 packed 添加到所有记录

当这不起作用时，我问了 Whosebug。

与此同时，我启动了 Visual Studio C++，并比较了原始结构的 sizeof 和翻译的 Delphi。

他们不匹配。

问题是packed条记录。

sizeof(EVENT_TRACE_LOGFILEW)：416 字节 （原为 404）
- sizeof(EVENT_TRACE)：88 字节 （原为 80）
  - sizeof(EVENT_TRACE_HEADER)：44 字节 （原为 40）
- sizeof(TRACE_LOGFILE_HEADER): 272 字节

删除记录打包修复它。

Windows 的事件跟踪：OpenTrace/ProcessTrace 未返回任何事件 - 未调用回调

Event Tracing for Windows: OpenTrace/ProcessTrace not returning any events - callback not being called

windows

delphi

winapi

etw

精简版

长版

完整的可重现的最小示例