V26.1 Node killed by OS due to 'Out of Memory' in heavy voting/traffic scenario

[jamescoxon]

Summary

In the last 24hrs my PR has repeatedly been killed by OS for 'Out of Memory' requiring restarting, it is running unmodified 26.1 and uses RocksDB.

Turning voting off didn't change the outcome, issue wasn't present in earlier periods of high traffic. Haven't seen similar issues on other nodes running lmdb backends.

Example Restarts:

Start time: Sun Mar  3 05:17:49 2024 UTC
Start time: Sun Mar  3 05:37:15 2024 UTC
Start time: Sun Mar  3 06:02:41 2024 UTC
Start time: Sun Mar  3 06:42:35 2024 UTC
Start time: Sun Mar  3 07:33:08 2024 UTC

dmesg output:

[47082.653915] nginx invoked oom-killer: gfp_mask=0x140cca(GFP_HIGHUSER_MOVABLE|__GFP_COMP), order=0, oom_score_adj=0
[47082.653925] CPU: 2 PID: 604 Comm: nginx Not tainted 6.2.0-20-generic #20-Ubuntu
[47082.653928] Hardware name: Dell Inc. PowerEdge R210 II/09T7VV, BIOS 2.10.0 05/24/2018
[47082.653930] Call Trace:
[47082.653932]  <TASK>
[47082.653935]  dump_stack_lvl+0x48/0x70
[47082.653942]  dump_stack+0x10/0x20
[47082.653945]  dump_header+0x50/0x290
[47082.653949]  oom_kill_process+0x10d/0x1c0
[47082.653951]  out_of_memory+0x101/0x370
[47082.653953]  __alloc_pages_may_oom+0x112/0x1e0
[47082.653957]  __alloc_pages_slowpath.constprop.0+0x4c7/0xa20
[47082.653961]  __alloc_pages+0x31d/0x350
[47082.653964]  alloc_pages+0x90/0x1a0
[47082.653966]  folio_alloc+0x1d/0x60
[47082.653968]  filemap_alloc_folio+0x31/0x40
[47082.653970]  __filemap_get_folio+0x1d4/0x3c0
[47082.653974]  filemap_fault+0x35c/0x6f0
[47082.653977]  __do_fault+0x39/0x150
[47082.653980]  do_read_fault+0xef/0x170
[47082.653983]  do_fault+0xa0/0x2f0
[47082.653985]  handle_pte_fault+0x118/0x240
[47082.653988]  __handle_mm_fault+0x661/0x720
[47082.653992]  handle_mm_fault+0x119/0x330
[47082.653996]  do_user_addr_fault+0x1c1/0x720
[47082.654000]  exc_page_fault+0x80/0x1b0
[47082.654003]  asm_exc_page_fault+0x27/0x30
[47082.654007] RIP: 0033:0x7f162c5abf39
[47082.654012] Code: Unable to access opcode bytes at 0x7f162c5abf0f.
[47082.654013] RSP: 002b:00007ffe629e6760 EFLAGS: 00010246
[47082.654016] RAX: 0000000000000000 RBX: 000055f700d89b00 RCX: 0000000000000000
[47082.654017] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
[47082.654019] RBP: 00007f162c91a1e4 R08: 0000000000000000 R09: 0000000000000000
[47082.654020] R10: 00007ffe629e65a0 R11: a39096a2da50670f R12: 00007f162c64df20
[47082.654021] R13: 00007f162c6409a0 R14: 000055f6ffd1a5a6 R15: 000055f700d27a70
[47082.654024]  </TASK>
[47082.654025] Mem-Info:
[47082.654026] active_anon:1179890 inactive_anon:660120 isolated_anon:0
                active_file:13 inactive_file:451 isolated_file:75
                unevictable:0 dirty:0 writeback:0
                slab_reclaimable:47176 slab_unreclaimable:32726
                mapped:693 shmem:658 pagetables:14327
                sec_pagetables:0 bounce:0
                kernel_misc_reclaimable:0
                free:33783 free_pcp:320 free_cma:0
[47082.654032] Node 0 active_anon:4719560kB inactive_anon:2640480kB active_file:52kB inactive_file:1804kB unevictable:0kB isolated(anon):0kB isolated(file):300kB mapped:2772kB dirty:0kB writeback:0kB shmem:2632kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB kernel_stack:3424kB pagetables:57308kB sec_pagetables:0kB all_unreclaimable? no
[47082.654037] Node 0 DMA free:14336kB boost:0kB min:128kB low:160kB high:192kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15360kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[47082.654043] lowmem_reserve[]: 0 2882 7792 7792 7792
[47082.654047] Node 0 DMA32 free:44736kB boost:2048kB min:26996kB low:33232kB high:39468kB reserved_highatomic:0KB active_anon:1829976kB inactive_anon:952680kB active_file:904kB inactive_file:1748kB unevictable:0kB writepending:4kB present:3097324kB managed:3031564kB mlocked:0kB bounce:0kB free_pcp:1280kB local_pcp:264kB free_cma:0kB
[47082.654052] lowmem_reserve[]: 0 0 4910 4910 4910
[47082.654056] Node 0 Normal free:76060kB boost:0kB min:42500kB low:53124kB high:63748kB reserved_highatomic:40960KB active_anon:2888896kB inactive_anon:1688132kB active_file:168kB inactive_file:24kB unevictable:0kB writepending:0kB present:5242880kB managed:5036576kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[47082.654061] lowmem_reserve[]: 0 0 0 0 0
[47082.654065] Node 0 DMA: 0*4kB 0*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB (M) 3*4096kB (M) = 14336kB
[47082.654076] Node 0 DMA32: 51*4kB (UME) 67*8kB (UE) 95*16kB (UE) 810*32kB (UME) 210*64kB (UM) 22*128kB (UM) 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 44436kB
[47082.654090] Node 0 Normal: 769*4kB (UME) 200*8kB (UME) 53*16kB (UME) 1160*32kB (UM) 352*64kB (UM) 72*128kB (UM) 7*256kB (UM) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 76180kB
[47082.654104] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[47082.654106] 23091 total pagecache pages
[47082.654107] 21924 pages in swap cache
[47082.654107] Free swap  = 0kB
[47082.654108] Total swap = 5197816kB
[47082.654109] 2089050 pages RAM
[47082.654110] 0 pages HighMem/MovableOnly
[47082.654111] 68175 pages reserved
[47082.654112] 0 pages hwpoisoned
[47082.654113] Tasks state (memory values in pages):
[47082.654113] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
...
...
[47082.654210] [  31537]     0 31537  3230007  1294731 20992000  1255530             0 nano_node
[47082.654212] [  31969]     0 31969      683       64    45056        0             0 logrotate
[47082.654214] [  31970]     0 31970     3414       96    61440       32             0 perl
[47082.654216] [  32539]   112 32539    10901      128    86016        0             0 pickup
[47082.654218] [  32865]     0 32865     3786      384    69632        0             0 sshd
[47082.654221] [  32885]     0 32885     2696        0    49152        0             0 sshd
[47082.654223] [  32886]     0 32886     2670       64    53248        0             0 sshd
[47082.654224] [  32887]     0 32887      411       32    32768        0             0 sshd
[47082.654226] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/user.slice/user-0.slice/session-2.scope,task=nano_node,pid=31537,uid=0
[47082.654300] Out of memory: Killed process 31537 (nano_node) total-vm:12920028kB, anon-rss:5178796kB, file-rss:128kB, shmem-rss:0kB, UID:0 pgtables:20500kB oom_score_adj:0

Running perf

Samples: 3M of event 'cycles', Event count (approx.): 1171564763991
Overhead  Command          Shared Object      Symbol
   9.85%  Vote processing  nano_node          [.] ed25519_sign_open
   4.76%  Vote processing  nano_node          [.] ge25519_double_p1p1
   1.63%  Vote processing  nano_node          [.] CryptoPP::Rijndael_Enc_AdvancedProcessBlocks_SSE2
   1.41%  Vote processing  nano_node          [.] CryptoPP::Rijndael::Base::UncheckedSetKey
   1.24%  Bootstrap work   nano_node          [.] rocksdb::MergingIterator::NextAndGetResult
   1.03%  Bootstrap work   [kernel.kallsyms]  [k] copy_user_generic_string
   1.03%  I/O              nano_node          [.] blake2b_compress
   0.93%  I/O              libc.so.6          [.] pthread_mutex_lock
   0.91%  Vote processing  nano_node          [.] curve25519_square_times.constprop.3
   0.90%  Vote processing  nano_node          [.] curve25519_square_times.constprop.4
   0.88%  I/O              [kernel.kallsyms]  [k] syscall_exit_to_user_mode
   0.87%  Bootstrap work   nano_node          [.] rocksdb::DBIter::FindNextUserEntryInternal
   0.85%  I/O              [kernel.kallsyms]  [k] try_to_wake_up
   0.85%  Bootstrap work   nano_node          [.] nano::store::rocksdb::iterator<nano::public_key, nano::account_info>::fill
   0.79%  Vote processing  nano_node          [.] nano::vote_cache::entry::tally
   0.74%  Bootstrap work   nano_node          [.] rocksdb::DBIter::Next
   0.72%  Vote processing  nano_node          [.] nano::rep_weights::get
   0.71%  I/O              nano_node          [.] std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release
   0.67%  I/O              [kernel.kallsyms]  [k] native_queued_spin_lock_slowpath
   0.66%  I/O              libc.so.6          [.] pthread_mutex_unlock
   0.64%  Bootstrap work   nano_node          [.] nano::uint256_union::uint256_union
   0.61%  I/O              [kernel.kallsyms]  [k] copy_user_generic_string
   0.59%  Bootstrap work   nano_node          [.] rocksdb::DataBlockIter::NextImpl
   0.56%  I/O              [kernel.kallsyms]  [k] __entry_text_start
   0.56%  Bootstrap work   nano_node          [.] XXH3_hashLong_64b_default.constprop.0
   0.54%  I/O              [kernel.kallsyms]  [k] syscall_return_via_sysret
   0.53%  Vote processing  libc.so.6          [.] pthread_mutex_lock
   0.53%  Vote processing  libc.so.6          [.] pthread_mutex_unlock
   0.52%  Bootstrap work   nano_node          [.] rocksdb::(anonymous namespace)::LevelIterator::NextAndGetResult
   0.52%  Vote processing  nano_node          [.] nano::vote_cache::vote
   0.51%  I/O              nano_node          [.] std::__shared_count<(__gnu_cxx::_Lock_policy)2>::__shared_count
   0.51%  Bootstrap work   nano_node          [.] nano::store::rocksdb::iterator<nano::public_key, nano::account_info>::operator++
   0.45%  Bootstrap asc    nano_node          [.] CryptoPP::Rijndael_Enc_AdvancedProcessBlocks_SSE2
   0.43%  Vote processing  nano_node          [.] std::_Hashtable<nano::block_hash, std::pair<nano::block_hash const, std::shared_ptr<nano::election> >, st
   0.41%  Vote processing  nano_node          [.] blake2b_compress
   0.40%  I/O              libc.so.6          [.] malloc
   0.39%  Bootstrap asc    nano_node          [.] CryptoPP::Rijndael::Base::UncheckedSetKey
   0.39%  I/O              nano_node          [.] rocksdb::MergingIterator::NextAndGetResult
   0.39%  I/O              [kernel.kallsyms]  [k] psi_group_change
   0.39%  Vote processing  nano_node          [.] boost::multi_index::detail::ordered_index_node_impl<boost::multi_index::detail::null_augment_policy, std:
   0.38%  Vote processing  nano_node          [.] boost::multi_index::detail::hashed_index<boost::multi_index::const_mem_fun<nano::vote_cache::entry, nano:
   0.37%  Bootstrap work   nano_node          [.] nano::uint256_union::uint256_union
   0.35%  I/O              nano_node          [.] nano::frontier_req_client::next
   0.33%  Bootstrap work   nano_node          [.] rocksdb::DBIter::FindNextUserEntry
   0.32%  Bootstrap work   nano_node          [.] nano::frontier_req_server::next
   0.32%  Bootstrap work   libc.so.6          [.] memcpy
   0.32%  Bootstrap work   nano_node          [.] rocksdb::DBIter::ParseKey
   0.32%  I/O              nano_node          [.] XXH3_hashLong_64b_default.constprop.0
   0.31%  Bootstrap work   nano_node          [.] rocksdb::BlockBasedTableIterator::NextAndGetResult
   0.31%  Bootstrap work   nano_node          [.] rocksdb::DBIter::TooManyInternalKeysSkipped

Node version

26.1

Build details

Network: live, version: V26.1
Build Info: 66d74ff "GNU C++ version " "12.2.0" "BOOST 108100" BUILT "Feb 28 2024"
Database backend: RocksDB 7.8.3

4 core, 8Gb Ram, 5G Swap

OS and version

Ubuntu 23.04 (GNU/Linux 6.2.0-20-generic x86_64)

Steps to reproduce the behavior

1. Run node
2. Wait for killed and restart node

Expected behavior

Node has run for many months without these issues.

Actual behavior

Repeatedly being killed due to out of memory (nano-node is clearly using the largest amount) - could this be due to the RocksDB itself?

Possible solution

No response

Supporting files

No response

[jamescoxon]

Outcome: Following more analysis it appeared that the RPC 'representatives_online' was consuming large amounts of ram due to the recent spamming of representatives which was causing the node to crash - to fix this the RPC command was aggressively cached.
This is now being fixed in PR #4482