RSDK-13768 Support Event Tracing for Windows (ETW) to improve logging performance

[EvanDorsky]

Background

Motivation for this PR was to speed up logging on Windows, which was found to be very slow on some Kongsberg machines (occasionally taking over 1 second for a single log line).

It looks like @aldenh-viam's fixes addressed whatever was causing these excessively slow logs, but the new ETW-based path for logging is still more modern and more performant than the old Event Logger path.

Changes

Windows now logs by default using the ETW path instead of the Event Logging path. Event Logging will still be used as a fallback if ETW fails to initialize.

ETW works differently from Event Logging. With ETW, there are two steps required to write logs to disk:

1. The application that will emit logs registers a trace provider (with a GUID) which it will send logs to.
2. A trace session must subscribe to the trace provider. The trace session receives the logs and can write them to disk.

If there is no trace session for a given provider, logs are just thrown away.

In this implementation, viam-server manages the trace session itself by making calls to logman, a mercifully straightforward tool for managing ETW subscribers. This is the lifecycle:

1. On startup, register the log provider viam-server with the GUID 66AFF7FE-2451-47AA-A0E3-8E3D2E432B30
2. Check for any existing ETW sessions named viam-server-trace and kill them
3. Create a new ETW session subscribed to viam-server called viam-server-trace
4. On shutdown, kill any ETW sessions called viam-server-trace.

Log retention and rotation

logman writes logs to disk in the default log directory $VIAM_HOME/logs into files named viam-server-trace-YYYY-MM-DDThh-mm-ss.etl.

A new .etl file is created every time viam-server is launched, and each .etl file has a 128 MB maximum size (a change from Event Logging which has a default 20 MB limit). If an individual file reaches the size limit, logs will begin to roll over in a circular manner with the newest logs replacing the oldest logs.

On startup, viam-server checks the disk usage of all .etl files in the logs folder. If the total usage is above the limit of 384 MB, it will delete log files (starting with the oldest) until total usage is below the limit.

I chose this strategy because logman offers two write modes - circular mode and append mode - which cannot be combined. Circular mode always overwrites an existing file, and append mode will just stop logging when the file reaches its size limit.

With this strategy:

• maximum filesystem usage is capped at ~512 MB (128 + 384)
• many past runs can be retained as long as the logs are not too loud
• in the worst case, with very loud logging, the past 4 runs will still be retained
• the implementation was fairly straightforward
• logs should never be dropped during a run, because rotation only happens at startup

The default values were just chosen by me so I'm very open to changing them, or changing the strategy if there's something that would better fit the use cases for local logs.

Viewing ETW logs

PerfView can be used to collect and view ETW traces.

Also, web/cmd/winlogproc, provided here, can be used to convert .etl traces into friendlier .tsv files for inspection / automated processing:

go run .\web\cmd\winlogproc

This command will pull the latest Event Logging logs and ETW logs into your current directory, and process them into sorted .tsv files. There are arguments for specifying the time window of logs to pull.

Performance improvements

Trace logging seems less likely to have instances of "really slow logs" (max log duration is called out with the vertical dotted lines)

Aside from that, baseline performance looks slightly improved. These plots were made with logs from two separate runs of viam-server, one with only ETW logging enabled and one with only Event Logging enabled. The machine config was otherwise the same, a modified kongsberg config with a log duration tester.

Testing

There are some new tests for the ETW logger along the same lines as the existing EventLogger test.

There is also an e2e test (currently gated behind the etw_e2e flag) that stands up a server, logs both Event Logging and ETW logs, and then pulls the logs and compares them line-by-line. I used this test while developing but then flagged it out, mostly because there's no way right now to run both Event Logging and ETW logs at the same time so the test is guaranteed to fail.

Future work

ETW has a bunch of other features that we could start using to do very detailed performance characterization in Windows, at least in viam-server. It shouldn't be too hard to add them now that the scaffolding is in.

Other paths considered

I prototyped a NetAppender-style queue for logging with Event Logging and found that this actually made logging slightly slower, so I abandoned that path.

[aldenh-viam]

Code LGTM assuming fully tested 🪟

cc @dgottlieb who set up the original Event Logger infra for RDK (#4713)

Should we consider doing the same in Agent, so we don't have Agent logging to the Event Logger only and RDK logging to ETW only?

These plots were made with logs from two separate runs of viam-server, one with only ETW logging enabled and one with only Event Logging enabled.

Why does the 1st plot have both blue (eventlog.tsv) & orange (trace.tsv)?

[dgottlieb]

Should we consider doing the same in Agent, so we don't have Agent logging to the Event Logger only and RDK logging to ETW only?

I'm unfamiliar with these windows APIs and whether there are more interesting constraints, but yes. I'd expect both to log to the same thing.

[EvanDorsky]

Ah good point, I'll see what it takes to migrate agent to this.

Why does the 1st plot have both blue (eventlog.tsv) & orange (trace.tsv)?

That's my fault, the plots are hard to interpret - both plots have data from eventlog and trace, but they're really quite close, so they overlap and it looks like there's only data from trace since it plots on top. If you zoom in really close on the second plot, you can see that eventlog (blue) has a slightly longer tail than trace:

On the first plot it's obvious that there's data from both log types because I put vertical lines by the min and max value for each - which shows that the slowest log for eventlog is slower than for trace.