Use functions for logging load & save game times (#328)

Less copy and paste. Allows these very simple timings to be logged from elsewhere as well.

Ja2/CMakeLists.txt

@@ -30,6 +30,7 @@ set(Ja2Src
 "${CMAKE_CURRENT_SOURCE_DIR}/SaveLoadScreen.cpp"
 "${CMAKE_CURRENT_SOURCE_DIR}/SCREENS.cpp"
 "${CMAKE_CURRENT_SOURCE_DIR}/Sys Globals.cpp"
+"${CMAKE_CURRENT_SOURCE_DIR}/TimeLogging.cpp"
 "${CMAKE_CURRENT_SOURCE_DIR}/ub_config.cpp"
 "${CMAKE_CURRENT_SOURCE_DIR}/XML_DifficultySettings.cpp"
 "${CMAKE_CURRENT_SOURCE_DIR}/XML_IntroFiles.cpp"

Ja2/SaveLoadGame.cpp

@@ -138,7 +138,6 @@
 #include "Map Screen Interface Map Inventory.h"//dnl ch51 081009
 #include "Sys Globals.h"//dnl ch74 201013
 #include "Ambient Control.h"		// added by Flugente for HandleNewSectorAmbience(...)
-
 /////////////////////////////////////////////////////
 //
 // Local Defines
@@ -177,7 +176,11 @@ extern void initMapViewAndBorderCoordinates(void);
 UINT32		guiNumberOfMapTempFiles;		//Test purposes
 UINT32		guiSizeOfTempFiles;
 CHAR			gzNameOfMapTempFile[128];
+#endif
+
 //#define LOADSAVEGAME_LOGTIME 1
+#ifdef LOADSAVEGAME_LOGTIME
+#include "TimeLogging.h"
 #endif
 
 extern		SOLDIERTYPE		*gpSMCurrentMerc;
@@ -3588,14 +3591,8 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 	alreadySaving = true;
 
 #ifdef LOADSAVEGAME_LOGTIME
-	// Flugente: log how long this takes
+	TimingLogInitialize("TimeLog_LoadSavedGame.txt");
-	clock_t starttime = clock();
-	clock_t t0;
-	clock_t t1 = starttime;
-
-	FILE* fp_timelog = fopen("LoadSavedGame_TimeLog.txt", "a");
 #endif
-
 	//clear out the save game header
 	memset( &SaveGameHeader, 0, sizeof( SAVED_GAME_HEADER ) );
 
@@ -3775,14 +3772,9 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 	//Create the name of the file
 	CreateSavedGameFileNameFromNumber( ubSaveGameID, zSaveGameName );
 #if LOADSAVEGAME_LOGTIME
-	if (fp_timelog)
+	TimingLogWrite("Save ");
-	{
+	TimingLogWrite(zSaveGameName);
-		fprintf(fp_timelog, "Save savegame: %s\n", zSaveGameName);
+	TimingLog("\nShutdown stuff", 10);
-
-		t0 = t1;
-		t1 = clock();
-		fprintf(fp_timelog, "Shutdown stuff\t\t\t\t\t\t\t\t\t\t\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-	}
 #endif
 
 	//if the file already exists, delete it
@@ -3919,12 +3911,7 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 		SaveGameFilePosition( FileGetPos( hFile ), "Tactical Status" );
 	#endif
 #if LOADSAVEGAME_LOGTIME
-		if (fp_timelog)
+	TimingLog("SaveTacticalStatusToSavedGame", 6);
-		{
-			t0 = t1;
-			t1 = clock();
-			fprintf(fp_timelog, "SaveTacticalStatusFromSavedGame done\t\t\t\t\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-		}
 #endif
 
 
@@ -3966,12 +3953,7 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 		SaveGameFilePosition( FileGetPos( hFile ), "Laptop Info" );
 	#endif
 #if LOADSAVEGAME_LOGTIME
-		if (fp_timelog)
+	TimingLog("SaveLaptopInfoToSavedGame", 7);
-		{
-			t0 = t1;
-			t1 = clock();
-			fprintf(fp_timelog, "SaveLaptopInfoFromSavedGame done\t\t\t\t\t\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-		}
 #endif
 
 	//
@@ -4003,12 +3985,7 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 		SaveGameFilePosition( FileGetPos( hFile ), "Soldier Structure" );
 	#endif
 #if LOADSAVEGAME_LOGTIME
-		if (fp_timelog)
+	TimingLog("SaveSoldierStructure", 8);
-		{
-			t0 = t1;
-			t1 = clock();
-			fprintf(fp_timelog, "SaveSoldierStructure done\t\t\t\t\t\t\t\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-		}
 #endif
 
 
@@ -4071,12 +4048,7 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 		SaveGameFilePosition( FileGetPos( hFile ), "Strategic Information" );
 	#endif
 #if LOADSAVEGAME_LOGTIME
-		if (fp_timelog)
+	TimingLog("SaveStrategicInfoToSavedFile", 6);
-		{
-			t0 = t1;
-			t1 = clock();
-			fprintf(fp_timelog, "SaveStrategicInfoFromSavedFile done\t\t\t\t\t\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-		}
 #endif
 
 	/*// Flugente: Save the strategic supply
@@ -4126,12 +4098,7 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 		SaveGameFilePosition( FileGetPos( hFile ), "Strategic Movement Groups" );
 	#endif
 #if LOADSAVEGAME_LOGTIME
-		if (fp_timelog)
+	TimingLog("SaveStrategicMovementGroupsToSaveGameFile", 3);
-		{
-			t0 = t1;
-			t1 = clock();
-			fprintf(fp_timelog, "SaveStrategicMovementGroupsFromSavedGameFile done\t\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-		}
 #endif
 
 
@@ -4148,12 +4115,7 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 		SaveGameFilePosition( FileGetPos( hFile ), "All the Map Temp files" );
 	#endif
 #if LOADSAVEGAME_LOGTIME
-		if (fp_timelog)
+	TimingLog("SaveMapTempFilesToSavedGameFile", 6);
-		{
-			t0 = t1;
-			t1 = clock();
-			fprintf(fp_timelog, "SaveMapTempFilesFromSavedGameFile done\t\t\t\t\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-		}
 #endif
 
 	if( !SaveQuestInfoToSavedGameFile( hFile ) )
@@ -4319,12 +4281,7 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 	SaveGameFilePosition( FileGetPos( hFile ), "Militia Movement" );
 #endif
 #if LOADSAVEGAME_LOGTIME
-	if (fp_timelog)
+	TimingLog("SaveMilitiaMovementInformationToSaveGameFile", 2);
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf(fp_timelog, "SaveMilitiaMovementInformationFromSavedGameFile done\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-	}
 #endif
 
 	if( !SaveBulletStructureToSaveGameFile( hFile ) )
@@ -4564,12 +4521,7 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 		SaveGameFilePosition( FileGetPos( hFile ), "Lua global" );
 	#endif
 #if LOADSAVEGAME_LOGTIME
-		if (fp_timelog)
+	TimingLog("SaveLuaGlobalToSaveGameFile", 7);
-		{
-			t0 = t1;
-			t1 = clock();
-			fprintf(fp_timelog, "SaveLuaGlobalFromLoadGameFile done\t\t\t\t\t\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-		}
 #endif
 
 	if( !SaveDataSaveToSaveGameFile( hFile ) )
@@ -4669,12 +4621,7 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 		goto FAILED_TO_SAVE;
 	}
 #if LOADSAVEGAME_LOGTIME
-	if (fp_timelog)
+	TimingLog("File read done", 10);
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf(fp_timelog, "File read done\t\t\t\t\t\t\t\t\t\t\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-	}
 #endif
 
 	//Close the saved game file
@@ -4755,22 +4702,9 @@ BOOLEAN SaveGame( int ubSaveGameID, STR16 pGameDesc )
 	alreadySaving = false;
 
 #if LOADSAVEGAME_LOGTIME
-	if (fp_timelog)
+	TimingLog("Update functions", 9);
-	{
+	TimingLogTotalTime("SaveSavedGame total", 9);
-		t0 = t1;
+	TimingLogStop();
-		t1 = clock();
-		fprintf(fp_timelog, "Update functions\t\t\t\t\t\t\t\t\t\t\t\t: %fs\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-	}
-
-	if (fp_timelog)
-	{
-		t0 = starttime;
-		t1 = clock();
-		fprintf(fp_timelog, "SaveSavedGame total\t\t\t\t\t\t\t\t\t\t\t\t: %fs\n\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
-	}
-
-	if (fp_timelog)
-		fclose(fp_timelog);
 #endif
 	return( TRUE );
 
@@ -4780,6 +4714,9 @@ FAILED_TO_SAVE:
 #ifdef JA2BETAVERSION
 	SaveGameFilePosition( FileGetPos( hFile ), "Failed to Save!!!" );
 #endif
+#if LOADSAVEGAME_LOGTIME
+	TimingLogStop();
+#endif
 
 	FileClose( hFile );
 
@@ -4825,8 +4762,6 @@ extern int gEnemyPreservedTempFileVersion[256];
 extern int gCivPreservedTempFileVersion[256];
 
 
-#include "time.h"
-
 BOOLEAN LoadSavedGame( int ubSavedGameID )
 {
 	HWFILE	hFile;
@@ -4845,12 +4780,7 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 #endif
 
 #ifdef LOADSAVEGAME_LOGTIME
-	// Flugente: log how long this takes
+	TimingLogInitialize("TimeLog_LoadSavedGame.txt");
-	clock_t starttime = clock();
-	clock_t t0;
-	clock_t t1 = starttime;
-	
-	FILE *fp_timelog = fopen( "LoadSavedGame_TimeLog.txt", "a" );
 #endif
 	
 	uiRelStartPerc = uiRelEndPerc =0;
@@ -4933,14 +4863,9 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 	CreateSavedGameFileNameFromNumber( ubSavedGameID, zSaveGameName );
 
 #if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
+	TimingLogWrite("Load ");
-	{
+	TimingLogWrite(zSaveGameName);
-		fprintf( fp_timelog, "Load savegame: %s\n", zSaveGameName );
+	TimingLog("\nShutdown stuff", 10);
-
-		t0 = t1;
-		t1 = clock();
-		fprintf( fp_timelog, "Shutdown stuff\t\t\t\t\t\t\t\t\t\t\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
 #endif
 
 	// open the save game file
@@ -5061,19 +4986,14 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 	#ifdef JA2BETAVERSION
 		LoadGameFilePosition( FileGetPos( hFile ), "Tactical Status" );
 	#endif
+#if LOADSAVEGAME_LOGTIME
+		TimingLog("LoadTacticalStatusFromSavedGame", 6);
+#endif
 
 
 	//This gets reset by the above function
 	gTacticalStatus.uiFlags |= LOADING_SAVED_GAME;
 
-#if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf( fp_timelog, "LoadTacticalStatusFromSavedGame done\t\t\t\t\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
-#endif
 
 	//Load the game clock ingo
 	if( !LoadGameClock( hFile ) )
@@ -5194,12 +5114,7 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 	#endif
 
 #if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
+	TimingLog("LoadLaptopInfoFromSavedGame", 7);
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf( fp_timelog, "LoadLaptopInfoFromSavedGame done\t\t\t\t\t\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
 #endif
 
 	uiRelEndPerc += 0;
@@ -5242,12 +5157,7 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 	#endif
 
 #if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
+	TimingLog("LoadSoldierStructure", 8);
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf( fp_timelog, "LoadSoldierStructure done\t\t\t\t\t\t\t\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
 #endif
 
 	uiRelEndPerc += 1;
@@ -5376,12 +5286,7 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 #endif
 
 #if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
+	TimingLog("LoadStrategicInfoFromSavedFile", 6);
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf( fp_timelog, "LoadStrategicInfoFromSavedFile done\t\t\t\t\t\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
 #endif
 
 	uiRelEndPerc += 1;
@@ -5442,12 +5347,7 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 	ValidateStrategicGroups();
 
 #if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
+	TimingLog("LoadStrategicMovementGroupsFromSavedGameFile", 2);
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf( fp_timelog, "LoadStrategicMovementGroupsFromSavedGameFile done\t\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
 #endif
 
 	uiRelEndPerc += 30;
@@ -5467,12 +5367,7 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 	#endif
 
 #if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
+	TimingLog("LoadMapTempFilesFromSavedGameFile", 5);
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf( fp_timelog, "LoadMapTempFilesFromSavedGameFile done\t\t\t\t\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
 #endif
 
 	uiRelEndPerc += 1;
@@ -5771,12 +5666,7 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 #endif
 
 #if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
+	TimingLog("LoadMilitiaMovementInformationFromSavedGameFile", 2);
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf( fp_timelog, "LoadMilitiaMovementInformationFromSavedGameFile done\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
 #endif
 
 	uiRelEndPerc += 1;
@@ -6336,12 +6226,7 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 	#endif
 
 #if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
+	TimingLog("LoadLuaGlobalFromLoadGameFile", 6);
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf( fp_timelog, "LoadLuaGlobalFromLoadGameFile done\t\t\t\t\t\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
 #endif
 	
 	if( guiCurrentSaveGameVersion >= VEHICLES_DATATYPE_CHANGE && guiCurrentSaveGameVersion < NO_VEHICLE_SAVE)
@@ -6573,12 +6458,7 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 	}
 
 #if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
+	TimingLog("File read done", 10);
-	{
-		t0 = t1;
-		t1 = clock();
-		fprintf( fp_timelog, "File read done\t\t\t\t\t\t\t\t\t\t\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
 #endif
 
 	//
@@ -7023,22 +6903,9 @@ BOOLEAN LoadSavedGame( int ubSavedGameID )
 	gGameExternalOptions.gfAllowReinforcements = zDiffSetting[gGameOptions.ubDifficultyLevel].bAllowReinforcements;
 
 #if LOADSAVEGAME_LOGTIME
-	if ( fp_timelog )
+	TimingLog("Update functions", 9);
-	{
+	TimingLogTotalTime("LoadSavedGame total", 9);
-		t0 = t1;
+	TimingLogStop();
-		t1 = clock();
-		fprintf( fp_timelog, "Update functions\t\t\t\t\t\t\t\t\t\t\t\t: %fs\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
-
-	if ( fp_timelog )
-	{
-		t0 = starttime;
-		t1 = clock();
-		fprintf( fp_timelog, "LoadSavedGame total\t\t\t\t\t\t\t\t\t\t\t\t: %fs\n\n", ( (float)( t1 - t0 ) / CLOCKS_PER_SEC ) );
-	}
-
-	if ( fp_timelog )
-		fclose( fp_timelog );
 #endif
 
 	DebugQuestInfo("\n--------- Game loaded ---------");

Ja2/TimeLogging.cpp

@@ -0,0 +1,72 @@
+#include "TimeLogging.h"
+#include "time.h"
+#include <stdio.h>
+
+
+clock_t starttime;
+clock_t t0;
+clock_t t1;
+FILE* fp_timelog = nullptr;
+
+
+static void indent(int n)
+{
+	for (int i = 0; i < n; i++)
+		fputc('\t', fp_timelog);
+}
+
+void TimingLogInitialize(const CHAR8* filename)
+{
+	starttime = clock();
+	t1 = starttime;
+
+	if (!fp_timelog)
+	{
+		fp_timelog = fopen(filename, "a");
+	}
+}
+
+
+void TimingLog(const CHAR8* logEvent, int n)
+{
+	if (fp_timelog)
+	{
+		t0 = t1;
+		t1 = clock();
+		fprintf(fp_timelog, "%s", logEvent);
+		indent(n);
+		fprintf(fp_timelog, ": %f s\n", ((float)(t1 - t0) / CLOCKS_PER_SEC));
+	}
+}
+
+
+void TimingLogTotalTime(const CHAR8* logEvent, int n)
+{
+	if (fp_timelog)
+	{
+		t1 = clock();
+		fprintf(fp_timelog, "%s", logEvent);
+		indent(n);
+		fprintf(fp_timelog, ": %f s\n", ((float)(t1 - starttime) / CLOCKS_PER_SEC));
+	}
+}
+
+
+void TimingLogWrite(const CHAR8* text)
+{
+	if (fp_timelog)
+	{
+		fprintf(fp_timelog, text);
+	}
+}
+
+
+void TimingLogStop()
+{
+	if (fp_timelog)
+	{
+		fprintf(fp_timelog, "\n");
+		fclose(fp_timelog);
+		fp_timelog = nullptr;
+	}
+}

Ja2/TimeLogging.h

@@ -0,0 +1,8 @@
+#pragma once
+#include "Types.h"
+
+void TimingLogInitialize(const CHAR8* filename);
+void TimingLog(const CHAR8* logEvent, int n);
+void TimingLogTotalTime(const CHAR8* logEvent, int n);
+void TimingLogWrite(const CHAR8* text);
+void TimingLogStop();