FTP ETW Tracing and IIS 8 - Part 2

Shortly after I published my FTP ETW Tracing and IIS 8 blog post, I was using the batch file from that blog to troubleshoot an issue that I was having with a custom FTP provider. One of the columns which I display in my results is Clock-Time, which is obviously a sequential timestamp that is used to indicate the time and order in which the events occurred.

(Click the following image to view it full-size.)

At first glance the Clock-Time values might appear to be a range of useless numbers, but I use Clock-Time values quite often when I import the data from my ETW traces into something like Excel and I need to sort the data by the various columns.

That being said, apart from keeping the trace events in order, Clock-Time isn't a very user-friendly value. However, LogParser has some great built-in functions for crunching date/time values, so I decided to update the script to take advantage of some LogParser coolness and reformat the Clock-Time value into a human-readable Date/Time value.

My first order of business was to figure out how to decode the Clock-Time value; since Clock-Time increases for each event, it is obviously an offset from some constant, and after a bit of searching I found that the Clock-Time value is the offset in 100-nanosecond intervals since midnight on January 1, 1601. (Windows uses that value in a lot of places, not just ETW.) Once I had that information, it was pretty easy to come up with a LogParser formula to convert the Clock-Time value into the local time for my system, which is much easier to read.

With that in mind, here is the modified batch file:

@echo off

rem ======================================================================

rem Clean up old log files
for %%a in (ETL CSV) do if exist "%~n0.%%a" del "%~n0.%%a"

echo Starting the ETW session for full FTP tracing...
LogMan.exe start "%~n0" -p "IIS: Ftp Server" 255 5 -ets
echo.
echo Now reproduce your problem.
echo.
echo After you have reproduced your issue, hit any key to close the FTP
echo tracing session. Your trace events will be displayed automatically.
echo.
pause>nul

rem ======================================================================

echo.
echo Closing the ETW session for full FTP tracing...
LogMan.exe stop "%~n0" -ets

rem ======================================================================

echo.
echo Parsing the results - this may take a long time depending on the size of the trace...
if exist "%~n0.etl" (
   TraceRpt.exe "%~n0.etl" -o "%~n0.csv" -of CSV
   LogParser.exe "SELECT [Clock-Time], TO_LOCALTIME(ADD(TO_TIMESTAMP('1601-01-01 00:00:00', 'yyyy-MM-dd hh:mm:ss'), TO_TIMESTAMP(DIV([Clock-Time],10000000)))) AS [Date/Time], [Event Name], Type, [User Data] FROM '%~n0.csv'" -i:csv -e 2 -o:DATAGRID -rtp 20
)

When you run this new batch file, it will display an additional "Date/Time" column with a more-informative value in local time for the sever where you captured the trace.

(Click the following image to view it full-size.)

The new Date/Time column is considerably more practical, so I'll probably keep it in the batch file that I use when I am troubleshooting. You will also notice that I kept the original Clock-Time column; I chose to do so because I will undoubtedly continue to use that column for sorting when I import the data into something else, but you can safely remove that column if you would prefer to use only the new Date/Time value.

That wraps it up for today's post. :-)