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) 61 % trace add execution p {enter enterstep leave leavestep} [list ::http::geturl $hprov]
unknown command "p"
(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.

<<categories>>Debugging | Windows