0001048: The new filesystem is extremely slow

Notes
(0002843) Ivan (developer) 2012-08-07 06:59	12 + 28 seconds? Wow. For me it is just 200 ms. In my case profiler reported that 50% of time is boost::to_upper conversion - not much can be helped here. Maybe boost uses some slow WinAPI function that we should avoid to use? >> don't collect entries of type OTHER they're used from time to time (e.g. .pal). I'll have to add some types first. >> get rid of initialLoader altogether What about such dirs like MP3 and Mp3? Linux case-sensivity causes problems here. It still can be improved by decreasing scanning depth though.

(0002845) Ivan (developer) 2012-08-07 11:34	I've made some tweak in rev. 2813 - initial loader checks only several types of data - same locations shouldn't be scanned multiple times - decreased amount of data scanned by initial loader Profiling on my side is almost useless - I don't have any notable bottlenecks. If loading speed is still an issue I will need to know where the bottleneck is.

(0002848) douggie_m (reporter) 2012-08-07 21:05 edited on: 2012-08-07 21:22	Steps to reproduce? Some strace/gdb/valgring/whatever command? I don't see any slowdown with starting a new game besides previous versions (like r2799 w/o "new filesystem"). I cannot save and cannot load saved game with current r2813 still though. Loading recovered-from-I-dunno-from game shown that it's not slower than in r2799.

(0002855) Tow (developer) 2012-08-08 08:28	Thanks, Ivan, r2813 is a big improvement. Initial loader time decreased to 0.2 s Data loading time firstly increased... but eventually I found out that MSVC 10 implementation of std::unordered_map destructor is extremely slow http://webcache.googleusercontent.com/search?q=cache:FjTgGTHZLocJ:connect.microsoft.com/VisualStudio/feedback/details/567859+&cd=1&hl=pl&ct=clnk&client=firefox-a [^] (bug is fixed in VC 11 only) After replacing with boost::unordered_map this step takes about 9 s. Mod loading is now only 2 ms. --- Now (as of r2815) my loading times look as follows: Creating console and logfile: 0 Initialization: 177 Loading resource at ALL/Config took 14 ms. Loading resource at ALL/Data/H3ab_bmp.lod took 407 ms. Loading resource at ALL/Data/H3bitmap.lod took 847 ms. Loading resource at ALL/Data took 989 ms. Loading resource at ALL/Maps took 3362 ms. Loading resource at ALL/Mp3 took 93 ms. Loading resource at LOCAL/Games took 165 ms. Loading resource at ALL/Data/H3ab_ahd.snd took 2 ms. Loading resource at ALL/Data/Heroes3-cd2.snd took 0 ms. Loading resource at ALL/Data/Heroes3.snd took 235 ms. Loading resource at ALL/Data took 1624 ms. Loading resource at ALL/Data/H3ab_spr.lod took 0 ms. Loading resource at ALL/Data/H3sprite.lod took 1102 ms. Loading resource at ALL/Sprites took 22 ms. Loading resource at ALL/Data/H3ab_ahd.vid took 5 ms. Loading resource at ALL/Data/H3ab_ahd.vid took 2 ms. Loading resource at ALL/Data/Video took 0 ms. Data loading: 8875 Mod filesystems: 2 File system handler: 9055 --- I ran profiler around LibClasses::loadFilesystem. Profiler says that 64,4% of time is spent in CFilesystemLoader::listFiles, that splits onto: - 43,3 pp (percent points) in operator++ for path -> almost everything is spent on internal slow text path operations (VC wstring debug implementation) - 5 pp in calling filesystem::extension - 4,3 pp in ResourceID c-tor - 8pp other 29,5% is in CResourceLoader::addLoader, including: - 16,5 pp for loader->getEntries (and in that 12 pp for ResourceID ctor) - 5,7 pp for unordered_map operator[] 4,5% is spent in CLodArchiveLoader::CLodArchiveLoader, of which 3,2 pp goes for unordered_map operator[]. Doesn't look good, the biggest time-eater is dir iterator, that probably can't be helped. I guesss I'll just have to clean my working directory and move away maps (2719 files, over 3s.). Or... build a .lod from them? ;)

(0002856) Ivan (developer) 2012-08-08 09:49	at least 1 second improvement is still possible - Data/ is scanned twice - once for "DATA" entry and once for "SOUNDS". I'll remove recursion for second one. In general loading should be a bit faster after sounds\video are controlled by new FS as well - right now .snd's and .vid's are scanned twice. >> Or... build a .lod from them? ;) That... should work :) This trick won't work with music - SDL_Mixer don't have API for loading from memory but everything else should work. Maybe we can add support for something like .zip at some point? May work as nice container for mods or map packs in future. BTW - and how fast release mode right now?

(0002857) Ivan (developer) 2012-08-08 12:06 edited on: 2012-08-08 12:18	And while you're on it - can you update windows video player to new FS? This is last area (along with linux video player) which still uses old archives system. It should be pretty much similar to sounds (rev 2818) EDIT: updated Linux player in rev 2819. SndHandler can be removed after Windows player update.

(0002866) Tow (developer) 2012-08-09 08:11	>> BTW - and how fast release mode right now? On my WoG installation: Initialization: 2 ms Data loading: 89 ms Mod filesystem: 1 ms When the bloating checks are gone and optimizations kick in, the new filesystem is quite fast. Still slightly slower than it was before (VCMI 0.89 took about 950ms to start, trunk needs 1200 ms) but I think it's acceptable price for gained functionality. >> Maybe we can add support for something like .zip at some point? May work as nice container for mods or map packs in future. Yes, sooner or later we'll have to. Alas, some new library dependency will be required. If you find a good library and want to add archive support, let me know. :) >> And while you're on it - can you update windows video player to new FS? Done in r2821. :) Not sure about that but I guess the "save resource to file" functionality could be moved to FS interface.

Issue History
Date Modified	Username	Field	Change
2012-08-07 03:44	Tow	New Issue
2012-08-07 03:44	Tow	Status	new => assigned
2012-08-07 03:44	Tow	Assigned To	=> Ivan
2012-08-07 03:45	Tow	Description Updated	View Revisions
2012-08-07 06:59	Ivan	Note Added: 0002843
2012-08-07 11:34	Ivan	Note Added: 0002845
2012-08-07 11:34	Ivan	Status	assigned => feedback
2012-08-07 21:05	douggie_m	Note Added: 0002848
2012-08-07 21:06	douggie_m	Note Edited: 0002848	View Revisions
2012-08-07 21:22	douggie_m	Note Edited: 0002848	View Revisions
2012-08-08 08:28	Tow	Note Added: 0002855
2012-08-08 08:28	Tow	Status	feedback => assigned
2012-08-08 09:49	Ivan	Note Added: 0002856
2012-08-08 12:06	Ivan	Note Added: 0002857
2012-08-08 12:18	Ivan	Note Edited: 0002857	View Revisions
2012-08-09 08:11	Tow	Note Added: 0002866
2012-08-09 08:11	Tow	Status	assigned => closed
2012-08-09 08:12	Tow	Resolution	open => fixed

Relationships