hub execution stats (#1011)

- Improvement: Hub hydration and dehydration completion logs now include per-phase wall time, bytes transferred, bits/s throughput, number of unique worker threads used, and the storage source/target URI
- Improvement: Hub storage server instance lifecycle logs now report elapsed time for spawn and shutdown
- Improvement: Hub deprovisioning now logs GC completion status and elapsed time; a GC that does not complete within the 5s deadline is logged as a warning and shutdown proceeds anyway

1 files changed, 26 insertions, 19 deletions

diff --git a/src/zenserver/hub/storageserverinstance.cpp b/src/zenserver/hub/storageserverinstance.cpp
index 97edc5223..9d477fb10 100644
--- a/src/zenserver/hub/storageserverinstance.cpp
+++ b/src/zenserver/hub/storageserverinstance.cpp
@@ -8,6 +8,8 @@
 #include <zencore/filesystem.h>
 #include <zencore/fmtutils.h>
 #include <zencore/logging.h>
+#include <zencore/string.h>
+#include <zencore/timer.h>
 
 namespace zen {
 
@@ -29,6 +31,8 @@ StorageServerInstance::~StorageServerInstance()
 void
 StorageServerInstance::SpawnServerProcess()
 {
+	Stopwatch SpawnTimer;
+
 	ZEN_ASSERT_FORMAT(!m_ServerInstance.IsRunning(), "Storage server instance for module '{}' is already running", m_ModuleId);
 	m_ServerInstance.ResetDeadProcess();
 
@@ -84,11 +88,29 @@ StorageServerInstance::SpawnServerProcess()
 	}
 
 	m_ServerInstance.SpawnServerAndWaitUntilReady(m_Config.BasePort, AdditionalOptions.ToView());
-	ZEN_DEBUG("Storage server instance for module '{}' started, listening on port {}", m_ModuleId, m_Config.BasePort);
+	ZEN_INFO("Storage server instance for module '{}' started, listening on port {}, spawn took {}",
+			 m_ModuleId,
+			 m_Config.BasePort,
+			 NiceLatencyNs(SpawnTimer.GetElapsedTimeUs() * 1000));
 
 	m_ServerInstance.EnableShutdownOnDestroy();
 }
 
+void
+StorageServerInstance::ShutdownServerProcess()
+{
+	if (!m_ServerInstance.IsRunning())
+	{
+		return;
+	}
+	Stopwatch ShutdownTimer;
+	// m_ServerInstance.Shutdown() never throws.
+	m_ServerInstance.Shutdown();
+	ZEN_INFO("Storage server instance for module '{}' shut down, took {}",
+			 m_ModuleId,
+			 NiceLatencyNs(ShutdownTimer.GetElapsedTimeUs() * 1000));
+}
+
 ProcessMetrics
 StorageServerInstance::GetProcessMetrics() const
 {
@@ -128,11 +150,7 @@ StorageServerInstance::ProvisionLocked()
 void
 StorageServerInstance::DeprovisionLocked()
 {
-	if (m_ServerInstance.IsRunning())
-	{
-		// m_ServerInstance.Shutdown() never throws.
-		m_ServerInstance.Shutdown();
-	}
+	ShutdownServerProcess();
 
 	// Crashed or Hibernated: process already dead; skip Shutdown.
 	// Dehydrate preserves instance state for future re-provisioning. Failure means saved state
@@ -151,11 +169,7 @@ StorageServerInstance::DeprovisionLocked()
 void
 StorageServerInstance::ObliterateLocked()
 {
-	if (m_ServerInstance.IsRunning())
-	{
-		// m_ServerInstance.Shutdown() never throws.
-		m_ServerInstance.Shutdown();
-	}
+	ShutdownServerProcess();
 
 	std::atomic<bool>					   AbortFlag{false};
 	std::atomic<bool>					   PauseFlag{false};
@@ -168,14 +182,7 @@ void
 StorageServerInstance::HibernateLocked()
 {
 	// Signal server to shut down, but keep data around for later wake
-
-	if (!m_ServerInstance.IsRunning())
-	{
-		return;
-	}
-
-	// m_ServerInstance.Shutdown() never throws.
-	m_ServerInstance.Shutdown();
+	ShutdownServerProcess();
 }
 
 void