.NET 7 application hangs during GC

[KenKozman-GE]

Description

We host our application in Azure App Service in the host dependent mode.

Each instance of our application can end up getting stuck in a busy loop where it eats 100% of the CPU and no other HTTP calls are able to make it into the app. This only started happening when we upgraded to .NET 7.

It looks like this is due to one thread being stuck performing a GC, so all the other managed threads are paused.

Our application has health checks that run against it. One of those checks runs ~1/second. This check ends up querying a pgsql database and pulling down records (10s-1000s). This is the place we have seen the hang occur, although this same code can be called by other parts of the system. Likely it is just the health check that is triggering due to the much higher frequency of that call being made.

Here are a few of the unmanaged portion of the GC allocate from two separate dumps taken during the high CPU times (this is me doing dump debugging in Visual Studio 2022):

I believe it is running the Workstation GC based on the WKS:: namespace (and because the other threads are frozen waiting on the GC and because the GC is being performed directly on the user thread). I believe this is happening because the app service plan instance shows up as having 1 processor. We specify to use the Server GC in our configuration but I believe it will use the workstation one if there is only one processor detected.

In one case I generated three dumps 5 minutes apart. In all three cases the managed code had not moved and was in the same exact place. The second unmanaged stack above is the top of the stack in those cases (although the very top most function changes in each, which is why I thought allocate_in_condemned_generations was the culprit). Here is the managed portion of the stack from those dumps:

Here are some outputs from the CrashHangAnalysis MHT which AppService also kindly created (this is from one of the three dumps mentioned):

As you can see in the thread times almost all of the time was eaten up by Thread 48. In each successive 5 minute dump you can see it has eaten up 5 more minutes of CPU time:

Here is the full call stack for Thread 48 reported by the CrashHangAnalysis:

There are also multiple CLR runtimes loaded in the process. I believe that AppService itself loads the .NET Framework 4.8, we are using .NET 7.0.0:

I attempted to find this issue reported already but my searching turned up nothing :( Apologies if I missed it.

Reproduction Steps

At this point I don't have a way to reproduce it reliably. One of our systems seems to be falling into this particular hole once a day or so. The SQL query on that system is a bit larger than other systems, but not massively so.

Expected behavior

To just have the GC complete its work and return to our application.

Actual behavior

It appears the GC gets stuck in WKS::gc_heap::allocate_in_condemned_generations. I see a retry label in there, perhaps it is stuck in an infinite loop?

Regression?

I believe so. We never saw this on .NET 6 (several sub-versions) and .NET 5. We ran similar code with earlier versions of .NET Core and never saw any issues either.

Known Workarounds

Perhaps downgrading to .NET 6?
It is uncertain if this would happen with .NET 7.0.1, I have not gotten to test that yet.
It is unclear if this is a workstation GC issue only; my guess is yes.

Configuration

.NET 7.0.0 (in the dumps this shows up as CLR version v7.0.22).
Azure App Service Platform version: 99.0.7.620
Windows Server 2016 - 14393
Number of Processors - 1
Architecture: x64

Other information

It seems like some sort of infinite loop issue in the gc_heap::allocate_in_condemned_generations function. But that is me using my "Jump to Conclusions" mat.

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

Issue Details

---

Description

We host our application in Azure App Service in the host dependent mode.

Each instance of our application can end up getting stuck in a busy loop where it eats 100% of the CPU and no other HTTP calls are able to make it into the app. This only started happening when we upgraded to .NET 7.

It looks like this is due to one thread being stuck performing a GC, so all the other managed threads are paused.

Our application has health checks that run against it. One of those checks runs ~1/second. This check ends up querying a pgsql database and pulling down records (10s-1000s). This is the place we have seen the hang occur, although this same code can be called by other parts of the system. Likely it is just the health check that is triggering due to the much higher frequency of that call being made.

Here are a few of the unmanaged portion of the GC allocate from two separate dumps taken during the high CPU times (this is me doing dump debugging in Visual Studio 2022):

I believe it is running the Workstation GC based on the WKS:: namespace (and because the other threads are frozen waiting on the GC and because the GC is being performed directly on the user thread). I believe this is happening because the app service plan instance shows up as having 1 processor. We specify to use the Server GC in our configuration but I believe it will use the workstation one if there is only one processor detected.

In one case I generated three dumps 5 minutes apart. In all three cases the managed code had not moved and was in the same exact place. The second unmanaged stack above is the top of the stack in those cases (although the very top most function changes in each, which is why I thought allocate_in_condemned_generations was the culprit). Here is the managed portion of the stack from those dumps:

Here are some outputs from the CrashHangAnalysis MHT which AppService also kindly created (this is from one of the three dumps mentioned):

As you can see in the thread times almost all of the time was eaten up by Thread 48. In each successive 5 minute dump you can see it has eaten up 5 more minutes of CPU time:

Here is the full call stack for Thread 48 reported by the CrashHangAnalysis:

There are also multiple CLR runtimes loaded in the process. I believe that AppService itself loads the .NET Framework 4.8, we are using .NET 7.0.0:

I attempted to find this issue reported already but my searching turned up nothing :( Apologies if I missed it.

Reproduction Steps

At this point I don't have a way to reproduce it reliably. One of our systems seems to be falling into this particular hole once a day or so. The SQL query on that system is a bit larger than other systems, but not massively so.

Expected behavior

To just have the GC complete its work and return to our application.

Actual behavior

It appears the GC gets stuck in WKS::gc_heap::allocate_in_condemned_generations. I see a retry label in there, perhaps it is stuck in an infinite loop?

Regression?

I believe so. We never saw this on .NET 6 (several sub-versions) and .NET 5. We ran similar code with earlier versions of .NET Core and never saw any issues either.

Known Workarounds

Perhaps downgrading to .NET 6?
It is uncertain if this would happen with .NET 7.0.1, I have not gotten to test that yet.
It is unclear if this is a workstation GC issue only; my guess is yes.

Configuration

.NET 7.0.0 (in the dumps this shows up as CLR version v7.0.22).
Azure App Service Platform version: 99.0.7.620
Windows Server 2016 - 14393
Number of Processors - 1
Architecture: x64

Other information

It seems like some sort of infinite loop issue in the gc_heap::allocate_in_condemned_generations function. But that is me using my "Jump to Conclusions" mat.

Author:	KenKozman-GE
Assignees:	-
Labels:	area-GC-coreclr
Milestone:	-

[cshung]

@KenKozman-GE Can you share a dump or something useful so that we can investigate?

[KenKozman-GE]

Yeah sorry...

Here are the crash hung analyses:
CrashHangAnalyses.zip

Let me see if I can push the dumps here or not (they are full memory dumps, so quite large).

[KenKozman-GE]

Ah yep, 25MB limit. Let me try putting them somewhere that I can share, one second.

[KenKozman-GE]

Okay here are a couple of full memory dumps (mentioned above) as well as the crash hang analyses.
Crash Hang Analysis
Dump #1
Dump #2

[KenKozman-GE]

One other workaround here would be to switch to an App Service Plan SKU which would show up as having multiple processors and thus use the Server GC (which would hopefully not exhibit the same issue).

Right now we are using P1V2 for some instances which have a single vCPU.

[KenKozman-GE]

One further update, we used to use S2 SKUs and switched to P1V2 in the middle of 2022. So this still seems like a regression from .NET 6 to .NET 7 for us, for the Workstation GC. But we would have been using the Server GC at the start of 2022 when we were still on S2 SKUs. We were on S2 SKUs during the .NET 5 timeframe as well.

(S2 SKUs have 2 vCPUs, P1V2 SKUs have only 1 vCPU)

[cshung]

I took a quick look at the dump and hypothesize that it may be an infinite loop because we forgot about the possibility of pinning.

Roughly speaking, the allocate_in_condemned_generations method does something along this line:

allocate_in_condemned_generations(...size...)
    retry:
    if we hit a pin or run out of space
        if we hit a pin
            deal with it
            goto retry
        if we run out of space
            deal with it
        goto retry
    ...

The key idea is that the deal with it should deal with the situation so that we should not be running into a pin or running out of space, as such, the loop is meant to be run for at most 3 iterations or less. (1 for pin, 1 for space, last for succeed).

There are no synchronization primitives involved in this loop, so this is pretty much a case of an infinite loop.

There are no more pins in the pin queue (i.e. gc_heap::mark_stack_bos == gc_heap::mark_stack_tos (c.f. gc_heap::pinned_plug_que_empty_p)), therefore, the problem has something to do with space.

Looking at the implementation of gc_heap::size_fit_p, I understand why we get stuck running out of space.

We have a just-fit allocation context:

0:046> ?? gen->allocation_context.alloc_ptr
unsigned char * 0x000001d2`72c00020

0:046> ?? gen->allocation_context.alloc_limit
unsigned char * 0x000001d2`73000000

0:046> ?? size
unsigned int64 0x3fffe0

Note that 0x000001d272c00020 + 0x3fffe0 == 0x000001d273000000, the allocation context should fit the allocation exactly, probably prepared so by the deal_with_it code for space and that's why it is so exact.

But then old_loc != nullptr, so the code in size_fit_p insists on requiring a bit more memory (i.e. + Align(min_object_size)), so that check will fail.

We are probably stuck in that situation and that is why the loop isn't breaking. What baffles me is that the old_loc is already considered in the deal with it section for running out of space by being passed as an argument to grow_heap_segment, not sure why we aren't processing that correctly.

[Maoni0]

it may be an infinite loop because we forgot about the possibility of pinning.

I don't know how to interpret this. allocate_in_condemned_generations has to handle pinning; otherwise every .net app would fail.

from the debug info given above, it doesn't look like it has to do with pinning - it says we have a huge plug where every single object on that region survived. and we are asking for an additional min object size when fitting in this case. can you check to see if it's asking for an additional min_obj_size because of USE_PADDING_FRONT or USE_PADDING_TAIL? what puzzled me is it seems like it shouldn't be due to USE_PADDING_FRONT because the plug is so huge which tells me this plug should belong to gen2 so this should be a gen2 GC. but if it's a gen2 GC, we should not be passing USE_PADDING_FRONT. and we should not be passing USE_PADDING_TAIL because generation_allocation_limit (gen) should be the same as heap_segment_plan_allocated (seg).

[cshung]

can you check to see if it's asking for an additional min_obj_size because of USE_PADDING_FRONT or USE_PADDING_TAIL?

It is because of USE_PADDING_FRONT.

0:046> dv
       ...
       pad_in_front = 0n1
       ...

what puzzled me is it seems like it shouldn't be due to USE_PADDING_FRONT because the plug is so huge which tells me this plug should belong to gen2 so this should be a gen2 GC.

It is a gen1 GC

0:046> ?? wks::gc_heap::settings
class WKS::gc_mechanisms
   +0x000 gc_index         : 0x6dc
   +0x008 condemned_generation : 0n1
   ...

This is on thread 46 of RD501AC5AE7597_w3wp_5784_638079619256436212.dmp

[Maoni0]

I looked at the 2 dumps and the really odd thing with both dumps is the first region in gen0 has no free objects whatsoever but all the other gen0 regions look normal, ie with free objects. this explains why we have such a huge plug in a gen1 GC but this is not what should happen - we are supposed to have free objects as padding between alloc contexts so we don't form potentially huge plugs like this.

@KenKozman-GE do you happen to have a dump where it's running normally, ie, not getting this hang? that would be helpful.