[FancyZones] Trace various function calls (#10183)

* Implement CallTracer

* Add CallTracer to various places

* Newline

* Fix unit tests not compiling for some reason

* Add macro
remove some trace calls

* Add indentation

* Add semicolon

* Update src/modules/fancyzones/lib/CallTracer.cpp

Co-authored-by: Enrico Giordani <enricogior@users.noreply.github.com>

* Actually indent/unindent output

* Fix initial indent level

Co-authored-by: Enrico Giordani <enrico.giordani@gmail.com>
Co-authored-by: Enrico Giordani <enricogior@users.noreply.github.com>

src/modules/fancyzones/lib/CallTracer.cpp

@@ -0,0 +1,53 @@
+#include "pch.h"
+#include "CallTracer.h"
+#include <thread>
+
+namespace
+{
+    // Non-localizable
+    const std::string entering = " Enter";
+    const std::string exiting = " Exit";
+
+    std::mutex indentLevelMutex;
+    std::map<std::thread::id, int> indentLevel;
+
+    std::string GetIndentation()
+    {
+        std::unique_lock lock(indentLevelMutex);
+        int level = indentLevel[std::this_thread::get_id()];
+
+        if (level <= 0)
+        {
+            return {};
+        }
+        else
+        {
+            return std::string(2 * min(level, 64) - 1, ' ') + " - ";
+        }
+    }
+
+    void Indent()
+    {
+        std::unique_lock lock(indentLevelMutex);
+        indentLevel[std::this_thread::get_id()]++;
+    }
+
+    void Unindent()
+    {
+        std::unique_lock lock(indentLevelMutex);
+        indentLevel[std::this_thread::get_id()]--;
+    }
+}
+
+CallTracer::CallTracer(const char* functionName) :
+    functionName(functionName)
+{
+    Logger::trace((GetIndentation() + functionName + entering).c_str());
+    Indent();
+}
+
+CallTracer::~CallTracer()
+{
+    Unindent();
+    Logger::trace((GetIndentation() + functionName + exiting).c_str());
+}

src/modules/fancyzones/lib/CallTracer.h

@@ -0,0 +1,13 @@
+#pragma once
+
+#include "common/logger/logger.h"
+
+#define _TRACER_ CallTracer callTracer(__FUNCTION__)
+
+class CallTracer
+{
+    std::string functionName;
+public:
+    CallTracer(const char* functionName);
+    ~CallTracer();
+};

src/modules/fancyzones/lib/FancyZones.cpp

@@ -19,6 +19,7 @@
 #include "VirtualDesktopUtils.h"
 #include "MonitorWorkAreaHandler.h"
 #include "util.h"
+#include "CallTracer.h"
 
 #include <lib/SecondaryMouseButtonsHook.h>
 
@@ -89,6 +90,7 @@ struct FancyZones : public winrt::implements<FancyZones, IFancyZones, IFancyZone
 
     void MoveSizeEnd(HWND window, POINT const& ptScreen) noexcept
     {
+        _TRACER_;
         std::unique_lock writeLock(m_lock);
         m_windowMoveHandler.MoveSizeEnd(window, ptScreen, m_workAreaHandler.GetWorkAreasByDesktopId(m_currentDesktopId));
     }
@@ -421,6 +423,7 @@ std::pair<winrt::com_ptr<IZoneWindow>, std::vector<size_t>> FancyZones::GetAppZo
 
 void FancyZones::MoveWindowIntoZone(HWND window, winrt::com_ptr<IZoneWindow> zoneWindow, const std::vector<size_t>& zoneIndexSet) noexcept
 {
+    _TRACER_;
     auto& fancyZonesData = FancyZonesDataInstance();
     if (!fancyZonesData.IsAnotherWindowOfApplicationInstanceZoned(window, zoneWindow->UniqueId()))
     {
@@ -592,6 +595,7 @@ FancyZones::OnKeyDown(PKBDLLHOOKSTRUCT info) noexcept
 // IFancyZonesCallback
 void FancyZones::ToggleEditor() noexcept
 {
+    _TRACER_;
     {
         std::shared_lock readLock(m_lock);
         if (m_terminateEditorEvent)
@@ -883,6 +887,7 @@ LRESULT FancyZones::WndProc(HWND window, UINT message, WPARAM wparam, LPARAM lpa
 
 void FancyZones::OnDisplayChange(DisplayChangeType changeType) noexcept
 {
+    _TRACER_;
     if (changeType == DisplayChangeType::VirtualDesktop ||
         changeType == DisplayChangeType::Initialization)
     {
@@ -920,6 +925,7 @@ void FancyZones::OnDisplayChange(DisplayChangeType changeType) noexcept
 
 void FancyZones::AddZoneWindow(HMONITOR monitor, const std::wstring& deviceId) noexcept
 {
+    _TRACER_;
     std::unique_lock writeLock(m_lock);
 
     if (m_workAreaHandler.IsNewWorkArea(m_currentDesktopId, monitor))
@@ -1005,7 +1011,9 @@ void FancyZones::UpdateZoneWindows() noexcept
 
 void FancyZones::UpdateWindowsPositions() noexcept
 {
+    _TRACER_;
     auto callback = [](HWND window, LPARAM data) -> BOOL {
+        _TRACER_;
         size_t bitmask = reinterpret_cast<size_t>(::GetProp(window, ZonedWindowProperties::PropertyMultipleZoneID));
 
         if (bitmask != 0)
@@ -1034,6 +1042,7 @@ void FancyZones::UpdateWindowsPositions() noexcept
 
 void FancyZones::CycleActiveZoneSet(DWORD vkCode) noexcept
 {
+    _TRACER_;
     auto window = GetForegroundWindow();
     if (FancyZonesUtils::IsCandidateForZoning(window, m_settings->GetSettings()->excludedAppsArray))
     {
@@ -1053,6 +1062,7 @@ void FancyZones::CycleActiveZoneSet(DWORD vkCode) noexcept
 
 bool FancyZones::OnSnapHotkeyBasedOnZoneNumber(HWND window, DWORD vkCode) noexcept
 {
+    _TRACER_;
     HMONITOR current;
 
     if (m_settings->GetSettings()->spanZonesAcrossMonitors)
@@ -1283,6 +1293,7 @@ bool FancyZones::ProcessDirectedSnapHotkey(HWND window, DWORD vkCode, bool cycle
 
 void FancyZones::RegisterVirtualDesktopUpdates(std::vector<GUID>& ids) noexcept
 {
+    _TRACER_;
     std::unique_lock writeLock(m_lock);
 
     m_workAreaHandler.RegisterUpdates(ids);
@@ -1368,6 +1379,7 @@ std::vector<HMONITOR> FancyZones::GetMonitorsSorted() noexcept
 
 std::vector<std::pair<HMONITOR, RECT>> FancyZones::GetRawMonitorData() noexcept
 {
+    _TRACER_;
     std::shared_lock readLock(m_lock);
 
     std::vector<std::pair<HMONITOR, RECT>> monitorInfo;

src/modules/fancyzones/lib/FancyZonesData.cpp

@@ -4,6 +4,7 @@
 #include "JsonHelpers.h"
 #include "ZoneSet.h"
 #include "Settings.h"
+#include "CallTracer.h"
 
 #include <common/utils/json.h>
 #include <fancyzones/lib/util.h>
@@ -153,6 +154,24 @@ FancyZonesData::FancyZonesData()
     editorParametersFileName = saveFolderPath + L"\\" + std::wstring(NonLocalizable::FancyZonesEditorParametersFile);
 }
 
+const JSONHelpers::TDeviceInfoMap& FancyZonesData::GetDeviceInfoMap() const
+{
+    std::scoped_lock lock{ dataLock };
+    return deviceInfoMap;
+}
+
+const JSONHelpers::TCustomZoneSetsMap& FancyZonesData::GetCustomZoneSetsMap() const
+{
+    std::scoped_lock lock{ dataLock };
+    return customZoneSetsMap;
+}
+
+const std::unordered_map<std::wstring, std::vector<FancyZonesDataTypes::AppZoneHistoryData>>& FancyZonesData::GetAppZoneHistoryMap() const
+{
+    std::scoped_lock lock{ dataLock };
+    return appZoneHistoryMap;
+}
+
 std::optional<FancyZonesDataTypes::DeviceInfoData> FancyZonesData::FindDeviceInfo(const std::wstring& zoneWindowId) const
 {
     std::scoped_lock lock{ dataLock };
@@ -169,6 +188,7 @@ std::optional<FancyZonesDataTypes::CustomZoneSetData> FancyZonesData::FindCustom
 
 bool FancyZonesData::AddDevice(const std::wstring& deviceId)
 {
+    _TRACER_;
     using namespace FancyZonesDataTypes;
 
     std::scoped_lock lock{ dataLock };
@@ -214,6 +234,7 @@ void FancyZonesData::CloneDeviceInfo(const std::wstring& source, const std::wstr
 
 void FancyZonesData::UpdatePrimaryDesktopData(const std::wstring& desktopId)
 {
+    _TRACER_;
     // Explorer persists current virtual desktop identifier to registry on a per session basis,
     // but only after first virtual desktop switch happens. If the user hasn't switched virtual
     // desktops in this session value in registry will be empty and we will use default GUID in
@@ -377,6 +398,7 @@ std::vector<size_t> FancyZonesData::GetAppLastZoneIndexSet(HWND window, const st
 
 bool FancyZonesData::RemoveAppLastZone(HWND window, const std::wstring_view& deviceId, const std::wstring_view& zoneSetId)
 {
+    _TRACER_;
     std::scoped_lock lock{ dataLock };
     auto processPath = get_process_path(window);
     if (!processPath.empty())
@@ -429,6 +451,7 @@ bool FancyZonesData::RemoveAppLastZone(HWND window, const std::wstring_view& dev
 
 bool FancyZonesData::SetAppLastZones(HWND window, const std::wstring& deviceId, const std::wstring& zoneSetId, const std::vector<size_t>& zoneIndexSet)
 {
+    _TRACER_;
     std::scoped_lock lock{ dataLock };
 
     if (IsAnotherWindowOfApplicationInstanceZoned(window, deviceId))
@@ -524,14 +547,14 @@ void FancyZonesData::SaveAppZoneHistoryAndZoneSettings() const
 
 void FancyZonesData::SaveZoneSettings() const
 {
-    Logger::trace("FancyZonesData::SaveZoneSettings()");
+    _TRACER_;
     std::scoped_lock lock{ dataLock };
     JSONHelpers::SaveZoneSettings(zonesSettingsFileName, deviceInfoMap, customZoneSetsMap);
 }
 
 void FancyZonesData::SaveAppZoneHistory() const
 {
-    Logger::trace("FancyZonesData::SaveAppZoneHistory()");
+    _TRACER_;
     std::scoped_lock lock{ dataLock };
     JSONHelpers::SaveAppZoneHistory(appZoneHistoryFileName, appZoneHistoryMap);
 }

src/modules/fancyzones/lib/FancyZonesData.h

@@ -42,23 +42,11 @@ class FancyZonesData
 
     std::optional<FancyZonesDataTypes::CustomZoneSetData> FindCustomZoneSet(const std::wstring& guid) const;
 
-    inline const JSONHelpers::TDeviceInfoMap & GetDeviceInfoMap() const
-    {
-        std::scoped_lock lock{ dataLock };
-        return deviceInfoMap;
-    }
+    const JSONHelpers::TDeviceInfoMap& GetDeviceInfoMap() const;
 
-    inline const JSONHelpers::TCustomZoneSetsMap & GetCustomZoneSetsMap() const
-    {
-        std::scoped_lock lock{ dataLock };
-        return customZoneSetsMap;
-    }
+    const JSONHelpers::TCustomZoneSetsMap& GetCustomZoneSetsMap() const;
 
-    inline const std::unordered_map<std::wstring, std::vector<FancyZonesDataTypes::AppZoneHistoryData>>& GetAppZoneHistoryMap() const
-    {
-        std::scoped_lock lock{ dataLock };
-        return appZoneHistoryMap;
-    }
+    const std::unordered_map<std::wstring, std::vector<FancyZonesDataTypes::AppZoneHistoryData>>& GetAppZoneHistoryMap() const;
 
     inline const std::wstring& GetZonesSettingsFileName() const 
     {

src/modules/fancyzones/lib/FancyZonesLib.vcxproj

@@ -37,6 +37,7 @@
     </ClCompile>
   </ItemDefinitionGroup>
   <ItemGroup>
+    <ClInclude Include="CallTracer.h" />
     <ClInclude Include="FancyZones.h" />
     <ClInclude Include="FancyZonesDataTypes.h" />
     <ClInclude Include="FancyZonesWinHookEventIDs.h" />
@@ -61,6 +62,7 @@
     <ClInclude Include="ZoneWindowDrawing.h" />
   </ItemGroup>
   <ItemGroup>
+    <ClCompile Include="CallTracer.cpp" />
     <ClCompile Include="FancyZones.cpp" />
     <ClCompile Include="FancyZonesDataTypes.cpp" />
     <ClCompile Include="FancyZonesWinHookEventIDs.cpp" />

src/modules/fancyzones/lib/FancyZonesLib.vcxproj.filters

@@ -81,6 +81,9 @@
     <ClInclude Include="FileWatcher.h">
       <Filter>Header Files</Filter>
     </ClInclude>
+    <ClInclude Include="CallTracer.h">
+      <Filter>Header Files</Filter>
+    </ClInclude>
   </ItemGroup>
   <ItemGroup>
     <ClCompile Include="pch.cpp">
@@ -140,6 +143,9 @@
     <ClCompile Include="FileWatcher.cpp">
       <Filter>Source Files</Filter>
     </ClCompile>
+    <ClCompile Include="CallTracer.cpp">
+      <Filter>Source Files</Filter>
+    </ClCompile>
   </ItemGroup>
   <ItemGroup>
     <None Include="packages.config" />

src/modules/fancyzones/lib/OnThreadExecutor.cpp

@@ -1,6 +1,7 @@
 #include "pch.h"
 
 #include "on_thread_executor.h"
+#include "CallTracer.h"
 
 OnThreadExecutor::OnThreadExecutor() :
     _shutdown_request{ false }, _worker_thread{ [this] { worker_thread(); } }
@@ -30,6 +31,7 @@ void OnThreadExecutor::worker_thread()
     {
         task_t task;
         {
+            CallTracer callTracer(__FUNCTION__ "(loop)");
             std::unique_lock task_lock{ _task_mutex };
             _task_cv.wait(task_lock, [this] { return !_task_queue.empty() || _shutdown_request; });
             if (_shutdown_request)

src/modules/fancyzones/lib/ZoneWindow.cpp

@@ -10,6 +10,7 @@
 #include "util.h"
 #include "on_thread_executor.h"
 #include "Settings.h"
+#include "CallTracer.h"
 
 #include <ShellScalingApi.h>
 #include <mutex>
@@ -41,6 +42,7 @@ namespace
 
         HWND ExtractWindow()
         {
+            _TRACER_;
             std::unique_lock lock(m_mutex);
 
             if (m_pool.empty())
@@ -80,6 +82,7 @@ namespace
 
         void FreeZoneWindow(HWND window)
         {
+            _TRACER_;
             Logger::info("Freeing zone window, hWnd = {}", (void*)window);
             SetWindowLongPtrW(window, GWLP_USERDATA, 0);
             ShowWindow(window, SW_HIDE);

src/modules/fancyzones/lib/ZoneWindowDrawing.cpp

@@ -1,5 +1,6 @@
 #include "pch.h"
 #include "ZoneWindowDrawing.h"
+#include "CallTracer.h"
 
 #include <algorithm>
 #include <map>
@@ -202,6 +203,7 @@ void ZoneWindowDrawing::Render()
 
 void ZoneWindowDrawing::Hide()
 {
+    _TRACER_;
     m_lowLatencyLock = true;
     std::unique_lock lock(m_mutex);
     m_lowLatencyLock = false;
@@ -215,6 +217,7 @@ void ZoneWindowDrawing::Hide()
 
 void ZoneWindowDrawing::Show(unsigned animationMillis)
 {
+    _TRACER_;
     m_lowLatencyLock = true;
     std::unique_lock lock(m_mutex);
     m_lowLatencyLock = false;
@@ -235,6 +238,7 @@ void ZoneWindowDrawing::DrawActiveZoneSet(const IZoneSet::ZonesMap& zones,
                        const std::vector<size_t>& highlightZones,
                        winrt::com_ptr<IZoneWindowHost> host)
 {
+    _TRACER_;
     m_lowLatencyLock = true;
     std::unique_lock lock(m_mutex);
     m_lowLatencyLock = false;