Additional trace instrumentation (#312)

* added trace instrumentation to upstreamcache
* added asio trace instrumentation
* added trace annotations for project store
* added trace annotations for BlockStore
* added trace annotations for HttpClient
* added trace annotations for CAS/GC

5 files changed, 65 insertions, 1 deletions

diff --git a/src/zenstore/blockstore.cpp b/src/zenstore/blockstore.cpp
index 427364f84..e0876070b 100644
--- a/src/zenstore/blockstore.cpp
+++ b/src/zenstore/blockstore.cpp
@@ -6,6 +6,7 @@
 #include <zencore/logging.h>
 #include <zencore/scopeguard.h>
 #include <zencore/timer.h>
+#include <zencore/trace.h>
 
 #include <algorithm>
 
@@ -121,6 +122,8 @@ constexpr uint64_t ScrubSmallChunkWindowSize = 4 * 1024 * 1024;
 std::unordered_map<uint32_t, uint64_t>
 BlockStore::Initialize(const std::filesystem::path& BlocksBasePath, uint64_t MaxBlockSize, uint64_t MaxBlockCount)
 {
+	ZEN_TRACE_CPU("BlockStore::Initialize");
+
 	ZEN_ASSERT(MaxBlockSize > 0);
 	ZEN_ASSERT(MaxBlockCount > 0);
 	ZEN_ASSERT(IsPow2(MaxBlockCount));
@@ -179,6 +182,8 @@ BlockStore::Initialize(const std::filesystem::path& BlocksBasePath, uint64_t Max
 void
 BlockStore::Prune(const std::vector<BlockStoreLocation>& KnownLocations)
 {
+	ZEN_TRACE_CPU("BlockStore::Prune");
+
 	RwLock::ExclusiveLockScope InsertLock(m_InsertLock);
 
 	std::unordered_set<uint32_t> KnownBlocks;
@@ -223,6 +228,8 @@ BlockStore::Close()
 void
 BlockStore::WriteChunk(const void* Data, uint64_t Size, uint64_t Alignment, const WriteChunkCallback& Callback)
 {
+	ZEN_TRACE_CPU("BlockStore::WriteChunk");
+
 	ZEN_ASSERT(Data != nullptr);
 	ZEN_ASSERT(Size > 0u);
 	ZEN_ASSERT(Size <= m_MaxBlockSize);
@@ -312,6 +319,8 @@ BlockStore::TryGetChunk(const BlockStoreLocation& Location) const
 void
 BlockStore::Flush()
 {
+	ZEN_TRACE_CPU("BlockStore::Flush");
+
 	RwLock::ExclusiveLockScope _(m_InsertLock);
 	if (m_CurrentInsertOffset > 0)
 	{
@@ -336,6 +345,9 @@ BlockStore::ReclaimSpace(const ReclaimSnapshotState&			Snapshot,
 	{
 		return;
 	}
+
+	ZEN_TRACE_CPU("BlockStore::ReclaimSpace");
+
 	uint64_t WriteBlockTimeUs		 = 0;
 	uint64_t WriteBlockLongestTimeUs = 0;
 	uint64_t ReadBlockTimeUs		 = 0;
@@ -665,6 +677,8 @@ BlockStore::IterateChunks(const std::vector<BlockStoreLocation>& ChunkLocations,
 						  const IterateChunksSmallSizeCallback&	 SmallSizeCallback,
 						  const IterateChunksLargeSizeCallback&	 LargeSizeCallback)
 {
+	ZEN_TRACE_CPU("BlockStore::IterateChunks");
+
 	ZEN_LOG_SCOPE("iterating chunks from '{}'", m_BlocksBasePath);
 
 	std::vector<size_t> LocationIndexes;
diff --git a/src/zenstore/cas.cpp b/src/zenstore/cas.cpp
index 33e1ae0e0..ab05e3e7c 100644
--- a/src/zenstore/cas.cpp
+++ b/src/zenstore/cas.cpp
@@ -85,6 +85,8 @@ CasImpl::~CasImpl()
 void
 CasImpl::Initialize(const CidStoreConfiguration& InConfig)
 {
+	ZEN_TRACE_CPU("Cas::Initialize");
+
 	m_Config = InConfig;
 
 	ZEN_INFO("initializing CAS pool at '{}'", m_Config.RootDirectory);
@@ -260,6 +262,8 @@ CasImpl::Flush()
 void
 CasImpl::ScrubStorage(ScrubContext& Ctx)
 {
+	ZEN_TRACE_CPU("Cas::ScrubStorage");
+
 	if (m_LastScrubTime == Ctx.ScrubTimestamp())
 	{
 		return;
@@ -275,6 +279,8 @@ CasImpl::ScrubStorage(ScrubContext& Ctx)
 void
 CasImpl::GarbageCollect(GcContext& GcCtx)
 {
+	ZEN_TRACE_CPU("Cas::GarbageCollect");
+
 	m_SmallStrategy.CollectGarbage(GcCtx);
 	m_TinyStrategy.CollectGarbage(GcCtx);
 	m_LargeStrategy.CollectGarbage(GcCtx);
diff --git a/src/zenstore/compactcas.cpp b/src/zenstore/compactcas.cpp
index 0f6f011e1..a8a4dc102 100644
--- a/src/zenstore/compactcas.cpp
+++ b/src/zenstore/compactcas.cpp
@@ -10,6 +10,7 @@
 #include <zencore/fmtutils.h>
 #include <zencore/logging.h>
 #include <zencore/scopeguard.h>
+#include <zencore/trace.h>
 #include <zenstore/scrubcontext.h>
 
 #include <gsl/gsl-lite.hpp>
@@ -234,6 +235,8 @@ CasContainerStrategy::Flush()
 void
 CasContainerStrategy::ScrubStorage(ScrubContext& Ctx)
 {
+	ZEN_TRACE_CPU("CasContainer::ScrubStorage");
+
 	ZEN_INFO("scrubbing '{}'", m_BlocksBasePath);
 
 	std::vector<IoHash>				BadKeys;
@@ -373,6 +376,8 @@ CasContainerStrategy::ScrubStorage(ScrubContext& Ctx)
 void
 CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 {
+	ZEN_TRACE_CPU("CasContainer::CollectGarbage");
+
 	// It collects all the blocks that we want to delete chunks from. For each such
 	// block we keep a list of chunks to retain and a list of chunks to delete.
 	//
@@ -513,6 +518,8 @@ CasContainerStrategy::StorageSize() const
 void
 CasContainerStrategy::MakeIndexSnapshot()
 {
+	ZEN_TRACE_CPU("CasContainer::MakeIndexSnapshot");
+
 	uint64_t LogCount = m_CasLog.GetLogCount();
 	if (m_LogFlushPosition == LogCount)
 	{
@@ -598,6 +605,8 @@ CasContainerStrategy::MakeIndexSnapshot()
 uint64_t
 CasContainerStrategy::ReadIndexFile(const std::filesystem::path& IndexPath, uint32_t& OutVersion)
 {
+	ZEN_TRACE_CPU("CasContainer::ReadIndexFile");
+
 	std::vector<CasDiskIndexEntry> Entries;
 	Stopwatch					   Timer;
 	const auto					   _ = MakeGuard([&] {
@@ -645,6 +654,8 @@ CasContainerStrategy::ReadIndexFile(const std::filesystem::path& IndexPath, uint
 uint64_t
 CasContainerStrategy::ReadLog(const std::filesystem::path& LogPath, uint64_t SkipEntryCount)
 {
+	ZEN_TRACE_CPU("CasContainer::ReadLog");
+
 	if (!TCasLogFile<CasDiskIndexEntry>::IsValid(LogPath))
 	{
 		ZEN_WARN("removing invalid cas log at '{}'", LogPath);
@@ -697,6 +708,8 @@ CasContainerStrategy::ReadLog(const std::filesystem::path& LogPath, uint64_t Ski
 void
 CasContainerStrategy::OpenContainer(bool IsNewStore)
 {
+	ZEN_TRACE_CPU("CasContainer::OpenContainer");
+
 	// Add .running file and delete on clean on close to detect bad termination
 
 	m_LocationMap.clear();
diff --git a/src/zenstore/filecas.cpp b/src/zenstore/filecas.cpp
index 88b847c51..2dd93a625 100644
--- a/src/zenstore/filecas.cpp
+++ b/src/zenstore/filecas.cpp
@@ -14,6 +14,7 @@
 #include <zencore/testutils.h>
 #include <zencore/thread.h>
 #include <zencore/timer.h>
+#include <zencore/trace.h>
 #include <zencore/uid.h>
 #include <zenstore/gc.h>
 #include <zenstore/scrubcontext.h>
@@ -125,6 +126,8 @@ FileCasStrategy::~FileCasStrategy()
 void
 FileCasStrategy::Initialize(const std::filesystem::path& RootDirectory, bool IsNewStore)
 {
+	ZEN_TRACE_CPU("FileCas::Initialize");
+
 	using namespace filecas::impl;
 
 	m_IsInitialized = true;
@@ -242,6 +245,8 @@ DeletePayloadFileOnClose(const void* FileHandle)
 CasStore::InsertResult
 FileCasStrategy::InsertChunk(IoBuffer Chunk, const IoHash& ChunkHash, CasStore::InsertMode Mode)
 {
+	ZEN_TRACE_CPU("FileCas::InsertChunk");
+
 	ZEN_ASSERT(m_IsInitialized);
 
 #if !ZEN_WITH_TESTS
@@ -321,7 +326,6 @@ FileCasStrategy::InsertChunk(IoBuffer Chunk, const IoHash& ChunkHash, CasStore::
 						IsNew = m_Index.insert({ChunkHash, IndexEntry{.Size = ChunkSize}}).second;
 					}
 					if (IsNew)
-
 					{
 						m_TotalSize.fetch_add(static_cast<uint64_t>(ChunkSize), std::memory_order::relaxed);
 					}
@@ -536,6 +540,8 @@ FileCasStrategy::InsertChunk(IoBuffer Chunk, const IoHash& ChunkHash, CasStore::
 CasStore::InsertResult
 FileCasStrategy::InsertChunk(const void* const ChunkData, const size_t ChunkSize, const IoHash& ChunkHash)
 {
+	ZEN_TRACE_CPU("FileCas::InsertChunkData");
+
 	ZEN_ASSERT(m_IsInitialized);
 
 	{
@@ -748,6 +754,8 @@ FileCasStrategy::FindChunk(const IoHash& ChunkHash)
 		}
 	}
 
+	ZEN_TRACE_CPU("FileCas::FindChunk");
+
 	ShardingHelper Name(m_RootDirectory.c_str(), ChunkHash);
 
 	RwLock::SharedLockScope _(LockForHash(ChunkHash));
@@ -767,6 +775,8 @@ FileCasStrategy::HaveChunk(const IoHash& ChunkHash)
 void
 FileCasStrategy::DeleteChunk(const IoHash& ChunkHash, std::error_code& Ec)
 {
+	ZEN_TRACE_CPU("FileCas::DeleteChunk");
+
 	ShardingHelper Name(m_RootDirectory.c_str(), ChunkHash);
 
 	uint64_t FileSize = static_cast<uint64_t>(std::filesystem::file_size(Name.ShardedPath.c_str(), Ec));
@@ -812,6 +822,8 @@ FileCasStrategy::FilterChunks(HashKeySet& InOutChunks)
 void
 FileCasStrategy::IterateChunks(std::function<void(const IoHash& Hash, IoBuffer&& Payload)>&& Callback)
 {
+	ZEN_TRACE_CPU("FileCas::IterateChunks");
+
 	ZEN_ASSERT(m_IsInitialized);
 
 	RwLock::SharedLockScope _(m_Lock);
@@ -827,6 +839,8 @@ FileCasStrategy::IterateChunks(std::function<void(const IoHash& Hash, IoBuffer&&
 void
 FileCasStrategy::Flush()
 {
+	ZEN_TRACE_CPU("FileCas::Flush");
+
 	m_CasLog.Flush();
 	MakeIndexSnapshot();
 }
@@ -834,6 +848,8 @@ FileCasStrategy::Flush()
 void
 FileCasStrategy::ScrubStorage(ScrubContext& Ctx)
 {
+	ZEN_TRACE_CPU("FileCas::ScrubStorage");
+
 	ZEN_INFO("scrubbing file CAS @ '{}'", m_RootDirectory);
 
 	ZEN_ASSERT(m_IsInitialized);
@@ -919,6 +935,8 @@ FileCasStrategy::ScrubStorage(ScrubContext& Ctx)
 void
 FileCasStrategy::CollectGarbage(GcContext& GcCtx)
 {
+	ZEN_TRACE_CPU("FileCas::CollectGarbage");
+
 	ZEN_ASSERT(m_IsInitialized);
 
 	ZEN_DEBUG("collecting garbage from {}", m_RootDirectory);
@@ -1038,6 +1056,8 @@ FileCasStrategy::ValidateEntry(const FileCasIndexEntry& Entry, std::string& OutR
 void
 FileCasStrategy::MakeIndexSnapshot()
 {
+	ZEN_TRACE_CPU("FileCas::MakeIndexSnapshot");
+
 	using namespace filecas::impl;
 
 	uint64_t LogCount = m_CasLog.GetLogCount();
@@ -1120,6 +1140,8 @@ FileCasStrategy::MakeIndexSnapshot()
 uint64_t
 FileCasStrategy::ReadIndexFile(const std::filesystem::path& IndexPath, uint32_t& OutVersion)
 {
+	ZEN_TRACE_CPU("FileCas::ReadIndexFile");
+
 	using namespace filecas::impl;
 
 	std::vector<FileCasIndexEntry> Entries;
@@ -1203,6 +1225,8 @@ FileCasStrategy::ReadIndexFile(const std::filesystem::path& IndexPath, uint32_t&
 uint64_t
 FileCasStrategy::ReadLog(const std::filesystem::path& LogPath, uint64_t SkipEntryCount)
 {
+	ZEN_TRACE_CPU("FileCas::ReadLog");
+
 	using namespace filecas::impl;
 
 	if (std::filesystem::is_regular_file(LogPath))
@@ -1255,6 +1279,8 @@ FileCasStrategy::ReadLog(const std::filesystem::path& LogPath, uint64_t SkipEntr
 std::vector<FileCasStrategy::FileCasIndexEntry>
 FileCasStrategy::ScanFolderForCasFiles(const std::filesystem::path& RootDir)
 {
+	ZEN_TRACE_CPU("FileCas::ScanFolderForCasFiles");
+
 	using namespace filecas::impl;
 
 	std::vector<FileCasIndexEntry> Entries;
diff --git a/src/zenstore/gc.cpp b/src/zenstore/gc.cpp
index 2d7e0e02f..dc19a9a35 100644
--- a/src/zenstore/gc.cpp
+++ b/src/zenstore/gc.cpp
@@ -14,6 +14,7 @@
 #include <zencore/testing.h>
 #include <zencore/testutils.h>
 #include <zencore/timer.h>
+#include <zencore/trace.h>
 #include <zenstore/cidstore.h>
 
 #include "cas.h"
@@ -379,6 +380,8 @@ GcManager::RemoveGcStorage(GcStorage* Storage)
 void
 GcManager::CollectGarbage(GcContext& GcCtx)
 {
+	ZEN_TRACE_CPU("Gc::CollectGarbage");
+
 	RwLock::SharedLockScope _(m_Lock);
 
 	// First gather reference set
@@ -415,6 +418,8 @@ GcManager::CollectGarbage(GcContext& GcCtx)
 GcStorageSize
 GcManager::TotalStorageSize() const
 {
+	ZEN_TRACE_CPU("Gc::TotalStorageSize");
+
 	RwLock::SharedLockScope _(m_Lock);
 
 	GcStorageSize TotalSize;