oplog output improvements (#474)

* include session id in oplog import/export output
* use Mbit/sec for transfer rates
* fix elapsed time conversion in buildremotprojectstore
* changelog

5 files changed, 43 insertions, 32 deletions

diff --git a/src/zenserver/projectstore/buildsremoteprojectstore.cpp b/src/zenserver/projectstore/buildsremoteprojectstore.cpp
index 52cdc5983..a9dd48510 100644
--- a/src/zenserver/projectstore/buildsremoteprojectstore.cpp
+++ b/src/zenserver/projectstore/buildsremoteprojectstore.cpp
@@ -49,7 +49,12 @@ public:
 				.UseTempBlockFiles = m_UseTempBlocks,
 				.AllowChunking	   = true,
 				.ContainerName	   = fmt::format("{}/{}/{}", m_Namespace, m_Bucket, m_BuildId),
-				.Description	   = fmt::format("[cloud] {} as {}/{}/{}"sv, m_Url, m_Namespace, m_Bucket, m_BuildId)};
+				.Description	   = fmt::format("[cloud] {}. SessionId: {}. {}/{}/{}"sv,
+											 m_Url,
+											 m_BuildStorageHttp->GetSessionId(),
+											 m_Namespace,
+											 m_Bucket,
+											 m_BuildId)};
 	}
 
 	virtual Stats GetStats() const override
@@ -71,7 +76,7 @@ public:
 
 		CreateContainerResult Result;
 		Stopwatch			  Timer;
-		auto				  _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() * 1000000.0; });
+		auto				  _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() / 1000000.0; });
 
 		CbObject Payload = LoadCompactBinaryObject(m_MetaData);
 		try
@@ -102,7 +107,7 @@ public:
 
 		SaveResult Result;
 		Stopwatch  Timer;
-		auto	   _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() * 1000000.0; });
+		auto	   _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() / 1000000.0; });
 
 		try
 		{
@@ -147,7 +152,7 @@ public:
 
 		SaveAttachmentResult Result;
 		Stopwatch			 Timer;
-		auto				 _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() * 1000000.0; });
+		auto				 _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() / 1000000.0; });
 
 		try
 		{
@@ -221,7 +226,7 @@ public:
 	{
 		SaveAttachmentsResult Result;
 		Stopwatch			  Timer;
-		auto				  _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() * 1000000.0; });
+		auto				  _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() / 1000000.0; });
 		for (const SharedBuffer& Chunk : Chunks)
 		{
 			CompressedBuffer	 Compressed	 = CompressedBuffer::FromCompressedNoValidate(Chunk.AsIoBuffer());
@@ -241,7 +246,7 @@ public:
 
 		FinalizeResult Result;
 		Stopwatch	   Timer;
-		auto		   _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() * 1000000.0; });
+		auto		   _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() / 1000000.0; });
 
 		try
 		{
@@ -310,7 +315,7 @@ public:
 
 		LoadContainerResult Result;
 		Stopwatch			Timer;
-		auto				_ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() * 1000000.0; });
+		auto				_ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() / 1000000.0; });
 
 		try
 		{
@@ -368,7 +373,7 @@ public:
 
 		GetKnownBlocksResult Result;
 		Stopwatch			 Timer;
-		auto				 _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() * 1000000.0; });
+		auto				 _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() / 1000000.0; });
 
 		try
 		{
@@ -403,7 +408,7 @@ public:
 
 		LoadAttachmentResult Result;
 		Stopwatch			 Timer;
-		auto				 _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() * 1000000.0; });
+		auto				 _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() / 1000000.0; });
 
 		try
 		{
@@ -429,7 +434,7 @@ public:
 	{
 		LoadAttachmentsResult Result;
 		Stopwatch			  Timer;
-		auto				  _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() * 1000000.0; });
+		auto				  _ = MakeGuard([&Timer, &Result]() { Result.ElapsedSeconds = Timer.GetElapsedTimeUs() / 1000000.0; });
 		for (const IoHash& Hash : RawHashes)
 		{
 			LoadAttachmentResult ChunkResult = LoadAttachment(Hash);
diff --git a/src/zenserver/projectstore/jupiterremoteprojectstore.cpp b/src/zenserver/projectstore/jupiterremoteprojectstore.cpp
index dba5cd4a7..d79ad3cb7 100644
--- a/src/zenserver/projectstore/jupiterremoteprojectstore.cpp
+++ b/src/zenserver/projectstore/jupiterremoteprojectstore.cpp
@@ -42,8 +42,9 @@ public:
 				.UseTempBlockFiles = m_UseTempBlocks,
 				.AllowChunking	   = true,
 				.ContainerName	   = fmt::format("{}/{}/{}", m_Namespace, m_Bucket, m_Key),
-				.Description	   = fmt::format("[cloud] {} as {}/{}/{}{}"sv,
+				.Description	   = fmt::format("[cloud] {}. SessionId: {}. {}/{}/{}{}"sv,
 											 m_JupiterClient->ServiceUrl(),
+											 m_JupiterClient->Client().GetSessionId(),
 											 m_Namespace,
 											 m_Bucket,
 											 m_Key,
diff --git a/src/zenserver/projectstore/projectstore.cpp b/src/zenserver/projectstore/projectstore.cpp
index d6dd6ef9b..7463e9caa 100644
--- a/src/zenserver/projectstore/projectstore.cpp
+++ b/src/zenserver/projectstore/projectstore.cpp
@@ -5774,13 +5774,6 @@ ProjectStore::Export(Ref<ProjectStore::Project> Project, ProjectStore::Oplog& Op
 	std::shared_ptr<RemoteProjectStore> RemoteStore = std::move(RemoteStoreResult.Store);
 	RemoteProjectStore::RemoteStoreInfo StoreInfo	= RemoteStore->GetInfo();
 
-	ZEN_INFO("Saving oplog '{}/{}' to {}, maxblocksize {}, maxchunkembedsize {}",
-			 Project->Identifier,
-			 Oplog.OplogId(),
-			 StoreInfo.Description,
-			 NiceBytes(MaxBlockSize),
-			 NiceBytes(MaxChunkEmbedSize));
-
 	JobId JobId = m_JobQueue.QueueJob(
 		fmt::format("Export oplog '{}/{}'", Project->Identifier, Oplog.OplogId()),
 		[this,
@@ -5793,6 +5786,13 @@ ProjectStore::Export(Ref<ProjectStore::Project> Project, ProjectStore::Oplog& Op
 		 EmbedLooseFile,
 		 Force,
 		 IgnoreMissingAttachments](JobContext& Context) {
+			Context.ReportMessage(fmt::format("Saving oplog '{}/{}' to {}, maxblocksize {}, maxchunkembedsize {}",
+											  Project->Identifier,
+											  OplogPtr->OplogId(),
+											  ActualRemoteStore->GetInfo().Description,
+											  NiceBytes(MaxBlockSize),
+											  NiceBytes(MaxChunkEmbedSize)));
+
 			RemoteProjectStore::Result Result	= SaveOplog(Project->GetCidStore(),
 															*ActualRemoteStore,
 															*Project.Get(),
@@ -5840,7 +5840,6 @@ ProjectStore::Import(ProjectStore::Project& Project, ProjectStore::Oplog& Oplog,
 	RemoteProjectStore::RemoteStoreInfo StoreInfo	= RemoteStore->GetInfo();
 	CidStore&							ChunkStore	= Project.GetCidStore();
 
-	ZEN_INFO("Loading oplog '{}/{}' from {}", Project.Identifier, Oplog.OplogId(), StoreInfo.Description);
 	JobId JobId = m_JobQueue.QueueJob(
 		fmt::format("Import oplog '{}/{}'", Project.Identifier, Oplog.OplogId()),
 		[this,
@@ -5850,6 +5849,11 @@ ProjectStore::Import(ProjectStore::Project& Project, ProjectStore::Oplog& Oplog,
 		 Force,
 		 IgnoreMissingAttachments,
 		 CleanOplog](JobContext& Context) {
+			Context.ReportMessage(fmt::format("Loading oplog '{}/{}' from {}",
+											  OplogPtr->GetOuterProject()->Identifier,
+											  OplogPtr->OplogId(),
+											  ActualRemoteStore->GetInfo().Description));
+
 			RemoteProjectStore::Result Result =
 				LoadOplog(*ChunkStore, *ActualRemoteStore, *OplogPtr, Force, IgnoreMissingAttachments, CleanOplog, &Context);
 			auto Response = ConvertResult(Result);
diff --git a/src/zenserver/projectstore/remoteprojectstore.cpp b/src/zenserver/projectstore/remoteprojectstore.cpp
index f96b3e185..857e868da 100644
--- a/src/zenserver/projectstore/remoteprojectstore.cpp
+++ b/src/zenserver/projectstore/remoteprojectstore.cpp
@@ -117,30 +117,31 @@ namespace remotestore_impl {
 	std::string GetStats(const RemoteProjectStore::Stats& Stats, uint64_t ElapsedWallTimeMS)
 	{
 		return fmt::format(
-			"Sent: {} ({}/s) Recv: {} ({}/s)",
+			"Sent: {} ({}bits/s) Recv: {} ({}bits/s)",
 			NiceBytes(Stats.m_SentBytes),
-			NiceBytes(ElapsedWallTimeMS > 0u ? static_cast<uint64_t>((Stats.m_SentBytes * 1000) / ElapsedWallTimeMS) : 0u),
+			NiceNum(ElapsedWallTimeMS > 0u ? static_cast<uint64_t>((Stats.m_SentBytes * 8 * 1000) / ElapsedWallTimeMS) : 0u),
 			NiceBytes(Stats.m_ReceivedBytes),
-			NiceBytes(ElapsedWallTimeMS > 0u ? static_cast<uint64_t>((Stats.m_ReceivedBytes * 1000) / ElapsedWallTimeMS) : 0u));
+			NiceNum(ElapsedWallTimeMS > 0u ? static_cast<uint64_t>((Stats.m_ReceivedBytes * 8 * 1000) / ElapsedWallTimeMS) : 0u));
 	}
 
 	void LogRemoteStoreStatsDetails(const RemoteProjectStore::Stats& Stats)
 	{
-		ZEN_INFO("Oplog request count: {}. Average request size: {}. Average request time: {}, Peak request speed: {}",
+		ZEN_INFO("Oplog request count: {}. Average request size: {}. Average request time: {}, Peak request speed: {}bits/s",
 				 Stats.m_RequestCount,
 				 NiceBytes(Stats.m_RequestCount > 0 ? (Stats.m_ReceivedBytes + Stats.m_SentBytes) / Stats.m_RequestCount : 0u),
 				 NiceLatencyNs(Stats.m_RequestCount > 0 ? (Stats.m_RequestTimeNS / Stats.m_RequestCount) : 0u),
-				 NiceBytes(Stats.m_PeakBytesPerSec));
+				 NiceNum(Stats.m_PeakBytesPerSec));
 		ZEN_INFO(
-			"Oplog sent request avg: {} ({}/s). Peak: {}",
+			"Oplog sent request avg: {} ({}bits/s). Peak: {}",
 			NiceBytes(Stats.m_RequestCount > 0u ? static_cast<uint64_t>((Stats.m_SentBytes) / Stats.m_RequestCount) : 0u),
-			NiceBytes(Stats.m_RequestTimeNS > 0u ? static_cast<uint64_t>((Stats.m_SentBytes * 1000000000) / Stats.m_RequestTimeNS) : 0u),
+			NiceNum(Stats.m_RequestTimeNS > 0u ? static_cast<uint64_t>((Stats.m_SentBytes * 8 * 1000000000) / Stats.m_RequestTimeNS) : 0u),
 			NiceBytes(Stats.m_PeakSentBytes));
-		ZEN_INFO("Oplog recv request avg: {} ({}/s). Peak: {}",
-				 NiceBytes(Stats.m_RequestCount > 0u ? static_cast<uint64_t>((Stats.m_ReceivedBytes) / Stats.m_RequestCount) : 0u),
-				 NiceBytes(Stats.m_RequestTimeNS > 0u ? static_cast<uint64_t>((Stats.m_ReceivedBytes * 1000000000) / Stats.m_RequestTimeNS)
-													  : 0u),
-				 NiceBytes(Stats.m_PeakReceivedBytes));
+		ZEN_INFO(
+			"Oplog recv request avg: {} ({}bits/s). Peak: {}",
+			NiceBytes(Stats.m_RequestCount > 0u ? static_cast<uint64_t>((Stats.m_ReceivedBytes) / Stats.m_RequestCount) : 0u),
+			NiceNum(Stats.m_RequestTimeNS > 0u ? static_cast<uint64_t>((Stats.m_ReceivedBytes * 8 * 1000000000) / Stats.m_RequestTimeNS)
+											   : 0u),
+			NiceBytes(Stats.m_PeakReceivedBytes));
 	}
 
 	size_t AddBlock(RwLock& BlocksLock, std::vector<ChunkBlockDescription>& Blocks)
diff --git a/src/zenserver/projectstore/zenremoteprojectstore.cpp b/src/zenserver/projectstore/zenremoteprojectstore.cpp
index 2ebf58a5d..21ddd6cff 100644
--- a/src/zenserver/projectstore/zenremoteprojectstore.cpp
+++ b/src/zenserver/projectstore/zenremoteprojectstore.cpp
@@ -36,7 +36,7 @@ public:
 				.UseTempBlockFiles = false,
 				.AllowChunking	   = false,
 				.ContainerName	   = fmt::format("{}/{}", m_Project, m_Oplog),
-				.Description	   = fmt::format("[zen] {}"sv, m_HostAddress)};
+				.Description	   = fmt::format("[zen] {}. SessionId: {}"sv, m_HostAddress, m_Client.GetSessionId())};
 	}
 
 	virtual Stats GetStats() const override