From e2de62347c4c515c507ca8be8a581908c7231f32 Mon Sep 17 00:00:00 2001
From: Florian Schmaus <flow@cs.fau.de>
Date: Tue, 12 Jan 2021 18:35:20 +0100
Subject: [PATCH] Add option to include timestamp in EMPER log messages

This also changes emper_log so that a std::ostringstream is used to
assemble the log message.
---
 .gitlab-ci.yml    |  9 +++++++++
 emper/Debug.cpp   | 40 ++++++++++++++++++++++++++++++++--------
 emper/Debug.hpp   |  2 ++
 emper/Emper.hpp   |  8 ++++++++
 iwyu-mappings.imp |  1 +
 meson.build       |  1 +
 meson_options.txt |  6 ++++++
 7 files changed, 59 insertions(+), 8 deletions(-)

diff --git a/.gitlab-ci.yml b/.gitlab-ci.yml
index e7629f99..675725ee 100644
--- a/.gitlab-ci.yml
+++ b/.gitlab-ci.yml
@@ -109,6 +109,10 @@ variables:
   variables:
     EMPER_WORKER_WAKEUP_STRATEGY: "all"
 
+.do-not-log-timestamp:
+  variables:
+    EMPER_LOG_TIMESTAMP: "false"
+
 test-gcc:
   extends:
     - .test
@@ -184,3 +188,8 @@ test-worker-wakeup-strategy-all:
   extends:
     - .test
     - .worker-wakeup-strategy-all
+
+test-do-not-log-timestamp:
+  extends:
+    - .test
+    - .do-not-log-timestamp
diff --git a/emper/Debug.cpp b/emper/Debug.cpp
index ffc6012f..6c324828 100644
--- a/emper/Debug.cpp
+++ b/emper/Debug.cpp
@@ -2,36 +2,60 @@
 // Copyright © 2020 Florian Schmaus
 #include "Debug.hpp"
 
+#include <chrono>
+#include <ctime>		 // for localtime
 #include <iomanip>	 // for operator<<, setfill, setw
 #include <iostream>	 // for operator<<, cerr, ostream, basic_ostream
 #include <mutex>		 // for mutex, unique_lock
 
 #include "Common.hpp"
+#include "Emper.hpp"
 #include "Worker.hpp"			 // for Runtime
 #include "emper-common.h"	 // for workerid_t
 #include "emper-config.h"	 // for EMPER_LOG_LEVEL
 
 static std::mutex emper_log_mutex;
 
+void emper_add_timestamp_to(std::ostringstream& logMessage) {
+	auto now = std::chrono::high_resolution_clock::now();
+
+	auto now_time_t = std::chrono::high_resolution_clock::to_time_t(now);
+	auto* now_localtime = std::localtime(&now_time_t);
+	logMessage << std::put_time(now_localtime, "%H%M.");
+
+	auto now_nanos = std::chrono::time_point_cast<std::chrono::nanoseconds>(now);
+	auto time_since_epoch = now_nanos.time_since_epoch();
+	long time_since_epoch_long = time_since_epoch.count();
+
+	long remaining_nanos = time_since_epoch_long % 1000000000;
+	logMessage << remaining_nanos;
+}
+
 void emper_log(const std::string& prefix, const std::string& message) {
 	Worker* worker = Worker::getCurrentWorker();
-	std::ostringstream workerPrefix;
+	std::ostringstream logMessage;
 	if (likely(worker)) {
 		workerid_t workerId = worker->getWorkerId();
 		std::string workerIdAsString = std::to_string(workerId);
-		workerPrefix << std::setfill('0') << std::setw(3) << workerIdAsString << " ";
+		logMessage << std::setfill('0') << std::setw(3) << workerIdAsString << " ";
 	} else {
-		workerPrefix << "    ";
+		logMessage << "    ";
+	}
+
+	if constexpr (emper::LOG_TIMESTAMP) {
+		emper_add_timestamp_to(logMessage);
 	}
 
-	std::unique_lock<std::mutex> lock(emper_log_mutex);
-	std::cerr << workerPrefix.str();
 	if (!prefix.empty()) {
-		std::cerr << " " << prefix << " ";
+		logMessage << " " << prefix << " ";
 	} else {
-		std::cerr << "       ";
+		logMessage << "       ";
 	}
-	std::cerr << message << std::endl;
+
+	logMessage << message;
+
+	std::unique_lock<std::mutex> lock(emper_log_mutex);
+	std::cerr << logMessage.str() << std::endl;
 }
 
 // global log_level which can be changed to control the log output
diff --git a/emper/Debug.hpp b/emper/Debug.hpp
index a2de8be4..71b9cea5 100644
--- a/emper/Debug.hpp
+++ b/emper/Debug.hpp
@@ -82,6 +82,8 @@ namespace emper {
 extern enum LogLevel log_level;
 }
 
+void emper_add_timestamp_to(std::ostringstream& logMessage);
+
 void emper_log(const std::string& prefix, const std::string& message);
 
 template <LogSubsystem logSubsystem>
diff --git a/emper/Emper.hpp b/emper/Emper.hpp
index b321dc1b..ef2ee4e1 100644
--- a/emper/Emper.hpp
+++ b/emper/Emper.hpp
@@ -48,5 +48,13 @@ static const bool DEBUG =
 #endif
 		;
 
+static const bool LOG_TIMESTAMP =
+#ifdef EMPER_LOG_TIMESTAMP
+		true
+#else
+		false
+#endif
+		;
+
 auto getFullVersion() -> std::string;
 }	 // namespace emper
diff --git a/iwyu-mappings.imp b/iwyu-mappings.imp
index 3b0d99be..d488f929 100644
--- a/iwyu-mappings.imp
+++ b/iwyu-mappings.imp
@@ -2,4 +2,5 @@
 	{ include: ["<bits/getopt_core.h>", "private", "<unistd.h>", "public"] },
 	{ include: ["@<gtest/.*>", "private", "<gtest/gtest.h>", "public"] },
 	{ include: ["<urcu/map/urcu-memb.h>", "private", "<urcu.h>", "public"] },
+	{ include: ["<bits/cxxabi_forced.h>", "private", "<ctime>", "public" ] },
 ]
diff --git a/meson.build b/meson.build
index 6d8f5d40..d0ae395f 100644
--- a/meson.build
+++ b/meson.build
@@ -44,6 +44,7 @@ elif log_level == 'OFF'
 	conf_data.set('EMPER_LOG_OFF', true)
 endif
 conf_data.set('EMPER_LOG_LEVEL', log_level)
+conf_data.set('EMPER_LOG_TIMESTAMP', get_option('log_timestamp'))
 
 subdir('emper')
 subdir('tests')
diff --git a/meson_options.txt b/meson_options.txt
index 99943e52..2fcd1b2c 100644
--- a/meson_options.txt
+++ b/meson_options.txt
@@ -10,6 +10,12 @@ option(
   choices: ['automatic', 'OFF', 'Error', 'Warning', 'Info', 'Debug', 'FineDebug', 'FinerDebug', 'FinestDebug', 'ALL'],
   value: 'automatic',
 )
+option(
+  'log_timestamp',
+  type: 'boolean',
+  value: true,
+  description: 'Add a timestamp to the EMPER log messages',
+)
 option(
   'worker_sleep',
   type: 'boolean',
-- 
GitLab