runtime: infinite loop in runtime.mapassign_faststr

[felixge]

Go version

go1.24.10

Output of go env in your module/workspace:

GOARCH=arm64

What did you do?

We are observing a Go application that occasionally becomes completely unresponsive while using 1 CPU core. We don't have Go CPU profiles or runtime metrics from this time period because they also stopped reporting.

However, we have profiles form the opentelemetry-ebpf-profiler, which indicate the the program is spending all of it's time spinning inside of runtime_mapassign_faststr (linked section corresponds to the line numbers we see in the profile below) as well as stopTheWorldWithSema. The latter seems stuck because the former is not async preemptible (and the function calls it makes are inlined).

We think we have ruled out concurrent access to the map (see SetTag holding a lock while and setMeta manipulates the map).

From the evidence we've gathered, we suspect a bug in the map implementation that is causing an infinite loop in the runtime.

cc @prattmic

What did you see happen?

Go program becoming unresponsive.

What did you expect to see?

Go program not becoming unresponsive.

[prattmic]

The symbols in the profile look like it is spending tons of time probing the map.

Do you know how big the map is? In theory if the map is absolutely humongous probing could take a long time and it will indeed (unfortunately) not be preemptible since it is in the runtime.

That does seem unlikely though, given how big the map would need to be. An actual infinite loop seems more likely.

Can you collect a core file so you can walk through what a specific probe sequence would look like?

[prattmic]

cc @golang/runtime

[randall77]

This could happen if we somehow got into a state where a table was completely full.
Of course, if the table was corrupted somehow that could cause it.

As far as errors in the map implementation, maybe we're computing growthLeft wrong somehow?

Do you use clear of maps in your program? How about maps.Clone? Those are odd-ish paths through the map code that may have had less scrutiny.

Felix, could you add debugging code to mapassign_faststr to count all the slot states (full/empty/tombstone) and check that growthLeft is set correctly?

Any problems in 1.25?

[thepudds]

One other debugging option could be to enable the invariant checking by temporarily commenting out the early return in checkInvariants:

go/src/internal/runtime/maps/table_debug.go

Lines 14 to 17 in dc913c3

	func (t *table) checkInvariants(typ *abi.MapType, m *Map) {
	if !debugLog {
	return
	}

(At least, that's what I recall, though I probably should try myself to see if that's the proper change.)

[felixge]

Thanks for all the initial thoughts an suggestions 🙇🏻‍♂️.

Do you know how big the map is? In theory if the map is absolutely humongous probing could take a long time and it will indeed (unfortunately) not be preemptible since it is in the runtime.

I'm not exactly sure how big the map is, but from talking to the devs of the service, some keys/values might be as big as O(10 KiB). Here is the RSS memory usage of the program during the incident, which I think rules out something humongous.

Can you collect a core file so you can walk through what a specific probe sequence would look like?

I'll try to get a core dump, but it might take a bit since we need to do some work to capture the data and then wait for the issue to happen again.

This could happen if we somehow got into a state where a table was completely full. Of course, if the table was corrupted somehow that could cause it.

Do you use clear of maps in your program? How about maps.Clone? Those are odd-ish paths through the map code that may have had less scrutiny.

I did an initial check and didn't find any usage of those constructs on the map that's experiencing the issue.

That being said, I should be clear that we can't fully rule out an unsynchronized concurrent map access problem. I've done a few passes over the code and don't see how it should be possible, and we're not seeing crashes on this map, but a small chance remains.

Felix, could you add debugging code to mapassign_faststr to count all the slot states (full/empty/tombstone) and check that growthLeft is set correctly?

We'll give this a shot. I'll let you know if we manage to set it up and what the results are.

Any problems in 1.25?

Not that I'm aware of. We're going to upgrade the repo that this app is in soon, so I'll let you know if this ends up resolving the problem.

[felixge]

We managed to produce a coredump, I'll email a copy to @prattmic.

I used dlv to identify the goroutine suspected of being in an infinite loop. Unfortunately we don't get the maps.probeSeq.index. The offset is large, but since it's masked IDK if that means anything.

(dlv) goroutine 170257
Switched from 170257 to 170257 (thread 17)
(dlv) bt
 0  0x00000000043fcf18 in runtime.mapassign_faststr
    at GOROOT/src/internal/runtime/maps/runtime_faststr_swiss.go:327
 1  0x0000000004d73d10 in github.com/DataDog/dd-trace-go/v2/ddtrace/tracer.(*Span).setMeta
    at external/com_github_datadog_dd_trace_go_v2/ddtrace/tracer/span.go:546
 2  0x0000000004d73d10 in github.com/DataDog/dd-trace-go/v2/ddtrace/tracer.(*Span).SetTag
    at external/com_github_datadog_dd_trace_go_v2/ddtrace/tracer/span.go:227
...
21  0x000000000448b264 in runtime.goexit
    at src/runtime/asm_arm64.s:1223

(dlv) args
typ = ("*internal/abi.SwissMapType")(0x7935a0)
m = ("*internal/runtime/maps.Map")(0x40106d4000)
key = "routing_layer"
~r0 = (unreadable empty OP stack)

(dlv) locals
k = "routing_layer"
hash = 12604134247887708130
slotElem = (unreadable could not find loclist entry at 0x11b0d9 for address 0x43fcf18)
idx = (unreadable could not find loclist entry at 0x11b1e7 for address 0x43fcf18)
t = ("*internal/runtime/maps.table")(0x404950c120)
seq = internal/runtime/maps.probeSeq {mask: 3, offset: 49325462943, index: (unreadable read out of bounds)}
firstDeletedGroup = internal/runtime/maps.groupReference {data: unsafe.Pointer(0x0)}
firstDeletedSlot = 0
g = internal/runtime/maps.groupReference {data: unsafe.Pointer(0x401d7cd0a0)}
match = 128
i = 0
slotKey = unsafe.Pointer(0x401d7cd0a8)

(dlv) p m
("*internal/runtime/maps.Map")(0x40106d4000)
*internal/runtime/maps.Map {used: 22, seed: 10186719144191894422, dirPtr: unsafe.Pointer(0x4033af3970), dirLen: 1, globalDepth: 0, globalShift: 64, writing: 1, clearSeq: 0}

(dlv) p t
("*internal/runtime/maps.table")(0x404950c120)
*internal/runtime/maps.table {
	used: 22,
	capacity: 32,
	growthLeft: 6,
	localDepth: 0,
	index: 0,
	groups: internal/runtime/maps.groupsReference {data: unsafe.Pointer(0x401d7ccd88), lengthMask: 3},}

[prattmic]

I don't have a full conclusion yet, but I extracted the group control words, which I think can at least explain the spinning. Our control words are:

Group 0: 0x000000401c2b4d0d
Group 1: 0x0000000000000024
Group 2: 0x000000000000000f
Group 3: 0x610d0d6764237862

The way the probe sequence works is:

1. Select an initial group based on the hash.
2. Check if the group contains a matching entry. If so, done.
3. If not and the group is fully populated (no empty slots), then an assignment may have had to go to another group, so continue to the next group and GOTO 2.
4. If the group contains an empty slot, then assignment would have used that slot, so no need to go to the next group, thus we are done.

An empty slot has byte 0x80 in the control word. There is not a single empty slot (0x80 byte) in any of these control words, thus probing will keep looking at the next group indefinitely (infinite loop). This should be impossible, as the map always leaves at least 1 empty slot to ensure that probing always terminates.

The Group 0 control word looks a lot like a heap address, and 1 and 2 like arbitrary small numbers. (0x00 bytes are technically valid, for a full slot where the lower 7 bits of the hash are 0, but having that many with the same has is implausible.)

[felixge]

Thanks @prattmic . This definitely smells like heap corruption 😬. I'm working with the service authors to go deeper and find any potential cgo/unsafe code paths that could be involved.