Better memory managment - `fatal error: runtime: out of memory`
Closed this issue · 2 comments
kingster commented
DKV Process get killed due to OOM
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: fatal error: runtime: out of memory
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: runtime stack:
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: runtime.throw(0x12e4daa, 0x16)
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: /usr/local/go/src/runtime/panic.go:774 +0x72
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: runtime.sysMap(0xc6c0000000, 0xac000000, 0x1d74998)
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: /usr/local/go/src/runtime/mem_linux.go:169 +0xc5
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: runtime.(*mheap).sysAlloc(0x1d48660, 0xaa68c000, 0x7fbca9cae7c8, 0x45fe37)
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: /usr/local/go/src/runtime/malloc.go:701 +0x1cd
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: runtime.(*mheap).grow(0x1d48660, 0x55346, 0x7fbcffffffff)
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: /usr/local/go/src/runtime/mheap.go:1255 +0xa3
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: runtime.(*mheap).allocSpanLocked(0x1d48660, 0x55346, 0x1d749a8, 0xc50515)
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: /usr/local/go/src/runtime/mheap.go:1170 +0x266
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: runtime.(*mheap).alloc_m(0x1d48660, 0x55346, 0x7fbc34000101, 0x0)
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: /usr/local/go/src/runtime/mheap.go:1022 +0xc2
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: runtime.(*mheap).alloc.func1()
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: /usr/local/go/src/runtime/mheap.go:1093 +0x4c
Jun 12 17:22:32 dkv-dkv-data-en-8293703 dkv[27627]: runtime.(*mheap).alloc(0x1d48660, 0x55346, 0xffffffffff010101, 0x20)
Jun 12 17:22:34 dkv-dkv-data-en-8293703 systemd[1]: dkv.service: Main process exited, code=exited, status=2/INVALIDARGUMENT
Jun 12 17:22:34 dkv-dkv-data-en-8293703 systemd[1]: dkv.service: Unit entered failed state.
kingster commented
After digging some more, I found that a lot of memory is being consumed dkv process.
DKV config
$ cat /etc/dkv/conf.ini
role=master
db-engine=rocksdb
db-engine-ini=/etc/dkv/rocksdb.ini
diskless=false
block-cache-size=10737412742 #10G
statsd-addr=127.0.0.1:8125
pprof=true
...
nexus-repl-timeout=5
nexus-max-snapshots=2
nexus-max-wals=20
nexus-snapshot-count=100000000
nexus-snapshot-catchup-entries=5000
root@dkv-dkv-data-en-8293703:/home/kinshuk.bairagi# ps -eo pid,ppid,cmd,%mem,%cpu --sort=-%mem | head
PID PPID CMD %MEM %CPU
16799 1 /var/lib/fk-3p-dkv/dkvsrv - 80.9 25.0
539 1 /lib/systemd/systemd-journa 0.2 0.0
4104 671 /usr/sbin/rsyslogd -n -i /v 0.0 0.0
675 667 /usr/local/bin/agent-bastio 0.0 0.0
16905 12507 journalctl -f -u dkv 0.0 0.0
1 0 /sbin/init 0.0 0.0
12490 962 sshd: kinshuk.bairagi [priv 0.0 0.0
12492 1 /lib/systemd/systemd --user 0.0 0.0
962 1 /usr/sbin/sshd -D 0.0 0.0
root@dkv-dkv-data-en-8293703:/home/kinshuk.bairagi# free -m
total used free shared buff/cache available
Mem: 40242 32892 1398 77 5951 6748
Swap: 0 0 0
pprof heap analysis at this time.
kingster commented
Here is a OOM Trace.
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: fatal error: runtime: out of memory
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime stack:
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.throw(0x12dfb36, 0x16)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/panic.go:1117 +0x72
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.sysMap(0xc880000000, 0x204000000, 0x1c239b0)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/mem_linux.go:169 +0xc6
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.(*mheap).sysAlloc(0x1bf68a0, 0x203400000, 0x455f17, 0x1bf68a8)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/malloc.go:729 +0x1e5
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.(*mheap).grow(0x1bf68a0, 0x1019d3, 0x0)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/mheap.go:1346 +0x85
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.(*mheap).allocSpan(0x1bf68a0, 0x1019d3, 0x460100, 0xc00041a780)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/mheap.go:1173 +0x609
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.(*mheap).alloc.func1()
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/mheap.go:910 +0x59
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.systemstack(0x0)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/asm_amd64.s:379 +0x66
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.mstart()
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/proc.go:1246
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: goroutine 123 [running]:
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.systemstack_switch()
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/asm_amd64.s:339 fp=0xc0008230c8 sp=0xc0008230c0 pc=0x499a00
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.(*mheap).alloc(0x1bf68a0, 0x1019d3, 0xd0101, 0x0)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/mheap.go:904 +0x85 fp=0xc000823118 sp=0xc0008230c8 pc=0x451bc5
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.(*mcache).allocLarge(0x7f75d5949878, 0x2033a51f9, 0x101, 0xc000823230)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/mcache.go:224 +0x97 fp=0xc000823170 sp=0xc000823118 pc=0x442237
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.mallocgc(0x2033a51f9, 0x118fea0, 0x2033a5101, 0x116d)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/malloc.go:1078 +0x925 fp=0xc0008231f8 sp=0xc000823170 pc=0x437c85
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: runtime.makeslice(0x118fea0, 0x2033a51f9, 0x2033a51f9, 0x200000000)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /usr/local/go/src/runtime/slice.go:98 +0x6c fp=0xc000823228 sp=0xc0008231f8 pc=0x47a44c
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: go.etcd.io/etcd/server/v3/etcdserver/api/snap/snappb.(*Snapshot).Marshal(0xc000823540, 0xc00014d400, 0xc67a526000, 0x2033a51ed, 0x2033a51ed, 0xc2a061f14e)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /root/go/pkg/mod/go.etcd.io/etcd/server/v3@v3.5.0-rc.1/etcdserver/api/snap/snappb/snap.pb.go:88 +0xd8 fp=0xc000823280 sp=0xc000823228 pc=0xa76378
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: go.etcd.io/etcd/server/v3/etcdserver/api/snap.(*Snapshotter).save(0xc00027bcf8, 0xc2d067c750, 0xc02e839ba23877f0, 0xf9fbbe00a)
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: /root/go/pkg/mod/go.etcd.io/etcd/server/v3@v3.5.0-rc.1/etcdserver/api/snap/snapshotter.go:82 +0x20e fp=0xc000823690 sp=0xc000823280 pc=0xa7c6ce
Jun 28 15:02:36 dkv-dkv-data-en-8293702 dkv[5877]: go.etcd.io/etcd/server/v3/etcdserver/api/snap.(*Snapshotter).SaveSnap(...)
OOM happens on snapshotting because it tries to load the entire snapshot of data in memory, which may not be possible. This (#72) needs to be fixed
Also, raftpb.(*Entry).Unmarshal are expected to remain in memory based on the snapshot-count count. This is already documented https://github.com/etcd-io/etcd/blob/af20c3969b5232131f58620eb0072bc7beb368a7/Documentation/upgrades/upgrade_3_2.md and etcd-io/etcd#84721 but reducing this leads to more often snapshots being taken, which blocks writes during that interval #61