Consolidate and clean up all API logging (#15737)

`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.)

src/host/tracing.cpp

@@ -18,7 +18,7 @@ enum TraceKeywords
     Output = 0x008, // _DBGOUTPUT
     General = 0x100,
     Input = 0x200,
-    API = 0x400,
+    //API = 0x400, // No longer used
     UIA = 0x800,
     CookedRead = 0x1000,
     ConsoleAttachDetach = 0x2000,
@@ -26,241 +26,8 @@ enum TraceKeywords
 };
 DEFINE_ENUM_FLAG_OPERATORS(TraceKeywords);
 
-// Routine Description:
-// - Creates a tracing object to assist with automatically firing a stop event
-//   when this object goes out of scope.
-// - Give it back to the caller and they will release it when the event period is over.
-// Arguments:
-// - onExit - Function to process when the object is destroyed (on exit)
-Tracing::Tracing(std::function<void()> onExit) :
-    _onExit(onExit)
-{
-}
-
-// Routine Description:
-// - Destructs a tracing object, running any on exit routine, if necessary.
-Tracing::~Tracing()
-{
-    if (_onExit)
-    {
-        _onExit();
-    }
-}
-
-// Routine Description:
-// - Provides generic tracing for all API call types in the form of
-//   start/stop period events for timing and region-of-interest purposes
-//   while doing performance analysis.
-// Arguments:
-// - result - Reference to the area where the result code from the Api call
-//            will be stored for use in the stop event.
-// - traceName - The name of the API call to list in the trace details
-// Return Value:
-// - An object for the caller to hold until the API call is complete.
-//   Then destroy it to signal that the call is over so the stop trace can be written.
-Tracing Tracing::s_TraceApiCall(const NTSTATUS result, PCSTR traceName)
-{
-    // clang-format off
-    TraceLoggingWrite(
-        g_hConhostV2EventTraceProvider,
-        "ApiCall",
-        TraceLoggingString(traceName, "ApiName"),
-        TraceLoggingOpcode(WINEVENT_OPCODE_START),
-        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-        TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-        TraceLoggingKeyword(TraceKeywords::API));
-
-    return Tracing([traceName, &result] {
-        TraceLoggingWrite(
-            g_hConhostV2EventTraceProvider,
-            "ApiCall",
-            TraceLoggingString(traceName, "ApiName"),
-            TraceLoggingHResult(result, "Result"),
-            TraceLoggingOpcode(WINEVENT_OPCODE_STOP),
-            TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-            TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-            TraceLoggingKeyword(TraceKeywords::API));
-    });
-    // clang-format on
-}
-
 ULONG Tracing::s_ulDebugFlag = 0x0;
 
-void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_GETLARGESTWINDOWSIZE_MSG* const a)
-{
-    TraceLoggingWrite(
-        g_hConhostV2EventTraceProvider,
-        "API_GetLargestWindowSize",
-        TraceLoggingHexInt32(status, "ResultCode"),
-        TraceLoggingInt32(a->Size.X, "MaxWindowWidthInChars"),
-        TraceLoggingInt32(a->Size.Y, "MaxWindowHeightInChars"),
-        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-        TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-        TraceLoggingKeyword(TraceKeywords::API));
-}
-
-void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_SCREENBUFFERINFO_MSG* const a, const bool fSet)
-{
-    // Duplicate copies required by TraceLogging documentation ("don't get cute" examples)
-    // Using logic inside these macros can make problems. Do all logic outside macros.
-
-    if (fSet)
-    {
-        TraceLoggingWrite(
-            g_hConhostV2EventTraceProvider,
-            "API_SetConsoleScreenBufferInfo",
-            TraceLoggingHexInt32(status, "ResultCode"),
-            TraceLoggingInt32(a->Size.X, "BufferWidthInChars"),
-            TraceLoggingInt32(a->Size.Y, "BufferHeightInChars"),
-            TraceLoggingInt32(a->CurrentWindowSize.X, "WindowWidthInChars"),
-            TraceLoggingInt32(a->CurrentWindowSize.Y, "WindowHeightInChars"),
-            TraceLoggingInt32(a->MaximumWindowSize.X, "MaxWindowWidthInChars"),
-            TraceLoggingInt32(a->MaximumWindowSize.Y, "MaxWindowHeightInChars"),
-            TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-            TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-            TraceLoggingKeyword(TraceKeywords::API));
-    }
-    else
-    {
-        TraceLoggingWrite(
-            g_hConhostV2EventTraceProvider,
-            "API_GetConsoleScreenBufferInfo",
-            TraceLoggingHexInt32(status, "ResultCode"),
-            TraceLoggingInt32(a->Size.X, "BufferWidthInChars"),
-            TraceLoggingInt32(a->Size.Y, "BufferHeightInChars"),
-            TraceLoggingInt32(a->CurrentWindowSize.X, "WindowWidthInChars"),
-            TraceLoggingInt32(a->CurrentWindowSize.Y, "WindowHeightInChars"),
-            TraceLoggingInt32(a->MaximumWindowSize.X, "MaxWindowWidthInChars"),
-            TraceLoggingInt32(a->MaximumWindowSize.Y, "MaxWindowHeightInChars"),
-            TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-            TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-            TraceLoggingKeyword(TraceKeywords::API));
-    }
-}
-
-void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_SETSCREENBUFFERSIZE_MSG* const a)
-{
-    TraceLoggingWrite(
-        g_hConhostV2EventTraceProvider,
-        "API_SetConsoleScreenBufferSize",
-        TraceLoggingHexInt32(status, "ResultCode"),
-        TraceLoggingInt32(a->Size.X, "BufferWidthInChars"),
-        TraceLoggingInt32(a->Size.Y, "BufferHeightInChars"),
-        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-        TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-        TraceLoggingKeyword(TraceKeywords::API));
-}
-
-void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_SETWINDOWINFO_MSG* const a)
-{
-    TraceLoggingWrite(
-        g_hConhostV2EventTraceProvider,
-        "API_SetConsoleWindowInfo",
-        TraceLoggingHexInt32(status, "ResultCode"),
-        TraceLoggingBool(a->Absolute, "IsWindowRectAbsolute"),
-        TraceLoggingInt32(a->Window.Left, "WindowRectLeft"),
-        TraceLoggingInt32(a->Window.Right, "WindowRectRight"),
-        TraceLoggingInt32(a->Window.Top, "WindowRectTop"),
-        TraceLoggingInt32(a->Window.Bottom, "WindowRectBottom"),
-        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-        TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-        TraceLoggingKeyword(TraceKeywords::API));
-}
-
-void Tracing::s_TraceApi(_In_ const void* const buffer, const CONSOLE_WRITECONSOLE_MSG* const a)
-{
-    // clang-format off
-    if (a->Unicode)
-    {
-        const auto buf = static_cast<const wchar_t* const>(buffer);
-        TraceLoggingWrite(
-            g_hConhostV2EventTraceProvider,
-            "API_WriteConsole",
-            TraceLoggingBoolean(a->Unicode, "Unicode"),
-            TraceLoggingUInt32(a->NumBytes, "NumBytes"),
-            TraceLoggingCountedWideString(buf, static_cast<UINT16>(a->NumBytes / sizeof(wchar_t)), "input buffer"),
-            TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-            TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-            TraceLoggingKeyword(TraceKeywords::API));
-    }
-    else
-    {
-        const auto buf = static_cast<const char* const>(buffer);
-        TraceLoggingWrite(
-            g_hConhostV2EventTraceProvider,
-            "API_WriteConsole",
-            TraceLoggingBoolean(a->Unicode, "Unicode"),
-            TraceLoggingUInt32(a->NumBytes, "NumBytes"),
-            TraceLoggingCountedString(buf, static_cast<UINT16>(a->NumBytes / sizeof(char)), "input buffer"),
-            TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-            TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-            TraceLoggingKeyword(TraceKeywords::API));
-    }
-    // clang-format on
-}
-
-void Tracing::s_TraceApi(const CONSOLE_SCREENBUFFERINFO_MSG* const a)
-{
-    TraceLoggingWrite(
-        g_hConhostV2EventTraceProvider,
-        "API_GetConsoleScreenBufferInfo",
-        TraceLoggingInt16(a->Size.X, "Size.X"),
-        TraceLoggingInt16(a->Size.Y, "Size.Y"),
-        TraceLoggingInt16(a->CursorPosition.X, "CursorPosition.X"),
-        TraceLoggingInt16(a->CursorPosition.Y, "CursorPosition.Y"),
-        TraceLoggingInt16(a->ScrollPosition.X, "ScrollPosition.X"),
-        TraceLoggingInt16(a->ScrollPosition.Y, "ScrollPosition.Y"),
-        TraceLoggingHexUInt16(a->Attributes, "Attributes"),
-        TraceLoggingInt16(a->CurrentWindowSize.X, "CurrentWindowSize.X"),
-        TraceLoggingInt16(a->CurrentWindowSize.Y, "CurrentWindowSize.Y"),
-        TraceLoggingInt16(a->MaximumWindowSize.X, "MaximumWindowSize.X"),
-        TraceLoggingInt16(a->MaximumWindowSize.Y, "MaximumWindowSize.Y"),
-        TraceLoggingHexUInt16(a->PopupAttributes, "PopupAttributes"),
-        TraceLoggingBoolean(a->FullscreenSupported, "FullscreenSupported"),
-        TraceLoggingHexUInt32FixedArray((UINT32 const*)a->ColorTable, _countof(a->ColorTable), "ColorTable"),
-        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-        TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-        TraceLoggingKeyword(TraceKeywords::API));
-    static_assert(sizeof(UINT32) == sizeof(*a->ColorTable), "a->ColorTable");
-}
-
-void Tracing::s_TraceApi(const CONSOLE_MODE_MSG* const a, const std::wstring_view handleType)
-{
-    TraceLoggingWrite(
-        g_hConhostV2EventTraceProvider,
-        "API_GetConsoleMode",
-        TraceLoggingHexUInt32(a->Mode, "Mode"),
-        TraceLoggingCountedWideString(handleType.data(), gsl::narrow_cast<ULONG>(handleType.size()), "Handle type"),
-        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-        TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-        TraceLoggingKeyword(TraceKeywords::API));
-}
-
-void Tracing::s_TraceApi(const CONSOLE_SETTEXTATTRIBUTE_MSG* const a)
-{
-    TraceLoggingWrite(
-        g_hConhostV2EventTraceProvider,
-        "API_SetConsoleTextAttribute",
-        TraceLoggingHexUInt16(a->Attributes, "Attributes"),
-        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-        TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-        TraceLoggingKeyword(TraceKeywords::API));
-}
-
-void Tracing::s_TraceApi(const CONSOLE_WRITECONSOLEOUTPUTSTRING_MSG* const a)
-{
-    TraceLoggingWrite(
-        g_hConhostV2EventTraceProvider,
-        "API_WriteConsoleOutput",
-        TraceLoggingInt16(a->WriteCoord.X, "WriteCoord.X"),
-        TraceLoggingInt16(a->WriteCoord.Y, "WriteCoord.Y"),
-        TraceLoggingHexUInt32(a->StringType, "StringType"),
-        TraceLoggingUInt32(a->NumRecords, "NumRecords"),
-        TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-        TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-        TraceLoggingKeyword(TraceKeywords::API));
-}
-
 void Tracing::s_TraceWindowViewport(const Viewport& viewport)
 {
     TraceLoggingWrite(
@@ -413,10 +180,10 @@ void Tracing::s_TraceCookedRead(_In_ ConsoleProcessHandle* const pConsoleProcess
         TraceLoggingWrite(
             g_hConhostV2EventTraceProvider,
             "CookedRead",
+            TraceLoggingPid(pConsoleProcessHandle->dwProcessId, "AttachedProcessId"),
             TraceLoggingCountedWideString(pwchCookedBuffer, cchCookedBufferLength, "ReadBuffer"),
             TraceLoggingULong(cchCookedBufferLength, "ReadBufferLength"),
-            TraceLoggingUInt32(pConsoleProcessHandle->dwProcessId, "AttachedProcessId"),
-            TraceLoggingUInt64(pConsoleProcessHandle->GetProcessCreationTime(), "AttachedProcessCreationTime"),
+            TraceLoggingFileTime(pConsoleProcessHandle->GetProcessCreationTime(), "AttachedProcessCreationTime"),
             TraceLoggingKeyword(TIL_KEYWORD_TRACE),
             TraceLoggingKeyword(TraceKeywords::CookedRead));
     }
@@ -431,8 +198,8 @@ void Tracing::s_TraceConsoleAttachDetach(_In_ ConsoleProcessHandle* const pConso
         TraceLoggingWrite(
             g_hConhostV2EventTraceProvider,
             "ConsoleAttachDetach",
-            TraceLoggingUInt32(pConsoleProcessHandle->dwProcessId, "AttachedProcessId"),
-            TraceLoggingUInt64(pConsoleProcessHandle->GetProcessCreationTime(), "AttachedProcessCreationTime"),
+            TraceLoggingPid(pConsoleProcessHandle->dwProcessId, "AttachedProcessId"),
+            TraceLoggingFileTime(pConsoleProcessHandle->GetProcessCreationTime(), "AttachedProcessCreationTime"),
             TraceLoggingBool(bIsAttach, "IsAttach"),
             TraceLoggingBool(bIsUserInteractive, "IsUserInteractive"),
             TraceLoggingKeyword(TIL_KEYWORD_TRACE),

src/host/tracing.hpp

@@ -35,25 +35,14 @@ Author(s):
 #define DBGOUTPUT(_params_)
 #endif
 
+#define TraceLoggingConsoleCoord(value, name) \
+    TraceLoggingStruct(2, name),              \
+        TraceLoggingInt32(value.X, "X"),      \
+        TraceLoggingInt32(value.Y, "Y")
+
 class Tracing
 {
 public:
-    ~Tracing();
-
-    static Tracing s_TraceApiCall(const NTSTATUS result, PCSTR traceName);
-
-    static void s_TraceApi(const NTSTATUS status, const CONSOLE_GETLARGESTWINDOWSIZE_MSG* const a);
-    static void s_TraceApi(const NTSTATUS status, const CONSOLE_SCREENBUFFERINFO_MSG* const a, const bool fSet);
-    static void s_TraceApi(const NTSTATUS status, const CONSOLE_SETSCREENBUFFERSIZE_MSG* const a);
-    static void s_TraceApi(const NTSTATUS status, const CONSOLE_SETWINDOWINFO_MSG* const a);
-
-    static void s_TraceApi(_In_ const void* const buffer, const CONSOLE_WRITECONSOLE_MSG* const a);
-
-    static void s_TraceApi(const CONSOLE_SCREENBUFFERINFO_MSG* const a);
-    static void s_TraceApi(const CONSOLE_MODE_MSG* const a, const std::wstring_view handleType);
-    static void s_TraceApi(const CONSOLE_SETTEXTATTRIBUTE_MSG* const a);
-    static void s_TraceApi(const CONSOLE_WRITECONSOLEOUTPUTSTRING_MSG* const a);
-
     static void s_TraceWindowViewport(const Microsoft::Console::Types::Viewport& viewport);
 
     static void s_TraceChars(_In_z_ const char* pszMessage, ...);
@@ -69,8 +58,4 @@ public:
 
 private:
     static ULONG s_ulDebugFlag;
-
-    Tracing(std::function<void()> onExit);
-
-    std::function<void()> _onExit;
 };

src/server/ApiDispatchers.cpp

@@ -12,6 +12,29 @@
 #include "../host/telemetry.hpp"
 #include "../host/cmdline.h"
 
+// Assumes that it will find <m> in the calling environment.
+#define TraceConsoleAPICallWithOrigin(ApiName, ...)                  \
+    TraceLoggingWrite(                                               \
+        g_hConhostV2EventTraceProvider,                              \
+        "API_" ApiName,                                              \
+        TraceLoggingPid(TraceGetProcessId(m), "OriginatingProcess"), \
+        TraceLoggingTid(TraceGetThreadId(m), "OriginatingThread"),   \
+        __VA_ARGS__ __VA_OPT__(, )                                   \
+            TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),               \
+        TraceLoggingKeyword(TIL_KEYWORD_TRACE));
+
+static DWORD TraceGetProcessId(CONSOLE_API_MSG* const m)
+{
+    const auto p = m->GetProcessHandle();
+    return p ? p->dwProcessId : 0;
+}
+
+static DWORD TraceGetThreadId(CONSOLE_API_MSG* const m)
+{
+    const auto p = m->GetProcessHandle();
+    return p ? p->dwThreadId : 0;
+}
+
 [[nodiscard]] HRESULT ApiDispatchers::ServerGetConsoleCP(_Inout_ CONSOLE_API_MSG* const m,
                                                          _Inout_ BOOL* const /*pbReplyPending*/)
 {
@@ -35,35 +58,22 @@
 {
     Telemetry::Instance().LogApiCall(Telemetry::ApiCall::GetConsoleMode);
     const auto a = &m->u.consoleMsgL1.GetConsoleMode;
-    std::wstring_view handleType = L"unknown";
-
-    TraceLoggingWrite(g_hConhostV2EventTraceProvider,
-                      "API_GetConsoleMode",
-                      TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-                      TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-                      TraceLoggingOpcode(WINEVENT_OPCODE_START));
-
-    auto tracing = wil::scope_exit([&]() {
-        Tracing::s_TraceApi(a, handleType);
-        TraceLoggingWrite(g_hConhostV2EventTraceProvider,
-                          "API_GetConsoleMode",
-                          TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
-                          TraceLoggingKeyword(TIL_KEYWORD_TRACE),
-                          TraceLoggingOpcode(WINEVENT_OPCODE_STOP));
-    });
 
     const auto pObjectHandle = m->GetObjectHandle();
     RETURN_HR_IF_NULL(E_HANDLE, pObjectHandle);
+
+    TraceConsoleAPICallWithOrigin(
+        "GetConsoleMode",
+        TraceLoggingBool(pObjectHandle->IsInputHandle(), "InputHandle"));
+
     if (pObjectHandle->IsInputHandle())
     {
-        handleType = L"input";
         InputBuffer* pObj;
         RETURN_IF_FAILED(pObjectHandle->GetInputBuffer(GENERIC_READ, &pObj));
         m->_pApiRoutines->GetConsoleInputModeImpl(*pObj, a->Mode);
     }
     else
     {
-        handleType = L"output";
         SCREEN_INFORMATION* pObj;
         RETURN_IF_FAILED(pObjectHandle->GetScreenBuffer(GENERIC_READ, &pObj));
         m->_pApiRoutines->GetConsoleOutputModeImpl(*pObj, a->Mode);
@@ -79,6 +89,12 @@
 
     const auto pObjectHandle = m->GetObjectHandle();
     RETURN_HR_IF_NULL(E_HANDLE, pObjectHandle);
+
+    TraceConsoleAPICallWithOrigin(
+        "SetConsoleMode",
+        TraceLoggingBool(pObjectHandle->IsInputHandle(), "InputHandle"),
+        TraceLoggingHexULong(a->Mode, "Mode"));
+
     if (pObjectHandle->IsInputHandle())
     {
         InputBuffer* pObj;
@@ -365,9 +381,6 @@
     // Get input parameter buffer
     PVOID pvBuffer;
     ULONG cbBufferSize;
-    auto tracing = wil::scope_exit([&]() {
-        Tracing::s_TraceApi(pvBuffer, a);
-    });
     RETURN_IF_FAILED(m->GetInputBuffer(&pvBuffer, &cbBufferSize));
 
     std::unique_ptr<IWaitRoutine> waiter;
@@ -385,6 +398,11 @@
         const std::wstring_view buffer(reinterpret_cast<wchar_t*>(pvBuffer), cbBufferSize / sizeof(wchar_t));
         size_t cchInputRead;
 
+        TraceConsoleAPICallWithOrigin(
+            "WriteConsoleW",
+            TraceLoggingUInt32(a->NumBytes, "NumBytes"),
+            TraceLoggingCountedWideString(buffer.data(), static_cast<ULONG>(buffer.size()), "Buffer"));
+
         hr = m->_pApiRoutines->WriteConsoleWImpl(*pScreenInfo, buffer, cchInputRead, requiresVtQuirk, waiter);
 
         // We must set the reply length in bytes. Convert back from characters.
@@ -395,6 +413,11 @@
         const std::string_view buffer(reinterpret_cast<char*>(pvBuffer), cbBufferSize);
         size_t cchInputRead;
 
+        TraceConsoleAPICallWithOrigin(
+            "WriteConsoleA",
+            TraceLoggingUInt32(a->NumBytes, "NumBytes"),
+            TraceLoggingCountedString(buffer.data(), static_cast<ULONG>(buffer.size()), "Buffer"));
+
         hr = m->_pApiRoutines->WriteConsoleAImpl(*pScreenInfo, buffer, cchInputRead, requiresVtQuirk, waiter);
 
         // Reply length is already in bytes (chars), don't need to convert.
@@ -581,10 +604,6 @@
     Telemetry::Instance().LogApiCall(Telemetry::ApiCall::GetConsoleScreenBufferInfoEx);
     const auto a = &m->u.consoleMsgL2.GetConsoleScreenBufferInfo;
 
-    auto tracing = wil::scope_exit([&]() {
-        Tracing::s_TraceApi(a);
-    });
-
     CONSOLE_SCREEN_BUFFER_INFOEX ex = { 0 };
     ex.cbSize = sizeof(CONSOLE_SCREEN_BUFFER_INFOEX);
 
@@ -640,6 +659,12 @@
     ex.wAttributes = a->Attributes;
     ex.wPopupAttributes = a->PopupAttributes;
 
+    TraceConsoleAPICallWithOrigin(
+        "SetConsoleScreenBufferInfoEx",
+        TraceLoggingConsoleCoord(a->Size, "BufferSize"),
+        TraceLoggingConsoleCoord(a->CurrentWindowSize, "WindowSize"),
+        TraceLoggingConsoleCoord(a->MaximumWindowSize, "MaxWindowSize"));
+
     return m->_pApiRoutines->SetConsoleScreenBufferInfoExImpl(*pObj, ex);
 }
 
@@ -655,6 +680,10 @@
     SCREEN_INFORMATION* pObj;
     RETURN_IF_FAILED(pObjectHandle->GetScreenBuffer(GENERIC_WRITE, &pObj));
 
+    TraceConsoleAPICallWithOrigin(
+        "SetConsoleScreenBufferSize",
+        TraceLoggingConsoleCoord(a->Size, "BufferSize"));
+
     return m->_pApiRoutines->SetConsoleScreenBufferSizeImpl(*pObj, til::wrap_coord_size(a->Size));
 }
 
@@ -731,15 +760,16 @@
     Telemetry::Instance().LogApiCall(Telemetry::ApiCall::SetConsoleTextAttribute);
     const auto a = &m->u.consoleMsgL2.SetConsoleTextAttribute;
 
-    auto tracing = wil::scope_exit([&]() {
-        Tracing::s_TraceApi(a);
-    });
-
     const auto pObjectHandle = m->GetObjectHandle();
     RETURN_HR_IF_NULL(E_HANDLE, pObjectHandle);
 
     SCREEN_INFORMATION* pObj;
     RETURN_IF_FAILED(pObjectHandle->GetScreenBuffer(GENERIC_WRITE, &pObj));
+
+    TraceConsoleAPICallWithOrigin(
+        "SetConsoleTextAttribute",
+        TraceLoggingHexUInt16(a->Attributes, "Attributes"));
+
     RETURN_HR(m->_pApiRoutines->SetConsoleTextAttributeImpl(*pObj, a->Attributes));
 }
 
@@ -755,6 +785,14 @@
     SCREEN_INFORMATION* pObj;
     RETURN_IF_FAILED(pObjectHandle->GetScreenBuffer(GENERIC_WRITE, &pObj));
 
+    TraceConsoleAPICallWithOrigin(
+        "SetConsoleWindowInfo",
+        TraceLoggingBool(a->Absolute, "IsWindowRectAbsolute"),
+        TraceLoggingInt32(a->Window.Left, "WindowRectLeft"),
+        TraceLoggingInt32(a->Window.Right, "WindowRectRight"),
+        TraceLoggingInt32(a->Window.Top, "WindowRectTop"),
+        TraceLoggingInt32(a->Window.Bottom, "WindowRectBottom"));
+
     return m->_pApiRoutines->SetConsoleWindowInfoImpl(*pObj, a->Absolute, til::wrap_small_rect(a->Window));
 }
 
@@ -911,10 +949,6 @@
 {
     const auto a = &m->u.consoleMsgL2.WriteConsoleOutputString;
 
-    auto tracing = wil::scope_exit([&]() {
-        Tracing::s_TraceApi(a);
-    });
-
     switch (a->StringType)
     {
     case CONSOLE_ATTRIBUTE:
@@ -951,6 +985,11 @@
     {
         const std::string_view text(reinterpret_cast<char*>(pvBuffer), cbBufferSize);
 
+        TraceConsoleAPICallWithOrigin(
+            "WriteConsoleOutputCharacterA",
+            TraceLoggingConsoleCoord(a->WriteCoord, "WriteCoord"),
+            TraceLoggingUInt32(a->NumRecords, "NumRecords"));
+
         hr = m->_pApiRoutines->WriteConsoleOutputCharacterAImpl(*pScreenInfo,
                                                                 text,
                                                                 til::wrap_coord(a->WriteCoord),
@@ -963,6 +1002,11 @@
     {
         const std::wstring_view text(reinterpret_cast<wchar_t*>(pvBuffer), cbBufferSize / sizeof(wchar_t));
 
+        TraceConsoleAPICallWithOrigin(
+            "WriteConsoleOutputCharacterW",
+            TraceLoggingConsoleCoord(a->WriteCoord, "WriteCoord"),
+            TraceLoggingUInt32(a->NumRecords, "NumRecords"));
+
         hr = m->_pApiRoutines->WriteConsoleOutputCharacterWImpl(*pScreenInfo,
                                                                 text,
                                                                 til::wrap_coord(a->WriteCoord),
@@ -974,6 +1018,11 @@
     {
         const std::span<const WORD> text(reinterpret_cast<WORD*>(pvBuffer), cbBufferSize / sizeof(WORD));
 
+        TraceConsoleAPICallWithOrigin(
+            "WriteConsoleOutputAttribute",
+            TraceLoggingConsoleCoord(a->WriteCoord, "WriteCoord"),
+            TraceLoggingUInt32(a->NumRecords, "NumRecords"));
+
         hr = m->_pApiRoutines->WriteConsoleOutputAttributeImpl(*pScreenInfo,
                                                                text,
                                                                til::wrap_coord(a->WriteCoord),

src/server/ApiSorter.cpp

@@ -174,7 +174,6 @@ PCONSOLE_API_MSG ApiSorter::ConsoleDispatchRequest(_Inout_ PCONSOLE_API_MSG Mess
     // alias API.
     NTSTATUS Status = S_OK;
     {
-        const auto trace = Tracing::s_TraceApiCall(Status, Descriptor->TraceName);
         Status = (*Descriptor->Routine)(Message, &ReplyPending);
     }
     if (Status != STATUS_BUFFER_TOO_SMALL)

src/server/ProcessHandle.cpp

@@ -28,7 +28,7 @@ ConsoleProcessHandle::ConsoleProcessHandle(const DWORD dwProcessId,
                                                  dwProcessId))),
     _policy(ConsoleProcessPolicy::s_CreateInstance(_hProcess.get())),
     _shimPolicy(_hProcess.get()),
-    _processCreationTime(0)
+    _processCreationTime{}
 {
     if (nullptr != _hProcess.get())
     {
@@ -77,24 +77,17 @@ const HANDLE ConsoleProcessHandle::GetRawHandle() const
 // Routine Description:
 // - Retrieves the process creation time (currently used in telemetry traces)
 // - The creation time is lazily populated on first call
-const ULONG64 ConsoleProcessHandle::GetProcessCreationTime() const
+const FILETIME ConsoleProcessHandle::GetProcessCreationTime() const
 {
-    if (_processCreationTime == 0 && _hProcess != nullptr)
+    if (_processCreationTime.dwHighDateTime == 0 && _processCreationTime.dwLowDateTime == 0 && _hProcess != nullptr)
     {
-        FILETIME ftCreationTime, ftDummyTime = { 0 };
-        ULARGE_INTEGER creationTime = { 0 };
+        FILETIME ftDummyTime = { 0 };
 
-        if (::GetProcessTimes(_hProcess.get(),
-                              &ftCreationTime,
-                              &ftDummyTime,
-                              &ftDummyTime,
-                              &ftDummyTime))
-        {
-            creationTime.HighPart = ftCreationTime.dwHighDateTime;
-            creationTime.LowPart = ftCreationTime.dwLowDateTime;
-        }
-
-        _processCreationTime = creationTime.QuadPart;
+        ::GetProcessTimes(_hProcess.get(),
+                          &_processCreationTime,
+                          &ftDummyTime,
+                          &ftDummyTime,
+                          &ftDummyTime);
     }
 
     return _processCreationTime;

src/server/ProcessHandle.h

@@ -53,14 +53,14 @@ public:
 
     CD_CONNECTION_INFORMATION GetConnectionInformation(IDeviceComm* deviceComm) const;
 
-    const ULONG64 GetProcessCreationTime() const;
+    const FILETIME GetProcessCreationTime() const;
 
 private:
     ULONG _ulTerminateCount;
     ULONG const _ulProcessGroupId;
     wil::unique_handle const _hProcess;
 
-    mutable ULONG64 _processCreationTime;
+    mutable FILETIME _processCreationTime;
 
     const ConsoleProcessPolicy _policy;
     const ConsoleShimPolicy _shimPolicy;