How to extract Processor Number field for Syscall/Cswitch events?

[phil-stumpy]

I've been testing the Kernel Trace "syscall" event provider as follows:

logman start "NT Kernel Logger" -p "Windows Kernel Trace" (syscall,cswitch) -o systemevents.etl -ets
tracerpt systemevents.etl -o systemevents.csv -of CSV

The output from tracerpt indicates that the "syscall" and "cswitch" events include a "Processor Number" property somewhere within the event data. I've tried creating a "syscall" trace via krabsetw, but I can't seem to find a way to extract the "Processor Number" property - am I missing something obvious, or has this not been implemented within krabsetw?

[phil-stumpy]

So a bit of further digging seems to show that there is a "Processor ID" field, within the ETW event execution parameters? The "Process ID" and "Thread ID" fields are also part of these execution parameters, but the "Processor ID" field doesn't appear to be extracted anywhere?

[phil-stumpy]

Sorry to keep replying to my own question 😉 So there is a "ProcessorNumber" attribute within the ETW_BUFFER_CONTEXT. I tried printing this value out, for syscall events, on a dual-core VM but the value was always zero. When testing using logman, on the same VM and for syscall events, the "Processor Number" attribute varied between one and zero (as expected).

[zacbrown]

Interesting - I'll take a look at the provider today and see if I can get you some clarity.

[phil-stumpy]

Awesome, thanks a lot 😁 I'll try and run a few more tests myself, and see if I can make any sense of it.

[zacbrown]

Just a heads up - didn't forget about you but work is a bit busy right now. It may take me a bit to look into this.

If you can provide me with the full sample code, that will speed things up for me.

[phil-stumpy]

Tracer.cpp.txt
Sorry for the delay in responding - been a bit busy here myself, so totally understand :-)

Sample code is attached.

[zacbrown]

Hi @phil-stumpy - I tried out your sample and was able to reproduce the behaviour you saw.

I'm unable to understand why the BufferContext struct appears to be in a weird state. I'm going to try writing a sample from scratch just using TDH APIs and see if I can still reproduce.

If I still can't get sensible data out of the BufferContext struct, then I'll reach out with some other folks and see what I can learn.

[phil-stumpy]

Glad it's not just me going mad 😀

Thanks for all your help on this, and hopefully you'll be able to find out where the confusion is.

[zacbrown]

Hi- haven’t forgotten about you. Fighting with some code to see if I can sort out what’s going on.

I suspect there’s a flag missing when we initialize ETW but I’ve yet to figure out what that flag is.

-Zac

[phil-stumpy]

Hi Zac, thanks for keeping in touch - hope you manage to find the missing flag 😀 It's going to be really handy, from a monitoring perspective, to help associate system calls with a process.

Phil

[zacbrown]

Hey,

I still haven’t managed to get the processor number to be sane even when not using krabs. I’m gonna reach out to some folks at MSFT and see if I can get some clarity.

-Zac

[phil-stumpy]

Hi Zac,

Thanks for keeping in touch - I'll keep my fingers crossed that the guys at MSFT can figure out what's going on.

Cheers,

Phil

[swannman]

I did a bit of research and I think this occurs because we set EVENT_TRACE_NO_PER_PROCESSOR_BUFFERING in nightmare.hpp.

MSDN says "Note that if you use the EVENT_TRACE_NO_PER_PROCESSOR_BUFFERING logging mode, the number of processors is assumed to be 1."

Does this still occur if we remove the EVENT_TRACE_NO_PER_PROCESSOR_BUFFERING flag?

[phil-stumpy]

That sounds promising - I'll test it out as soon as I can, and let you know how I get on.

Phil

[phil-stumpy]

So I noticed that I'm using the NuGet package for krabsetw, which appears to be somewhat behind the latest Git repo? I'll try modifying my build to work from the latest Git repo and see how far I get with that.

Phil

[swannman]

Sounds good Phil. My plan is to update the Nuget once #41 is closed.

[zacbrown]

Will we need a code change to expose that setting? It should be a default override ideally - don’t want to change default behavior of the library.

[phil-stumpy]

I tried removing the EVENT_TRACE_NO_PER_PROCESSOR_BUFFERING flag from nightmare.hpp

Unfortunately I still only appear to be receiving Processor Index/Number 0, for all syscall events. I was trying to stress the CPU at the time, so I would've expected to see syscall from different processors, but it is possible that the stressing wasn't working as I expected.

[jdu2600]

FWIW -
The Microsoft.Diagnostics.Tracing.TraceEvent .NET library seems to correctly return the processor number.
e.g. https://gist.github.com/jdu2600/a0898230dcb212c5e670a4d6fc0c4ad7

I believe that the EVENT_TRACE_PROPERTIES that they use are here -
https://github.com/microsoft/perfview/blob/master/src/TraceEvent/TraceEventSession.cs#L2123

[jdu2600]

This works for me?

I used the branch for #80 to remove the EVENT_TRACE_NO_PER_PROCESSOR_BUFFERING flag and started getting non-zero ProcessorNumbers.

I had to remember to manually add the EVENT_TRACE_SYSTEM_LOGGER_MODE flag though. We might want to still add this by default.

[swannman]

Closing this since we've merged #80 which makes this configurable.