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

@@ -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<RString>() );
-		else if( sKeyName == "BaseRotationX" )		SetBaseRotationX( pValue->GetValue<float>() );
-		else if( sKeyName == "BaseRotationY" )		SetBaseRotationY( pValue->GetValue<float>() );
-		else if( sKeyName == "BaseRotationZ" )		SetBaseRotationZ( pValue->GetValue<float>() );
-		else if( sKeyName == "BaseZoomX" )		SetBaseZoomX( pValue->GetValue<float>() );
-		else if( sKeyName == "BaseZoomY" )		SetBaseZoomY( pValue->GetValue<float>() );
-		else if( sKeyName == "BaseZoomZ" )		SetBaseZoomZ( pValue->GetValue<float>() );
-		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<RString>() );
+		else if( sKeyName == "BaseRotationX" )		SetBaseRotationX( pValue->GetValue<float>() );
+		else if( sKeyName == "BaseRotationY" )		SetBaseRotationY( pValue->GetValue<float>() );
+		else if( sKeyName == "BaseRotationZ" )		SetBaseRotationZ( pValue->GetValue<float>() );
+		else if( sKeyName == "BaseZoomX" )		SetBaseZoomX( pValue->GetValue<float>() );
+		else if( sKeyName == "BaseZoomY" )		SetBaseZoomY( pValue->GetValue<float>() );
+		else if( sKeyName == "BaseZoomZ" )		SetBaseZoomZ( pValue->GetValue<float>() );
 	}
 
 	LUA->Release( L );

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

src/RageLog.cpp

@@ -56,9 +56,10 @@ static map<RString, RString> 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();
 }
 

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();
 

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
 
 /*

src/RageUtil.cpp

@@ -667,6 +667,14 @@ RString join( const RString &sDeliminator, const vector<RString> &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<RString>::const_iterator begin,
 		return RString();
 
 	RString sRet;
+	size_t final_size= 0;
+	size_t delim_size= sDelimitor.size();
+	for(vector<RString>::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;

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<Steps*> 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);
 	}   
 };
 

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();

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

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

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<RString> 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<RString>& 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; i<m_pSongs.size(); i++ )
 		SAFE_DELETE( m_pSongs[i] );
 	m_pSongs.clear();
+	m_SongsByDir.clear();
 
 	// also free the songs that have been deleted from disk
 	for ( unsigned i=0; i<m_pDeletedSongs.size(); ++i ) 
@@ -1124,9 +1138,6 @@ void SongManager::SaveEnabledSongsToPref()
 
 void SongManager::LoadEnabledSongsFromPref()
 {
-	FOREACH( Song *, m_pSongs, s )
-		(*s)->SetEnabled( true );
-
 	vector<RString> 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<RString, Song*>::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.

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<Song*>		m_pSongs;
+	map<RString, Song*> 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<Song*>       m_pDeletedSongs;
 	/** @brief The most popular songs ranked by number of plays. */