Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Consolidate and clean up all API logging #15737

Merged
merged 4 commits into from Jul 21, 2023
Merged

Consolidate and clean up all API logging #15737

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
a749b59
Remove all API logging from tracing.cpp
DHowett Jul 14, 2023
8a4ee04
Switch ConsoleAttach and CookedRead to use PID and FILETIME
DHowett Jul 14, 2023
213c318
Switch to TraceGet(Process|Thread)Id
DHowett Jul 21, 2023
9dac590
Reformat TraceConsoleAPICall/s, add TraceLoggingConsoleCoord
DHowett Jul 21, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
243 changes: 5 additions & 238 deletions src/host/tracing.cpp
View file
Open in desktop
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
20 changes: 0 additions & 20 deletions src/host/tracing.hpp
View file
Open in desktop
Expand Up @@ -38,22 +38,6 @@ Author(s):
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 +53,4 @@ class Tracing

private:
static ULONG s_ulDebugFlag;

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

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