Work on tracing support

include/anki/core/Trace.h

@@ -27,6 +27,8 @@ enum class TraceEventType
 	SCENE_PHYSICS_UPDATE,
 	SCENE_NODES_UPDATE,
 	SCENE_VISIBILITY_TESTS,
+	SCENE_VISIBILITY_TEST,
+	SCENE_VISIBILITY_COMBINE_RESULTS,
 	RENDER,
 	RENDER_MS,
 	RENDER_IS,
@@ -34,6 +36,17 @@ enum class TraceEventType
 	RENDER_DRAWER,
 	GL_THREAD,
 	SWAP_BUFFERS,
+	IDLE,
+
+	COUNT
+};
+
+/// Trace counter type.
+enum class TraceCounterType
+{
+	GR_DRAWCALLS,
+	GR_DYNAMIC_UNIFORMS_SIZE,
+	RENDERER_LIGHT_COUNT,
 
 	COUNT
 };
@@ -50,46 +63,46 @@ public:
 	ANKI_USE_RESULT Error create(HeapAllocator<U8> alloc,
 		const CString& cacheDir);
 
-	void startEvent(TraceEventType type)
+	void startEvent();
+
+	void stopEvent(TraceEventType type);
+
+	void incCounter(TraceCounterType c, U64 val)
 	{
-		addEvent(type, true);
+		U idx = U(TraceEventType::COUNT) + U(c);
+		m_perFrameCounters[idx].fetchAdd(val);
+		m_perRunCounters[idx].fetchAdd(val);
 	}
 
-	void stopEvent(TraceEventType type)
+	void startFrame()
 	{
-		addEvent(type, false);
+		m_startFrameTime = HighRezTimer::getCurrentTime();
 	}
 
-	void flush();
+	void stopFrame();
 
 private:
 	class Entry
 	{
 	public:
 		TraceEventType m_event;
-		HighRezTimer::Scalar m_timestamp;
+		HighRezTimer::Scalar m_timestamp; ///< When it started.
+		HighRezTimer::Scalar m_duration;
 		Thread::Id m_tid;
-		Bool8 m_start;
 	};
 
 	static const U BUFFERED_ENTRIES = 1024 * 10;
 	Array<Entry, BUFFERED_ENTRIES> m_entries;
 	Atomic<U32> m_count = {0};
 	File m_file;
+	HighRezTimer::Scalar m_startFrameTime;
 
-	void addEvent(TraceEventType type, Bool start)
-	{
-		U id = m_count.fetchAdd(1);
-		if(id < BUFFERED_ENTRIES)
-		{
-			m_entries[id] = Entry{type, HighRezTimer::getCurrentTime(),
-				Thread::getCurrentThreadId(), start};
-		}
-		else
-		{
-			ANKI_LOGW("Increase the buffered trace entries");
-		}
-	}
+	Array<Atomic<U64>, U(TraceEventType::COUNT) + U(TraceCounterType::COUNT)>
+		m_perFrameCounters = {{}};
+	Array<Atomic<U64>, U(TraceEventType::COUNT) + U(TraceCounterType::COUNT)>
+		m_perRunCounters = {{}};
+
+	void flushCounters();
 };
 
 using TraceManagerSingleton = Singleton<TraceManager>;
@@ -100,19 +113,26 @@ using TraceManagerSingleton = Singleton<TraceManager>;
 #if ANKI_ENABLE_COUNTERS
 
 #	define ANKI_TRACE_START_EVENT(name_) \
-	TraceManagerSingleton::get().startEvent(TraceEventType::name_)
+	TraceManagerSingleton::get().startEvent()
 
 #	define ANKI_TRACE_STOP_EVENT(name_) \
 	TraceManagerSingleton::get().stopEvent(TraceEventType::name_)
 
-#	define ANKI_TRACE_FLUSH() \
-	TraceManagerSingleton::get().flush()
+#	define ANKI_TRACE_INC_COUNTER(name_, val_) \
+	TraceManagerSingleton::get().incCounter(TraceCounterType:: name_, val_)
+
+#	define ANKI_TRACE_START_FRAME() \
+	TraceManagerSingleton::get().startFrame()
+
+#	define ANKI_TRACE_STOP_FRAME() \
+	TraceManagerSingleton::get().stopFrame()
 
 #else
 
 #	define ANKI_TRACE_START_EVENT(name_) ((void)0)
 #	define ANKI_TRACE_STOP_EVENT(name_) ((void)0)
-#	define ANKI_TRACE_FLUSH() ((void)0)
+#	define ANKI_TRACE_START_FRAME() ((void)0)
+#	define ANKI_TRACE_STOP_FRAME() ((void)0)
 
 #endif
 /// @}

src/core/App.cpp

@@ -384,6 +384,7 @@ Error App::mainLoop(UserMainLoopCallback callback, void* userData)
 	ANKI_COUNTER_START_TIMER(FPS);
 	while(!quit)
 	{
+		ANKI_TRACE_START_FRAME();
 		HighRezTimer timer;
 		timer.start();
 
@@ -402,7 +403,6 @@ Error App::mainLoop(UserMainLoopCallback callback, void* userData)
 
 		m_gr->swapBuffers();
 		ANKI_COUNTERS_RESOLVE_FRAME();
-		ANKI_TRACE_FLUSH();
 
 		// Sleep
 		timer.stop();
@@ -412,6 +412,8 @@ Error App::mainLoop(UserMainLoopCallback callback, void* userData)
 		}
 
 		++m_globalTimestamp;
+
+		ANKI_TRACE_STOP_FRAME();
 	}
 
 	// Performance ends

src/core/Trace.cpp

@@ -8,33 +8,56 @@
 namespace anki {
 
 //==============================================================================
-static Array<const char*, U(TraceEventType::COUNT)> traceNames = {{
+// Misc                                                                        =
+//==============================================================================
+
+static Array<const char*, U(TraceEventType::COUNT)> eventNames = {{
 	"SCENE_UPDATE",
 	"SCENE_DELETE_STUFF",
 	"SCENE_PHYSICS_UPDATE",
 	"SCENE_NODES_UPDATE",
 	"SCENE_VISIBILITY_TESTS",
+	"SCENE_VISIBILITY_TEST",
+	"SCENE_VISIBILITY_COMBINE_RESULTS",
 	"RENDER",
 	"RENDER_MS",
 	"RENDER_IS",
 	"RENDER_SM",
 	"RENDER_DRAWER",
 	"GL_THREAD",
-	"SWAP_BUFFERS"
+	"SWAP_BUFFERS",
+	"IDLE"
 }};
 
+static Array<const char*, U(TraceCounterType::COUNT)> counterNames = {{
+	"GR_DRAWCALLS",
+	"GR_DYNAMIC_UNIFORMS_SIZE"
+	"RENDERER_LIGHT_COUNT",
+}};
+
+#define ANKI_TRACE_FILE_ERROR() \
+	if(err) { \
+		ANKI_LOGE("Error writing the trace file"); \
+	}
+
+const U MAX_EVENTS_DEPTH = 10;
+thread_local HighRezTimer::Scalar g_traceEventStartTime[MAX_EVENTS_DEPTH];
+thread_local I g_traceEventsInFlight = 0;
+
+//==============================================================================
+// TraceManager                                                                =
+//==============================================================================
+
 //==============================================================================
 TraceManager::~TraceManager()
 {
 	if(m_file.isOpen())
 	{
-		Error err = m_file.writeText(R"({"name": "dummy", "cat": "PERF", )"
-			R"("ph": "E", "pid": 666, "tid": 0, "ts": 0}]})");
+		Error err = m_file.writeText("{\"name\": \"dummy\", \"cat\": \"PERF\", "
+			"\"ph\": \"X\", \"pid\": 666, \"tid\": %llu, \"ts\": 0, "
+			"\"dur\": 1}]}", Thread::getCurrentThreadId());
 
-		if(err)
-		{
-			ANKI_LOGE("Error writting the trace file");
-		}
+		ANKI_TRACE_FILE_ERROR();
 	}
 }
 
@@ -55,8 +78,70 @@ Error TraceManager::create(HeapAllocator<U8> alloc, const CString& cacheDir)
 }
 
 //==============================================================================
-void TraceManager::flush()
+void TraceManager::startEvent()
+{
+	I i = ++g_traceEventsInFlight;
+	--i;
+	ANKI_ASSERT(i > 0 && <= MAX_EVENTS_DEPTH);
+
+	g_traceEventStartTime[i] = HighRezTimer::getCurrentTime();
+}
+
+//==============================================================================
+void TraceManager::stopEvent(TraceEventType type)
+{
+	I i = --g_traceEventsInFlight;
+	ANKI_ASSERT(i >= 0 && < MAX_EVENTS_DEPTH);
+	auto startedTime = g_traceEventStartTime[i];
+
+	U id = m_count.fetchAdd(1);
+	if(id < BUFFERED_ENTRIES)
+	{
+		auto now = HighRezTimer::getCurrentTime();
+		m_entries[id] = Entry{type, startedTime, now - startedTime,
+			Thread::getCurrentThreadId()};
+	}
+	else
+	{
+		ANKI_LOGW("Increase the buffered trace entries");
+	}
+}
+
+//==============================================================================
+void TraceManager::flushCounters()
 {
+	for(U i = 0; i < U(TraceCounterType::COUNT); ++i)
+	{
+		auto count =
+			m_perFrameCounters[U(TraceEventType::COUNT) + i].exchange(0);
+
+
+		Error err = m_file.writeText(
+			"{\"name\": \"%s\", \"cat\": \"PERF\", \"ph\": \"C\", "
+			"\"pid\": 666, \"ts\": %llu, \"args\": {\"val\": %llu}},\n",
+			counterNames[i], U64(m_startFrameTime * 1000000.0), count);
+
+		ANKI_TRACE_FILE_ERROR();
+	}
+}
+
+//==============================================================================
+void TraceManager::stopFrame()
+{
+	flushCounters();
+
+	// Write the FPS counter
+	HighRezTimer::Scalar now = HighRezTimer::getCurrentTime();
+	HighRezTimer::Scalar time = now - m_startFrameTime;
+	F32 fps = 1.0 / time;
+	Error err = m_file.writeText(
+		"{\"name\": \"FPS\", \"cat\": \"PERF\", \"ph\": \"C\", "
+		"\"pid\": 666, \"ts\": %llu, \"args\": {\"val\": %f}},\n",
+		U64(m_startFrameTime * 1000000.0), fps);
+
+	ANKI_TRACE_FILE_ERROR();
+
+	// Write the events
 	U count = m_count.exchange(0);
 	count = min<U>(count, BUFFERED_ENTRIES);
 
@@ -65,15 +150,12 @@ void TraceManager::flush()
 		const Entry& e = m_entries[i];
 
 		Error err = m_file.writeText(
-			"{\"name\": \"%s\", \"cat\": \"PERF\", \"ph\": \"%s\", "
-			"\"pid\": 666, \"tid\": %llu, \"ts\": %llu},\n",
-			traceNames[e.m_event], (e.m_start ? "B" : "E"), e.m_tid,
-			U64(e.m_timestamp * 1000000.0));
-
-		if(err)
-		{
-			ANKI_LOGE("Error writting the trace file");
-		}
+			"{\"name\": \"%s\", \"cat\": \"PERF\", \"ph\": \"X\", "
+			"\"pid\": 666, \"tid\": %llu, \"ts\": %llu, \"dur\": %llu},\n",
+			eventNames[e.m_event], e.m_tid, U64(e.m_timestamp * 1000000.0),
+			U64(e.m_duration * 1000000.0));
+
+		ANKI_TRACE_FILE_ERROR();
 	}
 }
 

src/gr/gl/CommandBuffer.cpp

@@ -213,6 +213,7 @@ public:
 				m_info.m_baseVertex,
 				m_info.m_baseInstance);
 
+			ANKI_TRACE_INC_COUNTER(GR_DRAWCALLS, 1);
 			ANKI_COUNTER_INC(GL_DRAWCALLS_COUNT, U64(1));
 			ANKI_COUNTER_INC(GL_VERTICES_COUNT,
 				U64(m_info.m_instanceCount * m_info.m_count));
@@ -256,6 +257,7 @@ public:
 				m_info.m_instanceCount,
 				m_info.m_baseInstance);
 
+			ANKI_TRACE_INC_COUNTER(GR_DRAWCALLS, 1);
 			ANKI_COUNTER_INC(GL_DRAWCALLS_COUNT, U64(1));
 		}
 

src/gr/gl/GlState.cpp

@@ -8,6 +8,7 @@
 #include <anki/gr/GrManager.h>
 #include <anki/util/Logger.h>
 #include <anki/core/Counters.h>
+#include <anki/core/Trace.h>
 #include <anki/misc/ConfigSet.h>
 #include <algorithm>
 #include <cstring>
@@ -222,6 +223,7 @@ void GlState::checkDynamicMemoryConsumption()
 			{
 			case BufferUsage::UNIFORM:
 				ANKI_COUNTER_INC(GR_DYNAMIC_UNIFORMS_SIZE, U64(bytesUsed));
+				ANKI_TRACE_INC_COUNTER(GR_DYNAMIC_UNIFORMS_SIZE, bytesUsed);
 				break;
 			case BufferUsage::STORAGE:
 				ANKI_COUNTER_INC(GR_DYNAMIC_STORAGE_SIZE, U64(bytesUsed));

src/gr/gl/RenderingThread.cpp

@@ -291,6 +291,8 @@ void RenderingThread::syncClientServer()
 //==============================================================================
 void RenderingThread::swapBuffersInternal(GlState& state)
 {
+	ANKI_TRACE_START_EVENT(SWAP_BUFFERS);
+
 	// Do the swap buffers
 	m_interface->swapBuffersCommand();
 
@@ -302,6 +304,8 @@ void RenderingThread::swapBuffersInternal(GlState& state)
 
 	m_frameCondVar.notifyOne();
 	state.checkDynamicMemoryConsumption();
+
+	ANKI_TRACE_STOP_EVENT(SWAP_BUFFERS);
 }
 
 //==============================================================================

src/renderer/Is.cpp

@@ -392,6 +392,8 @@ Error Is::lightPass(CommandBufferPtr& cmdb)
 
 	ANKI_COUNTER_INC(RENDERER_LIGHTS_COUNT,
 		U64(visiblePointLightsCount + visibleSpotLightsCount));
+	ANKI_TRACE_INC_COUNTER(RENDERER_LIGHT_COUNT,
+		U64(visiblePointLightsCount + visibleSpotLightsCount));
 
 	//
 	// Do shadows pass

src/scene/Visibility.cpp

@@ -151,6 +151,7 @@ public:
 void VisibilityTestTask::test(FrustumComponent& testedFrc,
 	U32 threadId, PtrSize threadsCount)
 {
+	ANKI_TRACE_START_EVENT(SCENE_VISIBILITY_TEST);
 	ANKI_ASSERT(testedFrc.anyVisibilityTestEnabled());
 
 	SceneNode& testedNode = testedFrc.getSceneNode();
@@ -396,12 +397,16 @@ void VisibilityTestTask::test(FrustumComponent& testedFrc,
 	}); // end for
 	(void)err;
 
+	ANKI_TRACE_STOP_EVENT(SCENE_VISIBILITY_TEST);
+
 	// Gather the results from all threads
 	m_shared->m_barrier.wait();
 
 	if(threadId == 0)
 	{
+		ANKI_TRACE_START_EVENT(SCENE_VISIBILITY_COMBINE_RESULTS);
 		combineTestResults(testedFrc, threadsCount);
+		ANKI_TRACE_STOP_EVENT(SCENE_VISIBILITY_COMBINE_RESULTS);
 	}
 }
 

testapp/Main.cpp

@@ -488,7 +488,7 @@ Error initSubsystems(int argc, char* argv[])
 	config.set("is.sm.poissonEnabled", true);
 	config.set("is.sm.resolution", 1024);
 	config.set("lf.maxFlares", 32);
-	config.set("pps.enabled", false);
+	config.set("pps.enabled", true);
 	config.set("pps.bloom.enabled", true);
 	config.set("pps.bloom.renderingQuality", 0.5);
 	config.set("pps.bloom.blurringDist", 1.0);