Time logger functions

tangrams · Feb 1, 2019 · 8b13e60 · 8b13e60
1 parent c3ac543
commit 8b13e60
Show file tree

Hide file tree

Showing 2 changed files with 54 additions and 0 deletions.
diff --git a/core/include/tangram/log.h b/core/include/tangram/log.h
@@ -66,3 +66,52 @@ do { Tangram::logMsg("ERROR %s:%d: " fmt "\n", __FILENAME__, __LINE__, ## __VA_A
 #define LOG(fmt, ...)
 #define LOGN(fmt, ...)
 #endif
+
+#if 1
+#include <mutex>
+#include <chrono>
+
+extern std::chrono::time_point<std::chrono::system_clock> tangram_log_time_start, tangram_log_time_last;
+extern std::mutex tangram_log_time_mutex;
+
+#define LOGTIME(fmt, ...) do { \
+    int l = strlen( __FILENAME__);  \
+    Tangram::logMsg("TIME %-18.*s " fmt "\n",                            \
+                    l > 4 ? l-4 : l, __FILENAME__, ##__VA_ARGS__); } while (0)
+
+// Overall timing init/reset
+#define LOGTOInit() do {                                                \
+        std::lock_guard<std::mutex> lock(tangram_log_time_mutex);       \
+        tangram_log_time_last = tangram_log_time_start = std::chrono::system_clock::now(); } while(0)
+
+// Overall timing
+#define LOGTO(fmt, ...) do {                                            \
+        std::lock_guard<std::mutex> lock(tangram_log_time_mutex);       \
+        std::chrono::time_point<std::chrono::system_clock> now = std::chrono::system_clock::now(); \
+        std::chrono::duration<double> t1 = now - tangram_log_time_start; \
+        std::chrono::duration<double> t2 = now - tangram_log_time_last; \
+        tangram_log_time_last = now;                                    \
+        LOGTIME("%7.2f %7.2f " fmt, t1.count()*1000.f, t2.count()*1000.f, ## __VA_ARGS__); } while(0)
+
+// Local timing init
+#define LOGTInit(fmt, ...)                                              \
+    std::chrono::time_point<std::chrono::system_clock> _time_last, _time_start; \
+    std::chrono::time_point<std::chrono::system_clock> now = std::chrono::system_clock::now(); \
+    std::chrono::duration<double> t0 = now - tangram_log_time_start;    \
+    _time_start = _time_last = now;                                     \
+    LOGTIME("%7.2f                 " fmt, t0.count()*1000.f, ## __VA_ARGS__)
+
+// Local timing
+#define LOGT(fmt, ...) do {                                               \
+        std::chrono::time_point<std::chrono::system_clock> now = std::chrono::system_clock::now(); \
+        std::chrono::duration<double> t0 = now - tangram_log_time_start; \
+        std::chrono::duration<double> t1 = now - _time_start;           \
+        std::chrono::duration<double> t2 = now - _time_last;            \
+        _time_last = now;                                               \
+        LOGTIME("%7.2f %7.2f %7.2f " fmt, t0.count()*1000.f, t1.count()*1000.f, t2.count()*1000.f, ## __VA_ARGS__); } while(0)
+#else
+#define LOGT(...)
+#define LOGTInit(...)
+#define LOGTOInit()
+#define LOGTO(...)
+#endif
diff --git a/core/src/platform.cpp b/core/src/platform.cpp
@@ -5,6 +5,11 @@
 #include <string>
 #include <cassert>
 
+#ifdef LOGTIME
+std::chrono::time_point<std::chrono::system_clock> tangram_log_time_start, tangram_log_time_last;
+std::mutex tangram_log_time_mutex;
+#endif
+
 constexpr char const* shutdown_message = "Shutting down";
 constexpr char const* cancel_message = "Request canceled";