gc history log (#519)

- Feature: Writes a `gc.log` with settings and detailed result after each GC execution (version 2 only)
- Break out file name rotate to allow access for gclog
- CompactBinaryToJson(MemoryView Data, StringBuilderBase& InBuilder)

1 files changed, 279 insertions, 8 deletions

diff --git a/src/zenstore/gc.cpp b/src/zenstore/gc.cpp
index 365eb10ab..778a47626 100644
--- a/src/zenstore/gc.cpp
+++ b/src/zenstore/gc.cpp
@@ -173,6 +173,166 @@ SaveCompactBinaryObject(const fs::path& Path, const CbObject& Object)
 
 //////////////////////////////////////////////////////////////////////////
 
+void
+WriteReferencerStats(CbObjectWriter& Writer, const GcReferencerStats& Stats, bool HumanReadable)
+{
+	if (Stats.Count == 0)
+	{
+		return;
+	}
+	Writer << "Count" << Stats.Count;
+	Writer << "Expired" << Stats.Expired;
+	Writer << "Deleted" << Stats.Deleted;
+
+	if (HumanReadable)
+	{
+		Writer << "RemovedDisk" << NiceBytes(Stats.RemovedDisk);
+		Writer << "RemovedMemory" << NiceBytes(Stats.RemovedMemory);
+	}
+	else
+	{
+		Writer << "RemovedDiskBytes" << Stats.RemovedDisk;
+		Writer << "RemovedMemoryBytes" << Stats.RemovedMemory;
+	}
+
+	if (HumanReadable)
+	{
+		Writer << "RemoveExpiredData" << NiceTimeSpanMs(Stats.RemoveExpiredDataMS.count());
+		Writer << "CreateReferenceCheckers" << NiceTimeSpanMs(Stats.CreateReferenceCheckersMS.count());
+		Writer << "LockState" << NiceTimeSpanMs(Stats.LockStateMS.count());
+		Writer << "Elapsed" << NiceTimeSpanMs(Stats.ElapsedMS.count());
+	}
+	else
+	{
+		Writer << "RemoveExpiredDataMS" << gsl::narrow<int64_t>(Stats.RemoveExpiredDataMS.count());
+		Writer << "CreateReferenceCheckersMS" << gsl::narrow<int64_t>(Stats.CreateReferenceCheckersMS.count());
+		Writer << "LockStateMS" << gsl::narrow<int64_t>(Stats.LockStateMS.count());
+		Writer << "ElapsedMS" << gsl::narrow<int64_t>(Stats.ElapsedMS.count());
+	}
+};
+
+void
+WriteReferenceStoreStats(CbObjectWriter& Writer, const GcReferenceStoreStats& Stats, bool HumanReadable)
+{
+	if (Stats.Count == 0)
+	{
+		return;
+	}
+	Writer << "Count" << Stats.Count;
+	Writer << "Pruned" << Stats.Pruned;
+	Writer << "Compacted" << Stats.Compacted;
+
+	if (HumanReadable)
+	{
+		Writer << "RemovedDisk" << NiceBytes(Stats.RemovedDisk);
+		Writer << "RemovedMemory" << NiceBytes(Stats.RemovedMemory);
+	}
+	else
+	{
+		Writer << "RemovedDiskBytes" << Stats.RemovedDisk;
+		Writer << "RemovedMemoryBytes" << Stats.RemovedMemory;
+	}
+
+	if (HumanReadable)
+	{
+		Writer << "CreateReferencePruner" << NiceTimeSpanMs(Stats.CreateReferencePrunerMS.count());
+		Writer << "RemoveUnreferencedData" << NiceTimeSpanMs(Stats.RemoveUnreferencedDataMS.count());
+		Writer << "CompactReferenceStore" << NiceTimeSpanMs(Stats.CompactReferenceStoreMS.count());
+		Writer << "Elapsed" << NiceTimeSpanMs(Stats.ElapsedMS.count());
+	}
+	else
+	{
+		Writer << "CreateReferencePrunerMS" << gsl::narrow<int64_t>(Stats.CreateReferencePrunerMS.count());
+		Writer << "RemoveUnreferencedDataMS" << gsl::narrow<int64_t>(Stats.RemoveUnreferencedDataMS.count());
+		Writer << "CompactReferenceStoreMS" << gsl::narrow<int64_t>(Stats.CompactReferenceStoreMS.count());
+		Writer << "ElapsedMS" << gsl::narrow<int64_t>(Stats.ElapsedMS.count());
+	}
+};
+
+void
+WriteGCResult(CbObjectWriter& Writer, const GcResult& Result, bool HumanReadable, bool IncludeDetails)
+{
+	if (HumanReadable)
+	{
+		Writer << "RemovedDisk" << NiceBytes(Result.RemovedDisk);
+		Writer << "RemovedMemory" << NiceBytes(Result.RemovedMemory);
+		Writer << "WriteBlock" << NiceTimeSpanMs(Result.WriteBlockMS.count());
+		Writer << "Elapsed" << NiceTimeSpanMs(Result.ElapsedMS.count());
+	}
+	else
+	{
+		Writer << "RemovedDiskBytes" << gsl::narrow<int64_t>(Result.RemovedDisk);
+		Writer << "RemovedMemoryBytes" << gsl::narrow<int64_t>(Result.RemovedMemory);
+		Writer << "WriteBlockMS" << gsl::narrow<int64_t>(Result.WriteBlockMS.count());
+		Writer << "ElapsedMS" << gsl::narrow<int64_t>(Result.ElapsedMS.count());
+	}
+
+	if (!IncludeDetails)
+	{
+		return;
+	}
+
+	if (HumanReadable)
+	{
+		Writer << "RemoveExpiredData" << NiceTimeSpanMs(Result.RemoveExpiredDataMS.count());
+		Writer << "CreateReferenceCheckers" << NiceTimeSpanMs(Result.CreateReferenceCheckersMS.count());
+		Writer << "LockState" << NiceTimeSpanMs(Result.LockStateMS.count());
+
+		Writer << "CreateReferencePruner" << NiceTimeSpanMs(Result.CreateReferencePrunerMS.count());
+		Writer << "RemoveUnreferencedData" << NiceTimeSpanMs(Result.RemoveUnreferencedDataMS.count());
+		Writer << "CompactReferenceStore" << NiceTimeSpanMs(Result.CompactReferenceStoreMS.count());
+	}
+	else
+	{
+		Writer << "RemoveExpiredDataMS" << gsl::narrow<int64_t>(Result.RemoveExpiredDataMS.count());
+		Writer << "CreateReferenceCheckersMS" << gsl::narrow<int64_t>(Result.CreateReferenceCheckersMS.count());
+		Writer << "LockStateMS" << gsl::narrow<int64_t>(Result.LockStateMS.count());
+
+		Writer << "CreateReferencePrunerMS" << gsl::narrow<int64_t>(Result.CreateReferencePrunerMS.count());
+		Writer << "RemoveUnreferencedDataMS" << gsl::narrow<int64_t>(Result.RemoveUnreferencedDataMS.count());
+		Writer << "CompactReferenceStoreMS" << gsl::narrow<int64_t>(Result.CompactReferenceStoreMS.count());
+	}
+
+	Writer.BeginObject("ReferencerStats");
+	{
+		WriteReferencerStats(Writer, Result.ReferencerStat, HumanReadable);
+	}
+	Writer.EndObject();
+
+	Writer.BeginObject("ReferenceStoreStats");
+	{
+		WriteReferenceStoreStats(Writer, Result.ReferenceStoreStat, HumanReadable);
+	}
+	Writer.EndObject();
+
+	if (!Result.ReferencerStats.empty())
+	{
+		Writer.BeginArray("Referencers");
+		{
+			for (const std::pair<std::string, GcReferencerStats>& It : Result.ReferencerStats)
+			{
+				Writer.BeginObject();
+				Writer << "Name" << It.first;
+				WriteReferencerStats(Writer, It.second, HumanReadable);
+				Writer.EndObject();
+			}
+		}
+		Writer.EndArray();
+	}
+	if (!Result.ReferenceStoreStats.empty())
+	{
+		Writer.BeginArray("ReferenceStores");
+		for (const std::pair<std::string, GcReferenceStoreStats>& It : Result.ReferenceStoreStats)
+		{
+			Writer.BeginObject();
+			Writer << "Name" << It.first;
+			WriteReferenceStoreStats(Writer, It.second, HumanReadable);
+			Writer.EndObject();
+		}
+		Writer.EndArray();
+	}
+};
+
 struct GcContext::GcState
 {
 	using CacheKeyContexts = std::unordered_map<std::string, std::vector<IoHash>>;
@@ -420,7 +580,6 @@ GcManager::CollectGarbage(const GcSettings& Settings)
 		}
 
 		Result.ReferencerStats.resize(m_GcReferencers.size());
-		Result.ReferenceStoreStats.resize(m_GcReferenceStores.size());
 
 		WorkerThreadPool ThreadPool(WorkerThreadPoolCount);
 
@@ -452,6 +611,8 @@ GcManager::CollectGarbage(const GcSettings& Settings)
 			return Result;
 		}
 
+		Result.ReferenceStoreStats.resize(m_GcReferenceStores.size());
+
 		ZEN_INFO("GCV2: Creating reference pruners from {} reference stores", m_GcReferenceStores.size());
 		std::unordered_map<size_t, std::unique_ptr<GcReferencePruner>> ReferencePruners;
 		if (!m_GcReferenceStores.empty())
@@ -1055,6 +1216,106 @@ GcScheduler::CheckDiskSpace()
 	return Space;
 }
 
+void
+GcScheduler::AppendGCLog(GcClock::TimePoint StartTime, const GcSettings& Settings, const GcResult& Result)
+{
+	try
+	{
+		std::vector<uint8_t> Blob;
+		{
+			CbObjectWriter Writer;
+			std::string	   Id = fmt::format("{}", gsl::narrow<int64_t>(StartTime.time_since_epoch().count()));
+			Writer.BeginObject(Id);
+			{
+				Writer << "StartTimeSec"sv
+					   << gsl::narrow<int64_t>(std::chrono::duration_cast<std::chrono::seconds>(StartTime.time_since_epoch()).count());
+				Writer.BeginObject("Settings"sv);
+				{
+					Writer << "CacheExpireTimeSec"sv
+						   << gsl::narrow<int64_t>(
+								  std::chrono::duration_cast<std::chrono::seconds>(Settings.CacheExpireTime.time_since_epoch()).count());
+					Writer << "ProjectStoreExpireTimeSec"sv
+						   << gsl::narrow<int64_t>(
+								  std::chrono::duration_cast<std::chrono::seconds>(Settings.ProjectStoreExpireTime.time_since_epoch())
+									  .count());
+					Writer << "CollectSmallObjects"sv << Settings.CollectSmallObjects;
+					Writer << "IsDeleteMode"sv << Settings.IsDeleteMode;
+					Writer << "SkipCidDelete"sv << Settings.SkipCidDelete;
+					Writer << "Verbose"sv << Settings.Verbose;
+					Writer << "SingleThread"sv << Settings.SingleThread;
+				}
+				Writer.EndObject();
+
+				const bool HumanReadable  = false;
+				const bool IncludeDetails = true;
+				Writer.BeginObject("Result"sv);
+				{
+					WriteGCResult(Writer, Result, HumanReadable, IncludeDetails);
+				}
+				Writer.EndObject();
+			}
+			Writer.EndObject();
+
+			CbObject Entry = Writer.Save();
+			Entry.AsFieldView().WriteToStream([&](const void* Data, size_t Size) {
+				const uint8_t* BlobData(reinterpret_cast<const uint8_t*>(Data));
+				Blob.insert(Blob.end(), BlobData, BlobData + Size);
+			});
+		}
+
+		BasicFile	   GcLogFile;
+		const fs::path Path = m_Config.RootDirectory / "gc.log";
+
+		MemoryView EntryBuffer(Blob.data(), Blob.size());
+		{
+			RwLock::ExclusiveLockScope _(m_GcLogLock);
+
+			GcLogFile.Open(Path, BasicFile::Mode::kWrite);
+			uint64_t AppendPos = GcLogFile.FileSize();
+
+			const uint64_t MaxGcLogFileSize	 = 1024 * 1024 * 8;
+			const uint64_t MaxGcLogFileCount = 16;
+
+			if (AppendPos + EntryBuffer.GetSize() > MaxGcLogFileSize)
+			{
+				GcLogFile.Close();
+				std::error_code Err = RotateFiles(Path, MaxGcLogFileCount);
+				if (Err)
+				{
+					ZEN_WARN("Failed to rotate gc log files at '{}'. Reason: '{}'", Path, Err.message());
+				}
+				GcLogFile.Open(Path, BasicFile::Mode::kWrite);
+				AppendPos = 0;
+			}
+
+			GcLogFile.Write(EntryBuffer, AppendPos);
+		}
+	}
+	catch (std::system_error& SystemError)
+	{
+		if (IsOOM(SystemError.code()))
+		{
+			ZEN_WARN("writing gc result ran out of memory: '{}'", SystemError.what());
+		}
+		else if (IsOOD(SystemError.code()))
+		{
+			ZEN_WARN("writing gc result ran out of disk space: '{}'", SystemError.what());
+		}
+		else
+		{
+			ZEN_ERROR("writing gc result failed with system error exception: '{}'", SystemError.what());
+		}
+	}
+	catch (std::bad_alloc& BadAlloc)
+	{
+		ZEN_WARN("writing gc result ran out of memory: '{}'", BadAlloc.what());
+	}
+	catch (std::exception& Ex)
+	{
+		ZEN_ERROR("writing gc result failed with: '{}'", Ex.what());
+	}
+}
+
 GcSchedulerState
 GcScheduler::GetState() const
 {
@@ -1552,17 +1813,20 @@ GcScheduler::CollectGarbage(const GcClock::TimePoint& CacheExpireTime,
 				break;
 			case GcVersion::kV2:
 				{
-					GcResult Result = m_GcManager.CollectGarbage({.CacheExpireTime		  = CacheExpireTime,
-																  .ProjectStoreExpireTime = ProjectStoreExpireTime,
-																  .CollectSmallObjects	  = CollectSmallObjects,
-																  .IsDeleteMode			  = Delete,
-																  .SkipCidDelete		  = SkipCid});
+					const GcSettings   Settings	   = {.CacheExpireTime		  = CacheExpireTime,
+													  .ProjectStoreExpireTime = ProjectStoreExpireTime,
+													  .CollectSmallObjects	  = CollectSmallObjects,
+													  .IsDeleteMode			  = Delete,
+													  .SkipCidDelete		  = SkipCid};
+					GcClock::TimePoint GcStartTime = GcClock::Now();
+					GcResult		   Result	   = m_GcManager.CollectGarbage(Settings);
 
 					ZEN_INFO(
 						"GCV2: Removed {} items out of {}, deleted {} out of {}. Pruned {} Cid entries out of {}, compacted {} Cid entries "
 						"out of {}, "
 						"freed "
-						"{} on disk and {} of memory in {}",
+						"{} on disk and {} of memory in {}. CacheExpireTime: {}, ProjectStoreExpireTime: {}, CollectSmallObjects: {}, "
+						"IsDeleteMode: {}, SkipCidDelete: {}",
 						Result.ReferencerStat.Expired,
 						Result.ReferencerStat.Count,
 						Result.ReferencerStat.Deleted,
@@ -1573,7 +1837,14 @@ GcScheduler::CollectGarbage(const GcClock::TimePoint& CacheExpireTime,
 						Result.ReferenceStoreStat.Pruned,
 						NiceBytes(Result.RemovedDisk),
 						NiceBytes(Result.RemovedMemory),
-						NiceTimeSpanMs(Result.ElapsedMS.count()));
+						NiceTimeSpanMs(Result.ElapsedMS.count()),
+						Settings.CacheExpireTime,
+						Settings.ProjectStoreExpireTime,
+						Settings.CollectSmallObjects,
+						Settings.IsDeleteMode,
+						Settings.SkipCidDelete);
+
+					AppendGCLog(GcStartTime, Settings, Result);
 
 					if (SkipCid)
 					{