Tcl Windows API extension

Windows includes a facility, Event Tracing for Windows (ETW), that allows the kernel and applications to log events that can either be written to a file or consumed in real time. This module provides access to this facility.

Overview

In ETW, events are written to an event trace by event providers under the control of event controllers which manage the mapping between the two. Event consumers read events from one or more such event traces for display to the user or any other purpose. TWAPI provides support for implementing all of the above.

There are two different technologies on which ETW is based. All modern (post-Windows XP up to Windows 7) versions of Windows support ETW based on Managed Object Format (MOF) event definitions. Windows Vista and later versions also implement a newer version of ETW based on XML manifests. TWAPI currently supports only MOF based event tracing.

Event trace

An event trace consists of a set of buffers, and optionally an associated file, to which events are written. The trace has other associated parameters such as the time stamping granularity, access control information and buffer limits. These are configured through event controllers.

Event controllers

An event controller manages event traces and their association with event providers. The following TWAPI commands can be used to implement an event controller:

To create a new event trace, use the command etw_start_trace which creates a new trace with configurable parameters.
To create and remove associations between event providers and traces, use the etw_enable_provider command. This command can also be used to communicate to the event providers what events are to be logged.
Use etw_query_trace and etw_update_trace to query and change the parameters of an existing trace.
To stop a trace, use the etw_stop_trace command. To flush the event trace buffers without terminating the trace, use etw_flush_trace command.
Use etw_get_traces to get a list of all current traces.

Note that the above commands can be used with any trace, not just those created using etw_start_trace. For example, traces created with the Windows logman or tracelog command can be controlled with the above command and vice versa.

Note that only processes running with elevated administrative privileges, or under accounts in the Performance Log Users group, and services running as LocalSystem, LocalService, NetworkService can start or control event traces.

Event providers

Event providers are components that write events to an event trace. Association with a specific trace is not under the control of the provider; that is a controller function. Of course, a single application may host both an event provider as well as an event controller. The list of providers on a system can be retrieved through the etw_get_providers command. The command etw_get_provider_guid can be used to map the provider name to its GUID.

Controllers send configuration information to providers in the form of enable flags and the enable level. The interpretation of these is entirely to the discretion of the event provider. Neither Windows, nor TWAPI, interpret these in any way. The TWAPI commands etw_provider_enable_flags and etw_provider_enable_level can be used to obtain the current values.

By convention, applications treat the enable flags as a bit mask that indicates the class(es) of events to log. For example, each bit might correspond to a specific subsystem. Note that a value of 0 does not mean the provider is disabled. It is up to the application as to how a value of 0 is interpreted. To determine whether a provider is actually enabled in the sense of being attached to an event trace, use the etw_trace_enabled command.

Similarly, the enable level is generally treated as a severity level, but again, this is not mandated.

Before any controller can add a provider to an event trace, the provider has to register itself. TWAPI includes a predefined provider that can be registered through the etw_twapi_provider_register call. Correspondingly, the command etw_unregister_provider unregisters the provider. Note that this must be done after the provider is detached from any event traces else Windows exhibits anomalous but harmless behaviour where the provider's calls to write events to the event trace still work but the provider is not notified of changes in the enable flags and level or when the trace is stopped.

Once the TWAPI provider is registered and attached to an event trace, events can be logged to the trace with the etw_log_message command.

Event consumers

ETW event consumers read events from event traces in real time or from a log file. An example of an event consumers is the command line program tracerpt which comes with Windows. The ETW interface allows a consumer to read events from multiple traces and merges them as needed.

TWAPI provides the high-level etw_dump and etw_dump_to_file commands which can read and format events.

For more control over the processing, call etw_open_file or etw_open_session to open each log file or real time event trace of interest. Then invoke the commands etw_process_events and etw_format_events to process the events.

event traces opened with etw_open_session should be closed with etw_close_session after processing.

Event definitions

Events written via ETW can have arbitrary binary formats. In order for consumers to be able to parse and extract data, they need to know the event definition. Providers use either Managed Object Format or XML manifests (Vista and later) to provide consumers with this information. When reading events, TWAPI will automatically look up event definitions as needed.

In order for event consumers to correctly parse events, TWAPI also has to make the MOF definitions for its ETW events available. This is done by calling the etw_install_twapi_mof command. This must be done on the system where the event consumer runs. It is not required on the system where the events are generated.

Tracing kernel events

There is a special event trace associated with the Windows kernel. The kernel logs events such as network events, process events, disk I/O etc. to this trace when enabled. This trace can be started and configured through the etw_start_kernel_trace command. The specific events to be logged are also specified as options to this command as the etw_enable_provider cannot be used with kernel traces.

See MSDN for the structure and description of the various events logged by the Windows kernel. The corresponding field names are returned by etw_format_events.

Tcl ETW traces

TWAPI includes commands etw_variable_tracker, etw_command_tracker and etw_execution_tracker that aid in logging Tcl variable, command and execution traces, respectively, to an ETW event trace.

set hprovider [etw_twapi_provider_register]
# Assume provider is added to event trace by some other means

# Add an execution trace to proc p
trace add execution p {enter leave enterstep leavestep} [list twapi::etw_execution_tracker $hprovider]

ETW Controller Commands

This section describes the commands that allow implementation of an ETW controller.

etw_disable_provider TRACEHANDLE PROVIDER

Disables the specified provider from logging to the event trace specified by TRACEHANDLE (as returned by etw_start_trace). PROVIDER can be the name or the GUID of the provider.

etw_enable_provider TRACEHANDLE PROVIDER ENABLEFLAGS LEVEL

Enables a provider to log to the event trace specified by TRACEHANDLE (as returned by etw_start_trace). PROVIDER can be the name or the GUID of the provider.

ENABLEFLAGS is an integer bitmask that indicates to the provider which classes of events are to be logged. The specific bits depend on the provider. Use the Windows command wevtutil gp PROVIDERNAME to list the event classes and the corresponding bitmask for a specific provider.

LEVEL is an integer between 0 and 255 that indicates the severity level at which events should be logged. The provider will log all events at LEVEL and below. Levels 1 through 5 can also be denoted as fatal, error, warning, informational and verbose respectively.

etw_flush_trace TRACE ?options?

Flushes the buffers belonging to an event trace. The trace TRACE may be specified either by its name or by its handle (as returned by etw_start_trace).

etw_get_provider_guid PROVIDERNAME

Returns the GUID of specified provider.

etw_get_providers ?-detail?

If -detail is not specified, returns a list containing the names of all providers registered on the system. If -detail is specified, returns a list each element of which is a dictionary with keys guid containing the GUID (same as the key), name containing the name of the provider and type which is one of mof or xml depending on whether the provider events are defined using WMI MOF or XML manifests.

etw_get_traces ?-detail?

If -detail is not specified, returns a list of the names of all traces currently running to which the calling process has access. If the -detail option is specified, returns a list each element of which is a dictionary in the same format as returned by etw_query_trace.

etw_query_trace TRACE

Returns a dictionary containing an event trace's settings and status. The trace TRACE may be specified either by its name or by its handle (as returned by etw_start_trace). The returned dictionary has the following keys (any additional keys should be ignored and not relied on being present):

buffer_size	Size of the buffers for the event trace.
buffers_written	Number of buffers flushed.
clock_resolution	One of qpc, system or cpucycle as described in etw_start_trace.
enable_flags	The provider enable mask for the event trace. This is valid only for kernel traces in which case it contains the enable mask for the kernel components.
events_lost	Number of events lost in the event trace that were not recorded.
flush_timer	Number of seconds after which buffers are automatically flushed.
free_buffers	Number of free buffers in the event trace.
log_buffers_lost	Number of buffers lost without being consumed.
logfile	The log file associated with the event trace.
logfile_mode	Bit flags indicating logging mode for the event trace.
logger_tid	Thread id of thread doing the logging for the event trace.
max_buffers	Maximum number of buffers that can be allocated for the event trace.
max_file_size	Maximum size specified for the file in megabytes.
min_buffers	Minimum number of buffers that can be allocated for the event trace.
buffer_count	Number of buffers in use.
real_time_buffers_lost	Number of buffers used for real time tracing that could not be written to the log file.
trace_guid	The GUID associated with the event trace.
trace_name	The name of the event trace.

etw_start_kernel_trace EVENTCLASSES ?options?

Starts an event trace with the Windows kernel provider. Returns a pair consisting of a event trace handle and a dictionary containing the event trace properties. Windows only supports one such event trace so an error is generated if another application already has a kernel trace open. In addition, the process must be running under an account with administrative privileges or as a service running as LocalSystem.

EVENTCLASSES specifies the kernel events that are to be captured and should be a list containing elements from the table below. Note that the captured events may include other events that are not included in EVENTCLASSES.

alpc	Advanced local procedure calls (Vista and later)
contextswitch	Thread context switches (Vista and later)
dbgprint	Kernel DbgPrint calls
diskfileio	File I/O
diskio	Disk I/O
dispatcher	Thread transitions to ready state (Windows 7 and later)
dpc	Device deferred procedure calls (Vista and later)
driver	Device driver requests (Vista and later)
hardfault	Hard page faults
imageload	Image loading
interrupt	Interrupt service routines (Vista and later)
pagefault	Page faults
process	Processes events
processcounter	Process counters (Vista and later)
profile	Processor profiling samples (Vista and later)
registry	Registry access
splitio	Split I/O events (Vista and later)
sysconfig	Includes events describing system configuration. These are collected when the trace is stopped.
systemcall	System calls (Vista and later)
tcpip	TCP and UDP events
thread	Thread events
vamap	Virtual address map and unmap events (Windows 8/Windows Server 2012 and later)
virtualalloc	Virtual memory allocation (Windows 7/Windows Server 2008 R2 and later)

See etw_start_trace for a description of the options that may be specified. However, note rotate is not a valid value for -filemode for kernel traces and the -usepagedmemory option must not be specified.

etw_start_trace TRACENAME ?options?

Starts a new ETW trace with the name TRACENAME and returns a handle to it.

The following options may be specified:

-buffersize BUFFERSIZE

Specifies the size in kilobytes of the buffers used in the event trace. This is only an requested size and will be adjusted by ETW.

-clockresolution RESOLUTION

The clock resolution to use when timestamping events in the event trace. Specify RESOLUTION as qpc to use the query performance counter. This is the highest resolution but is relatively expensive. Specify system to use system time. This is lower resolution but is cheaper in run time cost and is the default. Specify cpucycle to use the CPU cycle counter. This has the highest resolution and is the cheapest to obtain. However it can be very inaccurate as it is affected by power and temperature management features of the CPU.

-flushtimer SECONDS

Normally, ETW buffers are flushed as they become full. Use this option to force flushing of buffers every SECONDS seconds even when they are not full. However note that ETW flushes entire buffers to log files so flushing half empty buffers can greatly increase the log file size. Generally, use this option only for real time event traces.

-filemode FILEMODE

Specifies the file logging mode. FILEMODE must be one of the following values:

append	Events are written sequentially to a log file. Unlike sequential mode, existing log files are appended to instead of being overwritten. The -clockresolution option must be system and options -realtime, -private or -privateinproc must be false. Moreover, various configuration parameters like buffer size must be the same as those of the existing log file.
circular	This is the default mode. Events are written to the log file in circular fashion with newer events overwriting older events once the maximum file size is reached. If option -maxfilesize is not specified, it is defaulted to 1MB.
rotate	Sequentially writes to the log file and automatically creates a new file when the maximum file size is reached. The path specified with the -logfile option must contain the string %d which is replaced with a incremented counter every time a new file is created. If option -maxfilesize is not specified, it is defaulted to 1MB. On Windows versions prior to Windows 7 and Windows 2008 R2, the -private and -privateinproc options are not compatible with this mode.
sequential	Writes events sequentially to a log file. Existing log files are overwritten. If option -maxfilesize is specified, logging stops when the maximum size is reached. Otherwise, the file will grow as needed except for some system defined limits if it resides on the system drive.

-logfile FILEPATH

The name of the log file in which to write events. This option need not be specified if the event trace is only a real time trace. FILEPATH may be relative or absolute but should have the .etl extension. Depending on the other options specified, the actual file name may be modified.

-maxbuffers MINBUFS

Specifies the minimum number of buffers to allocate.

-minbuffers MAXBUFS

Specifies the maximum number of buffers to allocate.

-maxfilesize MAXMB

The maximum size of the log file in megabytes.

-paged BOOLEAN

If true, paged memory is used for the event trace buffers. If false (default), non-paged memory is used. Kernel-mode providers cannot log to paged buffers. If these are not used in the trace, it is recommended to set this option to true as non-paged memory is a limited resource.

-preallocate BOOLEAN

If true, any required file space is preallocated. Default is false.

-private BOOLEAN

If true, creates a private event trace to which only threads within the provider's process can log events. There can be only one private event trace per process. On Windows Vista and later, only processes running as LocalSystem and elevated processes can create private event traces. On earlier versions of Windows, processes in the Performance Log Users group could also create private traces. When multiple processes register the provider, any log files created are appended with the PID of the process except for the one created by the first process. This option cannot be used with -realtime. On Windows versions prior to Windows 7, this option cannot be used if -filemode is specified as rotate.

-privateinproc BOOLEAN

If true, creates an in-process event trace and enforces that only the process that registered a provider guid can start a trace with that guid. Unlike the -private option, processes need not be running in privileges accounts and up to three traces can be created. Default is false. Requires Vista or later.

-realtime BOOLEAN

If true, events are delivered to any subscribed consumers in real time when event buffers are flushed. Certain guidelines have to be followed when real time mode is requested. Please refer to Windows SDK ETW documentation. This option cannot be used with -private and -privateinproc. Default is false.

-secure BOOLEAN

If true, logging to the event trace requires the TRACELOG_LOG_EVENT permission. Default is false.Requires Vista or later.

-sequence SEQUENCETYPE

Events logged with the TraceMessage Windows API can contain a sequence number. If SEQUENCETYPE is none (default), no sequence number is added to the event. If SEQUENCETYPE is global, the added sequence number is global across multiple event traces and if local, it is unique to a trace.

-traceguid GUID

The GUID to assign to the event trace. If not specified, Windows will internally generate the GUID for the trace. The primary purpose for specifying this is to allow for setting access control on the trace.

For more details on the options, refer to the Windows SDK ETW documentation.

etw_stop_trace TRACE

Stops an event trace. The trace TRACE may be specified either by its name or by its handle (as returned by etw_start_trace).

The command returns a dictionary containing the stopped trace's status in the same format as etw_query_trace.

etw_update_trace TRACE ?options?

Updates the attributes associated with an event trace. If the trace is inactive (e.g. from a log files without an associated active trace), the command has no effect. The trace TRACE may be specified either by its name or by its handle (as returned by etw_start_trace). The command returns a dictionary containing a trace's settings and status in the same format as etw_query_trace. The following event trace attributes may be updated:

-enableflags FLAGS	Changes the enable flags for the event trace. Only applies if the trace is a "NT Kernel Logger" trace.
-flushtimer TIMERVAL	If non-0, changes the number of seconds after which buffers are automatically flushed.
-logfile FILEPATH	If specified, changes the log file associated with the trace.
-maxbuffers COUNT	If non-0, changes the maximum number of buffers that can be allocated for the trace.
-realtime BOOLEAN	If true, turns on realtime mode, else turns it off. Note if the command is called to update other options, and this option is not specified, it results in the real time mode being turned off.

ETW Provider Commands

This section describes the commands that allow implementation of an ETW provider.

etw_command_tracker HPROVIDER OLDNAME NEWNAME OP: Writes a CommandTrace event to the event trace associated with the provider handle HPROVIDER returned by etw_twapi_provider_register. The remaining arguments correspond to those passed to the callback function by Tcl's trace add command command. etw_command_tracker can be used as the callback similar to the example in Tcl ETW traces.
etw_execution_tracker HPROVIDER ARGS...: Writes a ExecutionTrace event to the event trace associated with the provider handle HPROVIDER returned by etw_twapi_provider_register. The remaining arguments correspond to those passed to the callback function by Tcl's trace add execution command. etw_execution_tracker can be used as the callback similar to the example in Tcl ETW traces.
etw_install_twapi_mof: Installs the TWAPI Managed Object Format (MOF) definition for the event trace formats used by TWAPI. This command needs to be called on the system where a ETW consumer will be parsing TWAPI logged events. The definition can be removed by calling etw_uninstall_twapi_mof.
etw_log_message HPROVIDER MESSAGE ?LEVEL?: Writes an event containing the MESSAGE string to the event trace attached to the provider handle HPROVIDER returned by etw_twapi_provider_register. LEVEL indicates the severity level at which the message is to be logged. LEVEL must be an integer or one of the following constants verbose (5), informational (4), warning (3), error (2) or fatal (1). By default, the message is logged at level 4 (informational).
etw_twapi_provider_register: Registers the TWAPI ETW provider so that it can be added to an event trace. The name and GUID corresponding to the provider can be retrieved through etw_twapi_provider_name and etw_twapi_provider_guid. These can then be passed to etw_enable_provider or any ETW controller program to add the TWAPI provider to a trace. Returns a handle to the registered provider.

The provider can be unregistered by calling the etw_unregister_provider command.
etw_twapi_eventclass_name: Returns the human readable name of the ETW event class used by etw_log_message.
etw_twapi_eventclass_guid: Returns the GUID of the ETW event class used by etw_log_message.
etw_twapi_provider_guid: Returns the GUID for the TWAPI ETW provider. This can be passed to etw_enable_provider or any ETW controller program to add the TWAPI provider to an event trace.
etw_twapi_provider_name: Returns the TWAPI ETW provider name.
etw_variable_tracker HPROVIDER NAME1 NAME2 OP: Writes a VariableTrace event to the event trace associated with the provider handle HPROVIDER returned by etw_twapi_provider_register. The remaining arguments correspond to those passed to the callback function by Tcl's trace add variable command and this command can be used as the callback as in the example in Tcl ETW traces.
etw_uninstall_twapi_mof: Uninstalls the TWAPI Managed Object Format (MOF) definition for the event trace formats used by TWAPI.
etw_unregister_provider PROVIDERHANDLE: Unregisters a previously registered provider. PROVIDERHANDLE is a handle returned by a previous call to etw_twapi_provider_register command.

ETW Consumer Commands

This section describes the commands that deal with consuming events from ETW.

etw_close_formatter FORMATTER

Closes and releases resources associated with a ETW formatter handle returned by a previous call to etw_open_formatter.

etw_dump_to_list LOGSOURCE ?LOGSOURCE ...?

Extracts events from one or more ETW log files or real time trace, returning them as a record array. Each LOGSOURCE argument must be the path to a ETW log file or the name of a ETW real time trace. At most one real time trace can be specified.

etw_dump_to_file ?options? ?LOGSOURCE LOGSOURCE ...?

Extracts events from one or more ETW log files or real time trace and writes them out in human readable form. Each LOGSOURCE argument must be the path to a ETW log file or the name of a ETW real time trace. At most one real time trace can be specified.

The command takes the following options:

-format FORMAT	Specifies the output format. FORMAT must be list or csv. The CSV format requires that the Tcl package csv be available.
-limit LIMIT	Stops after LIMIT events are written.
-output OUTPUT	Specifies where to write the events. OUTPUT may be a channel or a file path. If the latter, the file must not exist. The default is standard output.
-separator SEPARATOR	Specifies the separator character to use. Only used for CSV format. Defaults to the comma character.

Each record written consists of a fixed number of fields followed by event-specific data. The fixed fields include the time stamp, the thread id, the process id, the event's MOF class and the event name. The remaining fields are varying in number and consist of alternating pairs of the field name from the event's MOF definition and the corresponding value. If the MOF definition is not available, the field name is MofData and the corresponding value is a hexadecimal representation of the binary data.

etw_close_session HTRACE

Closes an event trace previously opened by a call to etw_open_file or etw_open_session.

etw_format_event_message FORMATSTRING EVENTPROPERTIES

Returns the message string constructed from FORMATSTRING by replacing the insert placeholders with the corresponding values from EVENTPROPERTIES. Normally, FORMATSTRING and EVENTPROPERTIES come from the message and properties fields returned by the etw_event command.

etw_format_events FORMATTER ?BUFDESC EVENTLIST...?

Processes the list of raw ETW events and returns a record array of formatted events. BUFDESC and EVENTLIST are the event buffer descriptor and the list of raw events for the event buffer as returned by etw_process_events or as passed to the -callback option of that command.

FORMATTER should be the handle to a formatter as returned by etw_open_formatter.

The command returns a recordarray with the fields in the table below. The recordarray commands can be used to access or transform the returned events. The value of a field may be the empty string if the logging application did not set it or if the field is not supported by the provider type.

-channel	The numeric identifier for the event log channel to which the event was logged.
-channelname	The name of the event log channel to which the event was logged.
-eventguid	The GUID identifying the event. For manifest based events, this is empty.
-eventid	The event identifier.
-kerneltime	The elapsed execution time for kernel-mode instructions in 100ns units. If the event was logged from a private trace, this will be 0 as all time will be counted towards -usertime.
-keywordmask	A bit mask corresponding to the keywords associated with the event.
-keywords	The list of keywords associated with the event.
-level	The numeric level at which the event was logged. Higher numeric levels are lower priority events.
-levelname	The name of the logging level at which the event was logged. Since this is localized, -level should be used for comparing event logging levels.
-message	The message associated with the event. This may contain string inserts for event parameters. Use the etw_format_event_message to retrieve the fully constructed message.
-opcode	The numeric opcode for the event, generally identifying one step in a sequence of operations.
-opcodename	The string name for the numeric opcode. For MOF based events, this is the event type.
-pid	The process identifier of the process that logged the event. This will be -1 if the event was not associated with any process.
-properties	A dictionary containing additional event parameters. The keys of the dictionary are dependent on the specific event type.
-providerguid	The GUID identifying the provider.
-providername	The name of the provider. For classical MOF based provider, this is the name of the MOF class.
-sid	The SID of the logging process or an empty string if not available.
-task	The numeric task identifying the general area within the application.
-taskname	The string name associated with task.
-tid	The thread identifier of the process that logged the event. This will be -1 if the event was not associated with any thread.
-timecreated	The time that the event was logged in system time format. Use large_system_time_to_secs_since_1970 to convert this to Tcl clock format.
-usertime	The elapsed execution time for user-mode instructions in 100ns units.
-version	The version of the event. Together with id, this identifies a specific event within a provider.

etw_open_file PATH

Opens a log file containing ETW events and returns a trace handle to it which can be passed to etw_process_events. The handle must be closed later by passing it to etw_close_session.

etw_open_formatter

Returns a handle to a ETW event formatter that can be passed to etw_format_events for formatting events. When no longer needed, the returned handle must be passed to etw_close_formatter so that associated resources may be released.

etw_open_session SESSIONNAME

Opens a real time ETW trace and returns a session handle to it which can be passed to etw_process_events. The handle must be closed later by passing it to etw_close_session.

etw_process_events ?-callback CALLBACK? ?-start STARTTIME? ?-end ENDTIME? HTRACE ?HTRACE...?

Processes events recorded in one or more event traces. The handles HTRACE are handles returned by etw_open_file or etw_open_session.

If -callback is not specified, the command returns a list consisting of alternative buffer descriptors and a raw event list. Each pair should be passed to etw_format_events which will in turn return a list of formatted events. If -callback is specified, the events are passed to the CALLBACK command prefix.

When ETW begins processing events, the callback is invoked repeatedly until there are no more unread events in the trace. On each invocation, two additional arguments are appended to the callback command prefix - the event buffer descriptor, and a list of raw event records. The callback should pass both these arguments to etw_format_events which in turn will return a record array of formatted events.

To terminate processing of events before all events from the traces are consumed, the callback can execute

return -code break

The options -start and -end can be specified to limit the time interval for which events are processed. Both STARTTIME and ENDTIME must be specified in the same format as get_system_time. You can use secs_since_1970_to_large_system_time to convert the format used by Tcl's clock command to this format.

Event Tracing

SYNOPSIS

DESCRIPTION