tracelog, UsePerfCounter and %4 in TRACE_FORMAT_PREFIX

NTDEV
1

Hi,

I am using WPP in my drivers. I like the ability of being about to stamp my Debug Messages with a 100 nanosecond timestamp. I use -UserPerfCounter which is default on Vista. I use -hires for tracefmt and then when I look at my txt file I have .xxxxxx numbers. I am trying to see the timescale for these with -UsePerfCounter for example here is a sample output.

[0]0000.0000::.611300 [filter] >>ENTER
[0]0000.0000::.614100 [filter] Irp->PendingReturned == TRUE
[0]0000.0000::.617200 [filter] DATA IoStatus.Information = 12
[0]0000.0000::.620000 [filter] plKey_Read = 0x1 0x800f040e 0x20
[0]0000.0000::.622500 [filter] return STATUS_CONTINUE_COMPLETION
[0]0000.0000::.659700 [filter] >>ENTER

This is just the standard TRACE_FORMAT_PREFIX. My question what is .611300 for example. Should I be seeing a full SystemTime with decimal part of a second out to 10-6 second.

2

Well in the interest of closure I have found that %5 does work with Perfcounter which is the default for tracelog. Note you have to use -hires for tracefmt and then the prefix variable %5 will have .xxxxxx which are 10 ^^-4 to 10^^-9. That is why 10^^-8 and 10^^9 are both 0 because tracefmt is using a clock that ticks to the nearest 10^^7. So if you wish to see the System Time you have to tracefmt without the -hires. There you get to the nearest millisecond. I found some other issues with tracelog / tracefmt / windbg also. At least this has an answer even it I must answer myself. Thanks Don and gurus.

3

Typo: All the exponents are negative. Sorry about that.