From d735e0f3ad90d2d781bf7290fd5bdf87434a51a6 Mon Sep 17 00:00:00 2001
From: Jason Watkins <jason-watkins@outlook.com>
Date: Thu, 30 Apr 2015 16:17:30 -0700
Subject: [PATCH] Updated plugin logging.

 - The plugin now keeps the log file open for the duration of its lifetime.
 - This greatly improves the performace of the logging component, which was previously a significant bottleneck even at low logging verbosity.
 - The log now prints timestamps to the millisecond.
---
 xpcPlugin/Log.cpp       | 47 +++++++++++++++++++++++++----------------
 xpcPlugin/Log.h         |  3 +++
 xpcPlugin/XPCPlugin.cpp |  1 +
 3 files changed, 33 insertions(+), 18 deletions(-)

diff --git a/xpcPlugin/Log.cpp b/xpcPlugin/Log.cpp
index 81ebf23..e754312 100644
--- a/xpcPlugin/Log.cpp
+++ b/xpcPlugin/Log.cpp
@@ -4,33 +4,42 @@
 
 #include "XPLMUtilities.h"
 
+#include <chrono>
 #include <cstdarg>
 #include <cstdio>
 #include <ctime>
+#include <iomanip>
+#include <sstream>
 
 // Implementation note: I initial wrote this class using C++ iostreams, but I couldn't find any
 // way to implement FormatLine without adding in a call to sprintf. It therefore seems more
 // efficient to me to just use C-style IO and call std::fprintf directly.
 namespace XPC
 {
+	static std::FILE* fd;
 	static void WriteTime(FILE* fd)
 	{
-		std::time_t rawtime;
-		std::tm* timeinfo;
-		std::time(&rawtime);
-		timeinfo = std::localtime(&rawtime);
+		using namespace std::chrono;
 
-		char buffer[16] = { 0 };
-		// Format is equivalent to [%F %T], but neither of those specifiers is
-		// supported on Windows as of Visual Studio 13
-		std::strftime(buffer, 16, "[%H:%M:%S] ", timeinfo);
+		system_clock::time_point now = system_clock::now();
+		std::time_t now_tt = system_clock::to_time_t(now);
+		system_clock::time_point now_sec = system_clock::from_time_t(now_tt);
+		milliseconds ms = duration_cast<milliseconds>(now - now_sec);
+		std::tm * tm = std::localtime(&now_tt);
+
+		std::stringstream ss;
+		ss << std::setfill('0') << "["
+			<< std::setw(2) << tm->tm_hour << ":"
+			<< std::setw(2) << tm->tm_min << ":"
+			<< std::setw(2) << tm->tm_sec << "."
+			<< std::setw(3) << ms.count() << "]";
 		
-		std::fprintf(fd, buffer);
+		std::fprintf(fd, ss.str().c_str());
 	}
 
 	void Log::Initialize(std::string version)
 	{
-		std::FILE* fd = std::fopen("XPCLog.txt", "w");
+		fd = std::fopen("XPCLog.txt", "w");
 		if (fd != NULL)
 		{
 			std::time_t rawtime;
@@ -39,8 +48,6 @@ namespace XPC
 			timeinfo = std::localtime(&rawtime);
 
 			char timeStr[16] = { 0 };
-			// Format is equivalent to %F, but neither of those specifiers is
-			// supported on Windows as of Visual Studio 13
 			std::strftime(timeStr, 16, "%Y-%m-%d", timeinfo);
 
 			std::fprintf(fd, "X-Plane Connect [Version %s]\n", version.c_str());
@@ -62,6 +69,14 @@ namespace XPC
 			std::fprintf(fd, "Plugin Manager Version: %d\n", xplmVer);
 			std::fprintf(fd, "Host Application ID: %d\n", hostID);
 			std::fprintf(fd, "Log file generated on %s.\n", timeStr);
+			std::fflush(fd);
+		}
+	}
+
+	void Log::Close()
+	{
+		if (fd)
+		{
 			std::fclose(fd);
 		}
 	}
@@ -73,7 +88,6 @@ namespace XPC
 
 	void Log::WriteLine(const char* value)
 	{
-		std::FILE* fd = std::fopen("XPCLog.txt", "a");
 		if (!fd)
 		{
 			return;
@@ -81,15 +95,13 @@ namespace XPC
 
 		WriteTime(fd);
 		std::fprintf(fd, "%s\n", value);
-
-		std::fclose(fd);
+		std::fflush(fd);
 	}
 
 	void Log::FormatLine(const char* format, ...)
 	{
 		va_list args;
 
-		std::FILE* fd = std::fopen("XPCLog.txt", "a");
 		if (!fd)
 		{
 			return;
@@ -99,8 +111,7 @@ namespace XPC
 		WriteTime(fd);
 		std::vfprintf(fd, format, args);
 		std::fprintf(fd, "\n");
-
-		std::fclose(fd);
+		std::fflush(fd);
 
 		va_end(args);
 	}
diff --git a/xpcPlugin/Log.h b/xpcPlugin/Log.h
index a7c941e..84d75c0 100644
--- a/xpcPlugin/Log.h
+++ b/xpcPlugin/Log.h
@@ -34,6 +34,9 @@ namespace XPC
 		/// writing header information to the log file.
 		static void Initialize(std::string header);
 
+		/// Closes the log file.
+		static void Close();
+
 		/// Writes the C string pointed to by format, followed by a line
 		/// terminator to the XPC log file. If format contains format
 		/// specifiers, additional arguments following format will be formatted
diff --git a/xpcPlugin/XPCPlugin.cpp b/xpcPlugin/XPCPlugin.cpp
index d8ff645..24063d9 100755
--- a/xpcPlugin/XPCPlugin.cpp
+++ b/xpcPlugin/XPCPlugin.cpp
@@ -119,6 +119,7 @@ PLUGIN_API void	XPluginStop(void)
 {
 	XPLMUnregisterFlightLoopCallback(XPCFlightLoopCallback, NULL);
 	XPC::Log::WriteLine("[EXEC] Plugin Shutdown");
+	XPC::Log::Close();
 }
 
 PLUGIN_API void XPluginDisable(void)