Excessive memory usage while working with X509Certificate (Linux, NET 5 and NET Core 3.1).

[serpop]

Description

We found an excessive memory usage in Linux containers. Every time we make a call which goes all way down to OpenSSL process working set grows up. The chart below shows working set and managed heap size for the test application. As you can see working set grows up to 1.8 GB and then stabilizes at this point. At the same time the managed heap size remains very small.

Test application is available here:
https://github.com/serpop/CertMemLeak

Configuration

Linux container based on mcr.microsoft.com/dotnet/aspnet:5.0-buster-slim image (NET 5, x64).

OR

Linux container based on mcr.microsoft.com/dotnet/core/aspnet:3.1-buster-slim image (NET Core 3.1, x64)

Host: any compatible.

Regression?

The problem doesn't exist on Windows.

[dotnet-issue-labeler]

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[ghost]

Tagging subscribers to this area: @bartonjs, @vcsjones, @krwq, @GrabYourPitchforks
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Description

We found an excessive memory usage in Linux containers. Every time we make a call which goes all way down to OpenSSL process working set grows up. The chart below shows working set and managed heap size for the test application. As you can see working set grows up to 1.8 GB and then stabilizes at this point. At the same time the managed heap size remains very small.

Test application is available here:
https://github.com/serpop/CertMemLeak

Configuration

Linux container based on mcr.microsoft.com/dotnet/aspnet:5.0-buster-slim image (NET 5, x64).

OR

Linux container based on mcr.microsoft.com/dotnet/core/aspnet:3.1-buster-slim image (NET Core 3.1, x64)

Host: any compatible.

Regression?

The problem doesn't exist on Windows.

Author:	serpop
Assignees:	-
Labels:	area-System.Security, untriaged
Milestone:	-

[bartonjs]

Since this is reported against 3.1 and 5, and 6 is already locking down, I've assigned it to 7.

Since it goes stable I don't think there's a leak, per se, but we might be throwing things off to the finalizer queue and it is deciding to not run since there's still more memory available. Or it's something about OpenSSL's memory management.

[vcsjones]

Linux container based on mcr.microsoft.com/dotnet/aspnet:5.0-buster-slim image (NET 5, x64).

Would it be possible for you to try with mcr.microsoft.com/dotnet/aspnet:6.0.0-preview.6-bullseye-slim? That would help us narrow down if the issue is still present in .NET 6 or not.

[serpop]

Linux container based on mcr.microsoft.com/dotnet/aspnet:5.0-buster-slim image (NET 5, x64).

Would it be possible for you to try with mcr.microsoft.com/dotnet/aspnet:6.0.0-preview.6-bullseye-slim? That would help us narrow down if the issue is still present in .NET 6 or not.

Tested it with NET 6, the behavior is exactly the same.

[bartonjs]

Tested it with NET 6, the behavior is exactly the same.

Thanks for checking and letting us know.

[bartonjs]

Using this loop

            using (X509Certificate2 cert = new X509Certificate2(path))
            {
                for (int iter = 0; iter < Iterations; iter++)
                {
                    if ((iter & mask) == 0 || iter == 1)
                    {
                        Console.Write($"At iteration {iter}: ");
                        ShowMem(ref lastMem);
                    }

                    X509Chain chain = new X509Chain();
                    chain.ChainPolicy.RevocationFlag = X509RevocationFlag.ExcludeRoot;
                    chain.ChainPolicy.RevocationMode = X509RevocationMode.NoCheck;
                    chain.ChainPolicy.VerificationFlags = X509VerificationFlags.NoFlag;

                    bool result = chain.Build(cert);
                    chain.Dispose();

                    if (!result)
                    {
                        throw new InvalidOperationException();
                    }
                }
            }

tracking WorkingSet64 shows

At iteration 0: +8,306,688
  Finalizations pending: 2
At iteration 1: +9,052,160
  Finalizations pending: 2
At iteration 1024: +2,928,640
  Finalizations pending: 2,227
At iteration 2048: 0
  Finalizations pending: 2,227
At iteration 3072: +507,904
  Finalizations pending: 6,891
At iteration 4096: 0
  Finalizations pending: 6,891
At iteration 5120: +270,336
  Finalizations pending: 6,078
At iteration 6144: 0
  Finalizations pending: 6,078
At iteration 7168: 0
  Finalizations pending: 6,087
At iteration 8192: +262,144
  Finalizations pending: 6,087
At iteration 9216: +270,336
  Finalizations pending: 6,099
At iteration 10240: 0
  Finalizations pending: 6,099
At iteration 11264: +536,576
  Finalizations pending: 6,087
At iteration 12288: 0
  Finalizations pending: 6,087
At iteration 13312: +57,344
  Finalizations pending: 6,099
At iteration 14336: 0
  Finalizations pending: 6,099
At iteration 15360: 0
  Finalizations pending: 6,105
At iteration 16384: 0
  Finalizations pending: 6,105
At iteration 17408: 0
  Finalizations pending: 6,087
At iteration 18432: +20,480
  Finalizations pending: 6,087
At iteration 19456: 0
  Finalizations pending: 6,099
At iteration 20480: 0
  Finalizations pending: 6,099
At iteration 21504: 0
  Finalizations pending: 6,105
At iteration 22528: 0
  Finalizations pending: 6,105
At iteration 23552: 0
  Finalizations pending: 6,090
At iteration 24576: 0
  Finalizations pending: 6,090
At iteration 25600: +4,096
  Finalizations pending: 6,099
At iteration 26624: 0
  Finalizations pending: 6,099
At iteration 27648: 0
  Finalizations pending: 6,102
At iteration 28672: 0
  Finalizations pending: 6,102
At iteration 29696: 0
  Finalizations pending: 6,108
Finished: 0
  Finalizations pending: 6,108
After GC: +167,936
  Finalizations pending: 2
Total change in memory: +22,384,640

Indicating that things eventually stabilize (matching the chart above, but at much lower numbers).

We get a big number at 0 because that woke up almost all of the .NET crypto stack, including waking up OpenSSL. We get another big number at 1 because the first chain build woke up the X509Chain system and our caches for building chains.

Since we're effectively done growing by 4096, let's zoom in.

At iteration 0: +8,290,304
  Finalizations pending: 2
At iteration 1: +9,117,696
  Finalizations pending: 2
At iteration 256: +1,593,344
  Finalizations pending: 2
At iteration 512: +786,432
  Finalizations pending: 2
At iteration 768: +536,576
  Finalizations pending: 2,155
At iteration 1024: 0
  Finalizations pending: 2,155
At iteration 1280: 0
  Finalizations pending: 2,155
At iteration 1536: 0
  Finalizations pending: 2,155
At iteration 1792: 0
  Finalizations pending: 2,155
At iteration 2048: 0
  Finalizations pending: 2,155
At iteration 2304: 0
  Finalizations pending: 2,155
At iteration 2560: 0
  Finalizations pending: 2,155
At iteration 2816: 0
  Finalizations pending: 2,155
At iteration 3072: +512,000
  Finalizations pending: 6,717
At iteration 3328: 0
  Finalizations pending: 6,717
At iteration 3584: 0
  Finalizations pending: 6,717
At iteration 3840: 0
  Finalizations pending: 6,717
Finished: 0
  Finalizations pending: 6,717
After GC: 0
  Finalizations pending: 2
Total change in memory: +20,836,352

So there's definitely some finalization going on, which seems to happen in fits and spurts. While some could be caused by general background operations, it's probably something we're doing.

Looking at our loop again, we call chain.Build, and then move on. It turns out that chain.Build populates the chain.ChainElements collection, and when it does so it creates new certificate objects for each element. Disposing the chain is goodness, but it doesn't free those elements, since you could have already saved a reference to any of them.

So let's change our loop.

            using (X509Certificate2 cert = new X509Certificate2(path))
            {
                for (int iter = 0; iter < Iterations; iter++)
                {
                    if ((iter & mask) == 0 || iter == 1)
                    {
                        Console.Write($"At iteration {iter}: ");
                        ShowMem(ref lastMem);
                    }

                    X509Chain chain = new X509Chain();
                    chain.ChainPolicy.RevocationFlag = X509RevocationFlag.ExcludeRoot;
                    chain.ChainPolicy.RevocationMode = X509RevocationMode.NoCheck;
                    chain.ChainPolicy.VerificationFlags = X509VerificationFlags.NoFlag;

                    bool result = chain.Build(cert);

                    if (dispose)
                    {
                        foreach (X509ChainElement element in chain.ChainElements)
                        {
                            element.Certificate.Dispose();
                        }
                    }

                    if (!result)
                    {
                        throw new InvalidOperationException();
                    }

                    chain.Dispose();
                }
            }

And run the test again with dispose=true

At iteration 0: +8,294,400
  Finalizations pending: 2
At iteration 1: +9,187,328
  Finalizations pending: 2
At iteration 256: +1,843,200
  Finalizations pending: 2
At iteration 512: +540,672
  Finalizations pending: 2
At iteration 768: +536,576
  Finalizations pending: 4
At iteration 1024: 0
  Finalizations pending: 4
At iteration 1280: 0
  Finalizations pending: 4
At iteration 1536: 0
  Finalizations pending: 4
At iteration 1792: 0
  Finalizations pending: 4
At iteration 2048: 0
  Finalizations pending: 4
At iteration 2304: 0
  Finalizations pending: 4
At iteration 2560: 0
  Finalizations pending: 4
At iteration 2816: 0
  Finalizations pending: 4
At iteration 3072: +512,000
  Finalizations pending: 0
At iteration 3328: 0
  Finalizations pending: 0
At iteration 3584: 0
  Finalizations pending: 0
At iteration 3840: 0
  Finalizations pending: 0
Finished: 0
  Finalizations pending: 0
After GC: 0
  Finalizations pending: 2
Total change in memory: +20,914,176

That didn't significantly change our total memory profile, but does change the number of objects that were hanging around.

So, what does explain your graph, then?

Well, let's run the app with the environment variable DOTNET_gcServer=1

 $ DOTNET_gcServer=1 ./test
Checking with disposing=False
At iteration 0: +8,192,000
At iteration 1: +9,441,280
At iteration 512: +1,892,352
At iteration 1024: +1,048,576
At iteration 1536: +1,081,344
At iteration 2048: +811,008
At iteration 2560: +1,077,248
At iteration 3072: +1,392,640
At iteration 3584: +1,077,248
At iteration 4096: +1,081,344
At iteration 4608: +1,081,344
At iteration 5120: +1,351,680
At iteration 5632: +1,081,344
At iteration 6144: +1,081,344
At iteration 6656: +1,081,344
At iteration 7168: +1,081,344
At iteration 7680: +1,327,104
At iteration 8192: +1,081,344
At iteration 8704: +1,081,344
At iteration 9216: +1,081,344
At iteration 9728: +946,176
At iteration 10240: +1,110,016
At iteration 10752: +1,351,680
At iteration 11264: +1,081,344
At iteration 11776: +1,081,344
At iteration 12288: +1,081,344
At iteration 12800: +1,081,344
At iteration 13312: +1,081,344
At iteration 13824: +1,081,344
At iteration 14336: +270,336
Finished: 0
After GC: 0
Total change in memory: +48,590,848

and with disposing

$ DOTNET_gcServer=1 ./test 1
Checking with disposing=True
At iteration 0: +8,196,096
At iteration 1: +9,474,048
At iteration 512: +2,134,016
At iteration 1024: +815,104
At iteration 1536: +1,384,448
At iteration 2048: +987,136
At iteration 2560: +1,077,248
At iteration 3072: +811,008
At iteration 3584: +1,167,360
At iteration 4096: +1,077,248
At iteration 4608: +1,351,680
At iteration 5120: +1,081,344
At iteration 5632: +1,081,344
At iteration 6144: +1,351,680
At iteration 6656: +1,081,344
At iteration 7168: +1,081,344
At iteration 7680: +1,191,936
At iteration 8192: +1,081,344
At iteration 8704: +1,081,344
At iteration 9216: +1,081,344
At iteration 9728: +1,081,344
At iteration 10240: +1,384,448
At iteration 10752: +1,081,344
At iteration 11264: +1,081,344
At iteration 11776: +1,081,344
At iteration 12288: +1,081,344
At iteration 12800: +1,351,680
At iteration 13312: +1,351,680
At iteration 13824: +1,081,344
At iteration 14336: +811,008
Finished: 0
After GC: 0
Total change in memory: +49,975,296

Wow, unbounded growth over that range!

So... let's change our loop.

            using (X509Certificate2 cert = new X509Certificate2(path))
            {
                for (int iter = 0; iter < Iterations; iter++)
                {
                    if ((iter & mask) == 0 || iter == 1)
                    {
                        Console.Write($"At iteration {iter}: ");
                        ShowMem(ref lastMem);
                    }

                    byte[] buf = new byte[1024];

                    if (buf[0] != 0)
                    {
                        throw new InvalidOperationException();
                    }
                }
            }

Turns out, that's "unbounded", too:

At iteration 0: +8,249,344
At iteration 1: +1,859,584
At iteration 512: +602,112
At iteration 1024: +540,672
At iteration 1536: +540,672
At iteration 2048: +536,576
At iteration 2560: +540,672
At iteration 3072: +536,576
At iteration 3584: +540,672
At iteration 4096: +540,672
At iteration 4608: +536,576
At iteration 5120: +811,008
At iteration 5632: +540,672
At iteration 6144: +536,576
At iteration 6656: +540,672
At iteration 7168: +540,672
At iteration 7680: +540,672
At iteration 8192: +540,672
At iteration 8704: +540,672
At iteration 9216: +540,672
At iteration 9728: +540,672
At iteration 10240: +540,672
At iteration 10752: +540,672
At iteration 11264: +811,008
At iteration 11776: +540,672
At iteration 12288: +540,672
At iteration 12800: +540,672
At iteration 13312: +540,672
At iteration 13824: +540,672
At iteration 14336: +540,672
Finished: 0
After GC: +331,776
Total change in memory: +26,165,248

Server GC is pretty lazy. As long as it can find more memory it doesn't like to clean things up.

The problem as described can be attributed mostly to running with server GC. The application disposing the certificates that come back from the chain build will help make the native portion of memory more predictable (and reduce finalization stalls). There's probably room for improvement in the X509 stack to reduce the use of temporary buffers; but it's not something that we'd keep a major tracking issue on.