Add some logging around startup, connection start timing (#2544)

Adds a number of TL events we can use to track startup time better. Adds events for:
* Initial exe start
* Time the window is created
* time we start loading settings
* time we finish loading setings
* time when a connection recieves its first byte

Also updates our `ConnectionCreated` event to include the session GUID, so that we can correlate that with the connection's `RecievedFirstByte` event.

src/cascadia/TerminalApp/App.cpp

@@ -392,6 +392,15 @@ namespace winrt::TerminalApp::implementation
     //      happening during startup, it'll need to happen on a background thread.
     void App::LoadSettings()
     {
+        auto start = std::chrono::high_resolution_clock::now();
+
+        TraceLoggingWrite(
+            g_hTerminalAppProvider,
+            "SettingsLoadStarted",
+            TraceLoggingDescription("Event emitted before loading the settings"),
+            TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
+            TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
+
         // Attempt to load the settings.
         // If it fails,
         //  - use Default settings,
@@ -408,6 +417,17 @@ namespace winrt::TerminalApp::implementation
             _settings->CreateDefaults();
         }
 
+        auto end = std::chrono::high_resolution_clock::now();
+        std::chrono::duration<double> delta = end - start;
+
+        TraceLoggingWrite(
+            g_hTerminalAppProvider,
+            "SettingsLoadComplete",
+            TraceLoggingDescription("Event emitted when loading the settings is finished"),
+            TraceLoggingFloat64(delta.count(), "Duration"),
+            TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
+            TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
+
         _loadedInitialSettings = true;
 
         // Register for directory change notification.

src/cascadia/TerminalApp/TerminalPage.cpp

@@ -411,6 +411,7 @@ namespace winrt::TerminalApp::implementation
         TerminalConnection::ITerminalConnection connection{ nullptr };
 
         GUID connectionType{ 0 };
+        GUID sessionGuid{ 0 };
 
         if (profile->HasConnectionType())
         {
@@ -427,12 +428,14 @@ namespace winrt::TerminalApp::implementation
 
         else
         {
-            connection = TerminalConnection::ConhostConnection(settings.Commandline(),
-                                                               settings.StartingDirectory(),
-                                                               settings.StartingTitle(),
-                                                               settings.InitialRows(),
-                                                               settings.InitialCols(),
-                                                               winrt::guid());
+            auto conhostConn = TerminalConnection::ConhostConnection(settings.Commandline(),
+                                                                     settings.StartingDirectory(),
+                                                                     settings.StartingTitle(),
+                                                                     settings.InitialRows(),
+                                                                     settings.InitialCols(),
+                                                                     winrt::guid());
+            sessionGuid = conhostConn.Guid();
+            connection = conhostConn;
         }
 
         TraceLoggingWrite(
@@ -440,6 +443,8 @@ namespace winrt::TerminalApp::implementation
             "ConnectionCreated",
             TraceLoggingDescription("Event emitted upon the creation of a connection"),
             TraceLoggingGuid(connectionType, "ConnectionTypeGuid", "The type of the connection"),
+            TraceLoggingGuid(profileGuid, "ProfileGuid", "The profile's GUID"),
+            TraceLoggingGuid(sessionGuid, "SessionGuid", "The WT_SESSION's GUID"),
             TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
             TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
 

src/cascadia/TerminalConnection/ConhostConnection.cpp

@@ -108,6 +108,8 @@ namespace winrt::Microsoft::Terminal::TerminalConnection::implementation
                          si,
                          extraEnvVars));
 
+        _startTime = std::chrono::high_resolution_clock::now();
+
         // Create our own output handling thread
         // This must be done after the pipes are populated.
         // Each connection needs to make sure to drain the output from its backing host.
@@ -209,6 +211,21 @@ namespace winrt::Microsoft::Terminal::TerminalConnection::implementation
                 return 0;
             }
 
+            if (!_recievedFirstByte)
+            {
+                auto now = std::chrono::high_resolution_clock::now();
+                std::chrono::duration<double> delta = now - _startTime;
+
+                TraceLoggingWrite(g_hTerminalConnectionProvider,
+                                  "RecievedFirstByte",
+                                  TraceLoggingDescription("An event emitted when the connection recieves the first byte"),
+                                  TraceLoggingGuid(_guid, "SessionGuid", "The WT_SESSION's GUID"),
+                                  TraceLoggingFloat64(delta.count(), "Duration"),
+                                  TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
+                                  TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
+                _recievedFirstByte = true;
+            }
+
             // Convert buffer to hstring
             auto hstr{ winrt::to_hstring(strView) };
 

src/cascadia/TerminalConnection/ConhostConnection.h

@@ -35,6 +35,8 @@ namespace winrt::Microsoft::Terminal::TerminalConnection::implementation
 
         bool _connected{};
         std::atomic<bool> _closing{ false };
+        bool _recievedFirstByte{ false };
+        std::chrono::high_resolution_clock::time_point _startTime{};
 
         wil::unique_hfile _inPipe; // The pipe for writing input to
         wil::unique_hfile _outPipe; // The pipe for reading output from

src/cascadia/TerminalConnection/TerminalConnection.vcxproj

@@ -35,6 +35,7 @@
     </ClInclude>
   </ItemGroup>
   <ItemGroup>
+    <ClCompile Include="init.cpp"/>
     <ClCompile Include="AzureConnection.cpp" Condition="'$(Platform)'!='ARM64'" />
     <ClCompile Include="AzureConnection-ARM64.cpp" Condition="'$(Platform)'=='ARM64'" />
     <ClCompile Include="pch.cpp">

src/cascadia/TerminalConnection/init.cpp

@@ -0,0 +1,31 @@
+// Copyright (c) Microsoft Corporation
+// Licensed under the MIT license.
+
+#include "pch.h"
+
+// Note: Generate GUID using TlgGuid.exe tool
+TRACELOGGING_DEFINE_PROVIDER(
+    g_hTerminalConnectionProvider,
+    "Microsoft.Windows.Terminal.Connection",
+    // {e912fe7b-eeb6-52a5-c628-abe388e5f792}
+    (0xe912fe7b, 0xeeb6, 0x52a5, 0xc6, 0x28, 0xab, 0xe3, 0x88, 0xe5, 0xf7, 0x92),
+    TraceLoggingOptionMicrosoftTelemetry());
+
+BOOL WINAPI DllMain(HINSTANCE hInstDll, DWORD reason, LPVOID /*reserved*/)
+{
+    switch (reason)
+    {
+    case DLL_PROCESS_ATTACH:
+        DisableThreadLibraryCalls(hInstDll);
+        TraceLoggingRegister(g_hTerminalConnectionProvider);
+        break;
+    case DLL_PROCESS_DETACH:
+        if (g_hTerminalConnectionProvider)
+        {
+            TraceLoggingUnregister(g_hTerminalConnectionProvider);
+        }
+        break;
+    }
+
+    return TRUE;
+}

src/cascadia/TerminalConnection/pch.h

@@ -19,3 +19,7 @@
 #include "winrt/Windows.Security.Credentials.h"
 #include "winrt/Windows.Foundation.Collections.h"
 #include <Windows.h>
+
+#include <TraceLoggingProvider.h>
+TRACELOGGING_DECLARE_PROVIDER(g_hTerminalConnectionProvider);
+#include <telemetry/ProjectTelemetry.h>

src/cascadia/WindowsTerminal/AppHost.cpp

@@ -201,6 +201,13 @@ void AppHost::_HandleCreateWindow(const HWND hwnd, const RECT proposedRect)
     // If we can't resize the window, that's really okay. We can just go on with
     // the originally proposed window size.
     LOG_LAST_ERROR_IF(!succeeded);
+
+    TraceLoggingWrite(
+        g_hWindowsTerminalProvider,
+        "WindowCreated",
+        TraceLoggingDescription("Event emitted upon creating the application window"),
+        TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
+        TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
 }
 
 // Method Description:

src/cascadia/WindowsTerminal/main.cpp

@@ -11,6 +11,15 @@ using namespace Windows::UI::Composition;
 using namespace Windows::UI::Xaml::Hosting;
 using namespace Windows::Foundation::Numerics;
 
+// Note: Generate GUID using TlgGuid.exe tool - seriously, it won't work if you
+// just generate an arbitrary GUID
+TRACELOGGING_DEFINE_PROVIDER(
+    g_hWindowsTerminalProvider,
+    "Microsoft.Windows.Terminal.Win32Host",
+    // {56c06166-2e2e-5f4d-7ff3-74f4b78c87d6}
+    (0x56c06166, 0x2e2e, 0x5f4d, 0x7f, 0xf3, 0x74, 0xf4, 0xb7, 0x8c, 0x87, 0xd6),
+    TraceLoggingOptionMicrosoftTelemetry());
+
 // Routine Description:
 // - Retrieves the string resource from the current module with the given ID
 //   from the resources files. See resource.h and the .rc definitions for valid IDs.
@@ -94,6 +103,14 @@ static void EnsureNativeArchitecture()
 
 int __stdcall wWinMain(HINSTANCE, HINSTANCE, LPWSTR, int)
 {
+    TraceLoggingRegister(g_hWindowsTerminalProvider);
+    TraceLoggingWrite(
+        g_hWindowsTerminalProvider,
+        "ExecutableStarted",
+        TraceLoggingDescription("Event emitted immediately on startup"),
+        TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES),
+        TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance));
+
     // Block the user from starting if they launched the incorrect architecture version of the project.
     // This should only be applicable to developer versions. The package installation process
     // should choose and install the correct one from the bundle.

src/cascadia/WindowsTerminal/pch.h

@@ -52,3 +52,10 @@ Abstract:
 
 #include <wil/resource.h>
 #include <wil/win32_helpers.h>
+
+// Including TraceLogging essentials for the binary
+#include <TraceLoggingProvider.h>
+#include <winmeta.h>
+TRACELOGGING_DECLARE_PROVIDER(g_hWindowsTerminalProvider);
+#include <telemetry\ProjectTelemetry.h>
+#include <TraceLoggingActivity.h>