ETW Tracing using rusttrace crate

[codri]

Hi,

I've wired up rusttrace(https://github.com/flowerinthenight/rusttrace) crate in xi-win ui.
It's a small mess to setup(can make a powershell script to automate it), but can be handy for debugging, in absence of println!, also ETW events can be used by tools like perfview for profiling.

Was wondering if you see any value in a pull request for this, if not so I could avoid the trouble of signing google license agreements.

Here's an example trace as displayed in the command line by mftrace.

Listening to ETW events (CTRL+C to end)
           __M_F_T_R_A_C_E___LOG__

PID, TID    Time (UTC)    TraceMessage
--------- --------------  ------------
19264,5614 20:26:32.28073 RustTrace Generic @xi-win-ui
19264,5614 20:26:32.32400 RustTrace Generic @Request {"method":"client_started","params":{}}
19264,5614 20:26:32.32405 RustTrace Generic @Request {"id":0,"method":"new_view","params":{}}
19264,3F9C 20:26:32.36444 RustTrace Generic @Response {"method":"available_themes","params":{"themes":["InspiredGitHub","Solarized (dark)","Solarized (light)","base16-eighties.dark","base16-mocha.dark","base16-ocean.dark","base16-ocean.light"]}}
19264,3F9C 20:26:32.36506 RustTrace Generic @Response {"id":0,"result":"view-id-1"}
19264,3F9C 20:26:32.36515 RustTrace Generic @Response {"method":"available_plugins","params":{"plugins":[],"view_id":"view-id-1"}}
19264,3F9C 20:26:32.36545 RustTrace Generic @Response {"method":"config_changed","params":{"changes":{"auto_indent":false,"font_face":"InconsolataGo","font_size":14,"line_ending":"\r\n","plugin_search_path":[],"scroll_past_end":false,"tab_size":4,"translate_tabs_to_spaces":true,"use_tab_stops":true,"wrap_width":0},"view_id":"view-id-1"}}
19264,3F9C 20:26:32.36580 RustTrace Generic @Response {"method":"update","params":{"update":{"ops":[{"lines":[{"cursor":[0],"styles":[],"text":""}],"n":1,"op":"ins"}],"pristine":true},"view_id":"view-id-1"}}
19264,3F9C 20:26:32.36585 RustTrace Generic @Response {"method":"scroll_to","params":{"col":0,"line":0,"view_id":"view-id-1"}}
19264,5614 20:26:35.02702 RustTrace Generic @Request {"method":"edit","params":{"method":"insert","params":{"chars":"a"},"view_id":"view-id-1"}}
19264,3F9C 20:26:35.02806 RustTrace Generic @Response {"method":"update","params":{"update":{"ops":[{"lines":[{"cursor":[1],"styles":[],"text":"a"}],"n":1,"op":"ins"}],"pristine":false},"view_id":"view-id-1"}}
19264,3F9C 20:26:35.02812 RustTrace Generic @Response {"method":"scroll_to","params":{"col":1,"line":0,"view_id":"view-id-1"}}
19264,5614 20:26:36.15279 RustTrace Generic @Request {"method":"edit","params":{"method":"insert_newline","params":[],"view_id":"view-id-1"}}
19264,3F9C 20:26:36.15366 RustTrace Generic @Response {"method":"update","params":{"update":{"ops":[{"lines":[{"styles":[],"text":"a\r\n"},{"cursor":[0],"styles":[],"text":""}],"n":2,"op":"ins"}],"pristine":false},"view_id":"view-id-1"}}
19264,3F9C 20:26:36.15371 RustTrace Generic @Response {"method":"scroll_to","params":{"col":0,"line":1,"view_id":"view-id-1"}}
19264,5614 20:26:36.91523 RustTrace Generic @Request {"method":"edit","params":{"method":"delete_backward","params":[],"view_id":"view-id-1"}}
19264,3F9C 20:26:36.91603 RustTrace Generic @Response {"method":"update","params":{"update":{"ops":[{"lines":[{"cursor":[1],"styles":[],"text":"a"}],"n":1,"op":"ins"}],"pristine":false},"view_id":"view-id-1"}}
19264,3F9C 20:26:36.91623 RustTrace Generic @Response {"method":"scroll_to","params":{"col":1,"line":0,"view_id":"view-id-1"}}
19264,5614 20:26:37.50286 RustTrace Generic @Request {"method":"edit","params":{"method":"delete_backward","params":[],"view_id":"view-id-1"}}
19264,3F9C 20:26:37.50363 RustTrace Generic @Response {"method":"update","params":{"update":{"ops":[{"lines":[{"cursor":[0],"styles":[],"text":""}],"n":1,"op":"ins"}],"pristine":true},"view_id":"view-id-1"}}
19264,3F9C 20:26:37.50369 RustTrace Generic @Response {"method":"scroll_to","params":{"col":0,"line":0,"view_id":"view-id-1"}}
19264,5614 20:26:38.98490 RustTrace Generic @cleanup

[LiHRaM]

Hey Codri - were you able to receive logging information from the core as well? I'm mostly interested in the errors, as currently they are ignored, but this might be a useful solution. (See #60)
Also, the CLA is no longer necessary. :)

[codri]

Hey @LiHRaM ,

No, I didn't wire it up for core. Only for requests/responses going from/into xi-win.
I was thinking about the whole state of xi logging, and tracing, as well as how to integrate with etw.
Here are a few notes/toughts:

1. There already seems to be an effort to add logging to xi-editor. see Real logging in xi-core (+ core RPC logging) xi-editor#408 but, this is not quite what etw can provide, since etw can be used for performance tracing and can be enabled/disabled on runtime, with it being zero cost when not enabled.
2. The library mentioned above(rusttrace) does only string tracing for etw, which is not ideal, etw has the concept of structured logging, which is more flexible and performant. For example, for the xi-rpc method one can define an enum, and not collect redundant strings, which will impact perf test more than collecting an integer would.
3. I've investigated using win32 rust bindings to do structured logging into etw. I guess it would end up looking a lot like lttng tracing client for rust https://docs.rs/lttng-ust-generate/0.1.1/lttng_ust_generate/
4. LTTng and ETW are very similar conceptually, maybe it's worth making a structured logging/tracing library that uses ETW on Windows and LTTng on Linux. Not sure it makes sense respecting the log interface, as that is mainly for string logging.
5. ETW has a series of modes to do logging, in one you specify a XML template(if I remember correctly) defining the schema of your logger, which is messy. There is another mode where you use system calls to register event schema on startup, and the client can ask the OS to get it for a certain process. The latter I think is the way to go.

So, long story short, ETW and LTTng are interesting pieces of technology, can be a great fit for high performance crossplatform tracing. But, I'm yet to make the thin wrapper library that can log into both.