The Mysterious Lost Memory Which Belongs To No Process

Sometimes you experience sluggish performance for no apparent reason. That are usually the harder issues since it is not clear what is causing it. Things will become a bit messy but I will give some advice how you can pinpoint sluggish system performance with basic OS tools and some advanced tools which are rarely used in public.

The Symptom

A server machine did become very slow once the in use memory reported by task manager reached ca. 70% (e.g. 90/128 GB) of the available memory. There was still plenty of free memory but when a new application was started it was very slow and the C drive was very busy. A first suspicion was that the application dlls were loaded from disk again which did not really make sense since the application was started many times before. Everything should be in the file system cache since a long time.

 

First Observations

If you are on a Windows server and you want to view the disk IO graphs in Task Manager like on your normal Windows (8 and later) you need to enable the Disk IO graphs explicitly with

C>diskperf -y 

A closer look on disk IO in the task manager showed that the drive hosting the page file was from the very beginning having writes to the page file at ca. 90 MB/s. We certainly did page out a lot of data but why was this happening when only 50/128 GB were in use? 

What was going on here?

Advanced Tools

To see where the memory is going to we can use RAMMap from Sysinternals. It can show system wide memory consumption of processes and the kernel as well. This is the only tool which can show also the lost memory because if it is allocated it must belong at least to the kernel which is also shown.

Here we find that the modified memory is coming form Shareable memory. Shareable memory is memory which is not backed by a physical file. The only possibility I am aware of to create such memory is to create a file mapping with no file name which creates a page file backed shared memory section. The suspicion here is that we have lost memory to page file backed sections which did land for some reason in the Modified list which is the sign for the kernel to write them back to their backing store. In this case it is the page file which nicely supports our theory because we have high page file write rates.

That is all nice but the question is which process is doing this? When I did look with Task manager through the processes I found no process with a very high Commit or Working set memory. If nothing helps try to reproduce the problem in isolation so you can better analyze it.

Create A Repro

The easiest repro is to create a file mapping, which is mapped, written to and then unmapped but the file mapping object is not closed.

In C#  this is a few lines of code:

        private unsafe void Allocate()
        {
            // CreateFileMapping
            var file = MemoryMappedFile.CreateNew(null, BytesToAlloc);

            Mappings.Add(file); // root object 

            var accessor = file.CreateViewAccessor(); // MapViewOfFile

            var handle = accessor.SafeMemoryMappedViewHandle;
            byte* ptr = null;
            handle.AcquirePointer(ref ptr);
            var pLong = (long*)ptr;

            Random rand = new Random();
            long nr;
            // fill page file allocated memory with random data which cannot be compressed
            // by Windows 10 memory compression to see the real impact of memory allocation.
            for (long i = 0; i < BytesToAlloc / 8L; i++)
            {
                nr = (long)((ulong)(rand.Next() << 32) | (ulong)rand.Next());
                *(pLong + i) = nr;
            }
            TotalAllocated += BytesToAlloc; 

            handle.ReleasePointer();
            accessor.Dispose();        // UnmapViewOfFile
            Console.WriteLine($"Modifed: {ModifiedBytes:N0} bytes");
        }

The full source code can be found here https://1drv.ms/f/s!AhcFq7XO98yJgfZdGGK8ahaOrVnggg. With this sample application we can indeed nicely reproduce the issue that every time the memory is unmapped the kernel takes our mapped memory from the process working set away and puts it into the modified byte list.

Now depending on the OS different things happen. On Server 2008-2016 the memory is immediately written to the page file. On Server 2016 you could enable memory compression also if you wish (see https://aloiskraus.wordpress.com/2016/10/09/how-buffered-io-can-ruin-performance/). On Windows 10 machines on the other hand the memory is compressed by default and kept in memory which is much later written to disk once physical memory gets low. Since we have reproduced the symptom we can search for ways how to find the offending process more easily.

Lets look in task manager when the process has eaten up all my physical memory:

Nope not a single number which points towards high memory consumption. That is not surprising because the memory was already unmapped and no longer belongs to any process. But our process still has a file mapping handle open which is reason enough for the kernel to keep the data alive. Lets take a dump and look for file mapping objects. In kernel lingo these are called Section objects.

Windbg – Dump Section Objects

To dump all file mappings and their size we can use the !handle command. The first argument 0 means to dump all handles, 0xf to dump all handle information and limit the output to file mapping (Section) objects only.

0:000>!handle 0 f Section

…

Handle 0000000000000734
  Type             Section
  Attributes       0
  GrantedAccess    0xf0007:
         Delete,ReadControl,WriteDac,WriteOwner
         Query,MapWrite,MapRead
  HandleCount      2
  PointerCount     65537
  Name             <none>
  Object specific information
    Section base address 0
    Section attributes 0x8000000
    Section max size 0x40000000
24 handles of type Section

We can sum up all open file mapping objects manually or use a pretty unknown Windbg extension called mex (see https://www.microsoft.com/en-us/download/details.aspx?id=53304). Mex is a Windbg extension written in managed code which is the reason for its name (managed extension). It is used by support engineers within MS quite a lot because it contains a lot of functionality in a single dll, which makes deployment pretty easy. It can even decompile C# code with some help from ILSpy from a memory dump which is pretty useful. When you have downloaded the zip file put the dll of the right bitness into the Windbg\winext folder where Windbg stores its extensions so you can load it simply by its name.

Now we can make the tedious summing the sizes of all shared memory sections a pretty one liner:

0:000>.load mex

0:000> !sum !cut -c 22-35 !grep -r "size" !handle 0 f Section
0x10000
0x1000
0x11000
0x40000000
0x40000000
0x40000000
0x40000000
0x2000
0x40000000
0x40000000
0x40000000
0x40000000
0x40000000
0x40000000
0x40000000
0x40000000
0x1000
0x1
0x40000000
0x40000000
0x40000000
0x40000000
0x40000000
0x40000000
Total = 0n19327504385 (0x480025001)

The !sum command is pretty self explaining. !cut will cut from each line the number by a fixed offset and length of all lines which are filtered for the lines which contain the size with !grep from the !handle command. This reminds me of old linux days where my command lines looked pretty similar like the Windbg commands above.

From the dump it is clear that we have 19 GB of file mappings created.  But Task Manager is not showing anything. Even the trustworthy VMMap tool

is not showing anything related to 19 GB of allocated shared memory. If you suspect only one process which is responsible for that you can use Windbg and check out if the process has a file mapping leak. If this is a problem you did either forget to close the file mapping, or someone was unmapping the shared memory too early.

You can set breakpoints on Windows 8+ at kernelbase or on earlier Windows version at kernel32 where the methods are actually defined. Windows 8 introduced API sets (https://msdn.microsoft.com/en-us/library/windows/desktop/hh802935(v=vs.85).aspx) which allows the OS guys to split formerly huge dlls into smaller parts where the implementation might be in a different dll. You need to be careful to set the breakpoints at the right location depending on the OS you are currently working on.

0:000> bp kernelbase!CreateFileMappingW
0:000> bp kernelbase!UnmapViewOfFile
0:000> bp kernelbase!UnmapViewOfFileEx

When you have hit a breakpoint and you are running managed code load the sos  dll get the call stacks

.loadby sos clr

Then it is easy to find e.g. who created the file mappings

KERNELBASE!CreateFileMappingW:
00007ffe`06280f20 4883ec48        sub     rsp,48h
0:000> !ClrStack
OS Thread Id: 0x59f8 (0)
        Child SP               IP Call Site
000000aa64d3e720 00007ffe06280f20 [InlinedCallFrame: 000000aa64d3e720] Microsoft.Win32.UnsafeNativeMethods.CreateFileMapping(Microsoft.Win32.SafeHandles.SafeFileHandle, SECURITY_ATTRIBUTES, Int32, Int32, Int32, System.String)
000000aa64d3e720 00007ffdd724c3e8 [InlinedCallFrame: 000000aa64d3e720] Microsoft.Win32.UnsafeNativeMethods.CreateFileMapping(Microsoft.Win32.SafeHandles.SafeFileHandle, SECURITY_ATTRIBUTES, Int32, Int32, Int32, System.String)
000000aa64d3e6e0 00007ffdd724c3e8 DomainBoundILStubClass.IL_STUB_PInvoke(Microsoft.Win32.SafeHandles.SafeFileHandle, SECURITY_ATTRIBUTES, Int32, Int32, Int32, System.String)
000000aa64d3e800 00007ffdd723014b System.IO.MemoryMappedFiles.MemoryMappedFile.CreateCore(Microsoft.Win32.SafeHandles.SafeFileHandle, System.String, System.IO.HandleInheritability, System.IO.MemoryMappedFiles.MemoryMappedFileSecurity, System.IO.MemoryMappedFiles.MemoryMappedFileAccess, System.IO.MemoryMappedFiles.MemoryMappedFileOptions, Int64)
000000aa64d3e890 00007ffdd72169af System.IO.MemoryMappedFiles.MemoryMappedFile.CreateNew(System.String, Int64, System.IO.MemoryMappedFiles.MemoryMappedFileAccess, System.IO.MemoryMappedFiles.MemoryMappedFileOptions, System.IO.MemoryMappedFiles.MemoryMappedFileSecurity, System.IO.HandleInheritability)
000000aa64d3e910 00007ffdd7436bd0 System.IO.MemoryMappedFiles.MemoryMappedFile.CreateNew(System.String, Int64)
000000aa64d3e950 00007ffd8c1c08a0 FileMappingModifiedBytes.PageFileAllocator.Allocate() [\FileMappingModifiedBytes\FileMappingModifiedBytes\PageFileAllocator.cs @ 60]
000000aa64d3ea50 00007ffd8c1c0736 FileMappingModifiedBytes.PageFileAllocator.SlowlyAllocateUntilOOM() [\FileMappingModifiedBytes\FileMappingModifiedBytes\PageFileAllocator.cs @ 49]
000000aa64d3ead0 00007ffd8c1c05b1 FileMappingModifiedBytes.Program.Main(System.String[]) [\FileMappingModifiedBytes\FileMappingModifiedBytes\Program.cs @ 20]
000000aa64d3ed80 00007ffdeb7b6a53 [GCFrame: 000000aa64d3ed80] 

When the mappings are closed you get also the full call stack

0:000> !ClrStack
OS Thread Id: 0x59f8 (0)
        Child SP               IP Call Site
000000aa64d3e328 00007ffe06285400 [InlinedCallFrame: 000000aa64d3e328] Microsoft.Win32.UnsafeNativeMethods.UnmapViewOfFile(IntPtr)
000000aa64d3e328 00007ffdd724b23e [InlinedCallFrame: 000000aa64d3e328] Microsoft.Win32.UnsafeNativeMethods.UnmapViewOfFile(IntPtr)
000000aa64d3e300 00007ffdd724b23e DomainBoundILStubClass.IL_STUB_PInvoke(IntPtr)
000000aa64d3e3b0 00007ffdd72305a7 Microsoft.Win32.SafeHandles.SafeMemoryMappedViewHandle.ReleaseHandle()
000000aa64d3e548 00007ffdeb7b6a53 [GCFrame: 000000aa64d3e548] 
000000aa64d3e6b8 00007ffdeb7b6a53 [GCFrame: 000000aa64d3e6b8] 
000000aa64d3e778 00007ffdeb7b6a53 [HelperMethodFrame_1OBJ: 000000aa64d3e778] System.Runtime.InteropServices.SafeHandle.InternalDispose()
000000aa64d3e870 00007ffdd72309c1 System.IO.MemoryMappedFiles.MemoryMappedView.Dispose(Boolean)
000000aa64d3e8a0 00007ffdd72307b9 System.IO.MemoryMappedFiles.MemoryMappedViewAccessor.Dispose(Boolean)
000000aa64d3e8e0 00007ffdd723075a System.IO.MemoryMappedFiles.MemoryMappedViewAccessor.Dispose(Boolean)
000000aa64d3e920 00007ffddab2b15a System.IO.UnmanagedMemoryAccessor.Dispose()
000000aa64d3e950 00007ffd8c1c0a48 FileMappingModifiedBytes.PageFileAllocator.Allocate() [\FileMappingModifiedBytes\FileMappingModifiedBytes\PageFileAllocator.cs @ 83]
000000aa64d3ea50 00007ffd8c1c0736 FileMappingModifiedBytes.PageFileAllocator.SlowlyAllocateUntilOOM() [\FileMappingModifiedBytes\FileMappingModifiedBytes\PageFileAllocator.cs @ 49]
000000aa64d3ead0 00007ffd8c1c05b1 FileMappingModifiedBytes.Program.Main(System.String[]) [\FileMappingModifiedBytes\FileMappingModifiedBytes\Program.cs @ 20]
000000aa64d3ed80 00007ffdeb7b6a53 [GCFrame: 000000aa64d3ed80] 

Now we have enough information to come up with a

Theory Of The Problem

This is how we got into that situation

1. Someone creates page file backed shared memory as file mapping.
2. These file mappings are put into the address space of our process with MapViewOfFile.
3. After usage the file mapping is removed from the process working set with UnmapViewOfFile. The file mapping object is closed much later or never.
4. The kernel removes the memory pages from the process working set and moves them to the Modified List.
5. No process owns that memory anymore and the OS is free to page it out to the page file.
6. After the modified pages were written to disk they are put into the standby list, overwriting other previously cached things.

The picture below shows the basic operations the kernel performs.

The end result is that the unmapped memory from our process is written to the page file and at the same time it is put into the file system cache where it replaces older entries. This has far reaching implications. If you unmap the memory but do not close the file mapping object almost at the same time the OS will page the memory out if no other process has the same memory mapped. An innocent file mapping handle leak with large memory mappings can flush your complete file system cache at random times and there is no clear indicator why your or other application suddenly did become much slower.

On Windows 10 Anniversary and later you can see the effect of flushing the file system cache more directly by looking at the task manager when the compressed memory goes up and up but the cached memory stored in the standby list is becoming less and less.

Fresh paged out memory seems to have the highest priority in the file system cache which can overwrite anything else what was inside it. This is also true on server OS where you can check with Rammap that the file system cache was flushed. That explains why we were having so much read activity on the C drive because our file system was flushed and the application dlls needed to be loaded from disk again. If you have a large amount of compressed memory in Windows 10 but not much In use memory the chances are pretty good that you have a file mapping leak somewhere.

How Things Look in ETW

On my Windows 10 Anniversary machine I can nicely see that my paged out memory directly goes into the working set of MemCompression (Memory Compression in Process Explorer, Hacker)  which is not shown by the Windows task manager. At some point it is so huge that it needs to page out memory to my SSD with up to 400 MB/s. While MemCompression (purple) allocates more memory, the standby lists (green) becomes smaller and smaller.

With ETW you can also find out who is responsible for the high modified bytes which are written to the page file with CPU Sampling tracing. That is very useful if you do not know which process is causing it and you cannot interrupt the server processes with memory dumps which might upset people working on the server. Since we know that based on our theory the modified bytes grow when we unmap the data we can simply view all callers of UnmapViewOfFile and follow the callers until you find the call stacks which have the best correlation between the growth of modified bytes and calling UnmapViewOfFile. With our tester application we get a perfect correlation:

The blue bars map perfectly to the rise of modified bytes when we unmap a file section. You can also treat the file mapping issue as handle leak where you can trace with ETW Handle Leak tracing all Section objects which call CreateFileMapping which can be used to verify that no file mappings of this type exist anymore to verify that a fix works as expected. WPA is the perfect tool to visually correlate different metrics to check if there is a dependency. You can come up with a theory what depends on what, graph the different things underneath and then you see a pattern …. or not. Then it is time for the next theory.

The Real Root Cause

Problem solved? Only partially. This only explains sluggish behavior when the machine gets into high memory load which then flushes the file system cache. But there were issues right from the beginning even when there still was plenty of data in the file system cache. Can you spot based on the given data above where the problem is?

.

.

.

We have a nice RAID on the machine but the pageouts were happening only with 100MB/s. That is not the write throughput one would expect from an expensive RAID. What I would expect is something like this

but it was about 5 times slower than usually. Perhaps one disk did fail and the RAID was not scaling properly anymore? Nope. But there was a warning logged somewhere that the RAID battery has failed. The battery in the RAID is there to write all cached data from its internal DRAM cache to the disks in the case of a power failure. What happens if the battery fails? The RAID turns off its internal cache to prevent data loss if there is a power failure. We were therefore running the sever the whole time without a much wanted cache! I am not the one to take credit for finding the disabled RAID cache. It is all about teamwork where everyone looks at different aspects of a problem to (hopefully) find all issues. Thanks for finding that one. You know who you are.

Luckily we do not need to wait to buy a new battery but we can enable the cache even when the battery is not present:

That setting enables the RAID cache regardless of the state of the battery which is exactly what we want. In fact the battery was not broken but opening the server and dusting off the battery did solve the battery issue as well.

It’s The Environment Stupid!

When you write software it is not always the software which causes a change. It still runs on hardware which can change/fail too. You need to monitor not only yourself but also the environment where it is running. If you fail to take that into account you can search for a long time at the wrong or not most significant spot.

Funny side note: I drive by car every day to work. When I did refill my windshield washing fluid yesterday I did notice an unauthorized hardware change:

A marten

seems to have brought into my car his own pet toys to make the place more cozy. Next action: Install some marten repellant to prevent more hardware changes:

Have a nice day and keep your hardware marten safe.

Advertisement