Nano-node: Memory usage during bootstrap - can't the data be temp stored on disk?

[requestingrequester]

Bootstrapping eats up so much memory that it's impossible to run the node on a Raspi at the moment. A swap file isn't a permanent solution and might make matters worse since there's no guarantee the swap file will be filled with data from rai_node instead of system data, making everything slow and destroying the flash drive over time. I actually just tested that the other day and that seemed to be the result.

So I figured I'd ask if these several gigabytes of data can't be written to disk and read back into RAM when needed? Surely this might make the process take a bit longer but it will be useable on smaller devices.

I'm a programmer but have almost no knowledge of C and I can't understand the node well enough to even begin to implement this myself.

[clemahieu]

Yea we should be able to do something about this, flushing without getting too full.

[requestingrequester]

Great, thanks! Looking forward to it.

[baryluk]

Hi, I am getting similar issue. I am bootstraping a node (using your docker images), and after about a day is now using 10GB of RSS RAM (and 1000 GB of virtual memory!). Also it "only" uses about 130% of CPU (1.3 cores, out of 6 cores on my machines, that can each run two threads).

Some kind of monitoring for internal data structure sizes (i.e. sizes of queues, caches, peer tables, buffers) would be extremely valuable. It could also be memory leak, but without memory allocator that tracks allocations it is rather hard to judge what is leaking.

Whatever it is that it is consuming so much memory, most likely it should be reworked to store some data on disk instead (i.e. if it is a queue, we only need elements from a head and tail to be in memory - middle of the queue can be stored and moved in and out to file asynchronously for example).

PS. Docker image looks to be 13.0. Some random snippets from the log:

[2018-05-30 03:24:30.253221]: Node starting, version: 13.0
...
[2018-05-30 03:45:44.869687]: 32510 accounts in pull queue
[2018-05-30 03:45:49.699647]: 8807396 blocks in processing queue
...
[2018-05-30 04:52:10.184841]: 12640589 blocks in processing queue
...
[2018-05-30 07:45:04.120658]: 21464386 blocks in processing queue
...
[2018-05-30 12:29:12.080495]: 34988090 blocks in processing queue
...
[2018-05-30 19:27:35.824671]: 49014031 blocks in processing queue
[2018-05-30 19:27:50.835093]: 49031574 blocks in processing queue

and still growing.

[baryluk]

After about 24 hours of work:

...
[2018-05-31 00:27:23.874943]: 58264886 blocks in processing queue
[2018-05-31 00:27:38.965968]: 58275762 blocks in processing queue
[2018-05-31 00:27:54.097008]: 58287366 blocks in processing queue
[2018-05-31 00:28:09.269567]: 58299214 blocks in processing queue

     PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                            
11065 root      20   0 1039.4g  11.1g  71476 S 113.5  35.4   1439:18 rai_node --daemon      

I am running out of swap space even:

$ LC_ALL=C free -h
              total        used        free      shared  buff/cache   available
Mem:           31Gi        27Gi       3.0Gi       438Mi       1.1Gi       3.3Gi
Swap:         7.4Gi       7.4Gi        12Mi

[clemahieu]

There aren’t that many blocks in the network so it shouldn’t have that many in the queue. What type of disk are you using? Either way I think we’ll add logic to hold off making more bootstrap requests until the processing queue is less full.

[baryluk]

After about 30 hours of work, it just crashed:

...
[2018-05-31 16:39:11.979892]: 112376339 blocks in processing queue
[2018-05-31 16:39:27.429521]: 112381282 blocks in processing queue

dmesg:

...
[1112093.864905] hddtemp invoked oom-killer: gfp_mask=0x14200ca(GFP_HIGHUSER_MOVABLE), nodemask=(null), order=0, oom_score_adj=0
[1112093.864949] hddtemp cpuset=/ mems_allowed=0
[1112093.864970] CPU: 0 PID: 3139 Comm: hddtemp Tainted: P           O     4.16.0-1-amd64 #1 Debian 4.16.5-1
[1112093.865002] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./X79 Extreme11, BIOS P3.30 02/14/2014
[1112093.865035] Call Trace:
[1112093.865053]  dump_stack+0x5c/0x85
[1112093.865069]  dump_header+0x6b/0x289
[1112093.865087]  ? apparmor_capable+0xa4/0xe0
[1112093.865103]  oom_kill_process+0x228/0x470
[1112093.865120]  out_of_memory+0x2ab/0x4b0
[1112093.865136]  __alloc_pages_slowpath+0x9f2/0xd80
[1112093.865155]  __alloc_pages_nodemask+0x236/0x250
[1112093.865173]  filemap_fault+0x1f9/0x630
[1112093.865189]  ? filemap_map_pages+0x182/0x340
[1112093.865207]  ? _cond_resched+0x15/0x40
[1112093.865238]  ext4_filemap_fault+0x2c/0x40 [ext4]
[1112093.865260]  __do_fault+0x1f/0xb0
[1112093.865274]  __handle_mm_fault+0xca6/0x1220
[1112093.865293]  handle_mm_fault+0xdc/0x210
[1112093.865310]  __do_page_fault+0x256/0x4e0
[1112093.865328]  ? page_fault+0x2f/0x50
[1112093.865343]  page_fault+0x45/0x50
[1112093.865357] RIP: 42fea680:          (null)
[1112093.865373] RSP: 42fea320:0000000000000001 EFLAGS: 557c879674d0
[1112093.865388] Mem-Info:
[1112093.865423] active_anon:6973762 inactive_anon:625270 isolated_anon:0
                  active_file:580 inactive_file:522 isolated_file:32
                  unevictable:12 dirty:3 writeback:1 unstable:0
                  slab_reclaimable:29435 slab_unreclaimable:196618
                  mapped:64086 shmem:73784 pagetables:51871 bounce:0
                  free:49913 free_pcp:2006 free_cma:0
[1112093.865537] Node 0 active_anon:27895048kB inactive_anon:2501080kB active_file:2320kB inactive_file:2088kB unevictable:48kB isolated(anon):0kB isolated(file):128kB mapped:256344kB dirty:12kB writeback:4kB shmem:295136kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 98304kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
[1112093.865627] Node 0 DMA free:15900kB min:32kB low:44kB high:56kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15996kB managed:15900kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[1112093.865711] lowmem_reserve[]: 0 2912 32072 32072 32072
[1112093.865732] Node 0 DMA32 free:122696kB min:6132kB low:9112kB high:12092kB active_anon:2339424kB inactive_anon:270936kB active_file:380kB inactive_file:980kB unevictable:0kB writepending:0kB present:3075880kB managed:3075880kB mlocked:0kB kernel_stack:7804kB pagetables:38168kB bounce:0kB free_pcp:1280kB local_pcp:68kB free_cma:0kB
[1112093.865828] lowmem_reserve[]: 0 0 29159 29159 29159
[1112093.865847] Node 0 Normal free:61056kB min:61416kB low:91272kB high:121128kB active_anon:25555624kB inactive_anon:2230144kB active_file:1916kB inactive_file:2860kB unevictable:48kB writepending:16kB present:30408704kB managed:29863980kB mlocked:48kB kernel_stack:37172kB pagetables:169316kB bounce:0kB free_pcp:6744kB local_pcp:464kB free_cma:0kB
[1112093.865946] lowmem_reserve[]: 0 0 0 0 0
[1112093.865962] Node 0 DMA: 1*4kB (U) 1*8kB (U) 1*16kB (U) 2*32kB (U) 3*64kB (U) 2*128kB (U) 0*256kB 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15900kB
[1112093.866015] Node 0 DMA32: 769*4kB (UME) 2256*8kB (UME) 2776*16kB (UMEH) 1136*32kB (UMEH) 228*64kB (UMEH) 13*128kB (UMEH) 17*256kB (UMH) 1*512kB (E) 0*1024kB 0*2048kB 0*4096kB = 123012kB
[1112093.866076] Node 0 Normal: 950*4kB (UME) 2536*8kB (UME) 1505*16kB (UM) 468*32kB (UM) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 63144kB
[1112093.866127] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
[1112093.866157] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[1112093.866186] 81986 total pagecache pages
[1112093.866203] 7111 pages in swap cache
[1112093.866217] Swap cache stats: add 10871839, delete 10865102, find 6981952/10585488
[1112093.866243] Free swap  = 0kB
[1112093.866255] Total swap = 7811068kB
[1112093.866269] 8375145 pages RAM
[1112093.866280] 0 pages HighMem/MovableOnly
[1112093.866295] 136205 pages reserved
[1112093.866308] 0 pages hwpoisoned
[1112093.866320] [ pid ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
...
[1112094.004453] [11065]     0 11065 276229564  6034288 62898176  1574144             0 rai_node
...
[1112094.144641] Out of memory: Kill process 11065 (rai_node) score 748 or sacrifice child
[1112094.145749] Killed process 11065 (rai_node) total-vm:1104918256kB, anon-rss:24137152kB, file-rss:0kB, shmem-rss:0kB
[1112095.456087] oom_reaper: reaped process 11065 (rai_node), now anon-rss:0kB, file-rss:4kB, shmem-rss:0kB

I am using RAID1 NVMe/M.2 Samsung using ZFS+LUKS, 1TB. It can do about 2000MB/s of writes, and 3000MB/s of reads, at more than 50k IOPS.

$ LC_ALL=C ls -lh
total 825M
-rw-r--r-- 1 root root 2.7K May 30 05:16 config.json
-rw------- 1 root root 817M May 31 18:39 data.ldb
-rw------- 1 root root 8.0K May 31 18:47 data.ldb-lock
drwxr-xr-x 2 root root    5 May 31 18:39 log

docker restarted container automaticall, and it is again doing bootstrap:

...
[2018-05-31 16:40:03.134960]: Starting bootstrap attempt
...
[2018-05-31 16:40:18.456678]: 8509 blocks in processing queue
...
...
[2018-05-31 16:49:06.100165]: Aborting frontier req because it was too slow
[2018-05-31 16:49:06.100586]: frontier_req failed, reattempting
[2018-05-31 16:49:11.104500]: frontier_req failed, reattempting
[2018-05-31 16:49:13.807233]: Received 1 frontiers from [::ffff:45.32.246.108]:7075
[2018-05-31 16:49:20.709434]: 317940 blocks in processing queue

[Roconda]

Similar issues, running out of memory from time to time.

Linux Kernel version: 4.4.0
Nano version: V13.0 (docker container)

RPC also becomes unresponsive due to timeouts.

[baryluk]

Same issue on docker image nanocurrency/nano:master yesterday. Unable to bootstrap / sync after days on previous versions.

[Roconda]

Upgraded to nanocurrency/nano:V14.0, seeing major improvements in RPC response times. Block count is also increasing.

My node has 2G mem and 2 CPUs hosted at a quality vps provider.

[rkeene]

Is this still an on-going issue ? We have made many many improvements in V14 and V15 and would like to confirm that none of them resolved the issue.

[clemahieu]

This was fixed in bootstrap_attempt::run() with: if (!node->block_processor.full ()). We can document this line an close.

[rkeene]

This issue has been fixed in commit [772b056a2729d6dc70287f387eb3564a79539e95], which is present in V14.0 and newer. I am closing this ticket based on this information. Let me know if you have any questions !