Skip to content

Commit

Permalink
Consolidate and clean up all API logging (#15737)
Browse files Browse the repository at this point in the history 
`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.)
  • Loading branch information
@DHowett
DHowett committed Jul 21, 2023
1 parent 3de496d commit 5daf498
Show file tree
Hide file tree
Showing 6 changed files with 103 additions and 310 deletions.
243 changes: 5 additions & 238 deletions src/host/tracing.cpp
View file
Expand Up @@ -18,249 +18,16 @@ enum TraceKeywords
Output = 0x008, // _DBGOUTPUT
General = 0x100,
Input = 0x200,
API = 0x400,
//API = 0x400, // No longer used
UIA = 0x800,
CookedRead = 0x1000,
ConsoleAttachDetach = 0x2000,
All = 0x1FFF
};
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(
Expand Down Expand Up @@ -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));
}
Expand All @@ -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),
Expand Down
25 changes: 5 additions & 20 deletions src/host/tracing.hpp
View file
Expand Up @@ -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, ...);
Expand All @@ -69,8 +58,4 @@ class Tracing

private:
static ULONG s_ulDebugFlag;

Tracing(std::function<void()> onExit);

std::function<void()> _onExit;
};

0 comments on commit 5daf498

Please sign in to comment.