Event Tracing for Windows

Windows provides a facility, Event Tracing for Windows (ETW), for tracing system and application execution similar to DTrace on Solaris.

Using TWAPI (4.0b50 or later) it is possible to both control, analyse and participate in these traces from script. Below is a simple example that traces through a http::geturl call that shows the script execution comingled with the actual network events at the system level.

First we generate a trace file from a http::geturl call. To do this, we need to register as a trace provider.

(tcl) 57 % package require http
2.8.5
(tcl) 58 % set hprov [etw_twapi_provider_register]
19421773398204560

Then we start the actual trace and add ourselves as well as the kernel network component to it. We also Tcl's standard trace execution mechanism to trace the script.

(tcl) 59 % set htrace [twapi::etw_start_trace MyHttpTrace -logfile http.etl]
16
(tcl) 60 % twapi::etw_enable_provider $htrace [twapi::etw_twapi_provider_guid] -1 5
(tcl) 62 % trace add execution ::http::geturl {enter enterstep leave leavestep} [list ::twapi::etw_execution_tracker $hprov]
(tcl) 63 % twapi::etw_enable_provider $htrace Microsoft-Windows-Kernel-Network 0x10 5

Now run the command and then stop the trace.

(tcl) 64 % http::geturl http://www.google.com
::http::1
(tcl) 65 % etw_stop_trace $htrace
logfile {C:\src\twapi\twapi\tcl\http.etl} trace_name MyHttpTrace trace_guid {{8B5576C2-BB33-11E3-BEF3-81AE96BEBD84}} buffer_size 64 min_buffers 8 max_buffers 30 max_file_size 1 logfile_mode 4194306 flush_timer 0 enable_flags 0 clock_resolution 2 age_limit 0 buffer_count 9 free_buffers 9 events_lost 0 buffers_written 8 log_buffers_lost 0 real_time_buffers_lost 0 logger_tid 7012

Now we dump the trace in kind of human-readable form. Prettying this up is left to interested parties as etw_dump_to_file is really just a test script. An application would use underlying calls to get the trace events in list form and process / print them as it wishes.

(tcl) 66 % etw_install_twapi_mof
(tcl) 67 % etw_dump_to_file -output http.txt -fields {-timecreated -taskname -opcodename -properties} http.etl

The output looks like the following (with many lines removed)

130410917799024641,0,ExecutionTrace,Operation enter Command {{http::geturl http://www.google.com}} Code {{}} Result {{}} Context {{}}
130410917799024641,0,ExecutionTrace,Operation enterstep Command {{variable http}} Code {{}} Result {{}} Context {{http::geturl http://www.google.com}}
....
130410917800274686,KERNEL_NETWORK_TASK_TCPIP,Connection attempted.,PID 6780 size 0 daddr 74.125.236.80 saddr 192.168.1.128 dport 80 sport 17371 mss 1430 sackopt 1 tsopt 0 wsopt 1 rcvwin 65780 rcvwinscale 8 sndwinscale 6 seqnum 0 connid 0
....
130410917801055852,0,ExecutionTrace,Operation leavestep Command {{info exists state(status)}} Code 0 Result 1 Context {{wait ::http::1}}
130410917801055852,0,ExecutionTrace,Operation enterstep Command {{vwait ::http::1(status)}} Code {{}} Result {{}} Context {{wait ::http::1}}
130410917801368380,KERNEL_NETWORK_TASK_TCPIP,Data sent.,PID 6780 size 187 daddr 74.125.236.80 saddr 192.168.1.128 dport 80 sport 17371 startime 1015872 endtime 1015872 seqnum 0 connid 0
130410917801368380,KERNEL_NETWORK_TASK_TCPIP,Data received.,PID 6780 size 542 daddr 74.125.236.80 saddr 192.168.1.128 dport 80 sport 17371 seqnum 0 connid 0
130410917801368380,0,ExecutionTrace,Operation leavestep Command {{tkcon_tcl_gets sock756 state(http)}} Code 0 Result 18 Context {{http::Event sock756 ::http::1}}
130410917801368380,0,ExecutionTrace,Operation leavestep Command {{uplevel 1 tkcon_tcl_gets {sock756 state(http)}}} Code 0 Result 18 Context {{::tkcon_gets sock756 state(http)}}
....
130410917802149649,0,ExecutionTrace,Operation enterstep Command {{return ::http::1}} Code {{}} Result {{}} Context {{http::geturl http://www.google.com}}
130410917802149649,0,ExecutionTrace,Operation leavestep Command {{return ::http::1}} Code 2 Result ::http::1 Context {{http::geturl http://www.google.com}}
130410917802149649,0,ExecutionTrace,Operation leave Command {{http::geturl http://www.google.com}} Code 0 Result ::http::1 Context {{}}
130410917802462189,KERNEL_NETWORK_TASK_TCPIP,Disconnect issued.,PID 6780 size 0 daddr 74.125.236.80 saddr 192.168.1.128 dport 80 sport 17371 seqnum 0 connid 0

Note you could of course do the script tracing using just trace execute but like DTrace, ETW allows you to trace through execution paths that are a combination of script, kernel operations and even multiple applications.

Category Debugging

Category Windows