From 4e47aa6d9e897a566db8ba43d01ff6e68b910d9f Mon Sep 17 00:00:00 2001
From: heck <heck@pep.foundation>
Date: Mon, 20 Apr 2020 21:22:40 +0200
Subject: [PATCH] pEpLog() / pEpErr() - Add high-res timestamp Add
 test_peplog.cc

---
 test/Makefile       |  5 ++++-
 test/test_peplog.cc | 16 ++++++++++++++++
 utils.hh            | 40 +++++++++++++++++++++++++++++++++++-----
 3 files changed, 55 insertions(+), 6 deletions(-)
 create mode 100644 test/test_peplog.cc

diff --git a/test/Makefile b/test/Makefile
index 7f8f4d2..0d64421 100644
--- a/test/Makefile
+++ b/test/Makefile
@@ -6,7 +6,7 @@ CXXFLAGS+=-I../
 
 .PHONY=all, test_adapter, test_adapter_cxx, test_library
 
-all: test_adapter test_adapter_cxx test_library
+all: test_adapter test_adapter_cxx test_library test_peplog
 
 test_adapter: test_adapter.cc ../libpEpAdapter.a
 
@@ -14,6 +14,9 @@ test_adapter_cxx: test_adapter_cxx.cc ../libpEpAdapter.a
 
 test_library: test_library.cc ../libpEpAdapter.a
 
+test_peplog: test_peplog.cc
+
+
 clean:	
 	rm -vf test_adapter
 	rm -rvf test_adapter.dSYM
diff --git a/test/test_peplog.cc b/test/test_peplog.cc
new file mode 100644
index 0000000..2210238
--- /dev/null
+++ b/test/test_peplog.cc
@@ -0,0 +1,16 @@
+// This file is under GNU General Public License 3.0
+// see LICENSE.txt
+
+#include "utils.hh"
+// Single threaded test of pEpLog() function.
+// check for uniformity of time
+
+int main()
+{
+    pEpLog("Test Starting... observe uniformity of timestamp.");
+    int nr_log_lines = 1000000;
+    for (int i; i < nr_log_lines; i++) {
+        pEpLog("log line nr: " << i);
+    }
+    return 0;
+}
diff --git a/utils.hh b/utils.hh
index 5ddb8be..f03b500 100644
--- a/utils.hh
+++ b/utils.hh
@@ -1,12 +1,42 @@
 #pragma once
-
 #include <iostream>
 #include <thread>
+#include <sstream>
+#include <iomanip>
+
+// Returns a timestamp string featuring microseconds precision
+// Uses system clock, so time might not pass uniformly
+
+inline std::string timestamp_usec() {
+    std::ostringstream buffer;
+    std::chrono::system_clock::duration d = std::chrono::system_clock::now().time_since_epoch();
+
+    std::chrono::microseconds us = std::chrono::duration_cast<std::chrono::microseconds>(d);
+    std::chrono::seconds       s = std::chrono::duration_cast<std::chrono::seconds>     (d);
+
+    std::time_t t = s.count();
+    std::tm tm = *std::localtime(&t);
+
+    std::size_t fractional_seconds = us.count() % 1000000;
+    buffer << std::put_time(&tm, "%H%:%M:%S") << "." << fractional_seconds;
+
+    return buffer.str();
+}
+
+// pEpLog(msg) - logs to STDOUT
+// pEpErr(msg) - logs to STDERR
+//
+// Log format is:
+// TIMESTAMP.usecs THREAD-ID SRC_FILE_NAME::FUNCTION_NAME - msg
+//
+// example:
+// 21:06:04.214884 Thread:0x10f2ce5c0 test_peplog.cc::main - test run nr: 436744
+//
+// if -DNDEBUG=1 (for release builds), all pEpLog() calls will be optimized away.
 
 #ifdef NDEBUG
-    #define pEpLog(msg)  do{}while(0)
+#define pEpLog(msg) do{}while(0)
 #else
-    #define pEpLog(msg) do{std::cout << "Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0)
+#define pEpLog(msg) do{ std::cout << timestamp_usec() << " Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0)
 #endif
-
-#define pEpErr(msg) do{std::cerr << "Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0)
\ No newline at end of file
+#define pEpErr(msg) do{ std::cout << timestamp_usec() << " Thread:" << std::this_thread::get_id() << ' ' <<__FILE__ << "::" << __FUNCTION__ << " - " << msg << '\n';} while(0)