Consolidate and clean up all API logging #15737

DHowett · 2023-07-20T22:44:43Z

s_TraceApi was a magic function in Tracing that logged a different
event based on what type it was called with. It was bad for two reasons:

I wanted to add a field to each trace indicating the originating
process and thread. This would have required adding a CONSOLE_API_MSG
parameter to every instance of s_TraceApi, and even then it would
have not been particularly consistent.
The design of Tracing, where the TraceLogging macros are hidden
inside opaque functions, subverts the lightweight trace probe detection
present in TraceLoggingWrite. Every tracing probe turned into a call
to a cold function which, in 99% of cases, returned immediately.

To that end, I've introduced a new macro only to ApiDispatchers that
emits a named probe with a set of preloaded information. It is a macro
to avoid any unnecessary branching or the emission of any explicit
tracing functions into the final binary.

I have also removed the generic handler for timing any/all API calls, as
we never used them and they were largely redundant with the information
we were capturing from API-specific reports.

I've also removed tracing from all APIs that do not mutate console
state. With the notable exception of ReadConsoleInput, we will see logs
only for things that change mutable console state.

All these things together allows us to construct a process+API-focused
timeline of console events, ala:

cmd.exe (20304)   CookedRead          pwsh                4                07/13/2023 22:02:53.751
cmd.exe (20304)   API_GetConsoleMode  True
cmd.exe (20304)   API_SetConsoleMode  False               0x00000003
cmd.exe (20304)   API_SetConsoleMode  True                0x000001F7
pwsh.exe (4032)   ConsoleAttachDetach 07/13/2023 22:03:17.393              True                True
pwsh.exe (4032)   API_GetConsoleMode  False
pwsh.exe (4032)   API_GetConsoleMode  False
pwsh.exe (4032)   API_SetConsoleMode  False               0x00000007

This pull request also switches the ConsoleAttachDetach and CookedRead
reports to use the PID and FILETIME markings for their pids and
filetimes. This is compatible with the uint32 and uint64 fields that
used to use those names, so anybody who was depending on them will
experience no change in functionality.

I also switched up their order to make them more ergonomic in WPA when
combined with the other API_ tracing (as viewed above.)

`s_TraceApi` was a magic function in Tracing that logged a different event based on what type it was called with. It was bad for two reasons: 1. I wanted to add a field to each trace indicating the originating process and thread. This would have required adding a `CONSOLE_API_MSG` parameter to _every instance_ of `s_TraceApi`, and even then it would have not been particularly consistent. 2. The design of Tracing, where the TraceLogging macros are hidden inside opaque functions, subverts the lightweight trace probe detection present in `TraceLoggingWrite`. Every tracing probe turned into a call to a cold function which, in 99% of cases, returned immediately. To that end, I've introduced a new macro _only_ to ApiDispatchers that emits a named probe with a set of preloaded information. It is a macro to avoid any unnecessary branching or the emission of any explicit tracing functions into the final binary. I have also removed the generic handler for timing any/all API calls, as we never used them and they were largely redundant with the information we were capturing from API-specific reports. I've also removed tracing from all APIs that do not mutate console state. With the notable exception of ReadConsoleInput, we will see logs only for things that change mutable console state. All these things together allows us to construct a process+API-focused timeline of console events, ala: ``` cmd.exe (20304) CookedRead pwsh 4 07/13/2023 22:02:53.751 cmd.exe (20304) API_GetConsoleMode True cmd.exe (20304) API_SetConsoleMode False 0x00000003 cmd.exe (20304) API_SetConsoleMode True 0x000001F7 pwsh.exe (4032) ConsoleAttachDetach 07/13/2023 22:03:17.393 True True pwsh.exe (4032) API_GetConsoleMode False pwsh.exe (4032) API_GetConsoleMode False pwsh.exe (4032) API_SetConsoleMode False 0x00000007 ```

They were originally using uint32/64, which did not allow for tools like WPA to infer their connection to processes and dates. I cleared this with David Kaplan, as he is relying on those events.

DHowett · 2023-07-20T22:46:11Z

src/server/ApiDispatchers.cpp

+    TraceLoggingWrite(                                    \
+        g_hConhostV2EventTraceProvider,                   \
+        "API_" ApiName,                                   \
+        TraceLoggingPid([&] { const auto p=m->GetProcessHandle(); return p ? p->dwProcessId : 0; }(), "OriginatingProcess"), \


These could be lifted out if reviewers desire.

I personally would prefer that. This will produce a unique lambda instance per macro invocation which then might get folded into a single instance in Release builds if the compiler realizes they're all the same assembly. But I believe it's safer if we add free-standing TraceGetProcessId and TraceGetThreadId functions instead that take a CONSOLE_API_MSG* and put them above the macro. It would also make compilation a teeny tiny bit cheaper.

(We could also add them as member functions to CONSOLE_API_MSG, but I would greatly prefer if we moved CONSOLE_API_MSG back to being a trivial class. I'm really not sure if the "writing data off the end of the class" thing is legal C++ when the struct is non-trivial and I'd rather not tempt fate. 😓)

I switched to functions. Trust me, the CONSOLE_API_MSG class gives me the ABSOLUTE willies

src/server/ApiDispatchers.cpp

lhecker · 2023-07-21T16:21:15Z

src/server/ApiDispatchers.cpp

+                                  TraceLoggingInt32(a->CurrentWindowSize.X, "WindowWidthInChars"),
+                                  TraceLoggingInt32(a->CurrentWindowSize.Y, "WindowHeightInChars"),


nit 1: These have a different name than the actual fields.

nit 2: Technically these are Int16 right? We can improve the way COORDs are formatted in traces if we use TraceLoggingStruct here. If we add a new macro like TraceLoggingConsoleCoord that abstracts this away, I think it might look pretty neat. Something like

#define TraceLoggingConsoleCoord(value, name) \ TraceLoggingStruct(2, name), \ TraceLoggingInt16(value.X, "X"), \ TraceLoggingInt16(value.Y, "Y")

Alternatively, we could also use TraceLoggingInt16FixedArray(&a->CurrentWindowSize, "CurrentWindowSize").

nit 3: People depend on our trace logs and we can't change their names? 😟

Ugh, these names, types and values were ported directly from the original tracing.cpp code. We can definitely change them. I like T.L.Struct.

The only logs people are depending on are CookedRead and ConsoleAttachDetach. The rest, we can blow up any way we wish.

DONE LOOKS GREAT

`s_TraceApi` was a magic function in Tracing that logged a different event based on what type it was called with. It was bad for two reasons: 1. I wanted to add a field to each trace indicating the originating process and thread. This would have required adding a `CONSOLE_API_MSG` parameter to _every instance_ of `s_TraceApi`, and even then it would have not been particularly consistent. 2. The design of Tracing, where the TraceLogging macros are hidden inside opaque functions, subverts the lightweight trace probe detection present in `TraceLoggingWrite`. Every tracing probe turned into a call to a cold function which, in 99% of cases, returned immediately. To that end, I've introduced a new macro _only_ to ApiDispatchers that emits a named probe with a set of preloaded information. It is a macro to avoid any unnecessary branching or the emission of any explicit tracing functions into the final binary. I have also removed the generic handler for timing any/all API calls, as we never used them and they were largely redundant with the information we were capturing from API-specific reports. I've also removed tracing from all APIs that do not mutate console state. With the notable exception of ReadConsoleInput, we will see logs only for things that change mutable console state. All these things together allows us to construct a process+API-focused timeline of console events, ala: ``` cmd.exe (20304) CookedRead pwsh 4 07/13/2023 22:02:53.751 cmd.exe (20304) API_GetConsoleMode True cmd.exe (20304) API_SetConsoleMode False 0x00000003 cmd.exe (20304) API_SetConsoleMode True 0x000001F7 pwsh.exe (4032) ConsoleAttachDetach 07/13/2023 22:03:17.393 True True pwsh.exe (4032) API_GetConsoleMode False pwsh.exe (4032) API_GetConsoleMode False pwsh.exe (4032) API_SetConsoleMode False 0x00000007 ``` This pull request also switches the ConsoleAttachDetach and CookedRead reports to use the PID and FILETIME markings for their pids and filetimes. This is compatible with the uint32 and uint64 fields that used to use those names, so anybody who was depending on them will experience no change in functionality. I also switched up their order to make them more ergonomic in WPA when combined with the other API_ tracing (as viewed above.) (cherry picked from commit 5daf498) Service-Card-Id: 90012630 Service-Version: 1.17

`s_TraceApi` was a magic function in Tracing that logged a different event based on what type it was called with. It was bad for two reasons: 1. I wanted to add a field to each trace indicating the originating process and thread. This would have required adding a `CONSOLE_API_MSG` parameter to _every instance_ of `s_TraceApi`, and even then it would have not been particularly consistent. 2. The design of Tracing, where the TraceLogging macros are hidden inside opaque functions, subverts the lightweight trace probe detection present in `TraceLoggingWrite`. Every tracing probe turned into a call to a cold function which, in 99% of cases, returned immediately. To that end, I've introduced a new macro _only_ to ApiDispatchers that emits a named probe with a set of preloaded information. It is a macro to avoid any unnecessary branching or the emission of any explicit tracing functions into the final binary. I have also removed the generic handler for timing any/all API calls, as we never used them and they were largely redundant with the information we were capturing from API-specific reports. I've also removed tracing from all APIs that do not mutate console state. With the notable exception of ReadConsoleInput, we will see logs only for things that change mutable console state. All these things together allows us to construct a process+API-focused timeline of console events, ala: ``` cmd.exe (20304) CookedRead pwsh 4 07/13/2023 22:02:53.751 cmd.exe (20304) API_GetConsoleMode True cmd.exe (20304) API_SetConsoleMode False 0x00000003 cmd.exe (20304) API_SetConsoleMode True 0x000001F7 pwsh.exe (4032) ConsoleAttachDetach 07/13/2023 22:03:17.393 True True pwsh.exe (4032) API_GetConsoleMode False pwsh.exe (4032) API_GetConsoleMode False pwsh.exe (4032) API_SetConsoleMode False 0x00000007 ``` This pull request also switches the ConsoleAttachDetach and CookedRead reports to use the PID and FILETIME markings for their pids and filetimes. This is compatible with the uint32 and uint64 fields that used to use those names, so anybody who was depending on them will experience no change in functionality. I also switched up their order to make them more ergonomic in WPA when combined with the other API_ tracing (as viewed above.) (cherry picked from commit 5daf498) Service-Card-Id: 90012631 Service-Version: 1.18

DHowett added 2 commits July 14, 2023 13:42

Switch ConsoleAttach and CookedRead to use PID and FILETIME

8a4ee04

They were originally using uint32/64, which did not allow for tools like WPA to infer their connection to processes and dates. I cleared this with David Kaplan, as he is relying on those events.

DHowett commented Jul 20, 2023

View reviewed changes

lhecker approved these changes Jul 21, 2023

View reviewed changes

DHowett added 2 commits July 21, 2023 12:17

Switch to TraceGet(Process|Thread)Id

213c318

Reformat TraceConsoleAPICall/s, add TraceLoggingConsoleCoord

9dac590

carlos-zamora approved these changes Jul 21, 2023

View reviewed changes

lhecker added the AutoMerge Marked for automatic merge by the bot when requirements are met label Jul 21, 2023

microsoft-github-policy-service bot merged commit 5daf498 into main Jul 21, 2023
16 checks passed

microsoft-github-policy-service bot deleted the dev/duhowett/trace-it-better-move-it-faster branch July 21, 2023 19:00

DHowett added this to To Cherry Pick in 1.17 Servicing Pipeline via automation Jul 27, 2023

DHowett added this to To Cherry Pick in 1.18 Servicing Pipeline via automation Jul 27, 2023

DHowett moved this from To Cherry Pick to Cherry Picked in 1.17 Servicing Pipeline Jul 27, 2023

DHowett moved this from To Cherry Pick to Cherry Picked in 1.18 Servicing Pipeline Jul 27, 2023

DHowett moved this from Cherry Picked to Validated in 1.17 Servicing Pipeline Aug 2, 2023

DHowett moved this from Cherry Picked to Validated in 1.18 Servicing Pipeline Sep 25, 2023

DHowett moved this from Validated to Shipped in 1.18 Servicing Pipeline Oct 26, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Consolidate and clean up all API logging #15737

Consolidate and clean up all API logging #15737

DHowett commented Jul 20, 2023 •

edited

DHowett Jul 20, 2023

lhecker Jul 21, 2023

DHowett Jul 21, 2023

lhecker Jul 21, 2023 •

edited

DHowett Jul 21, 2023

DHowett Jul 21, 2023

		TraceLoggingInt32(a->CurrentWindowSize.X, "WindowWidthInChars"),
		TraceLoggingInt32(a->CurrentWindowSize.Y, "WindowHeightInChars"),

Consolidate and clean up all API logging #15737

Consolidate and clean up all API logging #15737

Conversation

DHowett commented Jul 20, 2023 • edited

DHowett Jul 20, 2023

Choose a reason for hiding this comment

lhecker Jul 21, 2023

Choose a reason for hiding this comment

DHowett Jul 21, 2023

Choose a reason for hiding this comment

lhecker Jul 21, 2023 • edited

Choose a reason for hiding this comment

DHowett Jul 21, 2023

Choose a reason for hiding this comment

DHowett Jul 21, 2023

Choose a reason for hiding this comment

DHowett commented Jul 20, 2023 •

edited

lhecker Jul 21, 2023 •

edited