Open dasudiy opened 1 year ago
One thing I forgot to mention, I've seen a bunch of "Peer delivering stale transactions" messages in my logs, something I didn't see before. Not sure if it's normal or related to this problem.
Apr 18 03:29:45 eth geth[13045]: INFO [04-18|03:29:45.137] Generating state snapshot root=d34c15..84c4c8 in=159e48..5eae12 at=7cf278..d714e8 accounts=17,284,328 slots=119,872,199 storage=9.35GiB dangling=0 elapsed=21m56.042s
Apr 18 03:29:51 eth geth[13045]: WARN [04-18|03:29:51.031] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=47
Apr 18 03:29:53 eth geth[13045]: INFO [04-18|03:29:53.427] Generating state snapshot root=d34c15..84c4c8 in=159e48..5eae12 at=7d3445..a6aba1 accounts=17,284,328 slots=119,904,977 storage=9.36GiB dangling=0 elapsed=22m4.333s
Apr 18 03:29:56 eth geth[13045]: WARN [04-18|03:29:56.037] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=117
Apr 18 03:29:56 eth geth[13045]: WARN [04-18|03:29:56.873] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=72
Apr 18 03:29:59 eth geth[13045]: WARN [04-18|03:29:59.357] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=107
Apr 18 03:30:00 eth geth[13045]: WARN [04-18|03:30:00.444] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=106
Apr 18 03:30:01 eth geth[13045]: INFO [04-18|03:30:01.673] Generating state snapshot root=d34c15..84c4c8 in=159e48..5eae12 at=7d8ac1..98dcb6 accounts=17,284,328 slots=119,947,987 storage=9.36GiB dangling=0 elapsed=22m12.578s
Apr 18 03:30:02 eth geth[13045]: WARN [04-18|03:30:02.477] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=104
Apr 18 03:30:03 eth geth[13045]: WARN [04-18|03:30:03.405] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=89
Apr 18 03:30:05 eth geth[13045]: WARN [04-18|03:30:05.270] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=111
Apr 18 03:30:06 eth geth[13045]: WARN [04-18|03:30:06.047] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=69
Apr 18 03:30:08 eth geth[13045]: WARN [04-18|03:30:08.108] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=114
Apr 18 03:30:09 eth geth[13045]: WARN [04-18|03:30:09.016] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=84
Apr 18 03:30:09 eth geth[13045]: INFO [04-18|03:30:09.881] Generating state snapshot root=d34c15..84c4c8 in=159e48..5eae12 at=7dd8bb..4ae9e0 accounts=17,284,328 slots=119,986,906 storage=9.36GiB dangling=0 elapsed=22m20.786s
Apr 18 03:30:15 eth geth[13045]: INFO [04-18|03:30:15.468] Aborting state snapshot generation root=d34c15..84c4c8 in=159e48..5eae12 at=7dfdd5..6486fc accounts=17,284,328 slots=120,005,346 storage=9.36GiB dangling=0 elapsed=22m26.374s
Apr 18 03:30:15 eth geth[13045]: INFO [04-18|03:30:15.511] Resuming state snapshot generation root=060676..0c5107 in=159e48..5eae12 at=7dfdd5..6486fc accounts=17,284,328 slots=120,005,346 storage=9.36GiB dangling=0 elapsed=22m26.416s
Apr 18 03:30:18 eth geth[13045]: INFO [04-18|03:30:18.089] Imported new potential chain segment number=17,070,921 hash=391571..6238a6 blocks=1 txs=115 mgas=12.816 elapsed=6.581s mgasps=1.947 age=1m55s dirty=254.73MiB
Apr 18 03:30:20 eth geth[13045]: INFO [04-18|03:30:20.669] Chain head was updated number=17,070,921 hash=391571..6238a6 root=11a5d5..67de27 elapsed=41.374779ms age=1m57s
Apr 18 03:30:23 eth geth[13045]: INFO [04-18|03:30:23.710] Generating state snapshot root=060676..0c5107 in=159e48..5eae12 at=7e2949..b9817e accounts=17,284,328 slots=120,026,861 storage=9.36GiB dangling=0 elapsed=22m34.615s
Apr 18 03:30:31 eth geth[13045]: INFO [04-18|03:30:31.921] Generating state snapshot root=060676..0c5107 in=159e48..5eae12 at=7e56bc..e0dff4 accounts=17,284,328 slots=120,049,389 storage=9.37GiB dangling=0 elapsed=22m42.826s
Apr 18 03:30:38 eth geth[13045]: WARN [04-18|03:30:38.509] Peer delivering stale transactions peer=3361a085d5af828a74982e15181b1ea4ae1888185b94a69b0b6d32bd6097c142 rejected=112
What amount of ram do you have on the machine?
What amount of ram do you have on the machine?
12GB
It would be interesting to see what the oom-reaper says geth is using. Usually, in logs that when the OOM-reaper hits, it says what the size was. Could you check if you can see that in the syslog?
Are other processes (beacon node?) running on the same machine?
I found these logs, I am also running Prysm on the same machine.
Apr 19 11:29:18 eth kernel: geth invoked oom-killer: gfp_mask=0x1100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=0
Apr 19 11:29:18 eth kernel: CPU: 0 PID: 1182 Comm: geth Not tainted 5.15.0-70-generic #77-Ubuntu
Apr 19 11:29:18 eth kernel: Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 0.0.0 02/06/2015
Apr 19 11:29:18 eth kernel: Call Trace:
Apr 19 11:29:18 eth kernel: <TASK>
Apr 19 11:29:18 eth kernel: show_stack+0x52/0x5c
Apr 19 11:29:18 eth kernel: dump_stack_lvl+0x4a/0x63
Apr 19 11:29:18 eth kernel: dump_stack+0x10/0x16
Apr 19 11:29:18 eth kernel: dump_header+0x53/0x228
Apr 19 11:29:18 eth kernel: oom_kill_process.cold+0xb/0x10
Apr 19 11:29:18 eth kernel: out_of_memory+0x106/0x2e0
Apr 19 11:29:18 eth kernel: __alloc_pages_slowpath.constprop.0+0x9b7/0xa80
Apr 19 11:29:18 eth kernel: __alloc_pages+0x311/0x330
Apr 19 11:29:18 eth kernel: alloc_pages+0x9e/0x1e0
Apr 19 11:29:18 eth kernel: __page_cache_alloc+0x7e/0x90
Apr 19 11:29:18 eth kernel: pagecache_get_page+0x152/0x590
Apr 19 11:29:18 eth kernel: ? page_cache_ra_unbounded+0x166/0x210
Apr 19 11:29:18 eth kernel: filemap_fault+0x488/0xab0
Apr 19 11:29:18 eth kernel: ? filemap_map_pages+0x309/0x400
Apr 19 11:29:18 eth kernel: __do_fault+0x39/0x120
Apr 19 11:29:18 eth kernel: do_read_fault+0xeb/0x160
Apr 19 11:29:18 eth kernel: do_fault+0xa0/0x2e0
Apr 19 11:29:18 eth kernel: handle_pte_fault+0x1cd/0x240
Apr 19 11:29:18 eth kernel: __handle_mm_fault+0x405/0x6f0
Apr 19 11:29:18 eth kernel: handle_mm_fault+0xd8/0x2c0
Apr 19 11:29:18 eth kernel: do_user_addr_fault+0x1c9/0x670
Apr 19 11:29:18 eth kernel: exc_page_fault+0x77/0x170
Apr 19 11:29:18 eth kernel: asm_exc_page_fault+0x27/0x30
Apr 19 11:29:18 eth kernel: RIP: 0033:0x444f20
Apr 19 11:29:18 eth kernel: Code: Unable to access opcode bytes at RIP 0x444ef6.
Apr 19 11:29:18 eth kernel: RSP: 002b:00007f70d6d806b0 EFLAGS: 00010246
Apr 19 11:29:18 eth kernel: RAX: 00007f70d6d806f0 RBX: 00007f70d5507b90 RCX: 00000000000000e9
Apr 19 11:29:18 eth kernel: RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000002b77898
Apr 19 11:29:18 eth kernel: RBP: 00007f70d6d80d28 R08: 00000000000000e9 R09: 0000000000000072
Apr 19 11:29:18 eth kernel: R10: 0000000000000000 R11: 0000000000000200 R12: 0000000000000001
Apr 19 11:29:18 eth kernel: R13: 0000000000000040 R14: 000000c0000069c0 R15: 0000000000001000
Apr 19 11:29:18 eth kernel: </TASK>
Apr 19 11:29:18 eth kernel: Mem-Info:
Apr 19 11:29:18 eth kernel: active_anon:2572618 inactive_anon:372292 isolated_anon:64
Apr 19 11:29:18 eth kernel: Node 0 active_anon:10290472kB inactive_anon:1489168kB active_file:832kB inactive_file:148kB unevictable:27620kB isolated(anon):256kB isolated(file):0kB mapped:8988kB dirty:0kB writeback:0kB shmem:0kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 337920kB writeback_tmp:0kB kernel_stack:3520kB pagetables:88108kB all_unreclaimable? yes
Apr 19 11:29:18 eth kernel: Node 0 DMA free:12352kB min:76kB low:92kB high:108kB reserved_highatomic:0KB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15036kB managed:14400kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Apr 19 11:29:18 eth kernel: lowmem_reserve[]: 0 1860 12342 12342 12342
Apr 19 11:29:18 eth kernel: Node 0 DMA32 free:51904kB min:10176kB low:12720kB high:15264kB reserved_highatomic:0KB active_anon:1659684kB inactive_anon:216804kB active_file:0kB inactive_file:104kB unevictable:0kB writepending:0kB present:2078964kB managed:2013184kB mlocked:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Apr 19 11:29:18 eth kernel: lowmem_reserve[]: 0 0 10481 10481 10481
Apr 19 11:29:18 eth kernel: Node 0 Normal free:69388kB min:57328kB low:71660kB high:85992kB reserved_highatomic:12288KB active_anon:8631556kB inactive_anon:1270540kB active_file:720kB inactive_file:0kB unevictable:27620kB writepending:0kB present:11010048kB managed:10741912kB mlocked:27620kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Apr 19 11:29:18 eth kernel: lowmem_reserve[]: 0 0 0 0 0
Apr 19 11:29:18 eth kernel: Node 0 DMA: 0*4kB 0*8kB 0*16kB 2*32kB (U) 0*64kB 0*128kB 0*256kB 0*512kB 2*1024kB (U) 3*2048kB (UM) 1*4096kB (M) = 12352kB
Apr 19 11:29:18 eth kernel: Node 0 DMA32: 276*4kB (UME) 416*8kB (UME) 409*16kB (UME) 205*32kB (UME) 57*64kB (UME) 11*128kB (UME) 7*256kB (UE) 2*512kB (UM) 11*1024kB (UM) 6*2048kB (M) 1*4096kB (M) = 53056kB
Apr 19 11:29:18 eth kernel: Node 0 Normal: 7152*4kB (UME) 3831*8kB (UME) 601*16kB (UME) 56*32kB (UM) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 70664kB
Apr 19 11:29:18 eth kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Apr 19 11:29:18 eth kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Apr 19 11:29:18 eth kernel: 2995 total pagecache pages
Apr 19 11:29:18 eth kernel: 345 pages in swap cache
Apr 19 11:29:18 eth kernel: Swap cache stats: add 96860343, delete 96865791, find 25757905/49890483
Apr 19 11:29:18 eth kernel: Free swap = 0kB
Apr 19 11:29:18 eth kernel: Total swap = 16777212kB
Apr 19 11:29:18 eth kernel: 3276012 pages RAM
Apr 19 11:29:18 eth kernel: 0 pages HighMem/MovableOnly
Apr 19 11:29:18 eth kernel: 83638 pages reserved
Apr 19 11:29:18 eth kernel: 0 pages hwpoisoned
Apr 19 11:29:18 eth kernel: Tasks state (memory values in pages):
Apr 19 11:29:18 eth kernel: [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name
Apr 19 11:29:18 eth kernel: [ 401] 0 401 56645 499 421888 291 -250 systemd-journal
Apr 19 11:29:18 eth kernel: [ 444] 0 444 72328 6775 110592 0 -1000 multipathd
Apr 19 11:29:18 eth kernel: [ 453] 0 453 6337 491 73728 378 -1000 systemd-udevd
Apr 19 11:29:18 eth kernel: [ 587] 104 587 22339 567 77824 236 0 systemd-timesyn
Apr 19 11:29:18 eth kernel: [ 677] 101 677 4030 415 73728 279 0 systemd-network
Apr 19 11:29:18 eth kernel: [ 679] 102 679 7261 685 98304 1888 0 systemd-resolve
Apr 19 11:29:18 eth kernel: [ 697] 103 697 2148 771 53248 195 -900 dbus-daemon
Apr 19 11:29:18 eth kernel: [ 704] 0 704 7530 740 106496 2195 0 networkd-dispat
Apr 19 11:29:18 eth kernel: [ 705] 1003 705 64208624 805771 41398272 555664 0 beacon-chain-v4
Apr 19 11:29:18 eth kernel: [ 706] 1002 706 508045 0 413696 10906 0 validator-v4.0.
Apr 19 11:29:18 eth kernel: [ 710] 0 710 3755 524 69632 241 0 systemd-logind
Apr 19 11:29:18 eth kernel: [ 713] 0 713 392491 61 315392 3256 -999 containerd
Apr 19 11:29:18 eth kernel: [ 756] 0 756 798 209 45056 33 0 agetty
Apr 19 11:29:18 eth kernel: [ 764] 0 764 3856 634 77824 432 -1000 sshd
Apr 19 11:29:18 eth kernel: [ 796] 0 796 26801 820 110592 2063 0 unattended-upgr
Apr 19 11:29:18 eth kernel: [ 937] 0 937 398750 356 385024 5108 -500 dockerd
Apr 19 11:29:18 eth kernel: [ 1181] 1001 1181 6250520 2138001 46501888 3610861 0 geth
Apr 19 11:29:18 eth kernel: oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=geth.service,mems_allowed=0,global_oom,task_memcg=/system.slice/geth.service,task=geth,pid=1181,uid=1001
Apr 19 11:29:18 eth kernel: Out of memory: Killed process 1181 (geth) total-vm:25002080kB, anon-rss:8552004kB, file-rss:0kB, shmem-rss:0kB, UID:1001 pgtables:45412kB oom_score_adj:0
Apr 19 11:29:21 eth kernel: oom_reaper: reaped process 1181 (geth), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB
Hello, @dasudiy ,as I know messages about "Peer delivering stale transactions" in your logs may not be related to OOM errors, these messages are often harmless and can be caused by network congestion or delays in the propagation of transactions between nodes.
Hello, @dasudiy ,as I know messages about "Peer delivering stale transactions" in your logs may not be related to OOM errors, these messages are often harmless and can be caused by network congestion or delays in the propagation of transactions between nodes.
thanks for the info, but I don't know how to prevent it. I have googled it, and seems it is caused by my node not fully sync?
The message "Peer delivering stale transactions" indicates peer misbehavior. You can't do anything to stop this, we added the log message just to see how often this particular misbehavior occurs.
Occurring constantly - i mean continuously with breaks in-between.
I have a node that was previously running in a synchronized state. After updating to Geth 1.11.5, I started experiencing issues with the node. I ran removedb and preserved the ancients before attempting to resynchronize. However, during the state snapshot generation process, my node is repeatedly killed due to Out Of Memory (OOM) errors.
I have tried increasing the swapfile size to 32GB, but Geth still consumes all available memory, leading to OOM kills. I also attempted to set the --cache flag to 1024, but it does not seem to make any noticeable difference.
I'm seeking guidance on how to resolve this issue and prevent OOM kills during state snapshot generation. Thank you.