Improved RenderDoc logging

This commit is contained in:
Robert Beckebans 2022-02-21 22:08:04 +01:00
parent 1d93ad0a58
commit d557c82b35
4 changed files with 37 additions and 418 deletions

View file

@ -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" );

View file

@ -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

View file

@ -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

View file

@ -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__