From 8b09da8e64e49d424420c10b5439b5965cd1788d Mon Sep 17 00:00:00 2001 From: Kyzentun Date: Mon, 30 Mar 2015 17:45:52 -0600 Subject: [PATCH] Various changes to speed up start up time: Added delay_save_cache to SongCacheIndex so that it doesn't write the entire cache index file after every song is loaded when loading songs. Added m_SongsByDir to SongManager so that GetSongFromDir doesn't have to walk the entire list of songs. Minor changes to when LoadEnabledSongsFromPref occurs and how SanityCheckGroupDir works to speed up loading. Song::ReloadFromSongDir removes cache file to force an actual reload from the song dir instead of reloading from the cache. ReloadFromSongDir exposed to lua. Reordered Actor::LoadFromNode to put Command first because that case is more common. Course::GetTrailUnsorted reserves entries before starting to save time reallocating. join in RageUtil calculates the final size of the concatenated strings reserves it to save time reallocating. Added time log file to RageLog for profiling. --- src/Actor.cpp | 16 +++++----- src/Course.cpp | 1 + src/RageLog.cpp | 25 ++++++++++++++-- src/RageLog.h | 2 ++ src/RageTimer.h | 10 ++++++- src/RageUtil.cpp | 20 +++++++++++++ src/Song.cpp | 14 +++++++-- src/Song.h | 1 + src/SongCacheIndex.cpp | 10 ++++++- src/SongCacheIndex.h | 2 ++ src/SongManager.cpp | 67 +++++++++++++++++++++++++++--------------- src/SongManager.h | 2 ++ 12 files changed, 133 insertions(+), 37 deletions(-) diff --git a/src/Actor.cpp b/src/Actor.cpp index 361ff1aaa3..10c51a967f 100644 --- a/src/Actor.cpp +++ b/src/Actor.cpp @@ -269,14 +269,7 @@ void Actor::LoadFromNode( const XNode* pNode ) // Load Name, if any. const RString &sKeyName = pAttr->first; const XNodeValue *pValue = pAttr->second; - if( sKeyName == "Name" ) SetName( pValue->GetValue() ); - else if( sKeyName == "BaseRotationX" ) SetBaseRotationX( pValue->GetValue() ); - else if( sKeyName == "BaseRotationY" ) SetBaseRotationY( pValue->GetValue() ); - else if( sKeyName == "BaseRotationZ" ) SetBaseRotationZ( pValue->GetValue() ); - else if( sKeyName == "BaseZoomX" ) SetBaseZoomX( pValue->GetValue() ); - else if( sKeyName == "BaseZoomY" ) SetBaseZoomY( pValue->GetValue() ); - else if( sKeyName == "BaseZoomZ" ) SetBaseZoomZ( pValue->GetValue() ); - else if( EndsWith(sKeyName,"Command") ) + if( EndsWith(sKeyName,"Command") ) { LuaReference *pRef = new LuaReference; pValue->PushValue( L ); @@ -284,6 +277,13 @@ void Actor::LoadFromNode( const XNode* pNode ) RString sCmdName = sKeyName.Left( sKeyName.size()-7 ); AddCommand( sCmdName, apActorCommands( pRef ) ); } + else if( sKeyName == "Name" ) SetName( pValue->GetValue() ); + else if( sKeyName == "BaseRotationX" ) SetBaseRotationX( pValue->GetValue() ); + else if( sKeyName == "BaseRotationY" ) SetBaseRotationY( pValue->GetValue() ); + else if( sKeyName == "BaseRotationZ" ) SetBaseRotationZ( pValue->GetValue() ); + else if( sKeyName == "BaseZoomX" ) SetBaseZoomX( pValue->GetValue() ); + else if( sKeyName == "BaseZoomY" ) SetBaseZoomY( pValue->GetValue() ); + else if( sKeyName == "BaseZoomZ" ) SetBaseZoomZ( pValue->GetValue() ); } LUA->Release( L ); diff --git a/src/Course.cpp b/src/Course.cpp index 8b291d7b6a..6d9942bf9f 100644 --- a/src/Course.cpp +++ b/src/Course.cpp @@ -440,6 +440,7 @@ bool Course::GetTrailUnsorted( StepsType st, CourseDifficulty cd, Trail &trail ) trail.m_StepsType = st; trail.m_CourseType = GetCourseType(); trail.m_CourseDifficulty = cd; + trail.m_vEntries.reserve(entries.size()); // Set to true if CourseDifficulty is able to change something. bool bCourseDifficultyIsSignificant = (cd == Difficulty_Medium); diff --git a/src/RageLog.cpp b/src/RageLog.cpp index 12b1d123ee..5fe0f5f768 100644 --- a/src/RageLog.cpp +++ b/src/RageLog.cpp @@ -56,9 +56,10 @@ static map LogMaps; #define LOG_PATH "/Logs/log.txt" #define INFO_PATH "/Logs/info.txt" +#define TIME_PATH "/Logs/timelog.txt" #define USER_PATH "/Logs/userlog.txt" -static RageFile *g_fileLog, *g_fileInfo, *g_fileUserLog; +static RageFile *g_fileLog, *g_fileInfo, *g_fileUserLog, *g_fileTimeLog; /* Mutex writes to the files. Writing to files is not thread-aware, and this is the * only place we write to the same file from multiple threads. */ @@ -75,7 +76,8 @@ enum WRITE_TO_USER_LOG = 0x02, /* Whether this line should be loud when written to log.txt (warnings). */ - WRITE_LOUD = 0x04 + WRITE_LOUD = 0x04, + WRITE_TO_TIME= 0x08 }; RageLog::RageLog(): m_bLogToDisk(false), m_bInfoToDisk(false), @@ -84,6 +86,10 @@ m_bUserLogToDisk(false), m_bFlush(false), m_bShowLogOutput(false) g_fileLog = new RageFile; g_fileInfo = new RageFile; g_fileUserLog = new RageFile; + g_fileTimeLog = new RageFile; + + if(!g_fileTimeLog->Open(TIME_PATH, RageFile::WRITE|RageFile::STREAMED)) + { fprintf(stderr, "Couldn't open %s: %s\n", TIME_PATH, g_fileTimeLog->GetError().c_str()); } g_Mutex = new RageMutex( "Log" ); } @@ -105,6 +111,7 @@ RageLog::~RageLog() g_fileLog->Close(); g_fileInfo->Close(); g_fileUserLog->Close(); + g_fileTimeLog->Close(); SAFE_DELETE( g_Mutex ); SAFE_DELETE( g_fileLog ); @@ -222,6 +229,16 @@ void RageLog::Warn( const char *fmt, ... ) Write( WRITE_TO_INFO | WRITE_LOUD, sBuff ); } +void RageLog::Time(const char *fmt, ...) +{ + va_list va; + va_start(va, fmt); + RString sBuff = vssprintf(fmt, va); + va_end(va); + + Write(WRITE_TO_TIME, sBuff); +} + void RageLog::UserLog( const RString &sType, const RString &sElement, const char *fmt, ... ) { va_list va; @@ -274,6 +291,9 @@ void RageLog::Write( int where, const RString &sLine ) * and stdout. */ sStr.insert( 0, sTimestamp ); + if(where & WRITE_TO_TIME) + g_fileTimeLog->PutLine(sStr); + AddToRecentLogs( sStr ); if( m_bLogToDisk && g_fileLog->IsOpen() ) @@ -295,6 +315,7 @@ void RageLog::Flush() { g_fileLog->Flush(); g_fileInfo->Flush(); + g_fileTimeLog->Flush(); g_fileUserLog->Flush(); } diff --git a/src/RageLog.h b/src/RageLog.h index 8e3e262636..4ee91be7b1 100644 --- a/src/RageLog.h +++ b/src/RageLog.h @@ -12,6 +12,8 @@ public: void Trace( const char *fmt, ... ) PRINTF(2,3); void Warn( const char *fmt, ... ) PRINTF(2,3); void Info( const char *fmt, ... ) PRINTF(2,3); + // Time is purely for writing profiling time data to the time log. -Kyz + void Time( const char *fmt, ... ) PRINTF(2,3); void UserLog( const RString &sType, const RString &sElement, const char *fmt, ... ) PRINTF(4,5); void Flush(); diff --git a/src/RageTimer.h b/src/RageTimer.h index 6c55870771..3354145caa 100644 --- a/src/RageTimer.h +++ b/src/RageTimer.h @@ -54,9 +54,17 @@ extern const RageTimer RageZeroTimer; // For profiling how long some chunk of code takes. -Kyz #define START_TIME(name) uint64_t name##_start_time= RageTimer::GetUsecsSinceStart(); -#define END_TIME(name) uint64_t name##_end_time= RageTimer::GetUsecsSinceStart(); LOG->Warn(#name " time: %zu to %zu = %zu", name##_start_time, name##_end_time, name##_end_time - name##_start_time); +#define START_TIME_CALL_COUNT(name) START_TIME(name); ++name##_call_count; +#define END_TIME(name) uint64_t name##_end_time= RageTimer::GetUsecsSinceStart(); LOG->Time(#name " time: %zu to %zu = %zu", name##_start_time, name##_end_time, name##_end_time - name##_start_time); #define END_TIME_ADD_TO(name) uint64_t name##_end_time= RageTimer::GetUsecsSinceStart(); name##_total += name##_end_time - name##_start_time; +#define DECL_TOTAL_TIME(name) extern uint64_t name##_total; +#define DEF_TOTAL_TIME(name) uint64_t name##_total= 0; +#define PRINT_TOTAL_TIME(name) LOG->Time(#name " total time: %zu", name##_total); +#define DECL_TOT_CALL_PAIR(name) extern uint64_t name##_total; extern uint64_t name##_call_count; +#define DEF_TOT_CALL_PAIR(name) uint64_t name##_total= 0; uint64_t name##_call_count= 0; +#define PRINT_TOT_CALL_PAIR(name) LOG->Time(#name " calls: %zu, time: %zu", name##_call_count, name##_total); + #endif /* diff --git a/src/RageUtil.cpp b/src/RageUtil.cpp index 32cfd09cb3..ea10ac5fb3 100644 --- a/src/RageUtil.cpp +++ b/src/RageUtil.cpp @@ -667,6 +667,14 @@ RString join( const RString &sDeliminator, const vector &sSource) return RString(); RString sTmp; + size_t final_size= 0; + size_t delim_size= sDeliminator.size(); + for(size_t n= 0; n < sSource.size()-1; ++n) + { + final_size+= sSource[n].size() + delim_size; + } + final_size+= sSource.back().size(); + sTmp.reserve(final_size); for( unsigned iNum = 0; iNum < sSource.size()-1; iNum++ ) { @@ -683,6 +691,18 @@ RString join( const RString &sDelimitor, vector::const_iterator begin, return RString(); RString sRet; + size_t final_size= 0; + size_t delim_size= sDelimitor.size(); + for(vector::const_iterator curr= begin; curr != end; ++curr) + { + final_size+= curr->size(); + if(curr != end) + { + final_size+= delim_size; + } + } + sRet.reserve(final_size); + while( begin != end ) { sRet += *begin; diff --git a/src/Song.cpp b/src/Song.cpp index 904833ded0..1ae98e94fb 100644 --- a/src/Song.cpp +++ b/src/Song.cpp @@ -293,9 +293,9 @@ bool Song::LoadFromSongDir( RString sDir, bool load_autosave ) if( !DoesFileExist(sCacheFilePath) ) { bUseCache = false; } - if(!PREFSMAN->m_bFastLoad && GetHashForDirectory(m_sSongDir) != uCacheHash) + else if(!PREFSMAN->m_bFastLoad && GetHashForDirectory(m_sSongDir) != uCacheHash) { bUseCache = false; } // this cache is out of date - if(load_autosave) + else if(load_autosave) { bUseCache= false; } if( bUseCache ) @@ -390,6 +390,10 @@ bool Song::LoadFromSongDir( RString sDir, bool load_autosave ) * Song/Steps objects to reload themselves. -- djpohly */ bool Song::ReloadFromSongDir( RString sDir ) { + // Remove the cache file to force the song to reload from its dir instead + // of loading from the cache. -Kyz + FILEMAN->Remove(GetCacheFilePath()); + RemoveAutoGenNotes(); vector vOldSteps = m_vpSteps; @@ -2196,6 +2200,11 @@ public: lua_pushboolean( L, p->m_DisplayBPMType == DISPLAY_BPM_RANDOM ); return 1; } + static int ReloadFromSongDir(T* p, lua_State* L) + { + p->ReloadFromSongDir(); + COMMON_RETURN_SELF; + } LunaSong() { @@ -2262,6 +2271,7 @@ public: ADD_METHOD( HasPreviewVid ); ADD_METHOD( GetPreviewVidPath ); ADD_METHOD(GetPreviewMusicPath); + ADD_METHOD(ReloadFromSongDir); } }; diff --git a/src/Song.h b/src/Song.h index 9271abee89..db9c901c20 100644 --- a/src/Song.h +++ b/src/Song.h @@ -90,6 +90,7 @@ public: bool LoadFromSongDir( RString sDir, bool load_autosave= false ); // This one takes the effort to reuse Steps pointers as best as it can bool ReloadFromSongDir( RString sDir ); + bool ReloadFromSongDir() { return ReloadFromSongDir(GetSongDir()); } void LoadEditsFromSongDir(RString dir); bool HasAutosaveFile(); diff --git a/src/SongCacheIndex.cpp b/src/SongCacheIndex.cpp index aeb34a2da9..6ccf17c274 100644 --- a/src/SongCacheIndex.cpp +++ b/src/SongCacheIndex.cpp @@ -106,13 +106,21 @@ void SongCacheIndex::ReadCacheIndex() FILEMAN->FlushDirCache(); } +void SongCacheIndex::SaveCacheIndex() +{ + CacheIndex.WriteFile(CACHE_INDEX); +} + void SongCacheIndex::AddCacheIndex(const RString &path, unsigned hash) { if( hash == 0 ) ++hash; /* no 0 hash values */ CacheIndex.SetValue( "Cache", "CacheVersion", FILE_CACHE_VERSION ); CacheIndex.SetValue( "Cache", MangleName(path), hash ); - CacheIndex.WriteFile( CACHE_INDEX ); + if(!delay_save_cache) + { + CacheIndex.WriteFile(CACHE_INDEX); + } } unsigned SongCacheIndex::GetCacheHash( const RString &path ) const diff --git a/src/SongCacheIndex.h b/src/SongCacheIndex.h index 12c9d9e04d..8f8b6ffe7f 100644 --- a/src/SongCacheIndex.h +++ b/src/SongCacheIndex.h @@ -15,8 +15,10 @@ public: static RString GetCacheFilePath( const RString &sGroup, const RString &sPath ); void ReadCacheIndex(); + void SaveCacheIndex(); void AddCacheIndex( const RString &path, unsigned hash ); unsigned GetCacheHash( const RString &path ) const; + bool delay_save_cache; }; extern SongCacheIndex *SONGINDEX; // global and accessible from anywhere in our program diff --git a/src/SongManager.cpp b/src/SongManager.cpp index a0ff971daa..f42baea434 100644 --- a/src/SongManager.cpp +++ b/src/SongManager.cpp @@ -1,6 +1,7 @@ #include "global.h" #include "SongManager.h" #include "arch/LoadingWindow/LoadingWindow.h" +#include "ActorUtil.h" #include "AnnouncerManager.h" #include "BackgroundUtil.h" #include "BannerCache.h" @@ -24,6 +25,7 @@ #include "RageFileManager.h" #include "RageLog.h" #include "Song.h" +#include "SongCacheIndex.h" #include "SongUtil.h" #include "Sprite.h" #include "StatsManager.h" @@ -142,12 +144,18 @@ void SongManager::Reload( bool bAllowFastLoad, LoadingWindow *ld ) void SongManager::InitSongsFromDisk( LoadingWindow *ld ) { RageTimer tm; + // Tell SONGINDEX to not write the cache index file every time a song adds + // an entry. -Kyz + SONGINDEX->delay_save_cache= true; LoadStepManiaSongDir( SpecialFiles::SONGS_DIR, ld ); const bool bOldVal = PREFSMAN->m_bFastLoad; PREFSMAN->m_bFastLoad.Set( PREFSMAN->m_bFastLoadAdditionalSongs ); LoadStepManiaSongDir( ADDITIONAL_SONGS_DIR, ld ); PREFSMAN->m_bFastLoad.Set( bOldVal ); + LoadEnabledSongsFromPref(); + SONGINDEX->SaveCacheIndex(); + SONGINDEX->delay_save_cache= false; LOG->Trace( "Found %d songs in %f seconds.", (int)m_pSongs.size(), tm.GetDeltaTime() ); } @@ -157,12 +165,20 @@ void SongManager::SanityCheckGroupDir( RString sDir ) const { // Check to see if they put a song directly inside the group folder. vector arrayFiles; - GetDirListing( sDir + "/*.mp3", arrayFiles ); - GetDirListing( sDir + "/*.oga", arrayFiles ); - GetDirListing( sDir + "/*.ogg", arrayFiles ); - GetDirListing( sDir + "/*.wav", arrayFiles ); - if( !arrayFiles.empty() ) - RageException::Throw( FOLDER_CONTAINS_MUSIC_FILES.GetValue(), sDir.c_str() ); + GetDirListing( sDir + "/*", arrayFiles ); + const vector& audio_exts= ActorUtil::GetTypeExtensionList(FT_Sound); + FOREACH(RString, arrayFiles, fname) + { + const RString ext= GetExtension(*fname); + FOREACH_CONST(RString, audio_exts, aud) + { + if(ext == *aud) + { + RageException::Throw( + FOLDER_CONTAINS_MUSIC_FILES.GetValue(), sDir.c_str()); + } + } + } } void SongManager::AddGroup( RString sDir, RString sGroupDirName ) @@ -309,14 +325,13 @@ void SongManager::LoadStepManiaSongDir( RString sDir, LoadingWindow *ld ) ); } Song* pNewSong = new Song; - m_pSongs.push_back( pNewSong ); if( !pNewSong->LoadFromSongDir( sSongDirName ) ) { // The song failed to load. - m_pSongs.pop_back(); delete pNewSong; continue; } + AddSongToList(pNewSong); index_entry.push_back( pNewSong ); loaded++; @@ -341,8 +356,6 @@ void SongManager::LoadStepManiaSongDir( RString sDir, LoadingWindow *ld ) if( ld ) { ld->SetIndeterminate( true ); } - - LoadEnabledSongsFromPref(); } // Instead of "symlinks", songs should have membership in multiple groups. -Chris @@ -375,7 +388,7 @@ void SongManager::LoadGroupSymLinks(RString sDir, RString sGroupFolder) pNewSong->m_bIsSymLink = true; // Very important so we don't double-parse later pNewSong->m_sGroupName = sGroupFolder; - m_pSongs.push_back( pNewSong ); + AddSongToList(pNewSong); index_entry.push_back( pNewSong ); } } @@ -423,6 +436,7 @@ void SongManager::FreeSongs() for( unsigned i=0; iSetEnabled( true ); - vector asDisabledSongs; split( g_sDisabledSongs, ";", asDisabledSongs, true ); @@ -1355,17 +1366,18 @@ Course* SongManager::GetRandomCourse() return NULL; } -Song* SongManager::GetSongFromDir( RString sDir ) const +Song* SongManager::GetSongFromDir(RString dir) const { - if( sDir.Right(1) != "/" ) - sDir += "/"; - - sDir.Replace( '\\', '/' ); - - FOREACH_CONST( Song*, m_pSongs, s ) - if( sDir.EqualsNoCase((*s)->GetSongDir()) ) - return *s; + if(dir.Right(1) != "/") + { dir += "/"; } + dir.Replace('\\', '/'); + dir.MakeLower(); + map::const_iterator entry= m_SongsByDir.find(dir); + if(entry != m_SongsByDir.end()) + { + return entry->second; + } return NULL; } @@ -1849,6 +1861,15 @@ int SongManager::GetNumEditsLoadedFromProfile( ProfileSlot slot ) const return iCount; } +void SongManager::AddSongToList(Song* new_song) +{ + new_song->SetEnabled(true); + m_pSongs.push_back(new_song); + RString dir= new_song->GetSongDir(); + dir.MakeLower(); + m_SongsByDir.insert(make_pair(dir, new_song)); +} + void SongManager::FreeAllLoadedFromProfile( ProfileSlot slot ) { // Profile courses may refer to profile steps, so free profile courses first. diff --git a/src/SongManager.h b/src/SongManager.h index f96e995502..328df59183 100644 --- a/src/SongManager.h +++ b/src/SongManager.h @@ -178,8 +178,10 @@ protected: void AddGroup( RString sDir, RString sGroupDirName ); int GetNumEditsLoadedFromProfile( ProfileSlot slot ) const; + void AddSongToList(Song* new_song); /** @brief All of the songs that can be played. */ vector m_pSongs; + map m_SongsByDir; /** @brief Hold pointers to all the songs that have been deleted from disk but must at least be kept temporarily alive for smooth audio transitions. */ vector m_pDeletedSongs; /** @brief The most popular songs ranked by number of plays. */