fixes for log timestamps (#304)

* add GetTimeSinceProcessStart returning time since process start. implemented using https://github.com/maxliani/GetTimeSinceProcessStart/tree/main
* fix fractions when using epoch mode. Previously it would show the fraction from the absolute time stamp and not relative to epoch
* used GetTimeSinceProcessStart to offset the epoch so that it represents the process spawn time

5 files changed, 26 insertions, 3 deletions

diff --git a/src/zencore/include/zencore/timer.h b/src/zencore/include/zencore/timer.h
index e4ddc3505..767dc4314 100644
--- a/src/zencore/include/zencore/timer.h
+++ b/src/zencore/include/zencore/timer.h
@@ -21,6 +21,10 @@ ZENCORE_API uint64_t GetHifreqTimerFrequency();
 ZENCORE_API double	 GetHifreqTimerToSeconds();
 ZENCORE_API uint64_t GetHifreqTimerFrequencySafe();	 // May be used during static init
 
+// Query time since process was spawned (returns time in ms)
+
+uint64_t GetTimeSinceProcessStart();
+
 class Stopwatch
 {
 public:
diff --git a/src/zencore/timer.cpp b/src/zencore/timer.cpp
index 1655e912d..95536cb26 100644
--- a/src/zencore/timer.cpp
+++ b/src/zencore/timer.cpp
@@ -12,9 +12,20 @@
 #	include <unistd.h>
 #endif
 
+#define GTSPS_IMPLEMENTATION
+#include "GetTimeSinceProcessStart.h"
+
 namespace zen {
 
 uint64_t
+GetTimeSinceProcessStart()
+{
+	double TimeInSeconds = ::GetTimeSinceProcessStart();
+
+	return uint64_t(TimeInSeconds * 1000);
+}
+
+uint64_t
 GetHifreqTimerValue()
 {
 	uint64_t Timestamp;
diff --git a/src/zencore/xmake.lua b/src/zencore/xmake.lua
index b8b14084c..13611a2e9 100644
--- a/src/zencore/xmake.lua
+++ b/src/zencore/xmake.lua
@@ -29,6 +29,7 @@ target('zencore')
     end
 
     add_includedirs("include", {public=true})
+    add_includedirs("$(projectdir)/thirdparty/GetTimeSinceProcessStart")
     add_includedirs("$(projectdir)/thirdparty/utfcpp/source")
     add_includedirs("$(projectdir)/thirdparty/Oodle/include")
     add_includedirs("$(projectdir)/thirdparty/trace", {public=true})
diff --git a/src/zenutil/include/zenutil/logging/fullformatter.h b/src/zenutil/include/zenutil/logging/fullformatter.h
index 07ad408fa..0326870e5 100644
--- a/src/zenutil/include/zenutil/logging/fullformatter.h
+++ b/src/zenutil/include/zenutil/logging/fullformatter.h
@@ -45,6 +45,8 @@ public:
 
 		std::chrono::seconds TimestampSeconds;
 
+		std::chrono::milliseconds millis;
+
 		if (m_UseFullDate)
 		{
 			TimestampSeconds = std::chrono::duration_cast<std::chrono::seconds>(msg.time.time_since_epoch());
@@ -69,6 +71,8 @@ public:
 				spdlog::details::fmt_helper::pad2(m_CachedLocalTm.tm_sec, m_CachedDatetime);
 				m_CachedDatetime.push_back('.');
 			}
+
+			millis = spdlog::details::fmt_helper::time_fraction<std::chrono::milliseconds>(msg.time);
 		}
 		else
 		{
@@ -97,6 +101,8 @@ public:
 				spdlog::details::fmt_helper::pad2(LogSecs, m_CachedDatetime);
 				m_CachedDatetime.push_back('.');
 			}
+
+			millis = std::chrono::duration_cast<std::chrono::milliseconds>(ElapsedTime - TimestampSeconds);
 		}
 
 		{
@@ -104,7 +110,6 @@ public:
 			OutBuffer.append(m_CachedDatetime.begin(), m_CachedDatetime.end());
 		}
 
-		auto millis = spdlog::details::fmt_helper::time_fraction<std::chrono::milliseconds>(msg.time);
 		spdlog::details::fmt_helper::pad3(static_cast<uint32_t>(millis.count()), OutBuffer);
 		OutBuffer.push_back(']');
 		OutBuffer.push_back(' ');
diff --git a/src/zenutil/logging.cpp b/src/zenutil/logging.cpp
index 762b75a59..cb0fd6679 100644
--- a/src/zenutil/logging.cpp
+++ b/src/zenutil/logging.cpp
@@ -16,6 +16,7 @@ ZEN_THIRD_PARTY_INCLUDES_END
 #include <zencore/logging.h>
 #include <zencore/memory/llm.h>
 #include <zencore/string.h>
+#include <zencore/timer.h>
 #include <zenutil/logging/fullformatter.h>
 #include <zenutil/logging/jsonformatter.h>
 #include <zenutil/logging/rotatingfilesink.h>
@@ -191,8 +192,9 @@ FinishInitializeLogging(const LoggingOptions& LogOptions)
 	logging::RefreshLogLevels(LogLevel);
 	spdlog::flush_on(spdlog::level::err);
 	spdlog::flush_every(std::chrono::seconds{2});
-	spdlog::set_formatter(
-		std::make_unique<logging::full_formatter>(LogOptions.LogId, std::chrono::system_clock::now()));	 // default to duration prefix
+	spdlog::set_formatter(std::make_unique<logging::full_formatter>(
+		LogOptions.LogId,
+		std::chrono::system_clock::now() - std::chrono::milliseconds(GetTimeSinceProcessStart())));	 // default to duration prefix
 
 	if (g_FileSink)
 	{