RollingCache.ccc performance debugging and tuning … How?

User Support Hub Install, Performance & Graphics
, ,
107

2025.01.20 - v1.2.11.0 - Major performance problems of the index area (especially in a large RC)

Beware … you are (slowly) entering “Brave New Cache” territory.

Leading up to a future post about all the ideas for a “Brave New Cache” (BNC) release, which would require substantial code changes, I want to identify and explain individual (major performance) issues … one by one. I have the feeling that otherwise my “Brave New Cache” post might be even longer than the already long posts of the past.

As a goose I hold the … perhaps outdated … opinion, that bold claims demand bold evidence.

Today my bold claim will be:

  • The RC subsystem of the sim is suffering from a severe “index area full dump problem”.
    • As a consequence the entire caching and data processing pipeline will “stutter”
      • … which perhaps even might result in visible “FPS stutter”.

I might return to the “visible FPS stutter” in the future, as that is highly likely caused by a different problem. But I would file it as a “backpressure” consequence of todays major topic.

I have seen indications of the “index area full dump problem” early on in the Process Monitor recordings. But bold evidence demands a dedicated set of tests.

So now I performed the following:

  • Test A5
    • … was explained in full detail in my previous post
    • It mainly delivered a fresh new 256 GB RC file
      • … which then stored about 70 GB of landscape data from northern America
      • … written into consecutive blocks of around 2.5 Mio blob items and index items.
  • Test A6
    • Here I try to touch as little existing, old data as possible.
    • I took a 1.75 hours bush trip in the beautiful landscape of northern Chad.
    • The airstrip of FTTZ
      • … has no buildings, no ground vehicles, no ground personal, no nothing
        • (OK … for some reason it had a parked ATR aircraft … well).

The main idea of Test A6 was that there should be very large, totally untouched parts in the cache. And so the delta content painting comparing the first 600 MB of Test A5 with Test A6 looks like this:

ROLLINGCACHE.CCC_indexArea_600MB.bin.FCD_deltaz100pc_512B_A6_A5
ROLLINGCACHE.CCC_indexArea_600MB.bin.FCD_deltaz100pc_512B_A6_A53840×2160 73.9 KB
  • Each pixel represents 512 bytes.
  • Since the index area is only 512 MB …
    • the lower green area shows 88 MB of identical initial blob item content.
  • The tiny red line at the beginning references the essential scenery index data
    • … and other items which get touched and used during every sim launch.
  • The white region is the yet unused index area.
  • The red above the white area references all the new blob items
    • … which have been loaded during Test 6.
  • Within the large green at the top one can see sporadic red pixels
    • … they again indicate some Test 5 item reuse.

When painting the same data with a block size of 4 MB, the results becomes somewhat more interesting and … less and more obvious:

ROLLINGCACHE.CCC_indexArea_600MB.bin.FCD_deltaz100pc_4096KB_A6_A5

  • Many parts of the previously white area turned green!
    • That is because there are tiny green pixels in the high-res painting, which are hard to see.
      • It seems like the “zero-fill” does periodically leave some “marker” bytes … for yet unknown reasons.
  • The red pixels in the second row mark the actual end of the used index area.
  • Overall the first 46 pixels represent the 184 MB of used index area.
    • 18 (40%) are red, showing blocks with modified data.
    • 28 (60%) are green, showing blocks which have stayed untouched and identical over the entire 1.75 hour flight.

At a more detailed level Test A6 …

  • … lasted for around 1.75 hours … which is 6300 seconds.
  • There has been no TIN landscape in this flight.
  • It did (again) see an average blob item size of around 30 KB.
  • And with around 110,000 new blob item TOCs (Length: 28 bytes) written
    • … we are seeing ca. 17 blob items per second
      • or 0.5 MB per second … which is 30 MB per minute.

Index area write pattern

Looking at the CSV version of the Process Monitor recordings, and focusing on the write events related to the index area, one can see this pattern:

"07:13:49.4099631",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
..
"07:13:49.4665955",,,"FASTIO_WRITE",,,"O: 176,160,848, L: 4,194,304"
..

"08:00:01.2260702",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
..
"08:00:01.2932592",,,"FASTIO_WRITE",,,"O: 184,549,456, L: 4,194,304"
..

"09:04:27.6738518",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
..
"09:04:27.7271167",,,"FASTIO_WRITE",,,"O: 184,549,456, L: 4,194,304"

The above are three examples: the first index area write, some random in the middle, and the very last write. They all have this in common, and by “all” I do not mean the three examples, but actually “all” index area write activities that I can find in the recording:

  • The index area is always written as a full dump!
    • Each write has around 180 MB
      • … which are copied to “disk” in 4 MB blocks
      • … using the “FASTIO_WRITE” technique.
  • “Writing” the full 180 MB took … 54 to 67 milliseconds.
    • If we go with 60 ms … then this translates to 3,000 MB/s of storage throughput? Hmmm.

The key observation here is, that the RC subsystem always writes the full index area, even when basically nothing did change!

Index area write frequency

So how often does this happen … during a flight, or an hour, or a minute?

If I only focus on the “Offset: 80” events, which mark the beginning of a write process, during one hour in flight Test A6, then I can see this:

"08:00:01.2260702",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:00:47.7367668",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:06:12.0288421",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:09:28.8070146",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:10:21.8668873",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:12:35.5750656",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:14:48.9907696",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:17:27.3803098",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:20:22.6257179",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:23:06.4669770",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:25:55.7940173",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:28:41.9122268",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:31:36.7099956",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:34:31.2476710",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:37:23.2834541",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:40:29.6643522",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:43:28.5271062",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:46:11.9059819",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:48:54.1651227",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:52:04.7905014",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:55:46.5810911",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"08:59:21.2446528",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
  • Sometimes the delta is … 46 seconds
    • sometimes it is … over 5 minutes.

However, in the 11.5 hour Test A5 flight I can see segments with this pattern:

..
"17:07:02.1289697",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:07:20.0209665",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:07:39.3841972",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:07:57.8853231",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:08:15.8243826",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:08:35.2747403",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:08:54.4175400",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:09:13.0769473",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:09:32.6322394",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:09:45.8385360",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:10:06.6215734",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:10:27.7512239",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"17:10:54.0164214",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
..

… or this pattern, while I was (with heavy FPS stuttering) above the TIN landscape of Toronto:

"18:15:54.4138176",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:16:05.2952318",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:18:06.3384782",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:18:31.9234027",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:19:35.2588535",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:20:01.6700722",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:20:23.5176490",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:20:37.1728612",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:33:19.8139865",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:35:56.0415092",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:37:33.0595375",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:38:02.0353212",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:38:39.1219073",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:38:59.8414678",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:39:25.3549464",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:39:59.0339799",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:40:14.4490319",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:40:44.4258269",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:41:04.8299137",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:41:56.3904035",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:43:03.8270682",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:44:41.8691164",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
"18:46:18.3579385",,,"FASTIO_WRITE",,,"O: 80, L: 4,194,304"
..
  • The first shows a very consistent … 20 seconds … pattern!
  • And under heavy stuttering (around 18:20) it is … once every 13 minutes?

Even when I take into account, that especially under heavy system stress, Process Monitor will not be able reliably record 100% of all events, then the level of variation is still very large.

The most likely reason for the observed variations is, that index write operations are triggered by some RC control algorithm, which is not simply based on a fixed time interval.

Index area write volume

If I take a “best case” example, like the very low write activity during hour 08:xx, then the numbers are the following:

  • 22 index area write events
    • … each with 180 MB … is in total 3,960 MB per hour.
  • 17 blob items per second
    • … translates to 30 MB per minute … is in total 1,800 MB per hour.

I do not even want to do the math for the “worst case” example with 20 second intervals.

I also want to stress that the blob item numbers depend on the type of flight (speed, altitude) and landscape (TIN or not). But they are a fairly predictable (somewhat “constant”) subject.

However, the index area size will grow until either the blob area is full, or the index area is full. So for a 256 GB RC file the index area can actually grow up to the hard limit of 512 MB. In that case there will be factor 3 more index writes and they will required 3 x 60 = 180 ms to complete.

So …

50% to over 90% of all bytes written to disk in Test 6 are caused by totally unnecessary writes of unchanged index area.

What is this “FASTIO_WRITE” thing?

While scaling the RC up to 256 GB my observed “zero-fill” write rate to my SSD was 300 MB/s … so almost twice the 160 MB/s which I observed back on 2024.12.11 during a previous cache size increase operation. I cannot explain the difference, but at least those two values provide a reasonable “real world” corridor.

This raises two interesting questions:

  • How can I observe 3,000 MB/s index area write speed
    • … on a system that can only deliver 300 MB/s to the actual SSD drive?
  • What does “FASTIO_WRITE” mean?

The RAM caches inside an SSD cannot answer the first question, because the SATA III bus can only deliver around 600 MB/s to the SSD drive. So question two must be the answer to question one.

Access to the file is opened with the following event:

"07:09:48.3574311",,,"IRP_MJ_CREATE",,,"Desired Access: Generic Read/Write, Disposition: OpenIf, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: None, AllocationSize: 0, OpenResult: Opened"

So “fast” does not mean “asynchronous”.

The official Microsoft documentation explains “fast” like this:

“Fast I/O is designed for rapid synchronous I/O on cached files. In fast I/O operations, data is transferred directly between user buffers and the system cache, bypassing the file system and the storage driver stack.”

The key point is “cached files”. So the timing here is basically a “user process RAM” to “operating system RAM” copy operation. That explains the speed.

However, no matter how fast a storage subsystem is, doing (so much) useless work is never an efficient strategy … it never comes for free.

No other RC read or write operation can take place during that period of time (“Synchronous IO”).

Combined with the observed Read after Write RC usage pattern (see post “2025.01.08 - v1.2.8.0 - Rolling Cache read-to-write ratio”) unnecessary index writes will block (important?) data from reaching the rendering pipeline.

Rendering a single frame at 60 FPS means each frame must be finished in 16 ms, with all the visual magic.

At the same time, with a 256 GB RC full of cached data, for up to 10 frames (180 ms) the sim will not be able to read any data from the RC, due to a very simplistic index area full dump into the system file cache RAM.

But the story does not end there. Those writes will cause system file cache pages to be marked as “dirty”, needing a flush to disk at some point. So lots of bytes will be written to the SSD over and over again … even when the data never actually changed!

Or, if you look at it from another perspective; if you try to reduce the impact of the “LRU problem” by raising the size of the RC, you will automatically increase the effect of the “index area full dump problem”.

2025.01.19-08.10.00-East of FTTZ in AF-TD
2025.01.19-08.10.00-East of FTTZ in AF-TD1920×1080 180 KB

Increasingly the text of my posts will be covering “problems” .. and so I think I should try to balance that with beautiful FS2024 landscape images.

The northern part of Chad did teach this old goose that desert regions are mostly underappreciated. And there is so much more to discover in northern Chad.

To summarize the observations and claims presented above:

  • A major performance problem is:
    • The sim always writes (dumps) the entire index area … up to 512 MB
      • … even when very large parts of the index did not change.
      • And this happens so frequently, that 50 to over 90% of all data written into the RollingCache.ccc file is useless, unchanged index area!
  • It feels reasonable to suspect, that blocking the RC file for 50 to 200 milliseconds might cause visible FPS stutter … by means of backpressure.
    • People reported in other threads that they seem to observe less FPS stutter with fresh (new) empty RC files.
      • That would be consistent with bigger and slower index area writes … due to larger RC files.

Ideas for a Brave New Cache (BNC) …

  • Index item writes:
    • … should only take place, when data actually did change.
    • … should be better aligned with the system cache page size.
    • … should be performed in small chunks only … not a full 512 MB dump.
    • … should have a well defined “worst case” latency impact on the “real” data rendering pipeline.
    • … should never compete with “real” blob item data access.

In my next post I think I will try to provide more background on the nature of index concepts. This might be helpful to better understand some of my (future) BNC ideas. But I also want to come back to the “zero-fill” areas and the problems of “cache fragmentation”.