Merge branch 'feature/profiler' into 'main'

WIP: feature/profiler

See merge request beyondaka/beyond-protocol!79

.gitignore

@@ -10,3 +10,4 @@ docs/html
 /build*
 /.vs
 /CMakeSettings.json
+.vscode/*

.vscode/launch.json

@@ -5,12 +5,16 @@
     "version": "0.2.0",
     "configurations": [
         {
-            "name": "g++ - Debug Node",
+            "name": "(gdb) Launch",
             "type": "cppdbg",
             "request": "launch",
+            "program": "${command:cmake.launchTargetPath}",
             "args": [],
             "stopAtEntry": false,
             "cwd": "${workspaceFolder}/build",
+            "environment": [
+                {"name" : "ASAN_OPTIONS", "value" : "abort_on_error=1,protect_shadow_gap=0"}
+            ],
             "externalConsole": false,
             "MIMode": "gdb",
             "setupCommands": [
@@ -18,9 +22,38 @@
                     "description": "Enable pretty-printing for gdb",
                     "text": "-enable-pretty-printing",
                     "ignoreFailures": true
+                },
+                {
+                    "description": "Set Disassembly Flavor to Intel",
+                    "text": "-gdb-set disassembly-flavor intel",
+                    "ignoreFailures": true
+                }
+            ],
+            "sourceFileMap": {
+                "${workspaceFolder}": {	
+                    "editorPath": "${workspaceFolder}",
+                    "useForBreakpoints": "true"
+                }
+            }
+        },
+        {
+            "name": "(gdb) Attach",
+            "type": "cppdbg",
+            "request": "attach",
+            "program": "${command:cmake.launchTargetPath}",
+            "MIMode": "gdb",
+            "setupCommands": [
+                {
+                    "description": "Enable pretty-printing for gdb",
+                    "text": "-enable-pretty-printing",
+                    "ignoreFailures": true
+                },
+                {
+                    "description": "Set Disassembly Flavor to Intel",
+                    "text": "-gdb-set disassembly-flavor intel",
+                    "ignoreFailures": true
                 }
             ],
-            "miDebuggerPath": "/usr/bin/gdb",
             "sourceFileMap": {
                 "${workspaceFolder}": {
                     "editorPath": "${workspaceFolder}",

.vscode/settings.json

@@ -66,7 +66,18 @@
         "valarray": "cpp",
         "variant": "cpp",
         "any": "cpp",
-        "complex": "cpp"
+        "complex": "cpp",
+        "csignal": "cpp",
+        "compare": "cpp",
+        "concepts": "cpp",
+        "numbers": "cpp",
+        "ranges": "cpp",
+        "span": "cpp",
+        "stop_token": "cpp",
+        "typeindex": "cpp",
+        "semaphore": "cpp",
+        "*.ipp": "cpp"
     },
-    "cmake.cmakePath": "cmake"
+    "cmake.cmakePath": "cmake",
+    "cmake.configureOnOpen": true
 }
\ No newline at end of file

CMakeLists.txt

@@ -2,6 +2,7 @@ cmake_minimum_required (VERSION 3.18.0)
 include (CheckIncludeFile)
 include (CheckIncludeFileCXX)
 include (CheckFunctionExists)
+include (FetchContent)
 
 if (NOT FTL_VERSION)
 	set(FTL_VERSION 0.0.1)
@@ -18,6 +19,8 @@ option(WITH_GNUTLS "Enable TLS support" ON)
 option(USE_CPPCHECK "Apply cppcheck during build" ON)
 option(BUILD_TESTS "Compile all unit and integration tests" ON)
 option(BUILD_EXAMPLES "Compile the examples" ON)
+option(ENABLE_PROFILER "Enable builtin performance profiling" OFF)
+option(DEBUG_LOCKS "Enable lock profiling (requires ENABLE_PROFILER)" OFF)
 
 if (NOT WIN32)
 	option(WITH_PYTHON "Enable python support" ON)
@@ -98,6 +101,7 @@ if (USE_CPPCHECK)
 	endif()
 endif()
 
+include(ftl_tracy)
 include(git_version)
 include(ftl_paths)
 
@@ -177,6 +181,8 @@ target_include_directories(beyond-common PUBLIC
 	$<BUILD_INTERFACE:${CMAKE_CURRENT_SOURCE_DIR}/include>
 	$<INSTALL_INTERFACE:include>)
 
+target_link_libraries(beyond-common PUBLIC Tracy)
+
 add_library(beyond-protocol STATIC
 	$<TARGET_OBJECTS:beyond-common>
 	src/peer.cpp
@@ -207,7 +213,7 @@ add_library(beyond-protocol STATIC
 target_include_directories(beyond-protocol PUBLIC
 	$<BUILD_INTERFACE:${CMAKE_CURRENT_SOURCE_DIR}/include>
 	$<INSTALL_INTERFACE:include>)
-target_link_libraries(beyond-protocol Threads::Threads ${UUID_LIBRARIES})
+target_link_libraries(beyond-protocol Threads::Threads ${UUID_LIBRARIES} Tracy)
 
 if (WITH_GNUTLS)
 	target_link_libraries(beyond-protocol GnuTLS::GnuTLS)

cmake/ftl_tracy.cmake

+if (ENABLE_PROFILER)
+    set(TRACY_CXX_OPTIONS "-DTRACY_ENABLE -DTRACY_DELAYED_INIT -DTRACY_VERBOSE -DNOMINMAX")
+
+    if (DEBUG_LOCKS)
+        set(TRACY_CXX_OPTIONS "${TRACY_CXX_OPTIONS} -DDEBUG_LOCKS")
+        message(STATUS "Lock profiling enabled")
+    endif()
+
+    set(CMAKE_CXX_FLAGS "${CMAKE_CXX_FLAGS} ${TRACY_CXX_OPTIONS}")
+
+    FetchContent_Declare(tracy
+        GIT_REPOSITORY https://github.com/wolfpld/tracy.git
+        GIT_TAG 897aec5b062664d2485f4f9a213715d2e527e0ca # tags/v0.9.1
+        GIT_SHALLOW TRUE
+        GIT_PROGRESS TRUE
+    )
+    FetchContent_MakeAvailable(tracy)
+
+    add_library(Tracy ALIAS TracyClient)
+
+    message(STATUS "Profiling (Tracy) enabled")
+
+else()
+    add_library(Tracy INTERFACE)
+endif()

include/ftl/profiler.hpp

+/**
+ * @file profiler.hpp
+ * @copyright Copyright (c) 2020-2022 University of Turku, MIT License
+ * @author Nicolas Pope, Sebastian Hahta
+ */
+
+#pragma once
+
+#ifdef TRACY_ENABLE
+
+#include <tracy/Tracy.hpp>
+
+#define FTL_PROFILE_SCOPE(LABEL) ZoneScopedN(LABEL)
+
+// NOTE: Tracy expects Label to be a pointer to same address (this should be the case
+//       with GCC and MSVC with string pooling). If not, label has to be defined
+//       separately before use (static const char* ...) and exported if necessary
+
+/** Mark (secondary) frame start and stop. Each FTL_PROFILE_FRAME_BEGIN MUST be matched
+ * with FTL_PROFILE_FRAME_END */
+#define FTL_PROFILE_FRAME_BEGIN(LABEL) FrameMarkStart(#LABEL)
+#define FTL_PROFILE_FRAME_END(LABEL) FrameMarkEnd(#LABEL)
+
+/** Mark end of primary frame (main rendering/capture loop etc, if applicable) */
+#define FTL_PROFILE_PRIMARY_FRAME_END() FrameMark
+
+/// deprecated
+#define FTL_Profile(LABEL, LIMIT) FTL_PROFILE_SCOPE(LABEL)
+
+#else
+
+#define FTL_PROFILE_FRAME_BEGIN(LABEL) {}
+#define FTL_PROFILE_FRAME_END(LABEL) {}
+#define FTL_PROFILE_PRIMARY_FRAME_END() {}
+#define FTL_PROFILE_SCOPE(LABEL) {}
+
+/// deprectated
+#define FTL_Profile(LABEL, LIMIT) {}
+
+#endif

include/ftl/threads.hpp

@@ -12,29 +12,55 @@
 
 #define POOL_SIZE 10
 
-// #define DEBUG_MUTEX
-#define MUTEX_TIMEOUT 2
+/// consider using DECLARE_MUTEX(name) which allows (optional) profiling
+#define MUTEX std::mutex
+/// consider using DECLARE_RECURSIVE_MUTEX(name) which allows (optional) profiling
+#define RECURSIVE_MUTEX std::recursive_mutex
+/// consider using DECLARE_SHARED_MUTEX(name) which allows (optional) profiling
+#define SHARED_MUTEX std::shared_mutex
+
+#if defined(TRACY_ENABLE)
 
-#if defined DEBUG_MUTEX
-#include <ftl/lib/loguru.hpp>
-#include <chrono>
 #include <type_traits>
+#include <tracy/Tracy.hpp>
 
-#define MUTEX std::timed_mutex
-#define RECURSIVE_MUTEX std::recursive_timed_mutex
-#define SHARED_MUTEX std::shared_timed_mutex
+#define DECLARE_MUTEX(varname) TracyLockable(MUTEX, varname)
+#define DECLARE_RECURSIVE_MUTEX(varname) TracyLockable(RECURSIVE_MUTEX, varname)
+#define DECLARE_SHARED_MUTEX(varname) TracySharedLockable(SHARED_MUTEX, varname)
 
-#define UNIQUE_LOCK(M, L) std::unique_lock<std::remove_reference<decltype(M)>::type> L(M, std::chrono::milliseconds(MUTEX_TIMEOUT)); while (!L) { LOG(ERROR) << "Mutex timeout"; L.try_lock_for(std::chrono::milliseconds(MUTEX_TIMEOUT)); };
-#define SHARED_LOCK(M, L) std::shared_lock<std::remove_reference<decltype(M)>::type> L(M, std::chrono::milliseconds(MUTEX_TIMEOUT)); while (!L) { LOG(ERROR) << "Mutex timeout"; L.try_lock_for(std::chrono::milliseconds(MUTEX_TIMEOUT)); };
+#define DECLARE_MUTEX_N(varname, name) TracyLockableN(MUTEX, varname, name)
+#define DECLARE_RECURSIVE_MUTEX_N(varname, name) TracyLockableN(RECURSIVE_MUTEX, varname, name)
+#define DECLARE_SHARED_MUTEX_N(varname, name) TracySharedLockableN(SHARED_MUTEX, varname, name)
+
+/// mark lock acquired (mutex M);
+#define MARK_LOCK_AQUIRED(M) LockMark(M)
+// TODO: should automatic, but requires mutexes to be declared with DECLARE_..._MUTEX macros
+
+#define T_UNIQUE_LOCK(M) std::unique_lock<std::remove_reference<decltype(M)>::type>
+#define UNIQUE_LOCK(M, L) std::unique_lock<std::remove_reference<decltype(M)>::type> L(M)
+#define SHARED_LOCK(M, L) std::shared_lock<std::remove_reference<decltype(M)>::type> L(M)
 
 #else
-#define MUTEX std::mutex
-#define RECURSIVE_MUTEX std::recursive_mutex
-#define SHARED_MUTEX std::shared_mutex
 
-#define UNIQUE_LOCK(M, L) std::unique_lock<std::remove_reference<decltype(M)>::type> L(M);
-#define SHARED_LOCK(M, L) std::shared_lock<std::remove_reference<decltype(M)>::type> L(M);
-#endif  // DEBUG_MUTEX
+/// mutex with optional profiling (and debugging) when built with PROFILE_MUTEX.
+#define DECLARE_MUTEX(varname) MUTEX varname
+/// recursive mutex with optional profiling (and debugging) when built with PROFILE_MUTEX
+#define DECLARE_RECURSIVE_MUTEX(varname) RECURSIVE_MUTEX varname
+/// shared mutex with optional profiling (and debugging) when built with PROFILE_MUTEX
+#define DECLARE_SHARED_MUTEX(varname) SHARED_MUTEX varname
+
+#define DECLARE_MUTEX_N(varname, name) MUTEX varname
+#define DECLARE_RECURSIVE_MUTEX_N(varname, name) RECURSIVE_MUTEX varname
+#define DECLARE_SHARED_MUTEX_N(varname, name) SHARED_MUTEX varname
+
+/// mark lock acquired (mutex M)
+#define MARK_LOCK(M) {}
+
+#define T_UNIQUE_LOCK(M) std::unique_lock<std::remove_reference<decltype(M)>::type>
+#define UNIQUE_LOCK(M, L) std::unique_lock<std::remove_reference<decltype(M)>::type> L(M)
+#define SHARED_LOCK(M, L) std::shared_lock<std::remove_reference<decltype(M)>::type> L(M)
+
+#endif  // TRACY_ENABLE
 
 #define SHARED_LOCK_TYPE(M) std::shared_lock<M>
 

src/ctpl_stl.cpp

@@ -5,9 +5,20 @@
 
 #include <ftl/lib/ctpl_stl.hpp>
 
+#ifdef TRACY_ENABLE
+#include <tracy/Tracy.hpp>
+#endif
+
 void ctpl::thread_pool::set_thread(int i) {
     std::shared_ptr<std::atomic<bool>> flag(this->flags[i]);  // a copy of the shared ptr to the flag
     auto f = [this, i, flag/* a copy of the shared ptr to the flag */]() {
+        #if TRACY_ENABLE
+        {
+            const auto thread_name = "thread_pool/" + std::to_string(i);
+            tracy::SetThreadName(thread_name.c_str());
+        }
+        #endif
+        
         std::atomic<bool> & _flag = *flag;
         std::function<void(int id)> * _f;
         bool isPop = this->q.pop(_f);

src/peer.hpp

@@ -260,9 +260,8 @@ class Peer {
 
     // Send buffers
     msgpack::vrefbuffer send_buf_;
-    RECURSIVE_MUTEX send_mtx_;
-
-    RECURSIVE_MUTEX cb_mtx_;
+    DECLARE_RECURSIVE_MUTEX(send_mtx_);
+    DECLARE_RECURSIVE_MUTEX(cb_mtx_);
 
     const bool outgoing_;
     unsigned int local_id_;

src/protocol/connection.cpp

@@ -111,7 +111,7 @@ ssize_t SocketConnection::writev(const struct iovec *iov, int iovcnt) {
         writev_calls++;
 
         if (sent < 0) {
-            DLOG(ERROR) << "writev(): " << sock_.get_error_string();
+            LOG(2) << "writev(): " << sock_.get_error_string();
             if (sock_.is_fatal()) {
                 return sent;
             }
@@ -121,7 +121,7 @@ ssize_t SocketConnection::writev(const struct iovec *iov, int iovcnt) {
         sent_total += sent;
     }
 
-    DLOG(2) << "message required " << writev_calls << " writev() calls";
+    LOG(2) << "message required " << writev_calls << " writev() calls";
 
     /*if (can_increase_sock_buffer_) {
         auto send_buf_size = sock_.get_send_buffer_size();

src/universe.cpp

@@ -75,6 +75,7 @@ struct NetImplDetail {
 
 // TODO(Seb): move to ServerSocket and ClientSocket
 // Defaults, should be changed in config
+
 #define TCP_SEND_BUFFER_SIZE    (32*1024*1024)
 #define TCP_RECEIVE_BUFFER_SIZE (32*1024*1024)  // Perhaps try 24K?
 #define WS_SEND_BUFFER_SIZE     (32*1024*1024)