From d557c82b35839bbecfe8313ee21701d838f46b44 Mon Sep 17 00:00:00 2001 From: Robert Beckebans Date: Mon, 21 Feb 2022 22:08:04 +0100 Subject: [PATCH] Improved RenderDoc logging --- neo/renderer/NVRHI/RenderDebug_NVRHI.cpp | 2 +- neo/renderer/RenderBackend.cpp | 20 +- neo/renderer/RenderLog.cpp | 327 ++--------------------- neo/renderer/RenderLog.h | 106 +------- 4 files changed, 37 insertions(+), 418 deletions(-) diff --git a/neo/renderer/NVRHI/RenderDebug_NVRHI.cpp b/neo/renderer/NVRHI/RenderDebug_NVRHI.cpp index 17303c5a..48ccf0de 100644 --- a/neo/renderer/NVRHI/RenderDebug_NVRHI.cpp +++ b/neo/renderer/NVRHI/RenderDebug_NVRHI.cpp @@ -3650,7 +3650,7 @@ void idRenderBackend::DBG_RenderDebugTools( drawSurf_t** drawSurfs, int numDrawS return; } - renderLog.OpenMainBlock( MRB_DRAW_DEBUG_TOOLS ); + renderLog.OpenMainBlock( MRB_DRAW_DEBUG_TOOLS, commandList ); renderLog.OpenBlock( "Render_DebugTools", colorGreen ); RENDERLOG_PRINTF( "---------- RB_RenderDebugTools ----------\n" ); diff --git a/neo/renderer/RenderBackend.cpp b/neo/renderer/RenderBackend.cpp index 04b077a8..e7975445 100644 --- a/neo/renderer/RenderBackend.cpp +++ b/neo/renderer/RenderBackend.cpp @@ -1102,7 +1102,7 @@ void idRenderBackend::FillDepthBufferFast( drawSurf_t** drawSurfs, int numDrawSu return; } - renderLog.OpenMainBlock( MRB_FILL_DEPTH_BUFFER ); + renderLog.OpenMainBlock( MRB_FILL_DEPTH_BUFFER, commandList ); renderLog.OpenBlock( "Render_FillDepthBufferFast", colorBlue ); // force MVP change on first surface @@ -2283,7 +2283,7 @@ void idRenderBackend::AmbientPass( const drawSurf_t* const* drawSurfs, int numDr return; } - renderLog.OpenMainBlock( fillGbuffer ? MRB_FILL_GEOMETRY_BUFFER : MRB_AMBIENT_PASS ); + renderLog.OpenMainBlock( fillGbuffer ? MRB_FILL_GEOMETRY_BUFFER : MRB_AMBIENT_PASS, commandList ); renderLog.OpenBlock( fillGbuffer ? "Fill_GeometryBuffer" : "Render_AmbientPass", colorBlue ); if( fillGbuffer ) @@ -3646,7 +3646,7 @@ void idRenderBackend::DrawInteractions( const viewDef_t* _viewDef ) return; } - renderLog.OpenMainBlock( MRB_DRAW_INTERACTIONS ); + renderLog.OpenMainBlock( MRB_DRAW_INTERACTIONS, commandList ); renderLog.OpenBlock( "Render_Interactions", colorYellow ); GL_SelectTexture( 0 ); @@ -4643,7 +4643,7 @@ void idRenderBackend::FogAllLights() return; } - renderLog.OpenMainBlock( MRB_FOG_ALL_LIGHTS ); + renderLog.OpenMainBlock( MRB_FOG_ALL_LIGHTS, commandList ); renderLog.OpenBlock( "Render_FogAllLights", colorBlue ); // force fog plane to recalculate @@ -4897,7 +4897,7 @@ void idRenderBackend::Bloom( const viewDef_t* _viewDef ) return; } - renderLog.OpenMainBlock( MRB_BLOOM ); + renderLog.OpenMainBlock( MRB_BLOOM, commandList ); renderLog.OpenBlock( "Render_Bloom", colorBlue ); RENDERLOG_PRINTF( "---------- RB_Bloom( avg = %f, max = %f, key = %f ) ----------\n", hdrAverageLuminance, hdrMaxLuminance, hdrKey ); @@ -5055,7 +5055,7 @@ void idRenderBackend::DrawScreenSpaceAmbientOcclusion( const viewDef_t* _viewDef return; } - renderLog.OpenMainBlock( MRB_SSAO_PASS ); + renderLog.OpenMainBlock( MRB_SSAO_PASS, commandList ); renderLog.OpenBlock( "Render_SSAO", colorBlue ); currentSpace = &viewDef->worldSpace; @@ -5752,7 +5752,7 @@ void idRenderBackend::ExecuteBackEndCommands( const emptyCommand_t* cmds ) if( drawView3D_timestamps ) { // SRS - Capture separate timestamps for overlay GUI rendering when RC_DRAW_VIEW_3D timestamps are active - renderLog.OpenMainBlock( MRB_DRAW_GUI ); + renderLog.OpenMainBlock( MRB_DRAW_GUI, commandList ); renderLog.OpenBlock( "Render_DrawViewGUI", colorBlue ); // SRS - Disable detailed timestamps during overlay GUI rendering so they do not overwrite timestamps from 3D rendering glConfig.timerQueryAvailable = false; @@ -5979,7 +5979,7 @@ void idRenderBackend::DrawViewInternal( const viewDef_t* _viewDef, const int ste int processed = 0; if( !r_skipShaderPasses.GetBool() ) { - renderLog.OpenMainBlock( MRB_DRAW_SHADER_PASSES ); + renderLog.OpenMainBlock( MRB_DRAW_SHADER_PASSES, commandList ); float guiScreenOffset; if( _viewDef->viewEntitys != NULL ) { @@ -6053,7 +6053,7 @@ void idRenderBackend::DrawViewInternal( const viewDef_t* _viewDef, const int ste SetFragmentParm( RENDERPARM_WINDOWCOORD, windowCoordParm ); // rpWindowCoord // render the remaining surfaces - renderLog.OpenMainBlock( MRB_DRAW_SHADER_PASSES_POST ); + renderLog.OpenMainBlock( MRB_DRAW_SHADER_PASSES_POST, commandList ); DrawShaderPasses( drawSurfs + processed, numDrawSurfs - processed, 0.0f /* definitely not a gui */, stereoEye ); renderLog.CloseMainBlock(); } @@ -6363,7 +6363,7 @@ void idRenderBackend::PostProcess( const void* data ) return; #endif - renderLog.OpenMainBlock( MRB_POSTPROCESS ); + renderLog.OpenMainBlock( MRB_POSTPROCESS, commandList ); renderLog.OpenBlock( "Render_PostProcessing", colorBlue ); // FIXME diff --git a/neo/renderer/RenderLog.cpp b/neo/renderer/RenderLog.cpp index c50a7ef0..c19478ff 100644 --- a/neo/renderer/RenderLog.cpp +++ b/neo/renderer/RenderLog.cpp @@ -37,7 +37,7 @@ TODO: Emit statistics to the logfile at the end of views and frames. ================================================================================================ */ -idCVar r_logLevel( "r_logLevel", "2", CVAR_INTEGER, "1 = blocks only, 2 = everything", 1, 2 ); +idCVar r_logLevel( "r_logLevel", "0", CVAR_INTEGER, "1 = blocks only, 2 = everything", 1, 2 ); static const int LOG_LEVEL_BLOCKS_ONLY = 1; static const int LOG_LEVEL_EVERYTHING = 2; @@ -285,308 +285,7 @@ idRenderLog idRenderLog renderLog; -#if !defined( STUB_RENDER_LOG ) -/* -======================== -idRenderLog::idRenderLog -======================== -*/ -idRenderLog::idRenderLog() -{ - activeLevel = 0; - indentString[0] = '\0'; - indentLevel = 0; -// logFile = NULL; - - frameStartTime = 0; - closeBlockTime = 0; - logLevel = 0; -} - -/* -======================== -idRenderLog::StartFrame -======================== -*/ -void idRenderLog::StartFrame() -{ - if( r_logFile.GetInteger() == 0 ) - { - return; - } - - // open a new logfile - indentLevel = 0; - indentString[0] = '\0'; - activeLevel = r_logLevel.GetInteger(); - - /* - struct tm* newtime; - time_t aclock; - - char ospath[ MAX_OSPATH ]; - - char qpath[128]; - sprintf( qpath, "renderlogPC_%04i.txt", r_logFile.GetInteger() ); - //idStr finalPath = fileSystem->RelativePathToOSPath( qpath ); - sprintf( ospath, "%s", qpath ); - */ - /* - for ( int i = 0; i < 9999 ; i++ ) { - char qpath[128]; - sprintf( qpath, "renderlog_%04i.txt", r_logFile.GetInteger() ); - idStr finalPath = fileSystem->RelativePathToOSPath( qpath ); - fileSystem->RelativePathToOSPath( qpath, ospath, MAX_OSPATH ,FSPATH_BASE ); - if ( !fileSystem->FileExists( finalPath.c_str() ) ) { - break; // use this name - } - } - */ - - common->SetRefreshOnPrint( false ); // problems are caused if this print causes a refresh... - - /* - if( logFile != NULL ) - { - fileSystem->CloseFile( logFile ); - logFile = NULL; - } - - logFile = fileSystem->OpenFileWrite( ospath ); - if( logFile == NULL ) - { - idLib::Warning( "Failed to open logfile %s", ospath ); - return; - } - idLib::Printf( "Opened logfile %s\n", ospath ); - - // write the time out to the top of the file - time( &aclock ); - newtime = localtime( &aclock ); - const char* str = asctime( newtime ); - logFile->Printf( "// %s", str ); - logFile->Printf( "// %s\n\n", com_version.GetString() ); - */ - - frameStartTime = Sys_Microseconds(); - closeBlockTime = frameStartTime; - OpenBlock( "Frame" ); -} - -/* -======================== -idRenderLog::EndFrame -======================== -*/ -void idRenderLog::EndFrame() -{ - PC_EndFrame(); - - //if( logFile != NULL ) - if( r_logFile.GetInteger() != 0 ) - { - if( r_logFile.GetInteger() == 1 ) - { - Close(); - } - // log is open, so decrement r_logFile and stop if it is zero - //r_logFile.SetInteger( r_logFile.GetInteger() - 1 ); - //idLib::Printf( "Frame logged.\n" ); - return; - } -} - -/* -======================== -idRenderLog::Close -======================== -*/ -void idRenderLog::Close() -{ - //if( logFile != NULL ) - if( r_logFile.GetInteger() != 0 ) - { - CloseBlock(); - //idLib::Printf( "Closing logfile\n" ); - //fileSystem->CloseFile( logFile ); - //logFile = NULL; - activeLevel = 0; - } -} - -/* -======================== -idRenderLog::OpenMainBlock -======================== -*/ -void idRenderLog::OpenMainBlock( renderLogMainBlock_t block ) -{ -} - -/* -======================== -idRenderLog::CloseMainBlock -======================== -*/ -void idRenderLog::CloseMainBlock() -{ -} - -/* -======================== -idRenderLog::OpenBlock -======================== -*/ -void idRenderLog::OpenBlock( const char* label ) -{ - // Allow the PIX functionality even when logFile is not running. - PC_BeginNamedEvent( label ); - - //if( logFile != NULL ) - if( r_logFile.GetInteger() != 0 ) - { - LogOpenBlock( RENDER_LOG_INDENT_MAIN_BLOCK, "%s", label ); - } -} - -/* -======================== -idRenderLog::CloseBlock -======================== -*/ -void idRenderLog::CloseBlock() -{ - PC_EndNamedEvent(); - - //if( logFile != NULL ) - if( r_logFile.GetInteger() != 0 ) - { - LogCloseBlock( RENDER_LOG_INDENT_MAIN_BLOCK ); - } -} - -/* -======================== -idRenderLog::Printf -======================== -*/ -void idRenderLog::Printf( const char* fmt, ... ) -{ -#if !defined(USE_VULKAN) - if( activeLevel <= LOG_LEVEL_BLOCKS_ONLY ) - { - return; - } - - //if( logFile == NULL ) - if( r_logFile.GetInteger() == 0 || !glConfig.gremedyStringMarkerAvailable ) - { - return; - } - - va_list marker; - char msg[4096]; - - idStr out = indentString; - - va_start( marker, fmt ); - idStr::vsnPrintf( msg, sizeof( msg ), fmt, marker ); - va_end( marker ); - - msg[sizeof( msg ) - 1] = '\0'; - - out.Append( msg ); - - glStringMarkerGREMEDY( out.Length(), out.c_str() ); - - //logFile->Printf( "%s", indentString ); - //va_start( marker, fmt ); - //logFile->VPrintf( fmt, marker ); - //va_end( marker ); - - -// logFile->Flush(); this makes it take waaaay too long -#endif -} - -/* -======================== -idRenderLog::LogOpenBlock -======================== -*/ -void idRenderLog::LogOpenBlock( renderLogIndentLabel_t label, const char* fmt, ... ) -{ - uint64 now = Sys_Microseconds(); - - //if( logFile != NULL ) - if( r_logFile.GetInteger() != 0 ) - { - //if( now - closeBlockTime >= 1000 ) - //{ - //logFile->Printf( "%s%1.1f msec gap from last closeblock\n", indentString, ( now - closeBlockTime ) * ( 1.0f / 1000.0f ) ); - //} - -#if !defined(USE_VULKAN) - if( glConfig.gremedyStringMarkerAvailable ) - { - //Printf( fmt, args ); - //Printf( " {\n" ); - - //logFile->Printf( "%s", indentString ); - //logFile->VPrintf( fmt, args ); - //logFile->Printf( " {\n" ); - - va_list marker; - char msg[4096]; - - idStr out = indentString; - - va_start( marker, fmt ); - idStr::vsnPrintf( msg, sizeof( msg ), fmt, marker ); - va_end( marker ); - - msg[sizeof( msg ) - 1] = '\0'; - - out.Append( msg ); - out += " {"; - - glStringMarkerGREMEDY( out.Length(), out.c_str() ); - } -#endif - } - - Indent( label ); - - if( logLevel >= MAX_LOG_LEVELS ) - { - idLib::Warning( "logLevel %d >= MAX_LOG_LEVELS", logLevel ); - } - - - logLevel++; -} - -/* -======================== -idRenderLog::LogCloseBlock -======================== -*/ -void idRenderLog::LogCloseBlock( renderLogIndentLabel_t label ) -{ - closeBlockTime = Sys_Microseconds(); - - //assert( logLevel > 0 ); - logLevel--; - - Outdent( label ); - - //if( logFile != NULL ) - //{ - //} -} - -#else // !STUB_RENDER_LOG // RB begin /* @@ -605,8 +304,12 @@ idRenderLog::idRenderLog() idRenderLog::OpenMainBlock ======================== */ -void idRenderLog::OpenMainBlock( renderLogMainBlock_t block ) +void idRenderLog::OpenMainBlock( renderLogMainBlock_t block, nvrhi::ICommandList* _commandList ) { +#if defined( USE_NVRHI ) + commandList = _commandList; +#endif + // SRS - Use glConfig.timerQueryAvailable flag to control timestamp capture for all platforms if( glConfig.timerQueryAvailable ) { @@ -697,7 +400,14 @@ idRenderLog::OpenBlock */ void idRenderLog::OpenBlock( const char* label, const idVec4& color ) { +#if defined( USE_NVRHI ) + if( commandList && r_logLevel.GetInteger() > 0 ) + { + commandList->beginMarker( label ); + } +#else PC_BeginNamedEvent( label, color ); +#endif } /* @@ -707,8 +417,13 @@ idRenderLog::CloseBlock */ void idRenderLog::CloseBlock() { +#if defined( USE_NVRHI ) + if( commandList && r_logLevel.GetInteger() > 0 ) + { + commandList->endMarker(); + } +#else PC_EndNamedEvent(); +#endif } -// RB end - -#endif // !STUB_RENDER_LOG +// RB end \ No newline at end of file diff --git a/neo/renderer/RenderLog.h b/neo/renderer/RenderLog.h index 5dcdd5cd..80eafe42 100644 --- a/neo/renderer/RenderLog.h +++ b/neo/renderer/RenderLog.h @@ -35,9 +35,6 @@ Contains the RenderLog declaration. ================================================================================================ */ -#if 1 //defined(ID_RETAIL) && !defined(ID_RETAIL_INTERNAL) - #define STUB_RENDER_LOG -#endif enum renderLogMainBlock_t { @@ -74,102 +71,7 @@ enum renderLogIndentLabel_t // using this macro avoids printf parameter overhead if the renderlog isn't active #define RENDERLOG_PRINTF( ... ) if ( renderLog.activeLevel ) renderLog.Printf( __VA_ARGS__ ); -#if !defined( STUB_RENDER_LOG ) -/* -================================================ -idRenderLog contains block-based performance-tuning information. It combines -logfile, and msec accumulation code. -================================================ -*/ -class idRenderLog -{ -public: - idRenderLog(); - - void StartFrame(); - void EndFrame(); - void Close(); - int Active() - { - return activeLevel; // returns greater than 1 for more detailed logging - } - - // The label must be a constant string literal and may not point to a temporary. - void OpenMainBlock( renderLogMainBlock_t block ); - void CloseMainBlock(); - - void OpenBlock( const char* label ); - void CloseBlock(); - - void Indent( renderLogIndentLabel_t label = RENDER_LOG_INDENT_DEFAULT ); - void Outdent( renderLogIndentLabel_t label = RENDER_LOG_INDENT_DEFAULT ); - - void Printf( VERIFY_FORMAT_STRING const char* fmt, ... ); - - static const int MAX_LOG_LEVELS = 20; - - int activeLevel; - renderLogIndentLabel_t indentLabel[MAX_LOG_LEVELS]; - char indentString[MAX_LOG_LEVELS * 4]; - int indentLevel; - const char* lastLabel; - renderLogMainBlock_t lastMainBlock; -// idFile* logFile; - - struct logStats_t - { - uint64 startTiming; - int startDraws; - int startIndexes; - }; - - uint64 frameStartTime; - uint64 closeBlockTime; - logStats_t logStats[MAX_LOG_LEVELS]; - int logLevel; - - void LogOpenBlock( renderLogIndentLabel_t label, const char* fmt, ... ); - void LogCloseBlock( renderLogIndentLabel_t label ); -}; - -/* -======================== -idRenderLog::Indent -======================== -*/ -ID_INLINE void idRenderLog::Indent( renderLogIndentLabel_t label ) -{ - //if( logFile != NULL ) - if( r_logFile.GetInteger() != 0 ) - { - indentLabel[indentLevel] = label; - indentLevel++; - for( int i = 4; i > 0; i-- ) - { - indentString[indentLevel * 4 - i] = ' '; - } - indentString[indentLevel * 4] = '\0'; - } -} - -/* -======================== -idRenderLog::Outdent -======================== -*/ -ID_INLINE void idRenderLog::Outdent( renderLogIndentLabel_t label ) -{ - //if( logFile != NULL && indentLevel > 0 ) - if( r_logFile.GetInteger() != 0 && indentLevel > 0 ) - { - indentLevel--; - assert( indentLabel[indentLevel] == label ); // indent and outdent out of sync ? - indentString[indentLevel * 4] = '\0'; - } -} - -#else // !STUB_RENDER_LOG /* ================================================ @@ -185,6 +87,10 @@ class idRenderLog private: renderLogMainBlock_t mainBlock; +#if defined( USE_NVRHI ) + nvrhi::CommandListHandle commandList; +#endif + public: idRenderLog(); @@ -198,7 +104,7 @@ public: void OpenBlock( const char* label, const idVec4& color = colorBlack ); void CloseBlock(); - void OpenMainBlock( renderLogMainBlock_t block );// {} + void OpenMainBlock( renderLogMainBlock_t block, nvrhi::ICommandList* commandList ); void CloseMainBlock();// {} void Indent( renderLogIndentLabel_t label = RENDER_LOG_INDENT_DEFAULT ) {} void Outdent( renderLogIndentLabel_t label = RENDER_LOG_INDENT_DEFAULT ) {} @@ -208,8 +114,6 @@ public: int activeLevel; }; -#endif // !STUB_RENDER_LOG - extern idRenderLog renderLog; #endif // !__RENDERLOG_H__