cockroachdb / cockroachdb/cockroach

debug.zip: OOM during collection

Open
#159,874 3 comments 0 reactions 1 assignee Claimed by @aa-joshi View on GitHub
C-bug O-25.4-scale-testing P-2 T-supportability
Dominant language
Go
Stars
32.5k
Forks
4.1k
PR merge metrics
PR metrics pending

Description

### Background

During a scheduled run on `n1`, the node OOMed.

```
cockroach debug zip ${zip_file} --certs-dir /home/ubuntu/certs --files-from="$(date +"%Y-%m-%d %H:%M:%S" -d "yesterday")" --host ${n1}:26257
```

```
Dec 18 09:00:38 drt-scale-300-0001 kernel: [880673.750690] Tasks state (memory values in pages):
Dec 18 09:00:38 drt-scale-300-0001 kernel: [880673.750691] [ pid ] uid tgid total_vm rss rss_anon rss_file rss_shmem pgtables_bytes swapents oom_score_adj name
Dec 18 09:00:38 drt-scale-300-0001 kernel: [880673.750693] [ 117147] 1000 117147 1942 576 64 512 0 65536 0 0 bash
Dec 18 09:00:38 drt-scale-300-0001 kernel: [880673.750700] [ 117152] 1000 117152 27696232 15196307 15182899 13408 0 208474112 0 0 cockroach
Dec 18 09:00:38 drt-scale-300-0001 kernel: [880673.750703] oom-kill:constraint=CONSTRAINT_MEMCG,nodemask=(null),cpuset=/,mems_allowed=0,oom_memcg=/system.slice/cockroach-system.service,task_memcg=/system.slice/cockroach-system.service,task=cockroach,pid=117152,uid=1000
Dec 18 09:00:38 drt-scale-300-0001 kernel: [880673.750836] Memory cgroup out of memory: Killed process 117152 (cockroach) total-vm:110784928kB, anon-rss:60731596kB, file-rss:53632kB, shmem-rss:0kB, UID:1000 pgtables:203588kB oom_score_adj:0
```

### Analysis

Note the OOM occurred at `09:00:38`. These are the last two rows corresponding to the runtime stats, emitted at `08:59:46`,

```
I251218 08:59:46.689046 62047 2@util/log/event_log.go:90 ⋮ [T1,Vsystem,n1] 457222 ={"Timestamp":1766048386689024553,"EventType":"runtime_stats","MemRSSBytes":53302624256,"GoroutineCount":34379,"MemStackSysBytes":876085248,"GoAllocBytes":19277681928,"GoTotalBytes":34664865624,"HeapFragmentBytes":4790086392,"HeapReservedBytes":8892407808,"HeapReleasedBytes":6473187328,"CGoAllocBytes":16450007504,"CGoTotalBytes":18781188096,"CGoCallRate":20080.941,"CPUUserPercent":917.8938,"CPUSysPercent":121.13115,"GCPausePercent":0.01361346,"GCRunCount":6722,"NetHostRecvBytes":102283675,"NetHostSendBytes":103994006,"GoLimitBytes":36028555776}
```

and `08:59:56`,

```
I251218 08:59:56.699770 62047 2@util/log/event_log.go:90 ⋮ [T1,Vsystem,n1] 457240 ={"Timestamp":1766048396699766381,"EventType":"runtime_stats","MemRSSBytes":52832407552,"GoroutineCount":32133,"MemStackSysBytes":865796096,"GoAllocBytes":19837200248,"GoTotalBytes":34245066584,"HeapFragmentBytes":3947206792,"HeapReservedBytes":8772222976,"HeapReleasedBytes":6892986368,"CGoAllocBytes":16450251808,"CGoTotalBytes":18755727360,"CGoCallRate":19379.883,"CPUUserPercent":834.50366,"CPUSysPercent":128.6618,"GCRunCount":6722,"NetHostRecvBytes":108490080,"NetHostSendBytes":116470904,"GoLimitBytes":36028555776}
```

Since runtime stats are scheduled to be emitted periodically, roughly every ~10 seconds, we're missing `09:00:06`, `09:00:16`, `09:00:26`, `09:00:36`.

The cronjob (for `cockroach debug zip`) was triggered at `09:00:01` from a non-cluster node. This also happens to be the _last_ successful scrape of `sys_go_heap_allocbytes`,

Image

**NOTE**: at `09:00`, `GoAllocBytes` has a _smaller_ value than at `08:43`. Indeed, the `heapprofiler` was triggered at `08:43`,

```
-rw-r----- 1 ubuntu ubuntu 4436526 Dec 18 08:43 logs/heap_profiler/memprof.2025-12-18T08_43_13.947.30795056048.pprof
```

Since the heapprofiler is triggered on highWatermark, it would not be triggered at `09:00`. Yet,

```
-rw-r----- 1 ubuntu ubuntu 0 Dec 18 09:00 logs/heap_profiler/memprof.2025-12-18T09_00_38.379.30938474544.pprof
```

The clue is in the timestamp of the filename, i.e., `09_00_38.379`. Thus, we can surmise that `takeHeapProfile` was triggered right before the OOM; it created the empty file but didn't succeed in `pprof.WriteHeapProfile`.

### Potential Root Cause

In the above, from our last runtime stats, we have ~`52.8` GB in RSS. At OOM, the RSS grew to `59.6` GB, effectively the limit of the cgroup. Where did ~`7` GB come from?

`collectCPUProfiles` invokes `Profile` (rpc) on _every_ node in parallel, i.e., one goroutine per node, without a semaphore. Thus, in the worst-case, we're looking at 300 pprof payloads landing in `n1`'s heap. By crude estimates, that's ~`250` MB, considering the largest file on disk is ~750KB, e.g.,

```
-rw-r----- 1 ubuntu ubuntu 743K Dec 19 03:29 cpuprof.2025-12-19T03_29_06.778.95.pprof
```

`getStackInformation` invokes `Stacks` (rpc) on _every_ node in parallel, but its concurrency is limited to `15`. However, `allstacks.Get()` can get very large. From the runtime stats, we had ~35K goroutines on many nodes. By crude estimates, this can range between ~50MB to ~100MB per node. With the concurrency multiplier, we're looking at 1.5GB or worse, in total.

Altogether, `pprof.WriteHeapProfile`, `collectCPUProfiles`, `getStackInformation` could have added up to ~2GB. Thus, it's only a partial accounting of where some of the heavy heap allocations landed before the OOM.

Jira issue: CRDB-58052

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.