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

(cherry picked from commit 5daf498)
Service-Card-Id: 90012631
Service-Version: 1.18
  • Loading branch information
@DHowett
DHowett committed Jul 27, 2023
1 parent 3312c0f commit 531fc0c
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;
};

1 comment on commit 531fc0c

@github-actions
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@check-spelling-bot Report

🔴 Please review

See the 📜action log for details.

Unrecognized words (1)

HAX

Previously acknowledged words that are now absent countof homeglyphs xxyyzz :arrow_right:
To accept ✔️ these unrecognized words as correct and remove the previously acknowledged and now absent words, run the following commands

... in a clone of the git@github.com:microsoft/terminal.git repository
on the release-1.18 branch (ℹ️ how do I use this?):

curl -s -S -L 'https://raw.githubusercontent.com/check-spelling/check-spelling/v0.0.21/apply.pl' |
perl - 'https://github.com/microsoft/terminal/actions/runs/5683780417/attempts/1'
Pattern suggestions ✂️ (1)

You could add these patterns to .github/actions/spelling/patterns/531fc0c1b715a7e24dcee8d464403d5a4ae800ed.txt:

# Automatically suggested patterns
# hit-count: 1 file-count: 1
# Punycode
\bxn--[-0-9a-z]+
Warnings (1)

See the 📜action log for details.

ℹ️ Warnings Count
ℹ️ candidate-pattern 1

See ℹ️ Event descriptions for more information.

✏️ Contributor please read this

By default the command suggestion will generate a file named based on your commit. That's generally ok as long as you add the file to your commit. Someone can reorganize it later.

⚠️ The command is written for posix shells. If it doesn't work for you, you can manually add (one word per line) / remove items to expect.txt and the excludes.txt files.

If the listed items are:

  • ... misspelled, then please correct them instead of using the command.
  • ... names, please add them to .github/actions/spelling/allow/names.txt.
  • ... APIs, you can add them to a file in .github/actions/spelling/allow/.
  • ... just things you're using, please add them to an appropriate file in .github/actions/spelling/expect/.
  • ... tokens you only need in one place and shouldn't generally be used, you can add an item in an appropriate file in .github/actions/spelling/patterns/.

See the README.md in each directory for more information.

🔬 You can test your commits without appending to a PR by creating a new branch with that extra change and pushing it to your fork. The check-spelling action will run in response to your push -- it doesn't require an open pull request. By using such a branch, you can limit the number of typos your peers see you make. 😉

If the flagged items are 🤯 false positives

If items relate to a ...

  • binary file (or some other file you wouldn't want to check at all).

    Please add a file path to the excludes.txt file matching the containing file.

    File paths are Perl 5 Regular Expressions - you can test yours before committing to verify it will match your files.

    ^ refers to the file's path from the root of the repository, so ^README\.md$ would exclude README.md (on whichever branch you're using).

  • well-formed pattern.

    If you can write a pattern that would match it,
    try adding it to the patterns.txt file.

    Patterns are Perl 5 Regular Expressions - you can test yours before committing to verify it will match your lines.

    Note that patterns can't match multiline strings.

Please sign in to comment.