From ff3773c85d30d2ddf6317dc142b73b7e0b5ca7f6 Mon Sep 17 00:00:00 2001 From: Magne Sjaastad Date: Mon, 28 Jul 2025 15:29:01 +0200 Subject: [PATCH] Logging: Add accumulated timing for sub tasks when loading project --- .../Application/RiaApplication.cpp | 45 ++++++++++++++----- .../Application/Tools/RiaLogging.cpp | 23 ++++++++-- 2 files changed, 55 insertions(+), 13 deletions(-) diff --git a/ApplicationLibCode/Application/RiaApplication.cpp b/ApplicationLibCode/Application/RiaApplication.cpp index 57231a972d..03b1b229b6 100644 --- a/ApplicationLibCode/Application/RiaApplication.cpp +++ b/ApplicationLibCode/Application/RiaApplication.cpp @@ -473,8 +473,11 @@ bool RiaApplication::loadProject( const QString& projectFileName, ProjectLoadAct caf::ProgressInfo progress( 100, "Loading Project File" ); + bool logTiming = RiaPreferencesSystem::current()->isLoggingActivatedForKeyword( "RiaApplication" ); + { - auto task = progress.task( "Reading Project Structure from File", 10 ); + QString taskName = QString( "Reading Project Structure from File" ); + auto task = progress.task( taskName, 10 ); closeProject(); @@ -547,10 +550,13 @@ bool RiaApplication::loadProject( const QString& projectFileName, ProjectLoadAct { m_preferences->writePreferencesToApplicationStore(); } + + if ( logTiming ) RiaLogging::logElapsedTime( taskName, startTime ); } { - auto task = progress.task( "Loading Grid Data", 10 ); + QString taskName = QString( "Loading Grid Data" ); + auto task = progress.task( taskName, 10 ); for ( size_t oilFieldIdx = 0; oilFieldIdx < m_project->oilFields().size(); oilFieldIdx++ ) { @@ -608,9 +614,13 @@ bool RiaApplication::loadProject( const QString& projectFileName, ProjectLoadAct oilField->polygonCollection()->loadData(); } + + if ( logTiming ) RiaLogging::logElapsedTime( taskName, startTime ); } + { - auto task = progress.task( "Loading 2D Plot Data", 10 ); + QString taskName = QString( "Loading Data for 2D Plots" ); + auto task = progress.task( taskName, 10 ); { RimMainPlotCollection* mainPlotColl = RimMainPlotCollection::current(); @@ -663,10 +673,13 @@ bool RiaApplication::loadProject( const QString& projectFileName, ProjectLoadAct oilField->surfaceCollection()->loadData(); } + + if ( logTiming ) RiaLogging::logElapsedTime( taskName, startTime ); } { - auto task = progress.task( "Calculation Grid Statistics", 10 ); + QString taskName = QString( "Calculation Statistics for Grid Case Groups" ); + auto task = progress.task( taskName, 10 ); // If load action is specified to recalculate statistics, do it now. // Apparently this needs to be done before the views are loaded, lest the number of time steps for statistics will @@ -683,10 +696,13 @@ bool RiaApplication::loadProject( const QString& projectFileName, ProjectLoadAct } } } + + if ( logTiming ) RiaLogging::logElapsedTime( taskName, startTime ); } { - auto task = progress.task( "Creating 3D Views", 10 ); + QString taskName = QString( "Loading 3D Views" ); + auto task = progress.task( taskName, 10 ); // Now load the ReservoirViews for the cases // Add all "native" cases in the project @@ -794,6 +810,8 @@ bool RiaApplication::loadProject( const QString& projectFileName, ProjectLoadAct seisView->loadDataAndUpdate(); } } + + if ( logTiming ) RiaLogging::logElapsedTime( taskName, startTime ); } { @@ -837,10 +855,13 @@ bool RiaApplication::loadProject( const QString& projectFileName, ProjectLoadAct // current active view ( see restoreTreeViewState() ) // Default behavior for scripts is to use current active view for data read/write onProjectOpened(); + + if ( logTiming ) RiaLogging::logElapsedTime( "Load Summary Data", startTime ); } { - auto task = progress.task( "Performing Grid Calculations", 10 ); + QString taskName = QString( "Grid Cells Calculations" ); + auto task = progress.task( taskName, 10 ); // Recalculate the results from grid property calculations. // Has to be done late since the results are filtered by view cell visibility @@ -852,13 +873,17 @@ bool RiaApplication::loadProject( const QString& projectFileName, ProjectLoadAct RiaPlotWindowRedrawScheduler::instance()->performScheduledUpdates(); - RiaLogging::info( QString( "Completed open of project file : '%1'" ).arg( projectFileName ) ); + if ( logTiming ) RiaLogging::logElapsedTime( taskName, startTime ); } - bool isLoggingEnabled = RiaPreferencesSystem::current()->isLoggingActivatedForKeyword( "RiaApplication" ); - if ( isLoggingEnabled ) + auto logText = QString( "Project file '%1' loaded successfully." ).arg( projectFileName ); + if ( logTiming ) { - RiaLogging::logElapsedTime( QString( "Opened project file '%1' " ).arg( projectFileName ), startTime ); + RiaLogging::logElapsedTime( logText, startTime ); + } + else + { + RiaLogging::info( logText ); } return true; diff --git a/ApplicationLibCode/Application/Tools/RiaLogging.cpp b/ApplicationLibCode/Application/Tools/RiaLogging.cpp index cd1cd4c551..b7a7ddc42e 100644 --- a/ApplicationLibCode/Application/Tools/RiaLogging.cpp +++ b/ApplicationLibCode/Application/Tools/RiaLogging.cpp @@ -352,10 +352,27 @@ std::chrono::time_point RiaLogging::currentT //-------------------------------------------------------------------------------------------------- void RiaLogging::logElapsedTime( const QString& message, const std::chrono::time_point& startTime ) { - auto end = std::chrono::high_resolution_clock::now(); - + auto end = std::chrono::high_resolution_clock::now(); auto duration = std::chrono::duration_cast( end - startTime ); - auto text = message + QString( " (duration : %1 milliseconds)" ).arg( duration.count() ); + + QString text; + auto totalMs = duration.count(); + + if ( totalMs < 1000 ) + { + text = message + QString( " (duration: %1 milliseconds)" ).arg( totalMs ); + } + else if ( totalMs < 60000 ) + { + double seconds = totalMs / 1000.0; + text = message + QString( " (duration: %1 seconds)" ).arg( seconds, 0, 'f', 1 ); + } + else + { + auto minutes = totalMs / 60000; + auto remainingSeconds = ( totalMs % 60000 ) / 1000.0; + text = message + QString( " (duration: %1 minutes %2 seconds)" ).arg( minutes ).arg( remainingSeconds, 0, 'f', 1 ); + } RiaLogging::debug( text ); }