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

9 files changed, 139 insertions, 9 deletions

diff --git a/src/zenhttp/httpasio.cpp b/src/zenhttp/httpasio.cpp
index 0056103cd..b76f3d2e3 100644
--- a/src/zenhttp/httpasio.cpp
+++ b/src/zenhttp/httpasio.cpp
@@ -3,6 +3,7 @@
 #include "httpasio.h"
 
 #include <zencore/logging.h>
+#include <zencore/trace.h>
 #include <zenhttp/httpserver.h>
 
 #include <deque>
@@ -529,6 +530,8 @@ HttpServerConnection::HandleRequest()
 
 	if (HttpService* Service = m_Server.RouteRequest(m_RequestData.Url()))
 	{
+		ZEN_TRACE_CPU("asio::HandleRequest");
+
 		HttpAsioServerRequest Request(m_RequestData, *Service, m_RequestData.Body());
 
 		ZEN_TRACE_VERBOSE("handle request, connection '{}' request '{}'", m_ConnectionId, m_RequestCounter.load(std::memory_order_relaxed));
diff --git a/src/zenhttp/httpclient.cpp b/src/zenhttp/httpclient.cpp
index 761b4b08e..05ff6d07b 100644
--- a/src/zenhttp/httpclient.cpp
+++ b/src/zenhttp/httpclient.cpp
@@ -11,6 +11,7 @@
 #include <zencore/sharedbuffer.h>
 #include <zencore/stream.h>
 #include <zencore/testing.h>
+#include <zencore/trace.h>
 #include <zenhttp/httpshared.h>
 
 ZEN_THIRD_PARTY_INCLUDES_START
@@ -186,6 +187,8 @@ HttpClient::~HttpClient()
 HttpClient::Response
 HttpClient::TransactPackage(std::string_view Url, CbPackage Package)
 {
+	ZEN_TRACE_CPU("HttpClient::TransactPackage");
+
 	Impl::Session Sess = m_Impl->AllocSession(m_BaseUri, Url);
 
 	// First, list of offered chunks for filtering on the server end
@@ -283,6 +286,8 @@ HttpClient::TransactPackage(std::string_view Url, CbPackage Package)
 HttpClient::Response
 HttpClient::Put(std::string_view Url, const IoBuffer& Payload)
 {
+	ZEN_TRACE_CPU("HttpClient::Put");
+
 	Impl::Session Sess = m_Impl->AllocSession(m_BaseUri, Url);
 	Sess->SetBody(AsCprBody(Payload));
 	Sess->SetHeader(cpr::Header{{"Content-Type", std::string(MapContentTypeToString(Payload.GetContentType()))}});
@@ -293,6 +298,8 @@ HttpClient::Put(std::string_view Url, const IoBuffer& Payload)
 HttpClient::Response
 HttpClient::Get(std::string_view Url)
 {
+	ZEN_TRACE_CPU("HttpClient::Get");
+
 	Impl::Session Sess = m_Impl->AllocSession(m_BaseUri, Url);
 
 	return CommonResponse(Sess->Get());
@@ -301,6 +308,8 @@ HttpClient::Get(std::string_view Url)
 HttpClient::Response
 HttpClient::Delete(std::string_view Url)
 {
+	ZEN_TRACE_CPU("HttpClient::Delete");
+
 	Impl::Session Sess = m_Impl->AllocSession(m_BaseUri, Url);
 
 	return CommonResponse(Sess->Delete());
@@ -309,6 +318,8 @@ HttpClient::Delete(std::string_view Url)
 HttpClient::Response
 HttpClient::Post(std::string_view Url)
 {
+	ZEN_TRACE_CPU("HttpClient::PostNoPayload");
+
 	Impl::Session Sess = m_Impl->AllocSession(m_BaseUri, Url);
 	return CommonResponse(Sess->Post());
 }
@@ -316,6 +327,8 @@ HttpClient::Post(std::string_view Url)
 HttpClient::Response
 HttpClient::Post(std::string_view Url, const IoBuffer& Payload)
 {
+	ZEN_TRACE_CPU("HttpClient::PostWithPayload");
+
 	Impl::Session Sess = m_Impl->AllocSession(m_BaseUri, Url);
 
 	Sess->SetBody(AsCprBody(Payload));
@@ -327,6 +340,8 @@ HttpClient::Post(std::string_view Url, const IoBuffer& Payload)
 HttpClient::Response
 HttpClient::Post(std::string_view Url, CbObject Payload)
 {
+	ZEN_TRACE_CPU("HttpClient::PostObjectPayload");
+
 	Impl::Session Sess = m_Impl->AllocSession(m_BaseUri, Url);
 
 	Sess->SetBody(AsCprBody(Payload));
@@ -338,6 +353,8 @@ HttpClient::Post(std::string_view Url, CbObject Payload)
 HttpClient::Response
 HttpClient::Post(std::string_view Url, CbPackage Pkg)
 {
+	ZEN_TRACE_CPU("HttpClient::PostPackage");
+
 	CompositeBuffer Message = zen::FormatPackageMessageBuffer(Pkg);
 
 	Impl::Session Sess = m_Impl->AllocSession(m_BaseUri, Url);
diff --git a/src/zenserver/projectstore/projectstore.cpp b/src/zenserver/projectstore/projectstore.cpp
index 0beb207ae..dd4c7597c 100644
--- a/src/zenserver/projectstore/projectstore.cpp
+++ b/src/zenserver/projectstore/projectstore.cpp
@@ -1236,6 +1236,8 @@ ProjectStore::Project::Exists(const std::filesystem::path& BasePath)
 void
 ProjectStore::Project::Read()
 {
+	ZEN_TRACE_CPU("ProjectStore::Project::Read");
+
 	using namespace std::literals;
 
 	std::filesystem::path ProjectStateFilePath = m_OplogStoragePath / "Project.zcb"sv;
@@ -1921,6 +1923,8 @@ ProjectStore::CollectGarbage(GcContext& GcCtx)
 GcStorageSize
 ProjectStore::StorageSize() const
 {
+	ZEN_TRACE_CPU("ProjectStore::StorageSize");
+
 	using namespace std::literals;
 
 	GcStorageSize Result;
@@ -1952,6 +1956,8 @@ ProjectStore::StorageSize() const
 Ref<ProjectStore::Project>
 ProjectStore::OpenProject(std::string_view ProjectId)
 {
+	ZEN_TRACE_CPU("ProjectStore::OpenProject");
+
 	{
 		RwLock::SharedLockScope _(m_ProjectsLock);
 
@@ -1999,6 +2005,8 @@ ProjectStore::NewProject(const std::filesystem::path& BasePath,
 						 std::string_view			  ProjectRootDir,
 						 std::string_view			  ProjectFilePath)
 {
+	ZEN_TRACE_CPU("ProjectStore::NewProject");
+
 	RwLock::ExclusiveLockScope _(m_ProjectsLock);
 
 	Ref<Project>& Prj =
@@ -2017,6 +2025,8 @@ ProjectStore::NewProject(const std::filesystem::path& BasePath,
 bool
 ProjectStore::DeleteProject(std::string_view ProjectId)
 {
+	ZEN_TRACE_CPU("ProjectStore::DeleteProject");
+
 	ZEN_INFO("deleting project {}", ProjectId);
 
 	RwLock::ExclusiveLockScope ProjectsLock(m_ProjectsLock);
@@ -2054,6 +2064,8 @@ ProjectStore::Exists(std::string_view ProjectId)
 CbArray
 ProjectStore::GetProjectsList()
 {
+	ZEN_TRACE_CPU("ProjectStore::GetProjectsList");
+
 	using namespace std::literals;
 
 	DiscoverProjects();
@@ -2077,6 +2089,8 @@ ProjectStore::GetProjectsList()
 std::pair<HttpResponseCode, std::string>
 ProjectStore::GetProjectFiles(const std::string_view ProjectId, const std::string_view OplogId, bool FilterClient, CbObject& OutPayload)
 {
+	ZEN_TRACE_CPU("ProjectStore::GetProjectFiles");
+
 	using namespace std::literals;
 
 	Ref<ProjectStore::Project> Project = OpenProject(ProjectId);
@@ -2353,6 +2367,8 @@ ProjectStore::PutChunk(const std::string_view ProjectId,
 std::pair<HttpResponseCode, std::string>
 ProjectStore::WriteOplog(const std::string_view ProjectId, const std::string_view OplogId, IoBuffer&& Payload, CbObject& OutResponse)
 {
+	ZEN_TRACE_CPU("ProjectStore::WriteOplog");
+
 	Ref<ProjectStore::Project> Project = OpenProject(ProjectId);
 	if (!Project)
 	{
@@ -2422,6 +2438,8 @@ ProjectStore::ReadOplog(const std::string_view				  ProjectId,
 						const HttpServerRequest::QueryParams& Params,
 						CbObject&							  OutResponse)
 {
+	ZEN_TRACE_CPU("ProjectStore::ReadOplog");
+
 	Ref<ProjectStore::Project> Project = OpenProject(ProjectId);
 	if (!Project)
 	{
@@ -2472,6 +2490,8 @@ ProjectStore::ReadOplog(const std::string_view				  ProjectId,
 std::pair<HttpResponseCode, std::string>
 ProjectStore::WriteBlock(const std::string_view ProjectId, const std::string_view OplogId, IoBuffer&& Payload)
 {
+	ZEN_TRACE_CPU("ProjectStore::WriteBlock");
+
 	Ref<ProjectStore::Project> Project = OpenProject(ProjectId);
 	if (!Project)
 	{
@@ -2505,6 +2525,8 @@ ProjectStore::Rpc(HttpServerRequest&	 HttpReq,
 				  IoBuffer&&			 Payload,
 				  AuthMgr&				 AuthManager)
 {
+	ZEN_TRACE_CPU("ProjectStore::Rpc");
+
 	using namespace std::literals;
 	HttpContentType PayloadContentType = HttpReq.RequestContentType();
 	CbPackage		Package;
@@ -2635,6 +2657,8 @@ ProjectStore::Rpc(HttpServerRequest&	 HttpReq,
 std::pair<HttpResponseCode, std::string>
 ProjectStore::Export(ProjectStore::Project& Project, ProjectStore::Oplog& Oplog, CbObjectView&& Params, AuthMgr& AuthManager)
 {
+	ZEN_TRACE_CPU("ProjectStore::Export");
+
 	using namespace std::literals;
 
 	size_t MaxBlockSize		 = Params["maxblocksize"sv].AsUInt64(128u * 1024u * 1024u);
@@ -2673,6 +2697,8 @@ ProjectStore::Export(ProjectStore::Project& Project, ProjectStore::Oplog& Oplog,
 std::pair<HttpResponseCode, std::string>
 ProjectStore::Import(ProjectStore::Project& Project, ProjectStore::Oplog& Oplog, CbObjectView&& Params, AuthMgr& AuthManager)
 {
+	ZEN_TRACE_CPU("ProjectStore::Import");
+
 	using namespace std::literals;
 
 	size_t MaxBlockSize		 = Params["maxblocksize"sv].AsUInt64(128u * 1024u * 1024u);
@@ -3075,6 +3101,8 @@ HttpProjectService::HttpProjectService(CidStore& Store, ProjectStore* Projects,
 	m_Router.RegisterRoute(
 		"{project}/oplog/{log}/prep",
 		[this](HttpRouterRequest& Req) {
+			ZEN_TRACE_CPU("ProjectService::OplogPrep");
+
 			HttpServerRequest& HttpReq = Req.ServerRequest();
 
 			const auto& ProjectId = Req.GetCapture(1);
@@ -3133,6 +3161,8 @@ HttpProjectService::HttpProjectService(CidStore& Store, ProjectStore* Projects,
 	m_Router.RegisterRoute(
 		"{project}/oplog/{log}/new",
 		[this](HttpRouterRequest& Req) {
+			ZEN_TRACE_CPU("ProjectService::OplogNew");
+
 			HttpServerRequest& HttpReq = Req.ServerRequest();
 
 			if (!m_ProjectStore->AreDiskWritesAllowed())
@@ -3444,6 +3474,8 @@ HttpProjectService::HttpProjectService(CidStore& Store, ProjectStore* Projects,
 	m_Router.RegisterRoute(
 		"{project}/oplog/{log}/entries",
 		[this](HttpRouterRequest& Req) {
+			ZEN_TRACE_CPU("ProjectService::OplogEntries");
+
 			HttpServerRequest& HttpReq = Req.ServerRequest();
 
 			const auto& ProjectId = Req.GetCapture(1);
@@ -3601,6 +3633,8 @@ HttpProjectService::HttpProjectService(CidStore& Store, ProjectStore* Projects,
 	m_Router.RegisterRoute(
 		"{project}/oplog/{log}/save",
 		[this](HttpRouterRequest& Req) {
+			ZEN_TRACE_CPU("ProjectService::OplogSave");
+
 			HttpServerRequest& HttpReq = Req.ServerRequest();
 
 			if (!m_ProjectStore->AreDiskWritesAllowed())
@@ -3634,6 +3668,8 @@ HttpProjectService::HttpProjectService(CidStore& Store, ProjectStore* Projects,
 	m_Router.RegisterRoute(
 		"{project}/oplog/{log}/load",
 		[this](HttpRouterRequest& Req) {
+			ZEN_TRACE_CPU("ProjectService::OplogLoad");
+
 			HttpServerRequest& HttpReq	 = Req.ServerRequest();
 			const auto&		   ProjectId = Req.GetCapture(1);
 			const auto&		   OplogId	 = Req.GetCapture(2);
diff --git a/src/zenserver/upstream/upstreamcache.cpp b/src/zenserver/upstream/upstreamcache.cpp
index 2a9e67c06..ca3cde778 100644
--- a/src/zenserver/upstream/upstreamcache.cpp
+++ b/src/zenserver/upstream/upstreamcache.cpp
@@ -120,12 +120,14 @@ namespace detail {
 			m_Client = new CloudCacheClient(Options, std::move(TokenProvider));
 		}
 
-		virtual ~JupiterUpstreamEndpoint() = default;
+		virtual ~JupiterUpstreamEndpoint() {}
 
 		virtual const UpstreamEndpointInfo& GetEndpointInfo() const override { return m_Info; }
 
 		virtual UpstreamEndpointStatus Initialize() override
 		{
+			ZEN_TRACE_CPU("Upstream::Jupiter::Initialize");
+
 			try
 			{
 				if (m_Status.EndpointState() == UpstreamEndpointState::kOk)
@@ -185,7 +187,7 @@ namespace detail {
 															const CacheKey&	 CacheKey,
 															ZenContentType	 Type) override
 		{
-			ZEN_TRACE_CPU("Upstream::Horde::GetSingleCacheRecord");
+			ZEN_TRACE_CPU("Upstream::Jupiter::GetSingleCacheRecord");
 
 			try
 			{
@@ -303,7 +305,7 @@ namespace detail {
 													   std::span<CacheKeyRequest*> Requests,
 													   OnCacheRecordGetComplete&&  OnComplete) override
 		{
-			ZEN_TRACE_CPU("Upstream::Horde::GetCacheRecords");
+			ZEN_TRACE_CPU("Upstream::Jupiter::GetCacheRecords");
 
 			CloudCacheSession	   Session(m_Client);
 			GetUpstreamCacheResult Result;
@@ -366,7 +368,7 @@ namespace detail {
 														   const CacheKey&,
 														   const IoHash& ValueContentId) override
 		{
-			ZEN_TRACE_CPU("Upstream::Horde::GetSingleCacheChunk");
+			ZEN_TRACE_CPU("Upstream::Jupiter::GetSingleCacheChunk");
 
 			try
 			{
@@ -399,7 +401,7 @@ namespace detail {
 													  std::span<CacheChunkRequest*> CacheChunkRequests,
 													  OnCacheChunksGetComplete&&	OnComplete) override final
 		{
-			ZEN_TRACE_CPU("Upstream::Horde::GetCacheChunks");
+			ZEN_TRACE_CPU("Upstream::Jupiter::GetCacheChunks");
 
 			CloudCacheSession	   Session(m_Client);
 			GetUpstreamCacheResult Result;
@@ -454,7 +456,7 @@ namespace detail {
 													  std::span<CacheValueRequest*> CacheValueRequests,
 													  OnCacheValueGetComplete&&		OnComplete) override final
 		{
-			ZEN_TRACE_CPU("Upstream::Horde::GetCacheValues");
+			ZEN_TRACE_CPU("Upstream::Jupiter::GetCacheValues");
 
 			CloudCacheSession	   Session(m_Client);
 			GetUpstreamCacheResult Result;
@@ -529,7 +531,7 @@ namespace detail {
 													  IoBuffer					 RecordValue,
 													  std::span<IoBuffer const>	 Values) override
 		{
-			ZEN_TRACE_CPU("Upstream::Horde::PutCacheRecord");
+			ZEN_TRACE_CPU("Upstream::Jupiter::PutCacheRecord");
 
 			ZEN_ASSERT(CacheRecord.ValueContentIds.size() == Values.size());
 			const int32_t MaxAttempts = 3;
@@ -788,12 +790,14 @@ namespace detail {
 			}
 		}
 
-		~ZenUpstreamEndpoint() = default;
+		~ZenUpstreamEndpoint() {}
 
 		virtual const UpstreamEndpointInfo& GetEndpointInfo() const override { return m_Info; }
 
 		virtual UpstreamEndpointStatus Initialize() override
 		{
+			ZEN_TRACE_CPU("Upstream::Zen::Initialize");
+
 			try
 			{
 				if (m_Status.EndpointState() == UpstreamEndpointState::kOk)
@@ -1488,6 +1492,8 @@ public:
 
 	virtual void Initialize() override
 	{
+		ZEN_TRACE_CPU("Upstream::Initialize");
+
 		for (uint32_t Idx = 0; Idx < m_Options.ThreadCount; Idx++)
 		{
 			m_UpstreamThreads.emplace_back(&UpstreamCacheImpl::ProcessUpstreamQueue, this, Idx + 1);
@@ -1499,6 +1505,8 @@ public:
 
 	virtual void RegisterEndpoint(std::unique_ptr<UpstreamEndpoint> Endpoint) override
 	{
+		ZEN_TRACE_CPU("Upstream::RegisterEndpoint");
+
 		const UpstreamEndpointStatus Status = Endpoint->Initialize();
 		const UpstreamEndpointInfo&	 Info	= Endpoint->GetEndpointInfo();
 
@@ -1840,6 +1848,8 @@ public:
 
 	virtual void GetStatus(CbObjectWriter& Status) override
 	{
+		ZEN_TRACE_CPU("Upstream::GetStatus");
+
 		Status << "reading" << m_Options.ReadUpstream;
 		Status << "writing" << m_Options.WriteUpstream;
 		Status << "worker_threads" << m_Options.ThreadCount;
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;