Skip to content

Commit

Permalink
Set keyword flags on all tracelog events (#10098)
Browse files Browse the repository at this point in the history
Set keyword flags on all events so those sharing a provider with
telemetry do not fire unless tracing is enabled

## PR Checklist
* [x] Closes #10093
* [x] I work here
* [x] Tests passed
* [x] Documentation added in `til.h` about how keywords work and at the
  only other site of keywords we define in the Host project tracing
  files.

## Detailed Description of the Pull Request / Additional comments
I initially thought that we would need to split providers here to
accomplish this... but @DHowett helped me realize that might be a lot of
additional metadata and bloat binary size. So with help from a friend
from fundamentals, I realized that we could use Keywords to
differentiate here. We can no longer define 0 keywords as that
represents an any/all scenario. Every `TraceLoggingWrite` event now
needs a keyword. When our events have a keyword, they're not included in
any trace. Additionally, when we have an explicit keyword to check that
is different from the ones used for the telemetry pipeline, we can
ensure that we only do "hard work" to generate debug trace data when an
"ALL" type listener like TraceView or Windows Performance Recorder with
our profiles is listening to these providers for ALL keyworded events.

## Validation Steps Performed
- [x] - Built with full release build config to confirm performance is
  worse than dev builds BECAUSE of the telemetry event collector camping
  our provider and triggering full trace event generation on shared
  providers.
- [x] - Built with full release build config to enable statistics
  collection and validated trace event collection is excluded and trace
  event short-circuits work with this change.
- [x] - Checked that TraceView still sees both telemetry and tracing
  events
- [x] - Checked that WPR with our .wprp profile sees both telemetry and
  tracing events

(cherry picked from commit 66fdc64)

# Conflicts:
#	src/Terminal.wprp
#	src/cascadia/Remoting/Monarch.cpp
#	src/cascadia/Remoting/Peasant.cpp
#	src/cascadia/Remoting/WindowManager.cpp
#	src/cascadia/WindowsTerminal/IslandWindow.cpp
#	src/host/exe/exemain.cpp
  • Loading branch information
miniksa authored and DHowett committed May 17, 2021
1 parent 661fde5 commit 1db0b70
Show file tree
Hide file tree
Showing 9 changed files with 239 additions and 114 deletions.
2 changes: 2 additions & 0 deletions src/ConsolePerf.wprp
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,7 @@
<EventProvider Id="EventProvider-Microsoft.Windows.Console.Server" Name="1A541C01-589A-496E-85A7-A9E02170166D"/>
<EventProvider Id="EventProvider-Microsoft.Windows.Console.VirtualTerminal.Parser" Name="c9ba2a84-d3ca-5e19-2bd6-776a0910cb9d"/>
<EventProvider Id="EventProvider-Microsoft.Windows.Console.Render.VtEngine" Name="c9ba2a95-d3ca-5e19-2bd6-776a0910cb9d"/>
<EventProvider Id="EventProvider-Microsoft.Windows.Console.UIA" Name="e7ebce59-2161-572d-b263-2f16a6afb9e5"/>
<!-- Now define some profiles. We'll call them by ID when collecting. Also, the Base is where it is inheriting from and is a .wprpi file built... -->
<!-- ... into WPR automatically. Go look in the WPR install directory or in the documentation to find it. -->
<Profile Id="ConsolePerfProfile.Verbose.File" Base="GeneralProfile.Light.File" LoggingMode="File" Name="ConsolePerfProfile" DetailLevel="Verbose" Description="Console Performance default profile">
Expand All @@ -66,6 +67,7 @@
<EventProviderId Value="EventProvider-Microsoft.Windows.Console.Server"/>
<EventProviderId Value="EventProvider-Microsoft.Windows.Console.VirtualTerminal.Parser"/>
<EventProviderId Value="EventProvider-Microsoft.Windows.Console.Render.VtEngine"/>
<EventProviderId Value="EventProvider-Microsoft.Windows.Console.UIA"/>
</EventProviders>
</EventCollectorId>
</Collectors>
Expand Down
28 changes: 27 additions & 1 deletion src/host/tracing.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,8 @@

using namespace Microsoft::Console::Types;

// NOTE: See `til.h` for which keyword flags are reserved
// to ensure newly added ones do NOT overlap.
enum TraceKeywords
{
//Font = 0x001, // _DBGFONTS
Expand Down Expand Up @@ -63,6 +65,7 @@ Tracing Tracing::s_TraceApiCall(const NTSTATUS& result, PCSTR traceName)
TraceLoggingString(traceName, "ApiName"),
TraceLoggingOpcode(WINEVENT_OPCODE_START),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::API));

return Tracing([traceName, &result] {
Expand All @@ -73,6 +76,7 @@ Tracing Tracing::s_TraceApiCall(const NTSTATUS& result, PCSTR traceName)
TraceLoggingHResult(result, "Result"),
TraceLoggingOpcode(WINEVENT_OPCODE_STOP),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::API));
});
// clang-format on
Expand All @@ -89,6 +93,7 @@ void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_GETLARGESTWINDOWSI
TraceLoggingInt32(a->Size.X, "MaxWindowWidthInChars"),
TraceLoggingInt32(a->Size.Y, "MaxWindowHeightInChars"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::API));
}

Expand All @@ -110,6 +115,7 @@ void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_SCREENBUFFERINFO_M
TraceLoggingInt32(a->MaximumWindowSize.X, "MaxWindowWidthInChars"),
TraceLoggingInt32(a->MaximumWindowSize.Y, "MaxWindowHeightInChars"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::API));
}
else
Expand All @@ -125,6 +131,7 @@ void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_SCREENBUFFERINFO_M
TraceLoggingInt32(a->MaximumWindowSize.X, "MaxWindowWidthInChars"),
TraceLoggingInt32(a->MaximumWindowSize.Y, "MaxWindowHeightInChars"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::API));
}
}
Expand All @@ -138,6 +145,7 @@ void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_SETSCREENBUFFERSIZ
TraceLoggingInt32(a->Size.X, "BufferWidthInChars"),
TraceLoggingInt32(a->Size.Y, "BufferHeightInChars"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::API));
}

Expand All @@ -153,6 +161,7 @@ void Tracing::s_TraceApi(const NTSTATUS status, const CONSOLE_SETWINDOWINFO_MSG*
TraceLoggingInt32(a->Window.Top, "WindowRectTop"),
TraceLoggingInt32(a->Window.Bottom, "WindowRectBottom"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::API));
}

Expand All @@ -169,6 +178,7 @@ void Tracing::s_TraceApi(_In_ const void* const buffer, const CONSOLE_WRITECONSO
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
Expand All @@ -181,6 +191,7 @@ void Tracing::s_TraceApi(_In_ const void* const buffer, const CONSOLE_WRITECONSO
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
Expand All @@ -206,6 +217,7 @@ void Tracing::s_TraceApi(const CONSOLE_SCREENBUFFERINFO_MSG* const a)
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");
}
Expand All @@ -218,6 +230,7 @@ void Tracing::s_TraceApi(const CONSOLE_MODE_MSG* const a, const std::wstring_vie
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));
}

Expand All @@ -228,6 +241,7 @@ void Tracing::s_TraceApi(const CONSOLE_SETTEXTATTRIBUTE_MSG* const a)
"API_SetConsoleTextAttribute",
TraceLoggingHexUInt16(a->Attributes, "Attributes"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::API));
}

Expand All @@ -241,6 +255,7 @@ void Tracing::s_TraceApi(const CONSOLE_WRITECONSOLEOUTPUTSTRING_MSG* const a)
TraceLoggingHexUInt32(a->StringType, "StringType"),
TraceLoggingUInt32(a->NumRecords, "NumRecords"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::API));
}

Expand All @@ -254,6 +269,7 @@ void Tracing::s_TraceWindowViewport(const Viewport& viewport)
TraceLoggingInt32(viewport.Top(), "OriginTop"),
TraceLoggingInt32(viewport.Left(), "OriginLeft"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::General));
}

Expand All @@ -270,6 +286,7 @@ void Tracing::s_TraceChars(_In_z_ const char* pszMessage, ...)
"CharsTrace",
TraceLoggingString(szBuffer),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::Chars));

if (s_ulDebugFlag & TraceKeywords::Chars)
Expand All @@ -291,6 +308,7 @@ void Tracing::s_TraceOutput(_In_z_ const char* pszMessage, ...)
"OutputTrace",
TraceLoggingString(szBuffer),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::Output));

if (s_ulDebugFlag & TraceKeywords::Output)
Expand All @@ -308,6 +326,7 @@ void Tracing::s_TraceWindowMessage(const MSG& msg)
TraceLoggingHexUInt64(msg.wParam, "wParam"),
TraceLoggingHexUInt64(msg.lParam, "lParam"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::Input));
}

Expand All @@ -329,6 +348,7 @@ void Tracing::s_TraceInputRecord(const INPUT_RECORD& inputRecord)
TraceLoggingHexUInt8(inputRecord.Event.KeyEvent.uChar.AsciiChar, "Hex AsciiChar"),
TraceLoggingHexUInt32(inputRecord.Event.KeyEvent.dwControlKeyState, "dwControlKeyState"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::Input));
break;
case MOUSE_EVENT:
Expand All @@ -341,6 +361,7 @@ void Tracing::s_TraceInputRecord(const INPUT_RECORD& inputRecord)
TraceLoggingHexUInt32(inputRecord.Event.MouseEvent.dwControlKeyState, "dwControlKeyState"),
TraceLoggingHexUInt32(inputRecord.Event.MouseEvent.dwEventFlags, "dwEventFlags"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::Input));
break;
case WINDOW_BUFFER_SIZE_EVENT:
Expand All @@ -350,6 +371,7 @@ void Tracing::s_TraceInputRecord(const INPUT_RECORD& inputRecord)
TraceLoggingInt16(inputRecord.Event.WindowBufferSizeEvent.dwSize.X, "dwSize.X"),
TraceLoggingInt16(inputRecord.Event.WindowBufferSizeEvent.dwSize.Y, "dwSize.Y"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::Input));
break;
case MENU_EVENT:
Expand All @@ -358,6 +380,7 @@ void Tracing::s_TraceInputRecord(const INPUT_RECORD& inputRecord)
"Menu Event Input Record",
TraceLoggingHexUInt64(inputRecord.Event.MenuEvent.dwCommandId, "dwCommandId"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::Input));
break;
case FOCUS_EVENT:
Expand All @@ -366,6 +389,7 @@ void Tracing::s_TraceInputRecord(const INPUT_RECORD& inputRecord)
"Focus Event Input Record",
TraceLoggingBool(inputRecord.Event.FocusEvent.bSetFocus, "bSetFocus"),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::Input));
break;
default:
Expand All @@ -374,6 +398,7 @@ void Tracing::s_TraceInputRecord(const INPUT_RECORD& inputRecord)
"Unknown Input Record",
TraceLoggingHexUInt16(inputRecord.EventType, "EventType"),
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingKeyword(TIL_KEYWORD_TRACE),
TraceLoggingKeyword(TraceKeywords::Input));
break;
}
Expand All @@ -393,5 +418,6 @@ void __stdcall Tracing::TraceFailure(const wil::FailureInfo& failure) noexcept
TraceLoggingString(failure.pszModule, "Module"),
TraceLoggingPointer(failure.returnAddress, "Site"),
TraceLoggingString(failure.pszCode, "Code"),
TraceLoggingLevel(WINEVENT_LEVEL_ERROR));
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
TraceLoggingKeyword(TIL_KEYWORD_TRACE));
}
7 changes: 6 additions & 1 deletion src/inc/WilErrorReporting.h
Original file line number Diff line number Diff line change
Expand Up @@ -40,7 +40,12 @@ namespace Microsoft::Console::ErrorReporting
if (!alreadyReported && FallbackProvider)
{
#pragma warning(suppress : 26477 26485 26494 26482 26446) // We don't control TraceLoggingWrite
TraceLoggingWrite(FallbackProvider, "FallbackError", TraceLoggingKeyword(MICROSOFT_KEYWORD_TELEMETRY), TraceLoggingLevel(WINEVENT_LEVEL_ERROR), CONSOLE_WIL_TRACELOGGING_FAILURE_PARAMS(failure));
TraceLoggingWrite(FallbackProvider,
"FallbackError",
TraceLoggingKeyword(MICROSOFT_KEYWORD_TELEMETRY),
TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage),
TraceLoggingLevel(WINEVENT_LEVEL_ERROR),
CONSOLE_WIL_TRACELOGGING_FAILURE_PARAMS(failure));
}
}
catch (...)
Expand Down
28 changes: 28 additions & 0 deletions src/inc/til.h
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,34 @@
#include "til/visualize_control_codes.h"
#include "til/pmr.h"

// Use keywords on TraceLogging providers to specify the category
// of event that we are emitting for filtering purposes.
// The bottom 48 bits (0..47) are definable by each provider.
// The top 16 bits are reserved by Microsoft.
// NOTE: Any provider registering TraceLoggingOptionMicrosoftTelemetry
// should also reserve bits 43..47 for telemetry controls.
//
// To ensure that providers that transmit both telemetry
// and diagnostic information do not do excess work when only
// a telemetry listener is attached, please set a keyword
// on all TraceLoggingWrite statements.
//
// Use TIL_KEYWORD_TRACE if you are basically
// using it as a printf-like debugging tool for super
// deep diagnostics reasons only.
//
// Please do NOT leave events marked without a keyword
// or filtering on intent will not be possible.
//
// See also https://osgwiki.com/wiki/TraceLogging#Semantics
//
// Note that Conhost had already defined some keywords
// between bits 0..11 so be sure to not overlap those.
// See `TraceKeywords`.
// We will therefore try to reserve 32..42 for TIL
// as common flags for the entire Terminal team projects.
#define TIL_KEYWORD_TRACE 0x0000000100000000 // bit 32

namespace til // Terminal Implementation Library. Also: "Today I Learned"
{
template<typename T>
Expand Down
5 changes: 3 additions & 2 deletions src/renderer/dx/DxRenderer.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -1244,7 +1244,7 @@ try
_invalidMap.set_all();
}

if (TraceLoggingProviderEnabled(g_hDxRenderProvider, WINEVENT_LEVEL_VERBOSE, 0))
if (TraceLoggingProviderEnabled(g_hDxRenderProvider, WINEVENT_LEVEL_VERBOSE, TIL_KEYWORD_TRACE))
{
const auto invalidatedStr = _invalidMap.to_string();
const auto invalidated = invalidatedStr.c_str();
Expand All @@ -1253,7 +1253,8 @@ try
TraceLoggingWrite(g_hDxRenderProvider,
"Invalid",
TraceLoggingWideString(invalidated),
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE));
TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE),
TraceLoggingKeyword(TIL_KEYWORD_TRACE));
}

if (_isEnabled)
Expand Down
Loading

0 comments on commit 1db0b70

Please sign in to comment.