Loading Levels?

[mikeblas]

I'm not much of a gamer. (I like playing Age of Empires III and Rise of Nations, and my wife and I sometimes go on an XBox binge.)

I see posts from gamers that they're frustrated about loading levels. What does that mean? If I wanted to study the problem, what would be a good game (or two) to buy so that I could learn about the problem by measuring it and analysing it?

 

[k1pp3r]

battlefield 2 is one people complain a lot about

 

[DougLite]

Storage Review can give you a head start on this, and I will lend what knowledge I can.

Eugene Ra at SR has analysis of access patterns in FarCry and Gaming tests on TestBed4

Mike, if you are going to analyze game loading performance, I humbly request that you look at the two extremes in access patterns: FarCry, UT2004, and the like, which have over 1000 files that are <128KB, and at the other extreme, titles like World of Warcraft, which have their data stored in a handful of large repositories. WoW has eight MPQ files, ranging in size from 60MB to 1GB.

 

[mikeblas]

Storage Review can give you a head start on this, and I will lend what knowledge I can.

Unfortunately, SR quotes these numbers often -- like you seem to do in some of your posts. But the numbers aren't reproducable. Reproducable tests are important to benchmarks because they let me run the test my self to set a base line with my own equipment, then see the results with the equipment under review to see what performance gain (or loss!) I might realize when upgrading or reconfugring.

Eugene Ra at SR has analysis

That's an interesting post. Looks like everyone in that thread is wowed by the pretty pictures and is forgetting to ask questions: what files are under the horizontal stripes of access space?

So why is that clump at seek distance just larger than 16M so large? If someone on my team wrote software that was expected to be performant, but banged the disk head around like that, I'd kick them off the project.

What files is it accessing? Why are they so far apart? Is this inherent in the game, or was there a problem with the installation? Was the disk not defragmented?

Certainly, there are answers we'd like to assume, but Eugene doesn't mention any of these things in his writeup.

Mike, if you are going to analyze game loading performance, I humbly request that you look at the two extremes in access patterns: FarCry, UT2004, and the like, which have over 1000 files that are <128KB, and at the other extreme, titles like World of Warcraft, which have their data stored in a handful of large repositories. WoW has eight MPQ files, ranging in size from 60MB to 1GB.

Sorry -- I'm not a gamer, so you'll have to be really explicit for me to understand you.

WoW is World of Warcraft, right? Doesn't that require a subscription in order to play it? Then, it's probably right out.

I have a copy of FarCry around, but I've only played the demo. I never even opened the box! What does it take to load a level in the game? At what action in the game would I start my clock (or disk activity monitor), and when would I stop it?

What is UT2004?

I think part of the problem is that the games have pretty shitty code. If FarCry is causing that access pattern, either it's reading sequentially through two different files -- but interleaving the reads, or the disk has very bad fragmentation.

When I save a game in Age of Empires III, it takes a very long time, even though the game save file ends up being only a little over two megs. It should take less than half a second to write 2 megs on my machine, but Age of Empires III needs more than 45 seconds!

I've watched the game load, which takes a very long time. I was surprised to find that it is CPU-bound the whole time.

 

[DougLite]

Unreal Tournament 2004 (UT2004) can be had very cheaply: http://www.newegg.com/Product/Product.asp?Item=N82E16832129116 $12 shipped on Newegg

WoW is indeed World of Warcraft, and requires a subscription

Age of Empires III or Rise of Nations might be a worthy candidate for the large file type of game...how many files are in your AoE III installation folder Mike?

Many games are indeed CPU bound when they are loading. They may have to decompress archives, decide what file to load next, etc.

Also, on the structure of SR's tests, they are repeatable on your machine, provided that you have access to the IPEAK SPT (Intel Performance Evaluation and Analysis Kit Storage Performance Toolkit) and SR allows you access to the trace files they have created. The great thing about IPEAK traces played back through RankDisk is that the CPU bound factors you allude to only affect the recording of the trace, as RankDisk only issues commands to the storage driver, the actual commands and processes that cause those calls to the storage driver are not repeated, meaning that the CPU, memory, etc do not affect the playback of IPEAK traces.

As for the large seek distances, you are correct that fragmentation plays a role. While a disk defragmenter may make files contiguous, it does not make directories contiguous (at least not that I'm aware of). Also, the game doesn't know in advance what it will be loading, particularly in multiplayer instances. The game may have upwards of 100 character models/skins to choose from, as an example. The game may have to load user defined music tracks. The game may have to load different texture libraries depending on the user's image quality settings.

EDIT: If I wanted to measure the time elapsed for a game loading from desktop to main menu, I would probably want to measure the time from the launching of the executable to the first call of a 3D API (Direct3D or OpenGL, if noting when the API is started is possible). Unreal Tournament 2004 is an excellent choice here, as installing any of the official patches disabled the anti-piracy CD check, removing the optical drive as a potential limiting factor.

You may very well be able to use a similar timing mechanism to measure loading of individual levels as well.

 

[mikeblas]

Unreal Tournament 2004 (UT2004) can be had very cheaply: http://www.newegg.com/Product/Product.asp?Item=N82E16832129116 $12 shipped on Newegg

Thanks. maybe I'll look into it; I'll proably couple it with something else I need to order, tho.

Age of Empires III or Rise of Nations might be a worthy candidate for the large file type of game...how many files are in your AoE III installation folder Mike?

4976 files over 2,225,190,509 bytes allocated. That doesn't tell us anything, though: there's no telling how many are used, how many aren't, and when they're loaded.

Also, on the structure of SR's tests, they are repeatable on your machine, provided that you have access to the IPEAK SPT (Intel Performance Evaluation and Analysis Kit Storage Performance Toolkit) and SR allows you access to the trace files they have created.

Unfortunately, IPEAK SPT has been discontinued. According to SR itself, it cost $800 to license when it was available ... and I don't see their trace files anywhere on the site. Given that, it's really hard for me to call their tests reproducable.

As for the large seek distances, you are correct that fragmentation plays a role.

I know. My point was that Eugene doesn't specif anything about the test -- was the drive defragmented, or not? Is the problem that the defrag he ran put two large files far apart, even though they end up being accessed together during the loads?

While a disk defragmenter may make files contiguous, it does not make directories contiguous (at least not that I'm aware of).

They can and do -- it depends on the program and the settings used.

You may very well be able to use a similar timing mechanism to measure loading of individual levels as well.

I don't see how. I would expect that loading a level happens long after the first call to initialze or check for the presence of Direct3D. Is your answer, then, that in Far Cry a level load only happens when first starting up the game?

 

[mikeblas]

I ran File Monitor from sysinternals on AoE III.

The startup is slow because the application sits in a loop requesting all access to all directories on C:\ repeatedly -- tens of thousands of times.

The game start and save is slow because the game is doing very short reads, many of which are unaligned.

 

[unhappy_mage]

An alternative to WoW would be Guild Wars, which also keeps things in one big file and is an MMORPG. Also very addictive Not quite so cheap at $46 shipped. I think it's only $40 at wal-mart.

Good luck in your quest, I look forward to seeing results. If there are any benchmarks you can suggest (I have ut2004 and GW) I'll be glad to run them.

 

[mikeblas]

I dug a little deeper; the problem with Age of Empires III at startup has nothing to do with disk I/O. It's spinning! It creates a couple of events early on, and ends up waiting for one, then waiting for the other. I can't guess why it doesn't wait for both with a single call to WaitForMultipleObjectsEx().

Age.EXE ends up spawning a new process very early, and that's the process which is doing the repeated query calls for file name information and file volume information calls. The new process is code that Age3.EXE spits out with a WriteFile() into a temporary file name.

Because I'm using detours to spy on the calls the process is making, I can't trap what's going on in the new, dynamically created process all that easily.

Rise of Nations, on the other hand, is a lot more reasonable. It's doing large block I/O, doesn't appear to be spinning, and isn't doing these queries for FileNameInformation and FileFsVolumeInformation over and over and over.

I'll have to see if I can attach a debugger to the temporary process and see what it is doing ...

 

[mikeblas]

FarCry has similar problems. It's reading from one file mostly sequentially, but does so in very small and variable blocks. It intersperses these reads with reads from other files. Presumably, that's the reason for the seeks that the Storage Review guys noticed.

As I go along with this investigation, the more disappointed I am about software engineering. I've seen lots of posts where people say that a particular type of disk access depends on the file size: file size is relevant, but not as substantial a contributor as request size.

Instead of reading 4 bytes, 23 bytes, 512 bytes, then 4 bytes, a developer should be writing code to read 543 bytes -- or better yet, 4096 bytes. once the large block is in memory, chopping it up there is far less expensive than issuing repetitive calls that turn out to be different physical requests from the drive.

Scaling this to the whole level file drives the point home. Say the level is 2 megs. It's far better to read two megs all in one shot, get it into memory, and pick through the buffer than it is to make 15,000 or so (2 megs / average read of 135) requests. (I thought everyone who called themselves a software engineer or developer would know this kind of thing.)

Interspersing the requests with requests for other files just adds insult to injury.

 

[unhappy_mage]

But shouldn't the readahead of the drive be taking care of getting the whole sector and chopping it into pieces as requested? Not that it's the best approach, but it does make sense to me to have an intermediate layer that takes small requests, does big reads, and caches the answers for later small requests.

 

[mikeblas]

But shouldn't the readahead of the drive be taking care of getting the whole sector and chopping it into pieces as requested? Not that it's the best approach, but it does make sense to me to have an intermediate layer that takes small requests, does big reads, and caches the answers for later small requests.

Sure it does. But the program has to step through all of its overhead for each of those calls. It has to push the arguments required to call ReadFile, then make the call. The OS has to figure out what device serves the handle that was passed ot ReadFile, then wad up a file system request. The file system has to see if the file has been cached; if so, it can service the request from the cache by copying the bytes requested. Maybe there's only a partial hit in cache -- though that's unlikely, given the size of these requests I'm seeing.

No hit in cache? Then the file system has to wad up a driver request, find the responsible driver, and ask it to get the bytes. The driver has to go ask the device, setup a DMA request, and execute the command -- then wait for the device to respond. Given the response, it has to tell the file system about the response so it can cache the returned bytes. Then, return success or failure all the way back up to the caller.

If the final request is satisfied by the drive's cache, then that's helpful -- but it's still plenty of overhead for the application. The sad thing is, with just a little care, it can be completely avoided. Why do that 15,000 times for 130-something bytes each, when you could do it just once?

And I'm not even taking into account more interesting optimizations.

For example, the texture map file for FarCry is about 230 megs. It looks like all the requests from that file are misaligned; that is, they're not on 512 or 4096-byte boundaries. Aligning the requests helps the file system and the drive; otherwise, the request might be for less than a sector of data, but it ends up spanning pyhsical or logial sector and requires two read operations and some glue.

Yuck!

I'm working on hacking together some detours that will let me specifically spy on file operations. I should be able to provide some interesting dumps -- essentially, what I guess that the Storage Review guys recorded with their unobtainable Intel application.

For now, though, what I'm getting out of FileMon scares me. Here's a good sequential read. I'd rather see this be done with a single read, but at least the reads are all multiples of 512 and in order:

12:01:58	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\objects.pak	SUCCESS	Offset: 1098 Length: 3584	
12:01:58	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\objects.pak	SUCCESS	Offset: 4682 Length: 512	
12:01:58	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\objects.pak	SUCCESS	Offset: 1098 Length: 3584	
12:01:58	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\objects.pak	SUCCESS	Offset: 4682 Length: 512	
12:01:58	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\objects.pak	SUCCESS	Offset: 1098 Length: 3584

Here's a read while Far Cry is loading a level. Note that the read is sequential, but overlaps itself. There's a very long string of these:

12:02:05	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\sounds.pak	SUCCESS	Offset: 65618866 Length: 512	
12:02:05	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\sounds.pak	SUCCESS	Offset: 65618867 Length: 512	
12:02:05	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\sounds.pak	SUCCESS	Offset: 65618868 Length: 512	
12:02:05	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\sounds.pak	SUCCESS	Offset: 65618869 Length: 512	
12:02:05	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\sounds.pak	SUCCESS	Offset: 65618870 Length: 512	
12:02:05	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\sounds.pak	SUCCESS	Offset: 65618871 Length: 512	
12:02:05	FarCry.exe:2760	FASTIO_READ	C:\program files\ubisoft\crytek\far cry\fcdata\sounds.pak	SUCCESS	Offset: 65618872 Length: 512

So, they're reading 512 bytes starting at 65618870. Then reading 512 bytes from 65618871; that second read contains 511 bytes that they've already read!

It might be that FileMon is lying to me -- but I bet it's not. This string of reads seems to be what takes all the time while the progress bar is moving and I'm staring at the FarCry logo after I ask to start a new game. Is this what the gamers mean by "level loading"?

 

[mikeblas]

Yep; FileMon isn't lying. FarCry has a really inexplicable implementation. With my detours in to monitor file APIs, I can find it doing lots of silly things.

When I observed it, it took about 107 seconds to read the level (again, I'm not a gamer -- so hopefully I'm observing the right thing. I'm watching it grow the progress bar after selecting a new scenario, before I get dropped into the airshaft in the basement).


I can watch it open the textures file here:

20051223135501702  548 50.60: traceapi: 001 CreateFileA(c:\program files\ubisoft\crytek\far cry\fcdata\textures.pak,80000000,3,12d2d4,3,80,0)
20051223135501702  548 50.60: traceapi: 001   CreateFileW(c:\program files\ubisoft\crytek\far cry\fcdata\textures.pak,80000000,3,12d2d4,3,80,0)
20051223135501702  548 50.60: traceapi: 001   CreateFileW(,,,,,,) -> 71c
20051223135501702  548 50.60: traceapi: 001 CreateFileA(,,,,,,) -> 71c

The handle for reading the textures file is 0x71C.

It's opened for GENERIC_READ access, which is fine. But note that the file was opened with FILE_SHARE_READ and FILE_SHARE_WRITE. Wouldn't it be better to open with no file sharing, so that the OS can just lock the file and forget about it, instead of making a shared file? In particular, who would ever be writing to this file besides the game itself?

The game gives non-NULL security attributes, which is curious.

It doesn't provide any interesting file flags; FILE_ATTRIBUTE_NORMAL, which si fine. But why not FILE_FLAG_SEQUENTIAL_SCAN, since we seem to be mostly reading this file straight through? Even if we're not, then the file should be opened with the FILE_FLAG_RANDOM_ACCSES flag.

It gets worse, though. While reading the file, the program literally takes 512 steps forward and


These operations are all consecutive. We seek to offset 0xA9AB96D into the file, then read 0x200 bytes (Which is 512 bytes -- a very small read).

20051223135612558  548 50.60: traceapi: 001 SetFilePointer(71c,a9ab96d,0,0)
20051223135612558  548 50.60: traceapi: 001 SetFilePointer(,,,) -> a9ab96d
20051223135612558  548 50.60: traceapi: 001 ReadFile(71c,efc270,200,12e3f8,0)
20051223135612558  548 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20051223135612558  548 50.60: traceapi: 001 SetFilePointer(71c,a9ab9d6,0,0)
20051223135612558  548 50.60: traceapi: 001 SetFilePointer(,,,) -> a9ab9d6
20051223135612558  548 50.60: traceapi: 001 ReadFile(71c,efc270,200,12e434,0)
20051223135612558  548 50.60: traceapi: 001 ReadFile(,,,,) -> 1

Immediately afterwards, the program seeks to location 0xA9AB9D6, which is 105 (decimal) bytes after the previous seek to 0xA9AB96D, and 197 (decimal) bytes before where the file pointer landed after the previous read.

These calls go to a certain offset, read 512 bytes, backtrack 197 bytes, then read 512 bytes again. The two reads overlap by 407 bytes! We're doing 1024 bytes of I/O, but only getting 617 bytes from the file, in total.

There's a series of calls like this; the trace file I've generated is about 15 megs in size, with 194,910 events in it, so I can't count. But there are thousands of such calls.

The single byte reads followed by seeks really are happening as I observed in FileMon. Here's the detours trace:

20051223135716262  548 50.60: traceapi: 001 SetFilePointer(2ec,3e9576b,0,0)
20051223135716262  548 50.60: traceapi: 001 SetFilePointer(,,,) -> 3e9576b
20051223135716262  548 50.60: traceapi: 001 ReadFile(2ec,23d99cb0,200,12cb78,0)
20051223135716262  548 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20051223135716262  548 50.60: traceapi: 001 SetFilePointer(2ec,3e9576c,0,0)
20051223135716262  548 50.60: traceapi: 001 SetFilePointer(,,,) -> 3e9576c
20051223135716262  548 50.60: traceapi: 001 ReadFile(2ec,23d99cb0,200,12cb78,0)
20051223135716262  548 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20051223135716262  548 50.60: traceapi: 001 SetFilePointer(2ec,3e9576d,0,0)
20051223135716262  548 50.60: traceapi: 001 SetFilePointer(,,,) -> 3e9576d
20051223135716262  548 50.60: traceapi: 001 ReadFile(2ec,23d99cb0,200,12cb78,0)
20051223135716262  548 50.60: traceapi: 001 ReadFile(,,,,) -> 1

The code is reading 512 bytes, backtracking 511 bytes, then reading 512 bytes again. Again, no exact count -- but this goes on for hundreds of calls.

File handle 0x2EC is for "c:\program files\ubisoft\crytek\far cry\fcdata\sounds.pak", by the way: similarly opened without any flags that would enable optimization in the OS.

It's no wonder that this program is an example of very slow level loading! These misaligned, byte-at-a-time reads are far from optimal. While the OS and the filesystem try to resolve the overlaps from cache, they eventually have to do real reads. As I pointed out, even if the read is satisfied by system or on-drive cache, there's some real issues with this kind of code.

Unless someone wants me to go dig on something specific, I guess I'll conclude my investigation with the point that it's absurd to use a program like this for any benchmarking. The performance isn't capped by the drive: it's limited by the miserable code in the application itself. Sure, a faster drive might make the application ever so slightly faster, but that improvement is severely attenuated by the poor implementation application itself.

 

[Bullitt]

Mike, you've answered a ton of questions that I've always had but didn't know how to ask them. Assuming you are correct....

Please stop before you pick up Battlefield2, you are making me hate gaming. I cant stand half-assed code...

j/k man, interesting findings nonetheless. I expect half of the problem is that developers are on a tight time-schedule and unwilling to optimize things because they figure hardware will fill in the gaps and the "who cares as long as we make a pretty game, screw the load times" mentality.

 

[mikeblas]

Mike, you've answered a ton of questions that I've always had but didn't know how to ask them. Assuming you are correct....

Feel free to verify my results yourself. Unlike Storage Review, what I'm using is readily available so you can try this at home.

FileMon and DiskMon are available at http://www.sysinternals.com/

The Detours I'm writing are with the Detours 1.5 SDK, which you can download from the Detours page at the Microsoft Research website.

I'm not quite ready to publish the code for the tool I wrote, but it's pretty simple -- you can use the TraceAPI sample in the SDK to achieve the same results. You'll just have shitpiles more output to sift through. I just tore the sample up to report only for file and disk APIs.

I'd be thrilled to learn how it goes if you try to reproduce my results.

I expect half of the problem is that developers are on a tight time-schedule and unwilling to optimize things because they figure hardware will fill in the gaps and the "who cares as long as we make a pretty game, screw the load times" mentality.

It's a little surprising that they don't pay attention to load time, since it's apparently such a sore point for developers. But certainly the developers who write games have expertise in other areas, and focus on that -- that's what makes their income.

Far Cry is fun; I've played it a little as a result. I'm still hoping someone can confirm that "level loading" in the game means the progress bar while looking at the logo after starting the game. If my character is killed and I reload the checkpoint, is that also level loading?

After being killed, I find the load to go much faster. I'm assuming this is because of caching; while playing the game, my system cache physical memory goes very high. It seems like this is one of the games where more memory really helps -- I've got two gigs.

 

[stonedwaldo420]

You are correct that level load times make a crappy benchmark when it comes to analyzing the true performance potential of a disk system. However, if gaming is the only computationally intense task one performs on their computer (and for me it is), I would like to know which hard drive does the best job of making up for the garbage code. Saving 5 seconds on each level load can add up to a lot of time over the life of a gamer. Additionally, level loads are pretty much the only thing I sit around in front of my computer waiting for (I feel like i am on a dialup!!). Because of that, i really appreciate level load time specs in benchmarks, mainly just to see which HD loads the levels fastest in the games i play. Honestly, aside from reliability, it is the most important factor in my HD buying decisions.


Obviously the best solution would be to code the game properly in the first place, but i don’t see that happening. So in your opinion, what is the best hardware solution? Brute force (15K Raid0 SCSI), or 7200 with 16MB cache and extremely efficient firmware?

 

[mikeblas]

Obviously the best solution would be to code the game properly in the first place, but i don’t see that happening. So in your opinion, what is the best hardware solution? Brute force (15K Raid0 SCSI), or 7200 with 16MB cache and extremely efficient firmware?

Perhaps you misunderstood my explanation. The time spent loading in Far Cry isn't spent touching the hard drive. The time is spent bouncing between the code in the application, the operating system, and perhaps the driver.

No hard disk in the world is going to make that any faster. A better drive will make the time you spend reading less, but that isn't the dominant term in this equation. Using the fastest drive available isn't going to get your five seconds because the drive isn't the limiting factor.

 

[unhappy_mage]

My brother plays Guild Wars, and the level loads in that are really fast. Mainly dependent on your internet connection, in fact. It keeps everything in a single large file (currently >1 gb), so it has a very clean installation directory (3 files, plus screenshot directory, IIRC) I'd be interested in seeing how it loads. It uses about 200mb of memory, and I'm wondering if it is just really small or really well optimized. We'd run tests ourselves, but we're going AFC for a week.

If you don't want to get the game we can run the tests when we get back. Do you just run Filemon and Diskmon in the background while playing the game, then parse the info it gathers afterwards?

 

[mikeblas]

If you don't want to get the game we can run the tests when we get back. Do you just run Filemon and Diskmon in the background while playing the game, then parse the info it gathers afterwards?

Yep. I have a dual monitor setup, so I can push FileMon over to the other montior and let it run while I'm exercising the game. I'm not playing, so ALT+TABbing away from the game doesn't matter, and I can change settings on the tool easily.

The Detours tool works by injecting a DLL into the games process, intercepting all the calls the host process makes, and announcing the results to another process. That's far easier to work with.

One thing that drives the point home about the disk drive itself not helping much is comparing the output of FileMon to the output of DiskMon. As far as I can tell, FileMon is recording logical requests to the file sytem, while DiskMon shows physical requests that are actually executed by the driver.

If a program reads the same sector twice in a row, FileMon will show both requests. But the file system will certainly satisfy the second request out of cache. (And, heck; it might have even serviced the first request out of cache.)

Say the program reads the next sector, and that's a miss in the system file cache. FileMon shows the request. DiskMon shows the request, too, since it reached the driver. The driver asks the device, which might end up servicing the request with its lookahead cache (if that's what the cache on the drive is used for -- do we even know?) or by a physical read. We don't have tools to monitor what the drive does at that level. Finding a SATA or ATA protocol analyser will be easier than finding someone to pay for it!

Anyway, the problem is that I don't see an easy way to correlate the output of DiskMon with the output of FileMon. It would be neat to figure out which physical read activity (DiskMon, listed by sector number) came from which logical read requests (FileMon, listed by filename). We'd want to correlate by time, then work out which sector was in which file. Doable, but not fun code to be writing.

Given all that, then we'd have a neat way to measure system cache efficiency -- specific to whatever file (or request!) is being made, and not in aggregate like the PerfMon counters provide.

Then, I'd ideally like to write a tool that monitors the API requests (with detours), the the resulting low level requests (like DiskMon), and correlates them. If I could find a neat way to show both how much time was spent on requests per file and a high-level profile of what activity was happening (so you could zoom into the things you didn't like to get the low-level requests after even a very long run).

Such a profiler would be a really neat tool; maybe I'll have time to play with it after the holiday.

My brother plays Guild Wars, and the level loads in that are really fast. Mainly dependent on your internet connection, in fact. It keeps everything in a single large file (currently >1 gb), so it has a very clean installation directory (3 files, plus screenshot directory, IIRC) I'd be interested in seeing how it loads.

Er, so it's loading from this gigabyte file, or over the Internet?

What's AFC? Anyway, have a good trip!

 

[mikeblas]

Please stop before you pick up Battlefield2, you are making me hate gaming. I cant stand half-assed code...

Is this what people call "BF2"? Does it require a subscription to play? People seem to bitch about it a lot. Does it seem to take too much memory, or go slow at loading levels, or both?

I have some spare time. Should I analyse it, too? Do I want "Battlefield 2", or "Battlefield 2: Special Forces"? Both? (It looks like BF2:SF is an add-on pack. Is it required to make performance go bad?) Does it matter if I get the DVD version or the regulard version -- they're the same except for media?

 

[DougLite]

BF2 = Battlefield 2. It singlehandedly spurred the move from 1GB to 2GB of RAM being recommended for top flight gaming rigs. Use of 900MB of virtual memory (physical + paged) or more is not uncommon if you play BF2 with all of the eye candy on.

 

[mikeblas]

So it's more about memory usage? That's not much fun to measure; while I can easily observe the memory being allocated or freed, I can't learn what it's used for (and therefore, if it's being used sensibly or not) from the outside.

 

[unhappy_mage]

Well, it's still gotta load on the order of a gigabyte of stuff from disk to ram somehow. Sure, paging will *kill* BF2, but I imagine even without paging loading from disk will be a bottleneck at some point.

Have you made any updates on the Detours thing you were working? Willing to share? I've downloaded it and compiled the test apps, but I'm not sure how to go about duplicating your efforts. I have a good number of the games being mentioned available, and a dual monitor setup. It'd be cool to see what games do it right and still get hurt on performance.

 

[mikeblas]

I took the broadest sample (that purports to wrap nearly everything in the API) and chopped it down so it only did file I/O. Then, I tewaked the output so it was easy to read and sort and search. Then, I ran it outside of far cry:

c:>MyDetoursApp Farcry.EXe

and captured the output.

I think I outlined everything else here; the disk and file monitor tools are available on sysinternals.

I don't know what the game does or does not load -- I don't know a thing about it.

 

[mikeblas]

OK, I ordered BF2 from Amazon.com and helpfully I can do the analysis on it sometime over the next couple of weeks.

 

[mikeblas]

It's absolutely baffling. BF2 does the same thing; this trace is after the "Batttlefield 2" splash screen, but before any of the movies

start. This is just a snippet; it goes on for dozens of seconds:

20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3c8f7,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3c8f7
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d038,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3c960,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3c960
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d050,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3c960,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3c960
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d038,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3c9cc,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3c9cc
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d050,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3c9cc,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3c9cc
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d038,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3ca37,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3ca37
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d050,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3ca37,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3ca37
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d038,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3caa9,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3caa9
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d050,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3caa9,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3caa9
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d038,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3cb16,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3cb16
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d050,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3cb16,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3cb16
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d038,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3cb83,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3cb83
20060504002757640 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d050,0)
20060504002757640 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(748,2c3cb83,0,0)
20060504002757640 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3cb83
20060504002757656 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d038,0)
20060504002757656 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757656 2400 50.60: traceapi: 001 SetFilePointer(748,2c3cbf2,0,0)
20060504002757656 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3cbf2
20060504002757656 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d050,0)
20060504002757656 2400 50.60: traceapi: 001 ReadFile(,,,,) -> 1
20060504002757656 2400 50.60: traceapi: 001 SetFilePointer(748,2c3cbf2,0,0)
20060504002757656 2400 50.60: traceapi: 001 SetFilePointer(,,,) -> 2c3cbf2
20060504002757656 2400 50.60: traceapi: 001 ReadFile(748,1457228,200,12d038,0)

All this access is against a file called Common_client.ZIP. It's just hammering the file system, reading really stupid. You can see it sets the file pointer, then reads 512 bytes at a certain spot, then reads again. It's reading the same data over and over, at two different places in the file. They overlap by the read size.

I'm having problems getting the game to load with my monitor hooked up; maybe it knows I'm watching and is turtling itself as copy protection, or reverse engineering protection. Let's see if I can make it work ...

 

[mikeblas]

Well, I can't figure out how to get my tool to work. As soon as BF2 starts to load a level, it exits immediately. My tool must have a bug, or maybe BF2 detects the presence of my tool and thinks I'm trying to hack it.

Going forward only with filemon, I find plenty of things that make me thing loading levels could be faster.

If you play BF2, you can go look in your "My Documents" directory. Under there, you'll find a "Battlefield 2" folder, and in that you'll find some subdirectories. Navigate around; the subdirectories seem to have random names. On my machine, directory "C:\Documents and Settings\mikeblas\My Documents\Battlefield 2\mods\bf2\cache\{D7B71E3E-4381-11CF-B643-0A2003C2CB35}_2551_3" has some files that BF2 created. They're all about 16 kilobytes in size -- some 15, some 17. How many? There's 1350 of them right now. Nice going!

The program's access to files is not at all optimized. It'll read long stretches of a file sequentially; six or eight reads of 65536 bytes in a row. As you can imagine, the drive and file subsystem love this. But those reads are punctuated by random reads of 512 bytes from different locations in the same file.

There's also an alarming number of repeated accesses to files which don't actually exist; all have the extension *.OCC, like:

C:\Program Files\EA GAMES\Battlefield 2\mods\bf2\Objects\staticobjects\common\com_objects\wirefence_24m\wirefence_24m.occ

This directory doesn't even exist on my machine, but there are tens of dozens of hits trying to find files in there.

The game fires up Python; check out "C:\Program Files\EA GAMES\Battlefield 2\python\bf2" for the scripts it's using.

Your Battlefield 2 program directory contains not one, not two, but three versions of the MFC library. (How do I know? I worked on the team that wrote the library for five years.)

They have DBGHELP.DLL in there, which is scary. This library is used to get stack traces (you know, after a crash) and look for debugging symbols. Makes sense for a program that's debugging something, or dumping the content of an executable file. Maybe for a tool that sends crash reports back to a server. Does BF2 do that?

 

[Bullitt]

Does BF2 report crashes back to the publisher? HA!!! I doubt it. If they did, they might be overwhelmed. I do indeed love the game, but I have seen firsthand how it can frustrate someone with crash problems. Run a packet sniffer as you are crashing to see how it acts. That would definitely answer your question, but unfortunately, its outside the realm of a "disk access disection"


that Cache folder (in my documents) is "supposed" to make level loads faster by caching items like server banners, MOTD's and other items, but there's no harm in getting rid of them. They just come on back the next time you visit that server.

The random files, could they be compressed files that are being read? Sorta like the zipped PK3 files of Quake3?