Memory upscale doesn't happen when it should

[arssher]

User (and I) consistently get OOM when doing pgvector CREATE INDEX ... USING ivfflat on 15GB table. OOM logs show that compute wasn't upscaled to max CU. Example (here max cu is 4, i.e. 16GB, but OOM happened at 9GB): https://neonprod.grafana.net/goto/EAgSWo3Vg?orgId=1 endpoint: https://console.neon.tech/admin/endpoints/ep-sweet-feather-898825

a bit more context: https://neondb.slack.com/archives/C03TN5G758R/p1690319779712199?thread_ts=1690313755.185089&cid=C03TN5G758R

I have access to user db and can pass it to someone to repro.

[sharnoff]

The OOM logs are interesting. I've duplicated them here with Grafana's timestamps for posterity:

OOM logs

``` 2023-07-27T18:19:22Z [ 3126.745348] postgres invoked oom-killer: gfp_mask=0x400dc0(GFP_KERNEL_ACCOUNT|__GFP_ZERO), order=0, oom_score_adj=0 2023-07-27T18:19:22Z [ 3126.746571] CPU: 0 PID: 392 Comm: postgres Not tainted 5.15.80 #1 2023-07-27T18:19:22Z [ 3126.747243] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 2023-07-27T18:19:22Z [ 3126.748482] Call Trace: 2023-07-27T18:19:22Z [ 3126.748758] 2023-07-27T18:19:22Z [ 3126.748993] 0xffffffff993700cb 2023-07-27T18:19:22Z [ 3126.749350] 0xffffffff993700f0 2023-07-27T18:19:22Z [ 3126.749675] 0xffffffff99365bc8 2023-07-27T18:19:22Z [ 3126.750009] 0xffffffff99365e05 2023-07-27T18:19:22Z [ 3126.750346] 0xffffffff98c482e0 2023-07-27T18:19:22Z [ 3126.750708] 0xffffffff98c9eb16 2023-07-27T18:19:22Z [ 3126.751060] 0xffffffff98c9f0b8 2023-07-27T18:19:22Z [ 3126.751439] 0xffffffff98cb73b8 2023-07-27T18:19:22Z [ 3126.751785] 0xffffffff98abc044 2023-07-27T18:19:22Z [ 3126.752138] 0xffffffff98c7c466 2023-07-27T18:19:22Z [ 3126.752486] 0xffffffff98c7fa96 2023-07-27T18:19:22Z [ 3126.752835] 0xffffffff98c7fd56 2023-07-27T18:19:22Z [ 3126.753181] 0xffffffff9938b300 2023-07-27T18:19:22Z [ 3126.753553] 0xffffffff99400b64 2023-07-27T18:19:22Z [ 3126.753892] RIP: 0033:0x00007f2fdb3780a3 2023-07-27T18:19:22Z [ 3126.754311] Code: 2a 4c 8d 42 10 48 29 e8 48 8d 3d f8 ba 14 00 48 83 ce 04 48 89 4b 60 48 39 fb 48 0f 45 ee 48 83 c8 01 48 83 cd 01 48 89 6a 08 <48> 89 41 08 48 83 c4 48 4c 89 c0 5b 5d 41 5c 41 5d 41 5e 41 5f c3 2023-07-27T18:19:22Z [ 3126.756339] RSP: 002b:00007ffe0f5b0be0 EFLAGS: 00010206 2023-07-27T18:19:22Z [ 3126.756916] RAX: 0000000000020121 RBX: 00007f2fdb4c3b80 RCX: 000055cc9c68dee0 2023-07-27T18:19:22Z [ 3126.757695] RDX: 000055cc9c5a5aa0 RSI: 00000000000e8444 RDI: 00007f2fdb4c3b80 2023-07-27T18:19:22Z [ 3126.758451] RBP: 00000000000e8441 R08: 000055cc9c5a5ab0 R09: 00007f2fdb4c3be0 2023-07-27T18:19:22Z [ 3126.759203] R10: 00000000000e8460 R11: 000055cc9c5c6000 R12: 0000000000020560 2023-07-27T18:19:22Z [ 3126.759961] R13: fffffffffffff000 R14: 000055cc9c5a5aa0 R15: 00000000000e8460 2023-07-27T18:19:22Z [ 3126.760789] 2023-07-27T18:19:22Z [ 3126.761043] Mem-Info: 2023-07-27T18:19:22Z [ 3126.761314] active_anon:1353893 inactive_anon:420828 isolated_anon:0 2023-07-27T18:19:22Z [ 3126.761314] active_file:12840 inactive_file:476776 isolated_file:6 2023-07-27T18:19:22Z [ 3126.761314] unevictable:0 dirty:44589 writeback:0 2023-07-27T18:19:22Z [ 3126.761314] slab_reclaimable:26310 slab_unreclaimable:2665 2023-07-27T18:19:22Z [ 3126.761314] mapped:60517 shmem:1401164 pagetables:1823 bounce:0 2023-07-27T18:19:22Z [ 3126.761314] kernel_misc_reclaimable:0 2023-07-27T18:19:22Z [ 3126.761314] free:3273 free_pcp:233 free_cma:0 2023-07-27T18:19:22Z [ 3126.765267] Node 0 active_anon:5415572kB inactive_anon:1683312kB active_file:51360kB inactive_file:1907104kB unevictable:0kB isolated(anon):0kB isolated(file):24kB mapped:242068kB dirty:178356kB writeback:0kB shmem:5604656kB writeback_tmp:0kB kernel_stack:1920kB pagetables:7292kB all_unreclaimable? yes 2023-07-27T18:19:22Z [ 3126.768087] Node 0 DMA32 free:3544kB min:3812kB low:4756kB high:5700kB reserved_highatomic:10240KB active_anon:361692kB inactive_anon:316812kB active_file:100kB inactive_file:84kB unevictable:0kB writepending:0kB present:1048032kB managed:944612kB mlocked:0kB bounce:0kB free_pcp:596kB local_pcp:128kB free_cma:0kB 2023-07-27T18:19:22Z [ 3126.771065] lowmem_reserve[]: 0 0 8192 2023-07-27T18:19:22Z [ 3126.771479] Node 0 Movable free:9548kB min:3484kB low:11872kB high:20260kB reserved_highatomic:0KB active_anon:5053880kB inactive_anon:1366500kB active_file:51328kB inactive_file:1906884kB unevictable:0kB writepending:178452kB present:8388608kB managed:8388608kB mlocked:0kB bounce:0kB free_pcp:336kB local_pcp:152kB free_cma:0kB 2023-07-27T18:19:22Z [ 3126.774601] lowmem_reserve[]: 0 0 0 2023-07-27T18:19:22Z [ 3126.774978] Node 0 DMA32: 390*4kB (UMH) 144*8kB (UMH) 42*16kB (UMH) 3*32kB (H) 1*64kB (H) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3544kB 2023-07-27T18:19:22Z [ 3126.776451] Node 0 Movable: 1*4kB (M) 1*8kB (M) 0*16kB 0*32kB 1*64kB (M) 0*128kB 1*256kB (M) 0*512kB 1*1024kB (M) 0*2048kB 2*4096kB (M) = 9548kB 2023-07-27T18:19:22Z [ 3126.777867] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB 2023-07-27T18:19:22Z [ 3126.778812] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB 2023-07-27T18:19:22Z [ 3126.779720] 1890763 total pagecache pages 2023-07-27T18:19:22Z [ 3126.780210] 0 pages in swap cache 2023-07-27T18:19:22Z [ 3126.780702] Swap cache stats: add 0, delete 0, find 0/0 2023-07-27T18:19:22Z [ 3126.781304] Free swap = 0kB 2023-07-27T18:19:22Z [ 3126.781627] Total swap = 0kB 2023-07-27T18:19:22Z [ 3126.781930] 2359160 pages RAM 2023-07-27T18:19:22Z [ 3126.782254] 0 pages HighMem/MovableOnly 2023-07-27T18:19:22Z [ 3126.782667] 25855 pages reserved 2023-07-27T18:19:22Z [ 3126.783013] Tasks state (memory values in pages): 2023-07-27T18:19:22Z [ 3126.783512] [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name 2023-07-27T18:19:22Z [ 3126.784476] [ 118] 0 118 319 8 40960 0 0 udhcpc 2023-07-27T18:19:22Z [ 3126.785379] [ 119] 0 119 1210 161 45056 0 0 udevd 2023-07-27T18:19:22Z [ 3126.786234] [ 121] 0 121 209 19 40960 0 0 acpid 2023-07-27T18:19:22Z [ 3126.787092] [ 123] 0 123 27604 4251 221184 0 0 vector 2023-07-27T18:19:22Z [ 3126.787965] [ 125] 0 125 321 8 40960 0 0 vmstart 2023-07-27T18:19:22Z [ 3126.788901] [ 127] 0 127 1550 113 53248 0 0 su 2023-07-27T18:19:22Z [ 3126.789755] [ 131] 0 131 1550 113 53248 0 0 su 2023-07-27T18:19:22Z [ 3126.790592] [ 134] 0 134 1550 113 53248 0 0 su 2023-07-27T18:19:22Z [ 3126.791439] [ 137] 0 137 1040 436 40960 0 0 bash 2023-07-27T18:19:22Z [ 3126.792322] [ 148] 1000 148 321 1 45056 0 0 sh 2023-07-27T18:19:22Z [ 3126.793185] [ 149] 1000 149 121954 1132 131072 0 0 compute_ctl 2023-07-27T18:19:22Z [ 3126.794108] [ 150] 65534 150 620 17 45056 0 0 sh 2023-07-27T18:19:22Z [ 3126.794982] [ 151] 101 151 620 16 49152 0 0 sh 2023-07-27T18:19:22Z [ 3126.795823] [ 152] 65534 152 620 17 45056 0 0 sh 2023-07-27T18:19:22Z [ 3126.796701] [ 153] 65534 153 496 78 28672 0 0 pgbouncer 2023-07-27T18:19:22Z [ 3126.797629] [ 154] 65534 154 179954 328 98304 0 0 postgres_export 2023-07-27T18:19:22Z [ 3126.798587] [ 155] 101 155 186538 3915 167936 0 0 vm-informant 2023-07-27T18:19:22Z [ 3126.799516] [ 377] 1000 377 69130 18905 262144 0 0 postgres 2023-07-27T18:19:22Z [ 3126.800447] [ 379] 1000 379 69250 2417 212992 0 0 postgres 2023-07-27T18:19:22Z [ 3126.801353] [ 380] 1000 380 69230 36209 450560 0 0 postgres 2023-07-27T18:19:22Z [ 3126.802235] [ 382] 1000 382 69171 2575 151552 0 0 postgres 2023-07-27T18:19:22Z [ 3126.803167] [ 383] 1000 383 69785 3188 274432 0 0 postgres 2023-07-27T18:19:22Z [ 3126.804075] [ 384] 1000 384 70028 4503 258048 0 0 postgres 2023-07-27T18:19:22Z [ 3126.805187] [ 385] 1000 385 69731 2306 237568 0 0 postgres 2023-07-27T18:19:22Z [ 3126.806116] [ 386] 1000 386 69744 2380 159744 0 0 postgres 2023-07-27T18:19:22Z [ 3126.807002] [ 387] 1000 387 69227 1176 139264 0 0 postgres 2023-07-27T18:19:22Z [ 3126.807883] [ 388] 1000 388 69730 2151 184320 0 0 postgres 2023-07-27T18:19:22Z [ 3126.808958] [ 391] 1000 391 70213 5816 225280 0 0 postgres 2023-07-27T18:19:22Z [ 3126.809872] [ 392] 1000 392 70384 5303 212992 0 0 postgres 2023-07-27T18:19:22Z [ 3126.810775] [ 396] 101 396 186672 4836 176128 0 0 vm-informant 2023-07-27T18:19:22Z [ 3126.811709] [ 437] 1000 437 432420 403523 3399680 0 0 postgres 2023-07-27T18:19:22Z [ 3126.812765] [ 1138] 1000 1138 70404 5369 245760 0 0 postgres 2023-07-27T18:19:22Z [ 3126.813707] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=postgres,pid=437,uid=1000 2023-07-27T18:19:22Z [ 3126.815092] Out of memory: Killed process 437 (postgres) total-vm:1729680kB, anon-rss:1452148kB, file-rss:8700kB, shmem-rss:153244kB, UID:1000 pgtables:3320kB oom_score_adj:0 ```

Things that jump out:

1. Total RAM was 2359160 pages - about 8.99 GiB
2. Total rss was 511383 pages - about 1.95 GiB
3. Total pagecache was 1890763 pages - about 7.21 GiB

I'm not sure I'm reading that correctly, especially given 1.95 + 7.21 > 8.99, but broadly pagecache is very high. (I think that matches @knizhnik's analysis here?)

Some other information:

Memory usage, according to the metrics that the autoscaler-agent was receiving looked consistent:

So: Even though the memory was behaving in roughly the same way each time (and the VM did scale up from 8 → 9 GiB RAM [agent request at 18:19:01]), presumably we just crossed some threshold? The pattern of "gradual increase then drop-off to the baseline" occurred every 3.5 minutes, and peak memory (that we observed) was trending slightly higher each time. That said, this would mean that the VM's memory usage sharply increased at the end of the spike and we never observed it, which... may be true? I'm not sure.

[LizardWizzard]

Getting OOM on simple pgbench init workload: https://neonprod.grafana.net/goto/gCtQGCeVR?orgId=1

It worked before.

command used: pgbench -s300 -i -I dtGvp

[sharnoff]

I think this issue was due to OOM issues that have since been fixed (iirc, with neondatabase/neon#5333). In light of that, closing this — we can reopen if it persists.