Tracer is feature complete

src/anki/core/App.cpp

@@ -579,7 +579,11 @@ Error App::mainLoop()
 
 			// Render
 			TexturePtr presentableTex = m_gr->acquireNextPresentableTexture();
-			m_renderer->setStatsEnabled(m_displayStats);
+			m_renderer->setStatsEnabled(m_displayStats
+#if ANKI_ENABLE_TRACE
+										|| TracerSingleton::get().getEnabled()
+#endif
+			);
 			ANKI_CHECK(m_renderer->render(rqueue, presentableTex));
 
 			// Pause and sync async loader. That will force all tasks before the pause to finish in this frame.
@@ -628,6 +632,15 @@ Error App::mainLoop()
 				statsUi.m_drawableCount = rqueue.countAllRenderables();
 			}
 
+#if ANKI_ENABLE_TRACE
+			if(m_renderer->getStats().m_renderingGpuTime >= 0.0)
+			{
+				ANKI_TRACE_CUSTOM_EVENT(GPU_TIME,
+					m_renderer->getStats().m_renderingGpuSubmitTimestamp,
+					m_renderer->getStats().m_renderingGpuTime);
+			}
+#endif
+
 			++m_globalTimestamp;
 		}
 

src/anki/core/CoreTracer.cpp

@@ -6,6 +6,7 @@
 #include <anki/core/CoreTracer.h>
 #include <anki/util/DynamicArray.h>
 #include <anki/util/Tracer.h>
+#include <ctime>
 
 namespace anki
 {
@@ -99,19 +100,34 @@ CoreTracer::~CoreTracer()
 		s.destroy(m_alloc);
 	}
 	m_counterNames.destroy(m_alloc);
+
+	// Destroy the tracer
+	TracerSingleton::destroy();
 }
 
 Error CoreTracer::init(GenericMemoryPoolAllocator<U8> alloc, CString directory)
 {
+	TracerSingleton::init(alloc);
+
 	m_alloc = alloc;
 	m_thread.start(this,
 		[](ThreadCallbackInfo& info) -> Error { return static_cast<CoreTracer*>(info.m_userData)->threadWorker(); });
 
-	ANKI_CHECK(m_traceJsonFile.open(StringAuto(alloc).sprintf("%s.trace.json", directory.cstr()), FileOpenFlag::WRITE));
+	std::time_t t = std::time(nullptr);
+	std::tm* tm = std::localtime(&t);
+	StringAuto fname(m_alloc);
+	fname.sprintf("%s/%d-%d-%d-%d-%d_",
+		directory.cstr(),
+		tm->tm_year + 1900,
+		tm->tm_mon + 1,
+		tm->tm_mday,
+		tm->tm_hour,
+		tm->tm_min);
+
+	ANKI_CHECK(m_traceJsonFile.open(StringAuto(alloc).sprintf("%strace.json", fname.cstr()), FileOpenFlag::WRITE));
 	ANKI_CHECK(m_traceJsonFile.writeText("[\n"));
 
-	ANKI_CHECK(
-		m_countersCsvFile.open(StringAuto(alloc).sprintf("%s.trace.csv", directory.cstr()), FileOpenFlag::WRITE));
+	ANKI_CHECK(m_countersCsvFile.open(StringAuto(alloc).sprintf("%scounters.csv", fname.cstr()), FileOpenFlag::WRITE));
 
 	return Error::NONE;
 }
@@ -170,10 +186,13 @@ Error CoreTracer::writeEvents(const ThreadWorkItem& item)
 		const U64 startMicroSec = U64(event.m_start * 1000000.0);
 		const U64 durMicroSec = U64(event.m_duration * 1000000.0);
 
+		// Do a hack
+		const ThreadId tid = (event.m_name == "GPU_TIME") ? 1 : item.m_tid;
+
 		ANKI_CHECK(m_traceJsonFile.writeText("{\"name\": \"%s\", \"cat\": \"PERF\", \"ph\": \"X\", "
 											 "\"pid\": 1, \"tid\": %llu, \"ts\": %llu, \"dur\": %llu},\n",
 			event.m_name.cstr(),
-			item.m_tid,
+			tid,
 			startMicroSec,
 			durMicroSec));
 	}
@@ -195,7 +214,7 @@ void CoreTracer::gatherCounters(ThreadWorkItem& item)
 	DynamicArrayAuto<TracerCounter> mergedCounters(m_alloc);
 	for(U32 i = 0; i < item.m_counters.getSize(); ++i)
 	{
-		if(mergedCounters.getBack().m_name != item.m_counters[i].m_name)
+		if(mergedCounters.getSize() == 0 || mergedCounters.getBack().m_name != item.m_counters[i].m_name)
 		{
 			// New
 			mergedCounters.emplaceBack(item.m_counters[i]);
@@ -206,7 +225,7 @@ void CoreTracer::gatherCounters(ThreadWorkItem& item)
 			mergedCounters.getBack().m_value += item.m_counters[i].m_name;
 		}
 	}
-	ANKI_ASSERT(mergedCounters.getSize() > 0);
+	ANKI_ASSERT(mergedCounters.getSize() > 0 && mergedCounters.getSize() <= item.m_counters.getSize());
 
 	// Add missing counter names
 	Bool addedCounterName = false;
@@ -236,8 +255,8 @@ void CoreTracer::gatherCounters(ThreadWorkItem& item)
 		std::sort(m_counterNames.getBegin(), m_counterNames.getEnd());
 	}
 
-	// Get a per-structure
-	if(!m_frameCounters.isEmpty() && m_frameCounters.getBack().m_frame != item.m_frame)
+	// Get a per-frame structure
+	if(m_frameCounters.isEmpty() || m_frameCounters.getBack().m_frame != item.m_frame)
 	{
 		// Create new frame
 		PerFrameCounters* newPerFrame = m_alloc.newInstance<PerFrameCounters>(m_alloc);
@@ -259,6 +278,7 @@ void CoreTracer::gatherCounters(ThreadWorkItem& item)
 				{
 					existingCounter.m_value += newCounter.m_value;
 					found = true;
+					break;
 				}
 			}
 
@@ -318,17 +338,17 @@ Error CoreTracer::writeCountersForReal()
 	}
 
 	// Write the header
-	ANKI_CHECK(m_countersCsvFile.writeText("Frame,"));
+	ANKI_CHECK(m_countersCsvFile.writeText("Frame"));
 	for(U32 i = 0; i < m_counterNames.getSize(); ++i)
 	{
-		const char* fmt = (i < m_counterNames.getSize() - 1) ? "%s," : "%s\n";
-		ANKI_CHECK(m_countersCsvFile.writeText(fmt, m_counterNames[i].cstr()));
+		ANKI_CHECK(m_countersCsvFile.writeText(",%s", m_counterNames[i].cstr()));
 	}
+	ANKI_CHECK(m_countersCsvFile.writeText("\n"));
 
 	// Write each frame
 	for(const PerFrameCounters& frame : m_frameCounters)
 	{
-		ANKI_CHECK(m_countersCsvFile.writeText("%llu,", frame.m_frame));
+		ANKI_CHECK(m_countersCsvFile.writeText("%llu", frame.m_frame));
 
 		for(U32 j = 0; j < m_counterNames.getSize(); ++j)
 		{
@@ -343,9 +363,10 @@ Error CoreTracer::writeCountersForReal()
 				}
 			}
 
-			const char* fmt = (j < m_counterNames.getSize() - 1) ? "%llu," : "%llu\n";
-			ANKI_CHECK(m_countersCsvFile.writeText(fmt, value));
+			ANKI_CHECK(m_countersCsvFile.writeText(",%llu", value));
 		}
+
+		ANKI_CHECK(m_countersCsvFile.writeText("\n"));
 	}
 
 	// Write some statistics
@@ -356,7 +377,7 @@ Error CoreTracer::writeCountersForReal()
 		for(U32 i = 0; i < m_frameCounters.getSize(); ++i)
 		{
 			Array<char, 3> columnName;
-			getSpreadsheetColumnName(i + 2, columnName);
+			getSpreadsheetColumnName(i + 1, columnName);
 			ANKI_CHECK(m_countersCsvFile.writeText(
 				",=%s(%s2:%s%u)", func, &columnName[0], &columnName[0], m_frameCounters.getSize() + 1));
 		}

src/anki/gr/RenderGraph.cpp

@@ -13,6 +13,7 @@
 #include <anki/util/BitSet.h>
 #include <anki/util/File.h>
 #include <anki/util/StringList.h>
+#include <anki/util/HighRezTimer.h>
 
 namespace anki
 {
@@ -796,6 +797,7 @@ void RenderGraph::initBatches()
 
 				m_statistics.m_nextTimestamp = (m_statistics.m_nextTimestamp + 1) % MAX_TIMESTAMPS_BUFFERED;
 				m_statistics.m_timestamps[m_statistics.m_nextTimestamp * 2] = query;
+				m_statistics.m_cpuStartTimes[m_statistics.m_nextTimestamp] = HighRezTimer::getCurrentTime();
 			}
 		}
 		else
@@ -1294,10 +1296,12 @@ void RenderGraph::getStatistics(RenderGraphStatistics& statistics) const
 
 		const Second diff = end - start;
 		statistics.m_gpuTime = diff;
+		statistics.m_cpuStartTime = m_statistics.m_cpuStartTimes[oldFrame];
 	}
 	else
 	{
 		statistics.m_gpuTime = -1.0;
+		statistics.m_cpuStartTime = -1.0;
 	}
 }
 

src/anki/gr/RenderGraph.h

@@ -524,6 +524,7 @@ class RenderGraphStatistics
 {
 public:
 	Second m_gpuTime; ///< Time spent in the GPU.
+	Second m_cpuStartTime; ///< Time the work was submited from the CPU (almost)
 };
 
 /// Accepts a descriptor of the frame's render passes and sets the dependencies between them.
@@ -621,6 +622,7 @@ private:
 	{
 	public:
 		Array<TimestampQueryPtr, MAX_TIMESTAMPS_BUFFERED * 2> m_timestamps;
+		Array<Second, MAX_TIMESTAMPS_BUFFERED> m_cpuStartTimes;
 		U8 m_nextTimestamp = 0;
 	} m_statistics;
 

src/anki/renderer/MainRenderer.cpp

@@ -187,11 +187,12 @@ Error MainRenderer::render(RenderQueue& rqueue, TexturePtr presentTex)
 	if(m_statsEnabled)
 	{
 		static_cast<RendererStats&>(m_stats) = m_r->getStats();
-		m_stats.m_renderingCpuTime = HighRezTimer::getCurrentTime() - m_stats.m_renderingGpuTime;
+		m_stats.m_renderingCpuTime = HighRezTimer::getCurrentTime() - m_stats.m_renderingCpuTime;
 
 		RenderGraphStatistics rgraphStats;
 		m_rgraph->getStatistics(rgraphStats);
 		m_stats.m_renderingGpuTime = rgraphStats.m_gpuTime;
+		m_stats.m_renderingGpuSubmitTimestamp = rgraphStats.m_cpuStartTime;
 	}
 
 	return Error::NONE;

src/anki/renderer/MainRenderer.h

@@ -27,6 +27,7 @@ class MainRendererStats : public RendererStats
 public:
 	Second m_renderingCpuTime ANKI_DEBUG_CODE(= -1.0);
 	Second m_renderingGpuTime ANKI_DEBUG_CODE(= -1.0);
+	Second m_renderingGpuSubmitTimestamp ANKI_DEBUG_CODE(= -1.0);
 };
 
 /// Main onscreen renderer

src/anki/util/Tracer.cpp

@@ -24,9 +24,9 @@ public:
 class alignas(ANKI_CACHE_LINE_SIZE) Tracer::ThreadLocal
 {
 public:
-	ThreadId m_tid ANKI_DEBUG_CODE(= 0);
+	ThreadId m_tid = 0;
 
-	Chunk* m_currentChunk ANKI_DEBUG_CODE(= nullptr);
+	Chunk* m_currentChunk = nullptr;
 	IntrusiveList<Chunk> m_allChunks;
 	SpinLock m_currentChunkLock;
 };
@@ -35,7 +35,12 @@ thread_local Tracer::ThreadLocal* Tracer::m_threadLocal = nullptr;
 
 Tracer::~Tracer()
 {
-	// TODO
+	LockGuard<Mutex> lock(m_allThreadLocalMtx);
+	for(ThreadLocal* tlocal : m_allThreadLocal)
+	{
+		m_alloc.deleteInstance(tlocal);
+	}
+	m_allThreadLocal.destroy(m_alloc);
 }
 
 Tracer::ThreadLocal& Tracer::getThreadLocal()
@@ -45,7 +50,6 @@ Tracer::ThreadLocal& Tracer::getThreadLocal()
 	{
 		out = m_alloc.newInstance<ThreadLocal>();
 		out->m_tid = Thread::getCurrentThreadId();
-		out->m_currentChunk = nullptr;
 		m_threadLocal = out;
 
 		// Store it
@@ -60,8 +64,8 @@ Tracer::Chunk& Tracer::getOrCreateChunk(ThreadLocal& tlocal)
 {
 	Chunk* out;
 
-	if(tlocal.m_currentChunk && tlocal.m_currentChunk->m_eventCount + 1 < EVENTS_PER_CHUNK
-		&& tlocal.m_currentChunk->m_counterCount + 1 < COUNTERS_PER_CHUNK)
+	if(tlocal.m_currentChunk && tlocal.m_currentChunk->m_eventCount < EVENTS_PER_CHUNK
+		&& tlocal.m_currentChunk->m_counterCount < COUNTERS_PER_CHUNK)
 	{
 		// There is a chunk and it has enough space
 		out = tlocal.m_currentChunk;
@@ -80,7 +84,16 @@ Tracer::Chunk& Tracer::getOrCreateChunk(ThreadLocal& tlocal)
 TracerEventHandle Tracer::beginEvent()
 {
 	TracerEventHandle out;
-	out.m_start = HighRezTimer::getCurrentTime();
+
+	if(m_enabled)
+	{
+		out.m_start = HighRezTimer::getCurrentTime();
+	}
+	else
+	{
+		out.m_start = 0.0;
+	}
+
 	return out;
 }
 
@@ -100,19 +113,42 @@ void Tracer::endEvent(const char* eventName, TracerEventHandle event)
 	LockGuard<SpinLock> lock(tlocal.m_currentChunkLock);
 	Chunk& chunk = getOrCreateChunk(tlocal);
 
-	ANKI_ASSERT(chunk.m_eventCount + 1 < EVENTS_PER_CHUNK);
 	TracerEvent& writeEvent = chunk.m_events[chunk.m_eventCount++];
 	writeEvent.m_name = eventName;
 	writeEvent.m_start = event.m_start;
 	writeEvent.m_duration = timestamp - event.m_start;
 
 	// Write counter as well. In ns
-	ANKI_ASSERT(chunk.m_counterCount + 1 < COUNTERS_PER_CHUNK);
 	TracerCounter& writeCounter = chunk.m_counters[chunk.m_counterCount++];
 	writeCounter.m_name = eventName;
 	writeCounter.m_value = U64(writeEvent.m_duration * 1000000000.0);
 }
 
+void Tracer::addCustomEvent(const char* eventName, Second start, Second duration)
+{
+	ANKI_ASSERT(eventName && start >= 0.0 && duration >= 0.0);
+	if(!m_enabled)
+	{
+		return;
+	}
+
+	ThreadLocal& tlocal = getThreadLocal();
+
+	// Write the event
+	LockGuard<SpinLock> lock(tlocal.m_currentChunkLock);
+	Chunk& chunk = getOrCreateChunk(tlocal);
+
+	TracerEvent& writeEvent = chunk.m_events[chunk.m_eventCount++];
+	writeEvent.m_name = eventName;
+	writeEvent.m_start = start;
+	writeEvent.m_duration = duration;
+
+	// Write counter as well. In ns
+	TracerCounter& writeCounter = chunk.m_counters[chunk.m_counterCount++];
+	writeCounter.m_name = eventName;
+	writeCounter.m_value = U64(duration * 1000000000.0);
+}
+
 void Tracer::incrementCounter(const char* counterName, U64 value)
 {
 	if(!m_enabled)
@@ -125,7 +161,6 @@ void Tracer::incrementCounter(const char* counterName, U64 value)
 	LockGuard<SpinLock> lock(tlocal.m_currentChunkLock);
 	Chunk& chunk = getOrCreateChunk(tlocal);
 
-	ANKI_ASSERT(chunk.m_counterCount + 1 < COUNTERS_PER_CHUNK);
 	TracerCounter& writeTo = chunk.m_counters[chunk.m_counterCount++];
 	writeTo.m_name = counterName;
 	writeTo.m_value = value;

src/anki/util/Tracer.h

@@ -77,6 +77,10 @@ public:
 	/// @note It's thread-safe.
 	void endEvent(const char* eventName, TracerEventHandle event);
 
+	/// Add a custom event.
+	/// @note It's thread-safe.
+	void addCustomEvent(const char* eventName, Second start, Second duration);
+
 	/// Increment a counter.
 	/// @note It's thread-safe.
 	void incrementCounter(const char* counterName, U64 value);
@@ -145,9 +149,12 @@ private:
 
 #if ANKI_ENABLE_TRACE
 #	define ANKI_TRACE_SCOPED_EVENT(name_) TracerScopedEvent _tse##name_(#	name_)
+#	define ANKI_TRACE_CUSTOM_EVENT(name_, start_, duration_) \
+		TracerSingleton::get().addCustomEvent(#name_, start_, duration_)
 #	define ANKI_TRACE_INC_COUNTER(name_, val_) TracerSingleton::get().incrementCounter(#	name_, val_)
 #else
 #	define ANKI_TRACE_SCOPED_EVENT(name_) ((void)0)
+#	define ANKI_TRACE_CUSTOM_EVENT(name_, start_, duration_) ((void)0)
 #	define ANKI_TRACE_INC_COUNTER(name_, val_) ((void)0)
 #endif
 /// @}

tests/util/Tracer.cpp

@@ -14,6 +14,7 @@ ANKI_TEST(Util, Tracer)
 	HeapAllocator<U8> alloc(allocAligned, nullptr);
 	CoreTracer tracer;
 	ANKI_TEST_EXPECT_NO_ERR(tracer.init(alloc, "./"));
+	TracerSingleton::get().setEnabled(true);
 
 	// 1st frame
 	tracer.flushFrame(0);