Re: Утекает память
On 03.08.2015 00:08, Илья wrote:
я думаю это ругается /usr/lib/pm-utils/pm-functions:
При выборе режима сна? С чего бы?
К долгому сохранению (кстати, сколько по времени не могли дождаться и прерывали?) это возможно не относится, эта ошибка о том, что не смог "уснуть" .
В районе 5-10 минут.
Я смог вызвать эту ошибку двумя способами (выдает именно это сообщение sh: echo: I/O error):
1) swapoff -a
но тут понятно - система даже "ругается".
Интересно - почему? Откуда I/O error?
Мне не понятно.
2) забивал всю память, добиваясь заполнения свопа . Тут странно. Если полностью
заполнить всю память - в "сон" не уходит и в системных логах нет никаких следов: Если, места чуть есть (но не достаточно)
то выводит прогресс сжатия/записи образа и прервывется с сообщением сколько времени ушло на операцию и какова скорость записи.
Эта ошибка говорит скорее всего о том, что система не может быть сброшена в своп.
Да. Такое есть.
Вот, например сейчас (да, запишет наверное, но долго это будет идти, да и заметьте, что забито 5 Гб (!) свопа):
artiom@dana ~ $ free
total used free shared buffers cached
Mem: 19G 19G 254M 188M 711M 3,7G
-/+ buffers/cache: 14G 4,7G
Swap: 29G 5,3G 24G
Сделал, как рекомендовали, немного поменялось (сбросил дисковые буфера):
root@dana:/home# for i in $(seq 1 4); do echo $i > /proc/sys/vm/drop_caches; done
root@dana:/home# free
total used free shared buffers cached
Mem: 19G 14G 5,3G 188M 8,4M 584M
-/+ buffers/cache: 13G 5,9G
Swap: 29G 5,3G 24G
У меня пока только два предположения:
1) проблемы с файловой системой или диском
С диском - возможно, но маловероятно.
2) система "зависает" на таком объеме, можно оценить сколько ресурсов будет "съедено" при сжатии и записи всей памяти на диск.
Вот только как это понять.
Опять же, как правило, проблема проявляется со временем, на большом аптайме.
Нужно смотреть на момент когда возникает ошибка или зависание /var/log/kern.log. Там все есть.
Ошибки пока не было, но проскакивает что-то нездоровое:
Aug 2 23:01:58 dana kernel: [202584.677536] ata3.01: exception Emask 0x10 SAct 0x0 SErr 0x4000000 action 0x0
Aug 2 23:01:58 dana kernel: [202584.677540] ata3.01: SError: { DevExch }
Aug 2 23:01:58 dana kernel: [202584.677546] ata3.00: hard resetting link
Aug 2 23:01:58 dana kernel: [202585.397114] ata3.01: hard resetting link
Aug 2 23:01:59 dana kernel: [202586.281561] ata3.00: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
Aug 2 23:01:59 dana kernel: [202586.281572] ata3.01: SATA link down (SStatus 0 SControl 300)
Aug 2 23:01:59 dana kernel: [202586.295262] ata3.00: configured for UDMA/133
Aug 2 23:01:59 dana kernel: [202586.295579] ata3: EH complete
Aug 3 19:01:10 dana kernel: [202599.188167] PM: Syncing filesystems ... done.
Aug 3 19:01:11 dana kernel: [202599.459154] Freezing user space processes ... (elapsed 0.001 seconds) done.
Aug 3 19:01:11 dana kernel: [202599.461412] PM: Preallocating image memory...
Aug 3 19:01:11 dana kernel: [202660.494175] usb 1-1.1: reset high-speed USB device number 3 using ehci-pci
Aug 3 19:01:11 dana kernel: [202669.471882] kthreadd: page allocation failure: order:2, mode:0x2000d0
Aug 3 19:01:11 dana kernel: [202669.471886] CPU: 0 PID: 2 Comm: kthreadd Tainted: P O 3.16.7-ckt9 #4
Aug 3 19:01:11 dana kernel: [202669.471887] Hardware name: System manufacturer System Product Name/P7P55D, BIOS 2003 12/14/2010
Aug 3 19:01:11 dana kernel: [202669.471888] ffff88052e9abc70 ffffffff81579361 00000000002000d0 ffffffff810d32a9
Aug 3 19:01:11 dana kernel: [202669.471890] 0000000000000002 00000000002000d0 0000000000000002 ffffffff810df991
Aug 3 19:01:11 dana kernel: [202669.471892] 00000000000590b3 0000000000000000 0000000000000020 0000000000000000
Aug 3 19:01:11 dana kernel: [202669.471893] Call Trace:
Aug 3 19:01:11 dana kernel: [202669.471899] [<ffffffff81579361>] ? dump_stack+0x41/0x51
Aug 3 19:01:11 dana kernel: [202669.471903] [<ffffffff810d32a9>] ? warn_alloc_failed+0xd9/0x130
Aug 3 19:01:11 dana kernel: [202669.471906] [<ffffffff810df991>] ? try_to_free_pages+0x91/0xa0
Aug 3 19:01:11 dana kernel: [202669.471908] [<ffffffff810d6f68>] ? __alloc_pages_nodemask+0x588/0xc10
Aug 3 19:01:11 dana kernel: [202669.471911] [<ffffffff81041ebd>] ? copy_process.part.38+0x11d/0x1a10
Aug 3 19:01:11 dana kernel: [202669.471913] [<ffffffff81060e60>] ? kthread_create_on_node+0x170/0x170
Aug 3 19:01:11 dana kernel: [202669.471914] [<ffffffff81043954>] ? do_fork+0xd4/0x380
Aug 3 19:01:11 dana kernel: [202669.471916] [<ffffffff8157aba2>] ? __schedule+0x272/0x7a0
Aug 3 19:01:11 dana kernel: [202669.471918] [<ffffffff81043c1d>] ? kernel_thread+0x1d/0x20
Aug 3 19:01:11 dana kernel: [202669.471919] [<ffffffff810616c0>] ? kthreadd+0x150/0x1a0
Aug 3 19:01:11 dana kernel: [202669.471921] [<ffffffff81061570>] ? kthread_create_on_cpu+0x40/0x40
Aug 3 19:01:11 dana kernel: [202669.471923] [<ffffffff8157ec88>] ? ret_from_fork+0x58/0x90
Aug 3 19:01:11 dana kernel: [202669.471924] [<ffffffff81061570>] ? kthread_create_on_cpu+0x40/0x40
Aug 3 19:01:11 dana kernel: [202669.471925] Mem-Info:
Aug 3 19:01:11 dana kernel: [202669.471927] DMA per-cpu:
Aug 3 19:01:11 dana kernel: [202669.471928] CPU 0: hi: 0, btch: 1 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471929] CPU 1: hi: 0, btch: 1 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471930] CPU 2: hi: 0, btch: 1 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471931] CPU 3: hi: 0, btch: 1 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471931] DMA32 per-cpu:
Aug 3 19:01:11 dana kernel: [202669.471932] CPU 0: hi: 186, btch: 31 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471933] CPU 1: hi: 186, btch: 31 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471934] CPU 2: hi: 186, btch: 31 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471935] CPU 3: hi: 186, btch: 31 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471936] Normal per-cpu:
Aug 3 19:01:11 dana kernel: [202669.471937] CPU 0: hi: 186, btch: 31 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471938] CPU 1: hi: 186, btch: 31 usd: 17
Aug 3 19:01:11 dana kernel: [202669.471939] CPU 2: hi: 186, btch: 31 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471940] CPU 3: hi: 186, btch: 31 usd: 0
Aug 3 19:01:11 dana kernel: [202669.471942] active_anon:1970425 inactive_anon:182303 isolated_anon:64
Aug 3 19:01:11 dana kernel: [202669.471942] active_file:103 inactive_file:53 isolated_file:0
Aug 3 19:01:11 dana kernel: [202669.471942] unevictable:0 dirty:0 writeback:182357 unstable:0
Aug 3 19:01:11 dana kernel: [202669.471942] free:38379 slab_reclaimable:21431 slab_unreclaimable:54960
Aug 3 19:01:11 dana kernel: [202669.471942] mapped:30945 shmem:19951 pagetables:43137 bounce:0
Aug 3 19:01:11 dana kernel: [202669.471942] free_cma:652
Aug 3 19:01:11 dana kernel: [202669.471947] DMA free:15636kB min:52kB low:64kB high:76kB active_anon:0kB inactive_anon:0kB
active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15992kB managed:15908kB mlocked:0kB
dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:16kB kernel_stack:0kB pagetables:0kB
unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
Aug 3 19:01:11 dana kernel: [202669.471948] lowmem_reserve[]: 0 3237 20020 20020
Aug 3 19:01:11 dana kernel: [202669.471952] DMA32 free:78260kB min:10916kB low:13644kB high:16372kB active_anon:617892kB
inactive_anon:123620kB active_file:16kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3389888kB
managed:3315488kB mlocked:0kB dirty:0kB writeback:123700kB mapped:20988kB shmem:16340kB slab_reclaimable:13916kB
slab_unreclaimable:29736kB kernel_stack:2384kB pagetables:26396kB unstable:0kB bounce:0kB free_cma:0kB writeback_tmp:0kB
pages_scanned:92502 all_unreclaimable? no
Aug 3 19:01:11 dana kernel: [202669.471953] lowmem_reserve[]: 0 0 16782 16782
Aug 3 19:01:11 dana kernel: [202669.471957] Normal free:59620kB min:56612kB low:70764kB high:84916kB active_anon:7263808kB
inactive_anon:605592kB active_file:396kB inactive_file:212kB unevictable:0kB isolated(anon):256kB isolated(file):0kB
present:17563648kB managed:17185304kB mlocked:0kB dirty:0kB writeback:605728kB mapped:102792kB shmem:63464kB
slab_reclaimable:71808kB slab_unreclaimable:190088kB kernel_stack:14320kB pagetables:146152kB unstable:0kB bounce:0kB
free_cma:2608kB writeback_tmp:0kB pages_scanned:405755 all_unreclaimable? no
Aug 3 19:01:11 dana kernel: [202669.471958] lowmem_reserve[]: 0 0 0 0
Aug 3 19:01:11 dana kernel: [202669.471959] DMA: 1*4kB (U) 0*8kB 1*16kB (U) 2*32kB (U) 1*64kB (U) 1*128kB (U) 0*256kB 0*512kB
1*1024kB (U) 1*2048kB (R) 3*4096kB (M) = 15636kB
Aug 3 19:01:11 dana kernel: [202669.471966] DMA32: 19046*4kB (UM) 27*8kB (UM) 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB
0*1024kB 1*2048kB (R) 0*4096kB = 78448kB
Aug 3 19:01:11 dana kernel: [202669.471971] Normal: 14418*4kB (UMC) 65*8kB (MC) 29*16kB (MC) 11*32kB (C) 5*64kB (C) 3*128kB (C)
0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 59712kB
Aug 3 19:01:11 dana kernel: [202669.471977] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Aug 3 19:01:12 dana kernel: [202669.471978] 218777 total pagecache pages
Aug 3 19:01:12 dana kernel: [202669.471979] 198675 pages in swap cache
Aug 3 19:01:12 dana kernel: [202669.471980] Swap cache stats: add 2204130, delete 2005455, find 16058135/16093634
Aug 3 19:01:12 dana kernel: [202669.471981] Free swap = 24127328kB
Aug 3 19:01:12 dana kernel: [202669.471981] Total swap = 31264596kB
Aug 3 19:01:12 dana kernel: [202669.471982] 5242382 pages RAM
Aug 3 19:01:12 dana kernel: [202669.471982] 0 pages HighMem/MovableOnly
Aug 3 19:01:12 dana kernel: [202669.471983] 94586 pages reserved
Aug 3 19:01:12 dana kernel: [202669.471984] 0 pages hwpoisoned
Aug 3 19:01:12 dana kernel: [202669.523210] done (allocated 2762252 pages)
Aug 3 19:01:12 dana kernel: [202669.523214] PM: Allocated 11049008 kbytes in 69.98 seconds (157.88 MB/s)
Aug 3 19:01:12 dana kernel: [202669.523215] Freezing remaining freezable tasks ... (elapsed 7.432 seconds) done.
Aug 3 19:01:12 dana kernel: [202676.964182] Suspending console(s) (use no_console_suspend to debug)
Aug 3 19:01:12 dana kernel: [202676.964958] serial 00:05: disabled
Aug 3 19:01:12 dana kernel: [202676.964962] serial 00:05: System wakeup disabled by ACPI
Aug 3 19:01:12 dana kernel: [202677.167642] PM: freeze of devices complete after 203.217 msecs
Aug 3 19:01:12 dana kernel: [202677.168029] PM: late freeze of devices complete after 0.385 msecs
Aug 3 19:01:12 dana kernel: [202677.168707] PM: noirq freeze of devices complete after 0.675 msecs
Aug 3 19:01:12 dana kernel: [202677.168962] ACPI: Preparing to enter system sleep state S4
Aug 3 19:01:12 dana kernel: [202677.169186] PM: Saving platform NVS memory
Aug 3 19:01:12 dana kernel: [202677.169409] Disabling non-boot CPUs ...
Aug 3 19:01:12 dana kernel: [202677.169571] Broke affinity for irq 41
Aug 3 19:01:12 dana kernel: [202677.170584] kvm: disabling virtualization on CPU1
Aug 3 19:01:12 dana kernel: [202677.170602] smpboot: CPU 1 is now offline
Aug 3 19:01:12 dana kernel: [202677.171073] Broke affinity for irq 21
Aug 3 19:01:12 dana kernel: [202677.171075] Broke affinity for irq 42
Aug 3 19:01:12 dana kernel: [202677.172088] kvm: disabling virtualization on CPU2
Aug 3 19:01:12 dana kernel: [202677.273469] smpboot: CPU 2 is now offline
Aug 3 19:01:12 dana kernel: [202677.273879] Broke affinity for irq 23
Aug 3 19:01:12 dana kernel: [202677.273881] Broke affinity for irq 43
Aug 3 19:01:12 dana kernel: [202677.274893] kvm: disabling virtualization on CPU3
Aug 3 19:01:12 dana kernel: [202677.376928] smpboot: CPU 3 is now offline
Aug 3 19:01:12 dana kernel: [202677.377340] PM: Creating hibernation image:
Aug 3 19:01:12 dana kernel: [202677.543379] PM: Need to copy 2422607 pages
Aug 3 19:01:12 dana kernel: [202677.378006] PM: Restoring platform NVS memory
Aug 3 19:01:12 dana kernel: [202677.378535] Enabling non-boot CPUs ...
Aug 3 19:01:12 dana kernel: [202677.378565] x86: Booting SMP configuration:
Aug 3 19:01:12 dana kernel: [202677.378566] smpboot: Booting Node 0 Processor 1 APIC 0x2
Aug 3 19:01:12 dana kernel: [202677.381484] /dev/vmmon[13797]: HostIFReadUptimeWork: detected settimeofday: fixed uptimeBase old
18445305546136120844 new 18445305474283604369 attempts 1
В старых логах посмотрел, вроде более ли менее (периодически падает rdiff-backup - ещё одна вероятная причина, когда hibernate
попадает на процесс бэкапа):
Jul 13 08:23:23 dana kernel: [609420.431911] Freezing user space processes ...
Jul 13 08:23:23 dana kernel: [609440.461626] Freezing of tasks failed after 20.006 seconds (1 tasks refusing to freeze, wq_busy=0):
Jul 13 08:23:23 dana kernel: [609440.461756] rdiff-backup D 0000000000000000 0 19234 21026 0x00000004
Jul 13 08:23:23 dana kernel: [609440.461758] ffff8802422abd20 0000000000000086 0000000000009000 ffff8801319b2760
Jul 13 08:23:23 dana kernel: [609440.461760] ffff8802422abfd8 0000000000000000 0000000000000620 ffff88052fc110a0
Jul 13 08:23:23 dana kernel: [609440.461761] ffff88052ffbade8 ffff8802422abd90 0000000000000082 ffffffff810cdf30
Jul 13 08:23:23 dana kernel: [609440.461763] Call Trace:
Jul 13 08:23:23 dana kernel: [609440.461769] [<ffffffff810cdf30>] ? sleep_on_page+0x10/0x10
Jul 13 08:23:23 dana kernel: [609440.461773] [<ffffffff8157b3c6>] ? io_schedule+0xa6/0x140
Jul 13 08:23:23 dana kernel: [609440.461774] [<ffffffff810cdf35>] ? sleep_on_page_killable+0x5/0x40
Jul 13 08:23:23 dana kernel: [609440.461776] [<ffffffff8157b83c>] ? __wait_on_bit_lock+0x3c/0x90
Jul 13 08:23:23 dana kernel: [609440.461777] [<ffffffff810ce085>] ? __lock_page_killable+0x65/0x70
Jul 13 08:23:23 dana kernel: [609440.461781] [<ffffffff8107ab80>] ? autoremove_wake_function+0x30/0x30
Jul 13 08:23:23 dana kernel: [609440.461782] [<ffffffff810cfc08>] ? generic_file_read_iter+0x3b8/0x5b0
Jul 13 08:23:23 dana kernel: [609440.461786] [<ffffffff81120f1c>] ? new_sync_read+0x6c/0xa0
Jul 13 08:23:23 dana kernel: [609440.461787] [<ffffffff8112158a>] ? vfs_read+0x8a/0x170
Jul 13 08:23:23 dana kernel: [609440.461789] [<ffffffff8112218d>] ? SyS_read+0x3d/0xa0
Jul 13 08:23:23 dana kernel: [609440.461791] [<ffffffff8157ed36>] ? system_call_fast_compare_end+0x10/0x15
Jul 13 08:23:23 dana kernel: [609440.461792]
Jul 13 08:23:23 dana kernel: [609440.461793] Restarting tasks ...
Jul 13 08:23:23 dana kernel: [609440.466979] done.
И ещё вот такое:
Jul 17 21:19:04 dana kernel: [ 1296.090329] ------------[ cut here ]------------
Jul 17 21:19:04 dana kernel: [ 1296.090351] WARNING: CPU: 2 PID: 0 at net/sched/sch_generic.c:264 dev_watchdog+0x22f/0x240()
Jul 17 21:19:04 dana kernel: [ 1296.090356] NETDEV WATCHDOG: eth0 (r8169): transmit queue 0 timed out
Jul 17 21:19:04 dana kernel: [ 1296.090359] Modules linked in: udp_diag tcp_diag inet_diag ip6table_filter ip6_tables pci_stub
vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) tun xt_multiport ebt_snat ebt_dnat e
btable_nat ebtables xt_nat nf_nat_sip nf_nat_irc nf_nat_amanda nf_nat_ftp nf_nat_proto_sctp libcrc32c nf_nat_proto_udplite
nf_nat_tftp nf_nat_snmp_basic nf_nat_h323 iptable_nat nf_nat_pptp nf_nat_proto_gre nf_nat_
ipv4 nf_nat act_nat nf_conntrack_pptp nf_conntrack_proto_gre nf_conntrack_tftp nf_conntrack_proto_udplite nf_conntrack_h323
xt_conntrack nf_conntrack_proto_sctp nf_conntrack_netbios_ns nf_conntrack_ftp nf_conntrac
k_sip nf_conntrack_irc nf_conntrack_snmp nf_conntrack_broadcast nf_conntrack_netlink nfnetlink ts_kmp nf_conntrack_amanda
nf_conntrack_ipv4 nf_defrag_ipv4 nvidia(PO) uvcvideo snd_usb_audio videobuf2_vmalloc snd_us
bmidi_lib videobuf2_memops snd_rawmidi videobuf2_core joydev kvm_intel kvm serio_raw acpi_cpufreq ppdev parport xts gf128mul ecb
algif_skcipher af_alg dm_mirror dm_region_hash dm_log drm uas crc32c_intel [last unl
oaded: vmnet]
Jul 17 21:19:04 dana kernel: [ 1296.090439] CPU: 2 PID: 0 Comm: swapper/2 Tainted: P O 3.16.7-ckt9 #4
Jul 17 21:19:04 dana kernel: [ 1296.090443] Hardware name: System manufacturer System Product Name/P7P55D, BIOS 2003 12/14/2010
Jul 17 21:19:04 dana kernel: [ 1296.090450] 0000000000000009 ffffffff81579361 ffff88052fc83e28 ffffffff810446dd
Jul 17 21:19:04 dana kernel: [ 1296.090456] 0000000000000000 ffff88052fc83e78 0000000000000001 0000000000000002
Jul 17 21:19:04 dana kernel: [ 1296.090461] ffff880516f48000 ffffffff81044747 ffffffff81781210 0000000000000030
Jul 17 21:19:04 dana kernel: [ 1296.090466] Call Trace:
Jul 17 21:19:04 dana kernel: [ 1296.090469] <IRQ> [<ffffffff81579361>] ? dump_stack+0x41/0x51
Jul 17 21:19:04 dana kernel: [ 1296.090483] [<ffffffff810446dd>] ? warn_slowpath_common+0x6d/0x90
Jul 17 21:19:04 dana kernel: [ 1296.090488] [<ffffffff81044747>] ? warn_slowpath_fmt+0x47/0x50
Jul 17 21:19:04 dana kernel: [ 1296.090495] [<ffffffff81092dbc>] ? ktime_get+0x3c/0xe0
Jul 17 21:19:04 dana kernel: [ 1296.090501] [<ffffffff814b7eaf>] ? dev_watchdog+0x22f/0x240
Jul 17 21:19:04 dana kernel: [ 1296.090507] [<ffffffff814b7c80>] ? dev_graft_qdisc+0x70/0x70
Jul 17 21:19:04 dana kernel: [ 1296.090512] [<ffffffff814b7c80>] ? dev_graft_qdisc+0x70/0x70
Jul 17 21:19:04 dana kernel: [ 1296.090518] [<ffffffff8104e4f2>] ? call_timer_fn.isra.30+0x12/0x80
Jul 17 21:19:04 dana kernel: [ 1296.090524] [<ffffffff8104e728>] ? run_timer_softirq+0x1c8/0x270
Jul 17 21:19:04 dana kernel: [ 1296.090531] [<ffffffff8104893b>] ? __do_softirq+0x10b/0x220
Jul 17 21:19:04 dana kernel: [ 1296.090533] [<ffffffff81048b95>] ? irq_exit+0x95/0xa0
Jul 17 21:19:04 dana kernel: [ 1296.090536] [<ffffffff8100477c>] ? do_IRQ+0x4c/0xe0
Jul 17 21:19:04 dana kernel: [ 1296.090539] [<ffffffff8157f96a>] ? common_interrupt+0x6a/0x6a
Jul 17 21:19:04 dana kernel: [ 1296.090540] <EOI> [<ffffffff814039d1>] ? cpuidle_enter_state+0x41/0xb0
Jul 17 21:19:04 dana kernel: [ 1296.090544] [<ffffffff814039cd>] ? cpuidle_enter_state+0x3d/0xb0
Jul 17 21:19:04 dana kernel: [ 1296.090548] [<ffffffff8107afee>] ? cpu_startup_entry+0x27e/0x2b0
Jul 17 21:19:04 dana kernel: [ 1296.090550] ---[ end trace aaebcbeb49c4e033 ]---
Читали https://www.kernel.org/doc/Documentation/power/basic-pm-debugging.txt?
Не читал. Вроде там немного. Посмотрю, но вообще отлаживать hibernation нет большого желания.
Reply to: