[Solved] Dramatic ​FileStream.​Write performance difference based on passed in buffer size - Why?

I was testing some file related functionality and wanted to know what the raw file write performance on my system was. So I wrote a small test method like the one below:

public static TimeSpan PerformTest(long fileSize, int bufferSize)
{
    var buffer = new byte[bufferSize];
    var loops = fileSize / bufferSize;
    var path = @"C:\Test\Test.data";

    if (!Directory.Exists(Path.GetDirectoryName(path)))
        Directory.CreateDirectory(Path.GetDirectoryName(path));

    using (var file = new FileStream(path, FileMode.Create))
    {
        var stopwatch = Stopwatch.StartNew();

        for (var idx = 0; idx < loops; idx++)
        {
            file.Write(buffer, 0, bufferSize);
        }

        stopwatch.Stop();
        return stopwatch.Elapsed;
    }
}

I call it like this:

var elapsed = PerformTest(1024 * 1024 * 1024, 8 * 1024 * 1024);

In all cases I passed in 1GB as the file size (1st parameter). However I'm seeing a huge performance difference depending on the value I pass into the second parameter. Here is an example:

1K    5.4s
8K    2.5s
32K    1.1s
64K    0.9s
256K    0.7s
512K    0.7s
1M    0.7s
8M    0.8s
16M    0.8s
32M    6.1s
64M    8.3s
128M    9.7s
256M    9.7s
512M    9.9s
1G    11s

Unless I did something stoopid in my test method (very likely), why am I seeing such slow performance when passing in a large buffer into the Write call? The overall amount of data is still exactly the same in all cases. I would think it would already break up the buffer into multiple writes internally and should not really see much slowdown if a larger buffer is passed in.

Any ideas?

Yes I know that fitting the buffer into CPU cache should result in faster performance, but this is much more than what I would expect. Memory access should be much faster than disk access even if it doesn't fit in the CPU cache. Or so I would think.

OK when I create the following method:

private static void WriteFast(FileStream file, byte[] buffer, int offset, int count)
{
    var curOffset = offset;
    var remain = count;

    while (remain > 0)
    {
        var writeCount = Math.Min(remain, 1024 * 1024);

        file.Write(buffer, curOffset, writeCount);
        remain -= writeCount;
        curOffset += writeCount;
    }
}

And change line 16 to this:

WriteFast(file, buffer, 0, bufferSize);

...it doesn't matter what buffer size I pass in, it completes in less than 0.7s. The exception is when passing in 1GB, it completes in 1.1s.

For large buffers, that is more than an order of magnitude better performance. If MS simply adds the contents of the WriteFast method to the FileStream.Write method, we will see an instant performance improvement. BTW I tested with File.Create and it has exactly the same issue.

Nobody...noticed?

OK mystery solved...

Turns out the OS is actually caching almost all of the 1GB of data. When I pass in the FileOptions.WriteThrough flag, I'm seeing the same 11secs for all buffer sizes.

I initially though file caching won't play a big part due to the large 1GB file size, but apparently not. Task manager shows 4.5GB of memory is used for caching.

I'm still wondering though why a 16MB vs 32MB passed in buffer size would affect file caching so much (0.8s vs 6.1s).

Maybe you're just hitting some tipping point within the cache managers behaviour. I wonder if it just finds it easier to allocate contiguous space for very small buffers and 32MB is just the point at which it starts using an alternate strategy (or perhaps just flushing more often on the assumption that a large buffer means it's likely to be a very large file).

@BitFlipper: http://msdn.microsoft.com/en-us/library/system.io.bufferedstream.aspx

There are four things in play here:

1) The file is on disk
2) There is an filesystem buffer for the file in kernel mode
3) There is a per-handle filesystem buffer for the file in kernel mode
4) There is a per-handle user-mode buffer for the file in user mode

When you read from the System.IO.FileStream, the first port of call is the per-handle user-mode buffer which is read out to the out-buffer of the Read() request. If this isn't big enough, System.IO.FileStream calls ReadFile which syscalls to the kernel to get more data from the per-handle filesystem buffer in kernel mode. This is complicated. If this runs out it goes up a level and so on, until the file is read from disk if it doesn't exist in memory anywhere.

The size of the buffer that you are controlling isn't the kernel mode buffers. It's the user-mode buffer size of System.IO.FileStream - i.e. the number of bytes that are requested at once per syscall. By having a small buffer size you're forcing all of your reads to do lots of complicated syscalls with long and spindly paths through the kernel (many of which will force waits on your thread). By having a large usermode buffer you manage to make most of your Read()s have no syscalls associated with them, thus massively improving the speed of your application.

@evildictaitor: Which would be a great argument, were it not for the fact that buffers smaller than 32MB were generally performing better.

@AndyC

My results on a 600MB file with different buffer sizes disagree. There is a big improvement up to about 128KB, at which point the buffer size becomes largely irrelevant. I'm not sure any  slowdown for buffers over 32MB are significant (32MB =0.230280581053665 and 512MB= 0.231383713460809).

....................buffersize=1024bytes, time=2.25007988811465
....................buffersize=2KB, time=1.68639940418628
....................buffersize=4KB, time=1.29541369914393
....................buffersize=8KB, time=0.737160592137703
....................buffersize=16KB, time=0.462024269192857
....................buffersize=32KB, time=0.332775026205634
....................buffersize=64KB, time=0.260997596125811
....................buffersize=128KB, time=0.242374848562457
....................buffersize=256KB, time=0.219515605122729
....................buffersize=512KB, time=0.205800436923843
....................buffersize=1024KB, time=0.199390821053889
....................buffersize=2MB, time=0.202642185682837
....................buffersize=4MB, time=0.218147010924962
....................buffersize=8MB, time=0.222718640357936
....................buffersize=16MB, time=0.225861427125945
....................buffersize=32MB, time=0.230280581053665
....................buffersize=64MB, time=0.228971652198171
....................buffersize=128MB, time=0.225475398425936
....................buffersize=256MB, time=0.228067831890216
....................buffersize=512MB, time=0.231383713460809

Well I don't know why I'm seeing such different results with larger buffers on my system. I'm certainly not imagining it. I guess there could be many reasons, including a bug in the posted sample code. However no-one using the sample code has apparently been able to get similar results to mine so I would need to assume it is something to do with my system.

Bear in mind that your test also includes the allocation of a very large buffer which is very inefficient for the GC both to create initially and then every time it needs to perform a collection or when it needs to marshal data over from your managed byte[] to an unmanaged void* for the ReadFile() call which sits behind the FileStream's Read() method.

11 hours ago, evildictaitor wrote

Bear in mind that your test also includes the allocation of a very large buffer which is very inefficient for the GC both to create initially and then every time it needs to perform a collection or when it needs to marshal data over from your managed byte[] to an unmanaged void* for the ReadFile() call which sits behind the FileStream's Read() method.

The buffer allocation is done outside of the timing loop. The GC also doesn't need to do any collections of the large buffer during the test since I don't create a new one at each loop.

Next, if you look at the WriteFast method, it uses that same large buffer multiple times to call FileStream.Write. This very simple change causes a very large change in my results.

In addition, a large buffer doesn't take any longer than a small buffer to marshal since there is no memory copy involved in the case of a byte buffer.

So I don't think the issues you mention plays a part in the results I'm seeing.

1 hour ago, BitFlipper wrote

The GC also doesn't need to do any collections of the large buffer during the test since I don't create a new one at each loop.

The whole point of the GC is that it can move stuff around even if it's live, although I take your point that it's unlikely given the amount of work that needs to be done.

In addition, a large buffer doesn't take any longer than a small buffer to marshal since there is no memory copy involved in the case of a byte buffer.

Are you sure? Pinning a byte array causes a memory allocation, and I'm pretty sure you couldn't Pinvoke without a pin.

Anyway, I wasn't saying these were the issue you're seeing, just that there may be hidden variables you're not considering that are slowing you down for very large buffer sizes that have nothing to do with the filesystem cache.

2 hours ago, evildictaitor wrote

*snip*

The whole point of the GC is that it can move stuff around even if it's live, although I take your point that it's unlikely given the amount of work that needs to be done.

*snip*

It definitely does not copy any memory around while P/Invoking. For byte arrays it is a very fast operation since all it has to do it pin the memory.

Are you sure? Pinning a byte array causes a memory allocation, and I'm pretty sure you couldn't Pinvoke without a pin.

That is not what pinning does. It doesn't cause a memory allocation at all. It simply tells the GC not to move the memory around until it is unpinned again (in addition to giving you a pointer to the pinned memory).

8 hours ago, BitFlipper wrote

That is not what pinning does. It doesn't cause a memory allocation at all. It simply tells the GC not to move the memory around until it is unpinned again (in addition to giving you a pointer to the pinned memory).

It's a while since I played with the .NET GC, but last I heard pinned objects had their own heap to stay out of the way of the GC. When an object gets pinned it automatically gets relocated to the pin-heap, and when it gets unpinned it gets relocated to the unpinned heap in order to make life easier for the GC during a collect (because GC used to use split-heap collection and so nothing can live on the old heap after the collect).

But rather than trying to pick apart my specific suggestions of examples of possible hidden variables, why not concede that the existence of a hidden variable screwing over your timings is a possibility? No matter how much you want the filesystem to have some perversity that causes buffers of more than 32MB to be slower, it simply isn't the case. Your slowdown for large buffers is almost certainly caused somewhere in user-mode.

5 hours ago, evildictaitor wrote

*snip*

It's a while since I played with the .NET GC, but last I heard pinned objects had their own heap to stay out of the way of the GC. When an object gets pinned it automatically gets relocated to the pin-heap, and when it gets unpinned it gets relocated to the unpinned heap in order to make life easier for the GC during a collect (because GC used to use split-heap collection and so nothing can live on the old heap after the collect).

I'm not sure where you got that info from but it is 100% incorrect. Nothing gets moved around when pinning an object. From here:

Pinning temporarily locks the data in its current memory location, thus keeping it from being relocated by the common language runtime's garbage collector. The marshaler pins data to reduce the overhead of copying and enhance performance. The type of the data determines whether it is copied or pinned during the marshaling process.

The types of data that can be pinned is explained here. It specifically says that one-dimentional arrays of blittable types are also considered blittable. The byte buffer I'm using is therefore considered blittable and hence there is zero copying at all.

But rather than trying to pick apart my specific suggestions of examples of possible hidden variables, why not concede that the existence of a hidden variable screwing over your timings is a possibility? No matter how much you want the filesystem to have some perversity that causes buffers of more than 32MB to be slower, it simply isn't the case. Your slowdown for large buffers is almost certainly caused somewhere in user-mode.

If you understand what is happening in the WriteFast method in the sample code above, you would see that what you are saying doesn't make much sense. It passes in the exact same large buffer, but only asks to copy part of it at a time. In theory that should be slower (more calls), yet it is almost 10 times faster. If there is a bug in the sample code, please point it out.

1 hour ago, BitFlipper wrote

I'm not sure where you got that info from but it is 100% incorrect. Nothing gets moved around when pinning an object. From here:

I'm not sure why you've got all defensive and decided to make this a big issue - but a quick test on x86 shows that that's simply not the case. Pinning an object changes where it is and hence must involve a copy.

Here's my test program:

        [DllImport("kernel32.dll")]        static extern bool IsBadReadPtr(IntPtr ip, int cbSize);        static unsafe void Main(string[] args)        {            byte[] b = new byte[40];            int j;            int* jp = &j;            for (int i = 0; i < b.Length; i++)                b[i] = (byte)i;            Console.WriteLine("stack layout:");            for (int i = 0; i < 40; i++)            {                Console.Write("{0:x8}", jp[i]);                if (!IsBadReadPtr(new IntPtr(jp[i]), b.Length))                {                    Console.Write("->");                    for(int q = 0; q < b.Length / 4; q++)                        Console.Write(" {0:x8}", ((int*)jp[i])[q]);                }                Console.WriteLine();            }            Console.WriteLine("buffer ptr:");            fixed (byte* pb = b)            {                Console.WriteLine("Ptr: {0:x8}", new IntPtr(pb));            }            Console.ReadLine();        }

Here's it's output:

stack layout:00000000022856e0-> 6b674980 00000028 03020100 07060504 0b0a0908 0f0e0d0c 13121110 17161514 1b1a1918 1f1e1d1c02285614-> 6b626c64 00000000 6b66f9e8 80000000 6b66f9e8 0000000d 00740073 00630061 0020006b 0061006c00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000004d1a858-> 6c1e8dc0 0000b020 00000001 05d9eaa4 00000000 00000000 00000000 00000008 00000000 04d1a88005d9e8a0-> 05d9e8f0 6c23317c 05d9eaa4 c3ba250c 05d9ead0 05d9e940 00000000 00000001 05d9eaa4 04d1a85805d9e884-> 05d9e900 6c154227 05d9e950 00000000 05d9e920 00000000 0017c798 05d9e8f0 6c23317c 05d9eaa46c1221bb-> 83144d8b 077404f9 7408f983 d911eb0a 458bf85d dd09ebf8 458bf85d fc558bf8 0014c2c9 7883c18b00601f68-> 6b0b0002 00200006 0017c798 ffd004cc 2b0f0003 00000004 00000000 0017b0b8 00000000 0000000005d9e8bc-> 00000001 05d9eaa4 04d1a858 00000000 00000000 00000000 00000000 00000000 6c1311d5 05d9e8a005d9e900-> 05d9ea3c 6c1543c4 05d9e950 00000000 05d9e920 00000000 0017c798 00000000 05d9e950 022856146c154227-> 89c84589 7d89cc55 e0558be0 8964128b 00000015 fc45c700 fffffffe 3947ff33 850fd45d 001f940a05d9e950-> 00601218 00632870 00000002 00632870 00000002 00000000 00000000 0063286f 00000003 0063286d0000000005d9e920-> 05d9e950 02285614 05d9e950 05d9e944 6c155c3b 05d9e950 05d9eb08 05d9ea3c 6c154302 00000030000000000017c798-> 185ca3e9 00005f00 00601f68 00000000 fa5b3be8 00005e6b 006020a8 00000000 fa5b2be8 00005e6b05d9e8f0-> 05d9ebc4 6c230db8 aa768e6c 00000000 05d9ea3c 6c1543c4 05d9e950 00000000 05d9e920 000000006c23317c-> 8b55ff8b 10ec83ec 6a575653 4000be05 e8560000 ffeee7ef 8b105d8b c085087d 75ff2774 c4b3ff0c05d9eaa4-> 6c124268 05d9eef0 05d9eafc 00000001 04d1a858 00000000 04d1a858 04d1a858 05d9ead4 02285614c3ba250c05d9ead0-> 00000000 00601f68 6c1e0001 05d9ec10 05d9ef34 00000000 00000000 00000000 00000000 0000000005d9e940-> 6c154302 00000030 05d9ea28 6c154312 00601218 00632870 00000002 00632870 00000002 00000000000000000000000105d9eaa4-> 6c124268 05d9eef0 05d9eafc 00000001 04d1a858 00000000 04d1a858 04d1a858 05d9ead4 0228561404d1a858-> 6c1e8dc0 0000b020 00000001 05d9eaa4 00000000 00000000 00000000 00000008 00000000 04d1a8800000000000000000buffer ptr:Ptr: 36198120

Looking at that output I can clearly see the managed byte[] b has pointer 022856e0 on the heap - it begins with a DWORD which is the GC reserved DWORD followed by a DWORD which is the size of the array (0x28 = 40 dec) followed by the data in the array in little-endian.

I can see later in that function when I fix the array it suddenly has address 0x36198120, which is completely different.

EDIT: FFS when will C9 not suck at posting code!?

The reason the address at the end looks different is because there is a bug in your code. For whatever reason, the line...

Console.WriteLine("Ptr: {0:x8}", new IntPtr(pb));

...shows the value in decimal, not hex. It looks like IntPtr doesn't like to have itself converted to hex.Try it like this:

Console.WriteLine("Ptr: {0:x8}", (long)(pb);

Now you will see that the address at the end is always 8 bytes larger than the address of the array.

BTW, I'm not trying to be defensive. You are saying something that I know is not true. The MSDN documentation backs me up on this, and now your own test does as well. I'm not sure how I am supposed to react when you are saying that in my sample code I'm seeing specific results because of the way the GC works, when in fact I know that what you are saying is incorrect. I want to find out what is the cause of the specific performance issue I'm noticing on my system, not argue about incorrect GC assumptions.

To those that are not able to reproduce this... I'm guessing it has something to do with cache size. I have 8GB memory, and Task Manager says Windows is using 4.5GB as cache. Which means the 1GB file can easily fit into the cache. The fact that nobody else has seen less than 1 sec results tells me your available cache isn't large enough to hold the 1G file. Try it on a 500MB file maybe.