dotnet / runtime

.NET is a cross-platform runtime for cloud, mobile, desktop, and IoT apps.
https://docs.microsoft.com/dotnet/core/
MIT License
15.2k stars 4.72k forks source link

Resident Set Size high despite not using the backing pages #59003

Open luckerby opened 3 years ago

luckerby commented 3 years ago

Description

I'm running a tool that is allocating memory with an optional toggle of touching a percentage of that memory. The purpose is to run various tests on Windows and Linux. When the touch ratio is set to 0 - that is not touch any of the allocated memory - the result is as expected in Windows, but rather strange in Linux. Namely the working set (WS) in Windows is close to 0 (ok) but the resident set size (RSS) in Linux increases by the amount of memory allocated (not ok).

The tool - some small C# code allocating int[] arrays - is in this repo. Touching the memory is done based on the fact that an int always takes 4 bytes (regardless of 32/64 bit platform), that the page size under both Windows and Linux is usually 4 KB and that the contents of an array are stored in contiguous memory; hence writing every 1024th byte makes sure that the whole 4 KB page is brought to the physical RAM.

Configuration

Tested on Ubuntu 20.04.2 LTS under WSL2 on a Windows 10 64-bit. Both .NET 5 and .NET Core 3.1 encounter the same issue.

Regression?

Under .NET Core 3.1 the amount of RSS grows only to approximately 50% of the allocated size, as opposed to .NET 5 where the amount is about 100%.

Data

Using the tool to allocate 200 memory blocks, each of 1 MB. None of that memory is touched. On Windows, everything works as expected - note the roughly 200 MB in the private set (more because of the processes own aside the allocated data) and the extremely small working set:

image

Same application - with the same parameters (200 memory blocks, each of 1 MB) - running under Linux shows a very different picture. Note htop's RES (the equivalent of the resident set size) going up to 230 MB (it starts from ~30 MB, as the application pauses before starting to allocate and I'm able to see the value). image

Here's pmap running against the same process, showing 2 segments that are almost entirely present in RAM, corresponding to the memory allocated (I can identify them because I'm getting a previous pmap output before the allocation starts). Values are in KB: image

An interesting thing happens if the touch ratio is modified. Changing from 0 (no allocated memory is touched) to 10% (touch 10% of the 200 MB in the example above, namely 20 MB) results in the Windows app behaving just as expected (there's ~4 MB in the WS before the allocation starts):

image

Under Linux, with the same parameters, the results are almost correct (RES starts from ~30 MB before the allocation): image

.NET 5 was used for both Windows and Linux runs above.

Analysis

It's as if the CLR decides that if not a single byte of the allocated memory is touched (touch rate is 0), then it will bring it all in the physical RAM

dotnet-issue-labeler[bot] commented 3 years ago

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 commented 3 years ago

Tagging subscribers to this area: @dotnet/gc See info in area-owners.md if you want to be subscribed.

Issue Details
### Description I'm running a tool that is allocating memory with an optional toggle of touching a percentage of that memory. The purpose is to run various tests on Windows and Linux. When the touch ratio is set to 0 - that is not touch any of the allocated memory - the result is as expected in Windows, but rather strange in Linux. Namely the working set (WS) in Windows is close to 0 (ok) but the resident set size (RSS) in Linux increases by the amount of memory allocated (not ok). The tool - some small C# code allocating int[] arrays - is in [this repo](https://github.com/luckerby/AllocMem). Touching the memory is done based on the fact that an int always takes 4 bytes (regardless of 32/64 bit platform), that the page size under both Windows and Linux is usually 4 KB and that the contents of an array are stored in contiguous memory; hence writing every 1024th byte makes sure that the whole 4 KB page is brought to the physical RAM. ### Configuration Tested on Ubuntu 20.04.2 LTS under WSL2 on a Windows 10 64-bit. Both .NET 5 and .NET Core 3.1 encounter the same issue. ### Regression? Under .NET Core 3.1 the amount of RSS grows only to approximately 50% of the allocated size, as opposed to .NET 5 where the amount is about 100%. ### Data Using the tool to allocate 200 memory blocks, each of 1 MB. None of that memory is touched. On Windows, everything works as expected - note the roughly 200 MB in the private set (more because of the processes own aside the allocated data) and the extremely small working set: ![image](https://user-images.githubusercontent.com/31319583/132997611-92f4b78c-ec67-48e4-8ebe-9c4aff1ea576.png) Same application - with the same parameters (200 memory blocks, each of 1 MB) - running under Linux shows a very different picture. Note htop's RES (the equivalent of the resident set size) going up to 230 MB (it starts from ~30 MB, as the application pauses before starting to allocate and I'm able to see the value). ![image](https://user-images.githubusercontent.com/31319583/132997737-0346c131-425b-4145-99d8-718e532116cc.png) Here's pmap running against the same process, showing 2 segments that are almost entirely present in RAM, corresponding to the memory allocated (I can identify them because I'm getting a previous pmap output before the allocation starts). Values are in KB: ![image](https://user-images.githubusercontent.com/31319583/132997923-d8337248-c03f-4dbd-9221-e59e85ca9fe8.png) An interesting thing happens if the touch ratio is modified. Changing from 0 (no allocated memory is touched) to 10% (touch 10% of the 200 MB in the example above, namely 20 MB) results in the Windows app behaving just as expected (there's ~4 MB in the WS before the allocation starts): ![image](https://user-images.githubusercontent.com/31319583/132998019-73a5c550-a152-42f2-8264-a3a1f6061575.png) Under Linux, with the same parameters, the results are almost correct (RES starts from ~30 MB before the allocation): ![image](https://user-images.githubusercontent.com/31319583/132998039-e2cf2f2d-7ea9-4049-b84d-19cd7bf0f309.png) .NET 5 was used for both Windows and Linux runs above. ### Analysis It's as if the CLR decides that if not a single byte of the allocated memory is touched (touch rate is 0), then it will bring it all in the physical RAM
Author: luckerby
Assignees: -
Labels: `tenet-performance`, `area-GC-coreclr`, `untriaged`
Milestone: -
mangod9 commented 3 years ago

@luckerby this feels similar to https://github.com/dotnet/runtime/issues/52592, which have been fixed in 6.0. @PeterSolMS fyi.

luckerby commented 3 years ago

Same outcome running under .NET 6.0.0-preview.7.21377.19 when not touching any of the allocated data:

image

And also the same outcome as in my original post when just touching 10% of the allocated memory:

image

@mangod9 I've looked at the issue you referenced, but I believe there the problem was a high RSS a while after GC was running. In my case, the issue is visible right when allocating the memory. It's also rather weird, as not touching any of the bytes allocated results in all the corresponding memory pages to be brought in RAM, while touching a non-zero percentage does result in only the required memory pages being brought to RAM.

luckerby commented 3 years ago

@jkotas @mangod9 I'm not sure if this is a GC issue though, as the scenario (not touching any allocated memory paradoxically results in all of it in the resident set) should be handled by .NET - in my mind at least - way before GC has a chance to kick in.

mangod9 commented 3 years ago

so from your experiments there seems to be some regression in 5.0 compared to 3.1? Adding @janvorli in case you have seen something related to this.

janvorli commented 3 years ago

@luckerby I have tried to run your tool on my Ubuntu 16.04 physical device with x64 and 24GB of RAM. I am not getting the issue you are reporting. See this gist for the pmap dump at https://gist.github.com/janvorli/3f056a31df68d0b17e12755e661fc219.

I've ran your tool as follows: AllocMem -m 1 -f 0 -x 200

Am I using a wrong command line?

luckerby commented 3 years ago

@janvorli Command line is good, and your output looks just as it should be - most likely the 2 virtual memory areas that the app allocates using the int[] blocks are line 8 and 22 in your pmap dump, which sum up to the 200 MB requested but using almost nothing in terms of RSS. Btw which .NET version are you on? On my side I've tested on another Windows 10 machine that also has Ubuntu 20.04.2 LTS, but I get the same wrong outcome as in my original post. Since we're running the same distro, I can only think it's either due to something that changed between 16.04 and 20.04 for Ubuntu or it has to do with WSL2. I'm not quite sure where the issue comes from: would it be JITted code that explicitly touches all the pages due to some weird "optimization" the JIT compiler decides to do for that edge case? Or is it something at the OS level, where the pages get touched after `mmap?

luckerby commented 3 years ago

@mangod9 I wouldn't say it's a regression, as no page should have made it into physical RAM for the int[] arrrays allocated under the scenario specifying a 0 touch fill rate. It's more like both outcomes are wrong - the fact that .NET Core 3.1 only brings half of that data into RAM as compared to .NET 5 only makes the whole thing more puzzling.

janvorli commented 3 years ago

@luckerby the difference is that I am not running on WSL2, but rather on a device with Linux only installed. I wonder if the WSL2 is responsible for this misbehavior. I don't see anything in our JIT / runtime that would touch the memory. I was testing it with your project untouched and using dotnet publish -r linux-x64 --self-contained to build it and then executing the bin/Debug/net5.0/linux-x64/publish/AllocMem. So it was using .NET 5 as requested in your .csproj. I can see it was using 5.0.2 to be precise.

luckerby commented 3 years ago

@janvorli A quick check using C to simply allocate 400 MB shows that there's nothing being touched by default (below, with the corresponding code further down) under the same WSL2 system. I wonder how could we determine whether it's .NET's fault or not? Try and use LLDB to see the JITted code?

image

#include <stdlib.h>
#include <stdio.h>

#define MB 1024*1024

int main(int argc, char **argv)
{
        int* ptr = (int*)malloc(100 * MB * sizeof(int));
        //for (int i = 0; i < 100 * MB; i+= 4096)
    //  ptr[i] = 0;
    getchar();
}
luckerby commented 3 years ago

I've tested on a different distro on WSL2, and the bug isn't there. The same exact code running on Debian 9 on WSL2 in the top half, Ubuntu 20.04 LTS on WSL2 in the bottom half. Both systems have .NET 5.0.10 (second snapshot below), and the code is set to target .NET 5.

image

Versions: image

luckerby commented 3 years ago

Also tested on SLES 12 on WSL2, but the bug isn't present there as well. Note the process taking up ~20 MB in RAM after the allocations completed (size before allocation started was ~17 MB):

image

janvorli commented 3 years ago

Interesting, so it looks like an Ubuntu 20.04 issue then. It would be interesting to try it in an Ubuntu 20.04 docker container. It might also be related to a kernel version. @luckerby can you please check the kernel version on the distros you've tested?

luckerby commented 3 years ago

@janvorli the result of running inside an Ubuntu container is the same:

image

The Linux kernel versions for the distros I've tested in my previous posts is below. I think you might be on to something here, as the ones where the app behaved as expected were all 4.x.

Ubuntu 20.04 LTS: 5.10.16.3-microsoft-standard-WSL2 Debian 9: 4.4.0-19041-Microsoft SLES 12: 4.4.0-19041-Microsoft

luckerby commented 3 years ago

@janvorli I've spotted some extra weird behavior coming only from Ubuntu on WSL. I've ran the memory leak tool with a higher, non-zero, "touch" parameter, so that a quarter of the 200 MB actually get touched. Here's the outcome captured in a short movie here. Note what happens about 15 seconds after the application has finished its allocation/touch. That process continues gradually until all the allocated memory is eventually brought in the resident set, without the app doing anything (it has already finished its run, and only waiting the hotkey to exit).

janvorli commented 3 years ago

I just got an idea what can be going on here. Linux kernel >= 4.5 supports a new MADV_FREE flag that can be used by madvise to mark memory as no longer needed in the near future. We use that if it is supported. In kernels < 4.5, we use MADV_DONTNEED instead. That has a slightly different behavior. The MADV_FREE can keep the backing physical pages allocated until there is a memory pressure in the system. The MADV_DONTNEED seems to release the physical pages right away (at least that's what I understand from the doc). That could explain why the behavior we are seeing on Ubuntu 20.04 that has kernel 5.10.16.3 differs from the behavior on Debian 9 / SLES 12 that have kernel 4.4.0.

luckerby commented 2 years ago

@janvorli I've updated the WSL kernel to 5.10.60.1-microsoft-standard-WSL2 and I'm getting the same exact behavior as described previously. Using an alternate platform - and running the tool inside a container on top of AKS nodes (kernel 5.4.0-1059-azure) - results in a somewhat similar outcome, although the RSS is slightly smaller than when testing against the WSL distros. This appears to confirm your theory that there's something with the 5.x Linux kernel.

One additional pattern I've spotted in both cases is that the smaller the block used to allocate memory (e.g. 1 MB) the largest unjustified contribution to RAM usage is observed.

Outcome of running as a container in AKS under .NET 5 is below. The first 2 values printed every other line are extracted using System.Diagnostics.Process.GetCurrentProcess(). Whatever heuristic is used by Linux to keep the pages in RAM is interesting, particular since there's nothing being touched by the allocator app and in theory those backing pages shouldn't have been created in the first place (but instead Linux would wait - similar to Windows - until some access is requested that would mandate creating those pages). Note that when allocating the first blocks, there's more that goes into RAM than the size of the block that was just allocated :)

1500.00 MB of initial memory visible
Will allocate 200 blocks of memory each consuming 1 MB, as to hit a limit of 200 MB
List<int[]> will consume 1656 bytes

= process stats: 34.50 MB in RAM / 79.89 MB private / 0 gen2 GCs run so far
Block #0  +1 MB (touched 0%)  [so far total allocated= 1 MB / total touched= 0 MB]
= process stats: 37.78 MB in RAM / 80.96 MB private / 0 gen2 GCs run so far
Block #1  +1 MB (touched 0%)  [so far total allocated= 2 MB / total touched= 0 MB]
= process stats: 39.78 MB in RAM / 82.02 MB private / 0 gen2 GCs run so far
Block #2  +1 MB (touched 0%)  [so far total allocated= 3 MB / total touched= 0 MB]
= process stats: 39.78 MB in RAM / 83.08 MB private / 0 gen2 GCs run so far
Block #3  +1 MB (touched 0%)  [so far total allocated= 4 MB / total touched= 0 MB]
= process stats: 44.10 MB in RAM / 76.09 MB private / 1 gen2 GCs run so far
Block #4  +1 MB (touched 0%)  [so far total allocated= 5 MB / total touched= 0 MB]
= process stats: 44.10 MB in RAM / 77.09 MB private / 1 gen2 GCs run so far
Block #5  +1 MB (touched 0%)  [so far total allocated= 6 MB / total touched= 0 MB]
= process stats: 46.10 MB in RAM / 78.09 MB private / 1 gen2 GCs run so far
Block #6  +1 MB (touched 0%)  [so far total allocated= 7 MB / total touched= 0 MB]
= process stats: 46.10 MB in RAM / 79.19 MB private / 1 gen2 GCs run so far
Block #7  +1 MB (touched 0%)  [so far total allocated= 8 MB / total touched= 0 MB]
= process stats: 48.90 MB in RAM / 88.87 MB private / 1 gen2 GCs run so far
Block #8  +1 MB (touched 0%)  [so far total allocated= 9 MB / total touched= 0 MB]
= process stats: 49.16 MB in RAM / 90.09 MB private / 1 gen2 GCs run so far
Block #9  +1 MB (touched 0%)  [so far total allocated= 10 MB / total touched= 0 MB]
= process stats: 51.16 MB in RAM / 91.16 MB private / 1 gen2 GCs run so far
Block #10  +1 MB (touched 0%)  [so far total allocated= 11 MB / total touched= 0 MB]
= process stats: 51.16 MB in RAM / 92.22 MB private / 1 gen2 GCs run so far
Block #11  +1 MB (touched 0%)  [so far total allocated= 12 MB / total touched= 0 MB]
= process stats: 53.39 MB in RAM / 93.29 MB private / 1 gen2 GCs run so far
Block #12  +1 MB (touched 0%)  [so far total allocated= 13 MB / total touched= 0 MB]
= process stats: 53.39 MB in RAM / 94.29 MB private / 1 gen2 GCs run so far
Block #13  +1 MB (touched 0%)  [so far total allocated= 14 MB / total touched= 0 MB]
= process stats: 55.39 MB in RAM / 95.35 MB private / 1 gen2 GCs run so far
Block #14  +1 MB (touched 0%)  [so far total allocated= 15 MB / total touched= 0 MB]
= process stats: 59.39 MB in RAM / 184.56 MB private / 2 gen2 GCs run so far
Block #15  +1 MB (touched 0%)  [so far total allocated= 16 MB / total touched= 0 MB]
= process stats: 61.39 MB in RAM / 185.56 MB private / 2 gen2 GCs run so far
Block #16  +1 MB (touched 0%)  [so far total allocated= 17 MB / total touched= 0 MB]
= process stats: 61.39 MB in RAM / 186.56 MB private / 2 gen2 GCs run so far
Block #17  +1 MB (touched 0%)  [so far total allocated= 18 MB / total touched= 0 MB]
= process stats: 63.39 MB in RAM / 187.56 MB private / 2 gen2 GCs run so far
Block #18  +1 MB (touched 0%)  [so far total allocated= 19 MB / total touched= 0 MB]
= process stats: 63.39 MB in RAM / 188.56 MB private / 2 gen2 GCs run so far
Block #19  +1 MB (touched 0%)  [so far total allocated= 20 MB / total touched= 0 MB]
= process stats: 65.39 MB in RAM / 189.56 MB private / 2 gen2 GCs run so far
Block #20  +1 MB (touched 0%)  [so far total allocated= 21 MB / total touched= 0 MB]
= process stats: 65.39 MB in RAM / 190.56 MB private / 2 gen2 GCs run so far
Block #21  +1 MB (touched 0%)  [so far total allocated= 22 MB / total touched= 0 MB]
= process stats: 67.91 MB in RAM / 191.98 MB private / 2 gen2 GCs run so far
Block #22  +1 MB (touched 0%)  [so far total allocated= 23 MB / total touched= 0 MB]
= process stats: 67.91 MB in RAM / 192.98 MB private / 2 gen2 GCs run so far
Block #23  +1 MB (touched 0%)  [so far total allocated= 24 MB / total touched= 0 MB]
= process stats: 69.91 MB in RAM / 193.98 MB private / 2 gen2 GCs run so far
Block #24  +1 MB (touched 0%)  [so far total allocated= 25 MB / total touched= 0 MB]
= process stats: 69.91 MB in RAM / 194.98 MB private / 2 gen2 GCs run so far
Block #25  +1 MB (touched 0%)  [so far total allocated= 26 MB / total touched= 0 MB]
= process stats: 72.14 MB in RAM / 196.05 MB private / 2 gen2 GCs run so far
Block #26  +1 MB (touched 0%)  [so far total allocated= 27 MB / total touched= 0 MB]
= process stats: 72.14 MB in RAM / 197.11 MB private / 2 gen2 GCs run so far
Block #27  +1 MB (touched 0%)  [so far total allocated= 28 MB / total touched= 0 MB]
= process stats: 74.14 MB in RAM / 198.17 MB private / 2 gen2 GCs run so far
Block #28  +1 MB (touched 0%)  [so far total allocated= 29 MB / total touched= 0 MB]
= process stats: 74.14 MB in RAM / 199.23 MB private / 2 gen2 GCs run so far
Block #29  +1 MB (touched 0%)  [so far total allocated= 30 MB / total touched= 0 MB]
= process stats: 76.38 MB in RAM / 200.30 MB private / 2 gen2 GCs run so far
Block #30  +1 MB (touched 0%)  [so far total allocated= 31 MB / total touched= 0 MB]
= process stats: 76.38 MB in RAM / 201.36 MB private / 2 gen2 GCs run so far
Block #31  +1 MB (touched 0%)  [so far total allocated= 32 MB / total touched= 0 MB]
= process stats: 78.38 MB in RAM / 202.36 MB private / 2 gen2 GCs run so far
Block #32  +1 MB (touched 0%)  [so far total allocated= 33 MB / total touched= 0 MB]
= process stats: 78.38 MB in RAM / 203.42 MB private / 2 gen2 GCs run so far
Block #33  +1 MB (touched 0%)  [so far total allocated= 34 MB / total touched= 0 MB]
= process stats: 80.38 MB in RAM / 204.48 MB private / 2 gen2 GCs run so far
Block #34  +1 MB (touched 0%)  [so far total allocated= 35 MB / total touched= 0 MB]
= process stats: 80.63 MB in RAM / 205.55 MB private / 2 gen2 GCs run so far
Block #35  +1 MB (touched 0%)  [so far total allocated= 36 MB / total touched= 0 MB]
= process stats: 82.63 MB in RAM / 206.61 MB private / 2 gen2 GCs run so far
Block #36  +1 MB (touched 0%)  [so far total allocated= 37 MB / total touched= 0 MB]
= process stats: 82.89 MB in RAM / 207.94 MB private / 2 gen2 GCs run so far
Block #37  +1 MB (touched 0%)  [so far total allocated= 38 MB / total touched= 0 MB]
= process stats: 84.89 MB in RAM / 209.00 MB private / 2 gen2 GCs run so far
Block #38  +1 MB (touched 0%)  [so far total allocated= 39 MB / total touched= 0 MB]
= process stats: 85.14 MB in RAM / 210.07 MB private / 2 gen2 GCs run so far
Block #39  +1 MB (touched 0%)  [so far total allocated= 40 MB / total touched= 0 MB]
= process stats: 87.14 MB in RAM / 211.13 MB private / 2 gen2 GCs run so far
Block #40  +1 MB (touched 0%)  [so far total allocated= 41 MB / total touched= 0 MB]
= process stats: 87.14 MB in RAM / 212.13 MB private / 2 gen2 GCs run so far
Block #41  +1 MB (touched 0%)  [so far total allocated= 42 MB / total touched= 0 MB]
= process stats: 89.14 MB in RAM / 213.19 MB private / 2 gen2 GCs run so far
Block #42  +1 MB (touched 0%)  [so far total allocated= 43 MB / total touched= 0 MB]
= process stats: 89.14 MB in RAM / 214.25 MB private / 2 gen2 GCs run so far
Block #43  +1 MB (touched 0%)  [so far total allocated= 44 MB / total touched= 0 MB]
= process stats: 91.39 MB in RAM / 215.32 MB private / 2 gen2 GCs run so far
Block #44  +1 MB (touched 0%)  [so far total allocated= 45 MB / total touched= 0 MB]
= process stats: 91.39 MB in RAM / 216.38 MB private / 2 gen2 GCs run so far
Block #45  +1 MB (touched 0%)  [so far total allocated= 46 MB / total touched= 0 MB]
= process stats: 93.39 MB in RAM / 217.44 MB private / 2 gen2 GCs run so far
Block #46  +1 MB (touched 0%)  [so far total allocated= 47 MB / total touched= 0 MB]
= process stats: 93.39 MB in RAM / 218.50 MB private / 2 gen2 GCs run so far
Block #47  +1 MB (touched 0%)  [so far total allocated= 48 MB / total touched= 0 MB]
= process stats: 95.71 MB in RAM / 219.55 MB private / 2 gen2 GCs run so far
Block #48  +1 MB (touched 0%)  [so far total allocated= 49 MB / total touched= 0 MB]
= process stats: 95.71 MB in RAM / 220.62 MB private / 2 gen2 GCs run so far
Block #49  +1 MB (touched 0%)  [so far total allocated= 50 MB / total touched= 0 MB]
= process stats: 97.71 MB in RAM / 221.62 MB private / 2 gen2 GCs run so far
Block #50  +1 MB (touched 0%)  [so far total allocated= 51 MB / total touched= 0 MB]
= process stats: 97.71 MB in RAM / 222.68 MB private / 2 gen2 GCs run so far
Block #51  +1 MB (touched 0%)  [so far total allocated= 52 MB / total touched= 0 MB]
= process stats: 99.71 MB in RAM / 223.74 MB private / 2 gen2 GCs run so far
Block #52  +1 MB (touched 0%)  [so far total allocated= 53 MB / total touched= 0 MB]
= process stats: 99.96 MB in RAM / 224.80 MB private / 2 gen2 GCs run so far
Block #53  +1 MB (touched 0%)  [so far total allocated= 54 MB / total touched= 0 MB]
= process stats: 101.96 MB in RAM / 225.87 MB private / 2 gen2 GCs run so far
Block #54  +1 MB (touched 0%)  [so far total allocated= 55 MB / total touched= 0 MB]
= process stats: 101.96 MB in RAM / 226.93 MB private / 2 gen2 GCs run so far
Block #55  +1 MB (touched 0%)  [so far total allocated= 56 MB / total touched= 0 MB]
= process stats: 103.96 MB in RAM / 227.93 MB private / 2 gen2 GCs run so far
Block #56  +1 MB (touched 0%)  [so far total allocated= 57 MB / total touched= 0 MB]
= process stats: 103.96 MB in RAM / 228.99 MB private / 2 gen2 GCs run so far
Block #57  +1 MB (touched 0%)  [so far total allocated= 58 MB / total touched= 0 MB]
= process stats: 106.21 MB in RAM / 230.05 MB private / 2 gen2 GCs run so far
Block #58  +1 MB (touched 0%)  [so far total allocated= 59 MB / total touched= 0 MB]
= process stats: 106.21 MB in RAM / 231.12 MB private / 2 gen2 GCs run so far
Block #59  +1 MB (touched 0%)  [so far total allocated= 60 MB / total touched= 0 MB]
= process stats: 108.21 MB in RAM / 232.18 MB private / 2 gen2 GCs run so far
Block #60  +1 MB (touched 0%)  [so far total allocated= 61 MB / total touched= 0 MB]
= process stats: 108.21 MB in RAM / 233.24 MB private / 2 gen2 GCs run so far
Block #61  +1 MB (touched 0%)  [so far total allocated= 62 MB / total touched= 0 MB]
= process stats: 110.45 MB in RAM / 234.30 MB private / 2 gen2 GCs run so far
Block #62  +1 MB (touched 0%)  [so far total allocated= 63 MB / total touched= 0 MB]
= process stats: 110.45 MB in RAM / 235.30 MB private / 2 gen2 GCs run so far
Block #63  +1 MB (touched 0%)  [so far total allocated= 64 MB / total touched= 0 MB]
= process stats: 112.45 MB in RAM / 236.37 MB private / 2 gen2 GCs run so far
Block #64  +1 MB (touched 0%)  [so far total allocated= 65 MB / total touched= 0 MB]
= process stats: 112.45 MB in RAM / 237.43 MB private / 2 gen2 GCs run so far
Block #65  +1 MB (touched 0%)  [so far total allocated= 66 MB / total touched= 0 MB]
= process stats: 114.45 MB in RAM / 238.49 MB private / 2 gen2 GCs run so far
Block #66  +1 MB (touched 0%)  [so far total allocated= 67 MB / total touched= 0 MB]
= process stats: 114.70 MB in RAM / 239.55 MB private / 2 gen2 GCs run so far
Block #67  +1 MB (touched 0%)  [so far total allocated= 68 MB / total touched= 0 MB]
= process stats: 116.70 MB in RAM / 240.62 MB private / 2 gen2 GCs run so far
Block #68  +1 MB (touched 0%)  [so far total allocated= 69 MB / total touched= 0 MB]
= process stats: 116.70 MB in RAM / 241.62 MB private / 3 gen2 GCs run so far
Block #69  +1 MB (touched 0%)  [so far total allocated= 70 MB / total touched= 0 MB]
= process stats: 118.70 MB in RAM / 242.62 MB private / 3 gen2 GCs run so far
Block #70  +1 MB (touched 0%)  [so far total allocated= 71 MB / total touched= 0 MB]
= process stats: 118.70 MB in RAM / 243.62 MB private / 3 gen2 GCs run so far
Block #71  +1 MB (touched 0%)  [so far total allocated= 72 MB / total touched= 0 MB]
= process stats: 120.70 MB in RAM / 244.62 MB private / 3 gen2 GCs run so far
Block #72  +1 MB (touched 0%)  [so far total allocated= 73 MB / total touched= 0 MB]
= process stats: 120.70 MB in RAM / 245.62 MB private / 3 gen2 GCs run so far
Block #73  +1 MB (touched 0%)  [so far total allocated= 74 MB / total touched= 0 MB]
= process stats: 122.70 MB in RAM / 246.62 MB private / 3 gen2 GCs run so far
Block #74  +1 MB (touched 0%)  [so far total allocated= 75 MB / total touched= 0 MB]
= process stats: 122.70 MB in RAM / 247.62 MB private / 3 gen2 GCs run so far
Block #75  +1 MB (touched 0%)  [so far total allocated= 76 MB / total touched= 0 MB]
= process stats: 124.70 MB in RAM / 248.62 MB private / 3 gen2 GCs run so far
Block #76  +1 MB (touched 0%)  [so far total allocated= 77 MB / total touched= 0 MB]
= process stats: 124.70 MB in RAM / 249.62 MB private / 3 gen2 GCs run so far
Block #77  +1 MB (touched 0%)  [so far total allocated= 78 MB / total touched= 0 MB]
= process stats: 126.70 MB in RAM / 250.62 MB private / 3 gen2 GCs run so far
Block #78  +1 MB (touched 0%)  [so far total allocated= 79 MB / total touched= 0 MB]
= process stats: 126.70 MB in RAM / 251.62 MB private / 3 gen2 GCs run so far
Block #79  +1 MB (touched 0%)  [so far total allocated= 80 MB / total touched= 0 MB]
= process stats: 128.70 MB in RAM / 252.62 MB private / 3 gen2 GCs run so far
Block #80  +1 MB (touched 0%)  [so far total allocated= 81 MB / total touched= 0 MB]
= process stats: 128.70 MB in RAM / 253.62 MB private / 3 gen2 GCs run so far
Block #81  +1 MB (touched 0%)  [so far total allocated= 82 MB / total touched= 0 MB]
= process stats: 130.70 MB in RAM / 254.62 MB private / 3 gen2 GCs run so far
Block #82  +1 MB (touched 0%)  [so far total allocated= 83 MB / total touched= 0 MB]
= process stats: 130.70 MB in RAM / 255.62 MB private / 3 gen2 GCs run so far
Block #83  +1 MB (touched 0%)  [so far total allocated= 84 MB / total touched= 0 MB]
= process stats: 132.70 MB in RAM / 256.62 MB private / 3 gen2 GCs run so far
Block #84  +1 MB (touched 0%)  [so far total allocated= 85 MB / total touched= 0 MB]
= process stats: 132.70 MB in RAM / 257.62 MB private / 3 gen2 GCs run so far
Block #85  +1 MB (touched 0%)  [so far total allocated= 86 MB / total touched= 0 MB]
= process stats: 134.70 MB in RAM / 258.62 MB private / 3 gen2 GCs run so far
Block #86  +1 MB (touched 0%)  [so far total allocated= 87 MB / total touched= 0 MB]
= process stats: 134.70 MB in RAM / 259.62 MB private / 3 gen2 GCs run so far
Block #87  +1 MB (touched 0%)  [so far total allocated= 88 MB / total touched= 0 MB]
= process stats: 136.70 MB in RAM / 260.62 MB private / 3 gen2 GCs run so far
Block #88  +1 MB (touched 0%)  [so far total allocated= 89 MB / total touched= 0 MB]
= process stats: 136.70 MB in RAM / 261.62 MB private / 3 gen2 GCs run so far
Block #89  +1 MB (touched 0%)  [so far total allocated= 90 MB / total touched= 0 MB]
= process stats: 138.70 MB in RAM / 262.62 MB private / 3 gen2 GCs run so far
Block #90  +1 MB (touched 0%)  [so far total allocated= 91 MB / total touched= 0 MB]
= process stats: 138.70 MB in RAM / 263.62 MB private / 3 gen2 GCs run so far
Block #91  +1 MB (touched 0%)  [so far total allocated= 92 MB / total touched= 0 MB]
= process stats: 140.70 MB in RAM / 264.62 MB private / 3 gen2 GCs run so far
Block #92  +1 MB (touched 0%)  [so far total allocated= 93 MB / total touched= 0 MB]
= process stats: 140.70 MB in RAM / 265.68 MB private / 3 gen2 GCs run so far
Block #93  +1 MB (touched 0%)  [so far total allocated= 94 MB / total touched= 0 MB]
= process stats: 142.91 MB in RAM / 266.74 MB private / 3 gen2 GCs run so far
Block #94  +1 MB (touched 0%)  [so far total allocated= 95 MB / total touched= 0 MB]
= process stats: 142.91 MB in RAM / 267.80 MB private / 3 gen2 GCs run so far
Block #95  +1 MB (touched 0%)  [so far total allocated= 96 MB / total touched= 0 MB]
= process stats: 144.91 MB in RAM / 268.87 MB private / 3 gen2 GCs run so far
Block #96  +1 MB (touched 0%)  [so far total allocated= 97 MB / total touched= 0 MB]
= process stats: 144.91 MB in RAM / 269.93 MB private / 3 gen2 GCs run so far
Block #97  +1 MB (touched 0%)  [so far total allocated= 98 MB / total touched= 0 MB]
= process stats: 146.91 MB in RAM / 270.99 MB private / 3 gen2 GCs run so far
Block #98  +1 MB (touched 0%)  [so far total allocated= 99 MB / total touched= 0 MB]
= process stats: 147.16 MB in RAM / 271.99 MB private / 3 gen2 GCs run so far
Block #99  +1 MB (touched 0%)  [so far total allocated= 100 MB / total touched= 0 MB]
= process stats: 149.16 MB in RAM / 273.05 MB private / 3 gen2 GCs run so far
Block #100  +1 MB (touched 0%)  [so far total allocated= 101 MB / total touched= 0 MB]
= process stats: 149.16 MB in RAM / 274.12 MB private / 3 gen2 GCs run so far
Block #101  +1 MB (touched 0%)  [so far total allocated= 102 MB / total touched= 0 MB]
= process stats: 151.16 MB in RAM / 275.18 MB private / 3 gen2 GCs run so far
Block #102  +1 MB (touched 0%)  [so far total allocated= 103 MB / total touched= 0 MB]
= process stats: 151.41 MB in RAM / 276.24 MB private / 3 gen2 GCs run so far
Block #103  +1 MB (touched 0%)  [so far total allocated= 104 MB / total touched= 0 MB]
= process stats: 153.41 MB in RAM / 277.30 MB private / 3 gen2 GCs run so far
Block #104  +1 MB (touched 0%)  [so far total allocated= 105 MB / total touched= 0 MB]
= process stats: 153.41 MB in RAM / 278.37 MB private / 3 gen2 GCs run so far
Block #105  +1 MB (touched 0%)  [so far total allocated= 106 MB / total touched= 0 MB]
= process stats: 155.41 MB in RAM / 279.37 MB private / 3 gen2 GCs run so far
Block #106  +1 MB (touched 0%)  [so far total allocated= 107 MB / total touched= 0 MB]
= process stats: 155.41 MB in RAM / 280.43 MB private / 3 gen2 GCs run so far
Block #107  +1 MB (touched 0%)  [so far total allocated= 108 MB / total touched= 0 MB]
= process stats: 157.66 MB in RAM / 281.49 MB private / 3 gen2 GCs run so far
Block #108  +1 MB (touched 0%)  [so far total allocated= 109 MB / total touched= 0 MB]
= process stats: 157.66 MB in RAM / 282.55 MB private / 3 gen2 GCs run so far
Block #109  +1 MB (touched 0%)  [so far total allocated= 110 MB / total touched= 0 MB]
= process stats: 159.66 MB in RAM / 283.62 MB private / 3 gen2 GCs run so far
Block #110  +1 MB (touched 0%)  [so far total allocated= 111 MB / total touched= 0 MB]
= process stats: 159.66 MB in RAM / 284.68 MB private / 3 gen2 GCs run so far
Block #111  +1 MB (touched 0%)  [so far total allocated= 112 MB / total touched= 0 MB]
= process stats: 161.66 MB in RAM / 285.68 MB private / 3 gen2 GCs run so far
Block #112  +1 MB (touched 0%)  [so far total allocated= 113 MB / total touched= 0 MB]
= process stats: 161.90 MB in RAM / 286.74 MB private / 3 gen2 GCs run so far
Block #113  +1 MB (touched 0%)  [so far total allocated= 114 MB / total touched= 0 MB]
= process stats: 163.90 MB in RAM / 287.80 MB private / 3 gen2 GCs run so far
Block #114  +1 MB (touched 0%)  [so far total allocated= 115 MB / total touched= 0 MB]
= process stats: 163.90 MB in RAM / 288.87 MB private / 3 gen2 GCs run so far
Block #115  +1 MB (touched 0%)  [so far total allocated= 116 MB / total touched= 0 MB]
= process stats: 165.90 MB in RAM / 289.93 MB private / 3 gen2 GCs run so far
Block #116  +1 MB (touched 0%)  [so far total allocated= 117 MB / total touched= 0 MB]
= process stats: 166.15 MB in RAM / 290.99 MB private / 3 gen2 GCs run so far
Block #117  +1 MB (touched 0%)  [so far total allocated= 118 MB / total touched= 0 MB]
= process stats: 168.15 MB in RAM / 292.05 MB private / 3 gen2 GCs run so far
Block #118  +1 MB (touched 0%)  [so far total allocated= 119 MB / total touched= 0 MB]
= process stats: 168.15 MB in RAM / 293.05 MB private / 3 gen2 GCs run so far
Block #119  +1 MB (touched 0%)  [so far total allocated= 120 MB / total touched= 0 MB]
= process stats: 170.15 MB in RAM / 294.12 MB private / 3 gen2 GCs run so far
Block #120  +1 MB (touched 0%)  [so far total allocated= 121 MB / total touched= 0 MB]
= process stats: 170.15 MB in RAM / 295.18 MB private / 3 gen2 GCs run so far
Block #121  +1 MB (touched 0%)  [so far total allocated= 122 MB / total touched= 0 MB]
= process stats: 172.40 MB in RAM / 296.24 MB private / 3 gen2 GCs run so far
Block #122  +1 MB (touched 0%)  [so far total allocated= 123 MB / total touched= 0 MB]
= process stats: 172.40 MB in RAM / 297.30 MB private / 3 gen2 GCs run so far
Block #123  +1 MB (touched 0%)  [so far total allocated= 124 MB / total touched= 0 MB]
= process stats: 174.40 MB in RAM / 298.37 MB private / 3 gen2 GCs run so far
Block #124  +1 MB (touched 0%)  [so far total allocated= 125 MB / total touched= 0 MB]
= process stats: 174.40 MB in RAM / 299.43 MB private / 3 gen2 GCs run so far
Block #125  +1 MB (touched 0%)  [so far total allocated= 126 MB / total touched= 0 MB]
= process stats: 176.40 MB in RAM / 300.43 MB private / 3 gen2 GCs run so far
Block #126  +1 MB (touched 0%)  [so far total allocated= 127 MB / total touched= 0 MB]
= process stats: 176.65 MB in RAM / 301.49 MB private / 3 gen2 GCs run so far
Block #127  +1 MB (touched 0%)  [so far total allocated= 128 MB / total touched= 0 MB]
= process stats: 176.65 MB in RAM / 302.56 MB private / 3 gen2 GCs run so far
Block #128  +1 MB (touched 0%)  [so far total allocated= 129 MB / total touched= 0 MB]
= process stats: 176.65 MB in RAM / 303.62 MB private / 3 gen2 GCs run so far
Block #129  +1 MB (touched 0%)  [so far total allocated= 130 MB / total touched= 0 MB]
= process stats: 176.65 MB in RAM / 304.68 MB private / 3 gen2 GCs run so far
Block #130  +1 MB (touched 0%)  [so far total allocated= 131 MB / total touched= 0 MB]
= process stats: 176.91 MB in RAM / 305.75 MB private / 3 gen2 GCs run so far
Block #131  +1 MB (touched 0%)  [so far total allocated= 132 MB / total touched= 0 MB]
= process stats: 176.91 MB in RAM / 306.75 MB private / 3 gen2 GCs run so far
Block #132  +1 MB (touched 0%)  [so far total allocated= 133 MB / total touched= 0 MB]
= process stats: 176.91 MB in RAM / 307.81 MB private / 3 gen2 GCs run so far
Block #133  +1 MB (touched 0%)  [so far total allocated= 134 MB / total touched= 0 MB]
= process stats: 176.91 MB in RAM / 308.87 MB private / 3 gen2 GCs run so far
Block #134  +1 MB (touched 0%)  [so far total allocated= 135 MB / total touched= 0 MB]
= process stats: 176.91 MB in RAM / 309.93 MB private / 3 gen2 GCs run so far
Block #135  +1 MB (touched 0%)  [so far total allocated= 136 MB / total touched= 0 MB]
= process stats: 177.16 MB in RAM / 311.00 MB private / 3 gen2 GCs run so far
Block #136  +1 MB (touched 0%)  [so far total allocated= 137 MB / total touched= 0 MB]
= process stats: 177.16 MB in RAM / 312.06 MB private / 3 gen2 GCs run so far
Block #137  +1 MB (touched 0%)  [so far total allocated= 138 MB / total touched= 0 MB]
= process stats: 177.16 MB in RAM / 313.12 MB private / 3 gen2 GCs run so far
Block #138  +1 MB (touched 0%)  [so far total allocated= 139 MB / total touched= 0 MB]
= process stats: 177.16 MB in RAM / 314.12 MB private / 3 gen2 GCs run so far
Block #139  +1 MB (touched 0%)  [so far total allocated= 140 MB / total touched= 0 MB]
= process stats: 177.42 MB in RAM / 315.18 MB private / 3 gen2 GCs run so far
Block #140  +1 MB (touched 0%)  [so far total allocated= 141 MB / total touched= 0 MB]
= process stats: 177.42 MB in RAM / 316.25 MB private / 3 gen2 GCs run so far
Block #141  +1 MB (touched 0%)  [so far total allocated= 142 MB / total touched= 0 MB]
= process stats: 177.42 MB in RAM / 317.31 MB private / 3 gen2 GCs run so far
Block #142  +1 MB (touched 0%)  [so far total allocated= 143 MB / total touched= 0 MB]
= process stats: 177.42 MB in RAM / 318.37 MB private / 3 gen2 GCs run so far
Block #143  +1 MB (touched 0%)  [so far total allocated= 144 MB / total touched= 0 MB]
= process stats: 177.42 MB in RAM / 319.43 MB private / 3 gen2 GCs run so far
Block #144  +1 MB (touched 0%)  [so far total allocated= 145 MB / total touched= 0 MB]
= process stats: 177.68 MB in RAM / 320.50 MB private / 3 gen2 GCs run so far
Block #145  +1 MB (touched 0%)  [so far total allocated= 146 MB / total touched= 0 MB]
= process stats: 177.68 MB in RAM / 321.50 MB private / 3 gen2 GCs run so far
Block #146  +1 MB (touched 0%)  [so far total allocated= 147 MB / total touched= 0 MB]
= process stats: 177.68 MB in RAM / 322.56 MB private / 3 gen2 GCs run so far
Block #147  +1 MB (touched 0%)  [so far total allocated= 148 MB / total touched= 0 MB]
= process stats: 177.68 MB in RAM / 323.62 MB private / 3 gen2 GCs run so far
Block #148  +1 MB (touched 0%)  [so far total allocated= 149 MB / total touched= 0 MB]
= process stats: 177.94 MB in RAM / 324.68 MB private / 3 gen2 GCs run so far
Block #149  +1 MB (touched 0%)  [so far total allocated= 150 MB / total touched= 0 MB]
= process stats: 177.94 MB in RAM / 325.75 MB private / 3 gen2 GCs run so far
Block #150  +1 MB (touched 0%)  [so far total allocated= 151 MB / total touched= 0 MB]
= process stats: 177.94 MB in RAM / 326.81 MB private / 3 gen2 GCs run so far
Block #151  +1 MB (touched 0%)  [so far total allocated= 152 MB / total touched= 0 MB]
= process stats: 177.94 MB in RAM / 327.87 MB private / 3 gen2 GCs run so far
Block #152  +1 MB (touched 0%)  [so far total allocated= 153 MB / total touched= 0 MB]
= process stats: 177.94 MB in RAM / 328.87 MB private / 3 gen2 GCs run so far
Block #153  +1 MB (touched 0%)  [so far total allocated= 154 MB / total touched= 0 MB]
= process stats: 178.20 MB in RAM / 329.93 MB private / 3 gen2 GCs run so far
Block #154  +1 MB (touched 0%)  [so far total allocated= 155 MB / total touched= 0 MB]
= process stats: 178.20 MB in RAM / 331.00 MB private / 3 gen2 GCs run so far
Block #155  +1 MB (touched 0%)  [so far total allocated= 156 MB / total touched= 0 MB]
= process stats: 178.20 MB in RAM / 332.06 MB private / 3 gen2 GCs run so far
Block #156  +1 MB (touched 0%)  [so far total allocated= 157 MB / total touched= 0 MB]
= process stats: 178.20 MB in RAM / 333.12 MB private / 3 gen2 GCs run so far
Block #157  +1 MB (touched 0%)  [so far total allocated= 158 MB / total touched= 0 MB]
= process stats: 178.45 MB in RAM / 334.18 MB private / 3 gen2 GCs run so far
Block #158  +1 MB (touched 0%)  [so far total allocated= 159 MB / total touched= 0 MB]
= process stats: 178.45 MB in RAM / 335.18 MB private / 3 gen2 GCs run so far
Block #159  +1 MB (touched 0%)  [so far total allocated= 160 MB / total touched= 0 MB]
= process stats: 178.45 MB in RAM / 336.25 MB private / 3 gen2 GCs run so far
Block #160  +1 MB (touched 0%)  [so far total allocated= 161 MB / total touched= 0 MB]
= process stats: 178.45 MB in RAM / 337.31 MB private / 3 gen2 GCs run so far
Block #161  +1 MB (touched 0%)  [so far total allocated= 162 MB / total touched= 0 MB]
= process stats: 178.45 MB in RAM / 338.37 MB private / 3 gen2 GCs run so far
Block #162  +1 MB (touched 0%)  [so far total allocated= 163 MB / total touched= 0 MB]
= process stats: 178.71 MB in RAM / 339.43 MB private / 3 gen2 GCs run so far
Block #163  +1 MB (touched 0%)  [so far total allocated= 164 MB / total touched= 0 MB]
= process stats: 178.71 MB in RAM / 340.50 MB private / 3 gen2 GCs run so far
Block #164  +1 MB (touched 0%)  [so far total allocated= 165 MB / total touched= 0 MB]
= process stats: 178.71 MB in RAM / 341.56 MB private / 3 gen2 GCs run so far
Block #165  +1 MB (touched 0%)  [so far total allocated= 166 MB / total touched= 0 MB]
= process stats: 178.71 MB in RAM / 342.56 MB private / 3 gen2 GCs run so far
Block #166  +1 MB (touched 0%)  [so far total allocated= 167 MB / total touched= 0 MB]
= process stats: 178.97 MB in RAM / 343.62 MB private / 3 gen2 GCs run so far
Block #167  +1 MB (touched 0%)  [so far total allocated= 168 MB / total touched= 0 MB]
= process stats: 178.97 MB in RAM / 344.68 MB private / 3 gen2 GCs run so far
Block #168  +1 MB (touched 0%)  [so far total allocated= 169 MB / total touched= 0 MB]
= process stats: 178.97 MB in RAM / 345.75 MB private / 3 gen2 GCs run so far
Block #169  +1 MB (touched 0%)  [so far total allocated= 170 MB / total touched= 0 MB]
= process stats: 178.97 MB in RAM / 346.81 MB private / 3 gen2 GCs run so far
Block #170  +1 MB (touched 0%)  [so far total allocated= 171 MB / total touched= 0 MB]
= process stats: 178.97 MB in RAM / 347.87 MB private / 3 gen2 GCs run so far
Block #171  +1 MB (touched 0%)  [so far total allocated= 172 MB / total touched= 0 MB]
= process stats: 179.23 MB in RAM / 348.93 MB private / 3 gen2 GCs run so far
Block #172  +1 MB (touched 0%)  [so far total allocated= 173 MB / total touched= 0 MB]
= process stats: 179.23 MB in RAM / 349.93 MB private / 3 gen2 GCs run so far
Block #173  +1 MB (touched 0%)  [so far total allocated= 174 MB / total touched= 0 MB]
= process stats: 179.23 MB in RAM / 351.00 MB private / 3 gen2 GCs run so far
Block #174  +1 MB (touched 0%)  [so far total allocated= 175 MB / total touched= 0 MB]
= process stats: 179.23 MB in RAM / 352.06 MB private / 3 gen2 GCs run so far
Block #175  +1 MB (touched 0%)  [so far total allocated= 176 MB / total touched= 0 MB]
= process stats: 179.48 MB in RAM / 353.12 MB private / 3 gen2 GCs run so far
Block #176  +1 MB (touched 0%)  [so far total allocated= 177 MB / total touched= 0 MB]
= process stats: 179.48 MB in RAM / 354.18 MB private / 3 gen2 GCs run so far
Block #177  +1 MB (touched 0%)  [so far total allocated= 178 MB / total touched= 0 MB]
= process stats: 179.48 MB in RAM / 355.25 MB private / 3 gen2 GCs run so far
Block #178  +1 MB (touched 0%)  [so far total allocated= 179 MB / total touched= 0 MB]
= process stats: 179.48 MB in RAM / 356.25 MB private / 3 gen2 GCs run so far
Block #179  +1 MB (touched 0%)  [so far total allocated= 180 MB / total touched= 0 MB]
= process stats: 179.48 MB in RAM / 357.31 MB private / 3 gen2 GCs run so far
Block #180  +1 MB (touched 0%)  [so far total allocated= 181 MB / total touched= 0 MB]
= process stats: 179.74 MB in RAM / 358.37 MB private / 3 gen2 GCs run so far
Block #181  +1 MB (touched 0%)  [so far total allocated= 182 MB / total touched= 0 MB]
= process stats: 179.74 MB in RAM / 359.43 MB private / 3 gen2 GCs run so far
Block #182  +1 MB (touched 0%)  [so far total allocated= 183 MB / total touched= 0 MB]
= process stats: 179.74 MB in RAM / 360.50 MB private / 3 gen2 GCs run so far
Block #183  +1 MB (touched 0%)  [so far total allocated= 184 MB / total touched= 0 MB]
= process stats: 179.74 MB in RAM / 361.56 MB private / 3 gen2 GCs run so far
Block #184  +1 MB (touched 0%)  [so far total allocated= 185 MB / total touched= 0 MB]
= process stats: 180.00 MB in RAM / 362.81 MB private / 3 gen2 GCs run so far
Block #185  +1 MB (touched 0%)  [so far total allocated= 186 MB / total touched= 0 MB]
= process stats: 180.00 MB in RAM / 363.81 MB private / 3 gen2 GCs run so far
Block #186  +1 MB (touched 0%)  [so far total allocated= 187 MB / total touched= 0 MB]
= process stats: 180.00 MB in RAM / 364.87 MB private / 3 gen2 GCs run so far
Block #187  +1 MB (touched 0%)  [so far total allocated= 188 MB / total touched= 0 MB]
= process stats: 180.00 MB in RAM / 365.93 MB private / 3 gen2 GCs run so far
Block #188  +1 MB (touched 0%)  [so far total allocated= 189 MB / total touched= 0 MB]
= process stats: 180.25 MB in RAM / 367.00 MB private / 3 gen2 GCs run so far
Block #189  +1 MB (touched 0%)  [so far total allocated= 190 MB / total touched= 0 MB]
= process stats: 180.25 MB in RAM / 368.06 MB private / 3 gen2 GCs run so far
Block #190  +1 MB (touched 0%)  [so far total allocated= 191 MB / total touched= 0 MB]
= process stats: 180.25 MB in RAM / 369.12 MB private / 3 gen2 GCs run so far
Block #191  +1 MB (touched 0%)  [so far total allocated= 192 MB / total touched= 0 MB]
= process stats: 180.25 MB in RAM / 370.18 MB private / 3 gen2 GCs run so far
Block #192  +1 MB (touched 0%)  [so far total allocated= 193 MB / total touched= 0 MB]
= process stats: 180.51 MB in RAM / 371.18 MB private / 3 gen2 GCs run so far
Block #193  +1 MB (touched 0%)  [so far total allocated= 194 MB / total touched= 0 MB]
= process stats: 180.51 MB in RAM / 372.25 MB private / 3 gen2 GCs run so far
Block #194  +1 MB (touched 0%)  [so far total allocated= 195 MB / total touched= 0 MB]
= process stats: 180.51 MB in RAM / 373.31 MB private / 3 gen2 GCs run so far
Block #195  +1 MB (touched 0%)  [so far total allocated= 196 MB / total touched= 0 MB]
= process stats: 180.51 MB in RAM / 374.37 MB private / 3 gen2 GCs run so far
Block #196  +1 MB (touched 0%)  [so far total allocated= 197 MB / total touched= 0 MB]
= process stats: 180.51 MB in RAM / 375.43 MB private / 3 gen2 GCs run so far
Block #197  +1 MB (touched 0%)  [so far total allocated= 198 MB / total touched= 0 MB]
= process stats: 180.77 MB in RAM / 376.50 MB private / 3 gen2 GCs run so far
Block #198  +1 MB (touched 0%)  [so far total allocated= 199 MB / total touched= 0 MB]
= process stats: 180.77 MB in RAM / 377.56 MB private / 3 gen2 GCs run so far
Block #199  +1 MB (touched 0%)  [so far total allocated= 200 MB / total touched= 0 MB]
= process stats: 180.77 MB in RAM / 378.56 MB private / 3 gen2 GCs run so far
Allocating memory complete. Press Ctrl+C to exit
Maoni0 commented 2 years ago

I don't think this needs to be 7.0 but let me know if you don't agree. @janvorli what do you think needs to be done here?

janvorli commented 2 years ago

From most of the results found so far, it seems to me that it just reflects the new MADV_FREE usage. It should not result in OOM, it just keeps pages as resident until memory pressure occurs. It doesn't seem we need to do anything to address that.

As for the last comment with test results, my guess is that although the code doesn't touch the contents of the arrays allocated, the growing consumed physical memory may be caused by the fact that each array allocation will touch at least one page to store the object header, the MethodTable and few other array specific fields. And maybe also by the GC helper tables.

joelwkall commented 2 years ago

Is there a way to configure the runtime to use MADV_DONTNEED instead? We use total memory usage as a parameter in our orchestration, and with .NET 6 it looks like a machine is full even when it isn't.

Maoni0 commented 2 years ago

from what @janvorli said above -

The MADV_DONTNEED seems to release the physical pages right away

we'd like to keep the pages resident unless we are under memory pressure so it would be undesirable to enable this (even under a config) just so for accounting purposes. could you please verify that this is only for accounting purposes, and that you are not actually getting a premature OOM?

joelwkall commented 2 years ago

could you please verify that this is only for accounting purposes, and that you are not actually getting a premature OOM?

Yes, we have not seen any premature OOMs, or at least not been able to verify it. But we are also not running .NET 6 in production because of this so we don't have a lot of data. But our concern is mainly about accounting purposes.

it would be undesirable to enable this (even under a config) just so for accounting purposes

I understand that for performance reasons, keeping pages resident is better, all else equal. I'm not sure exactly how much it impacts performance, but releasing them seems to work fine in earlier versions of .NET, so being able to set a config flag to prevent regression if your setup depends on this behavior does not seem undesirable to me. Of course I am aware that it would incur costs to create and maintain this flag.

Havret commented 1 year ago

@Maoni0, @janvorli Shouldn't we use MADV_FREE_REUSE and MADV_FREE_REUSABLE?

janvorli commented 1 year ago

@Havret I have not found these two documented officially, but from what I was able to find by googling, it seems these are macOS only. It seems that go and chromium use these instead of MADV_FREE. I am a bit hesitant to use undocumented features.