Home / server / Questions / 548736
Accepted
Grant
Asked: 2013-10-26 10:47:10 +0800 CST

How to read oom-killer syslog messages?

  • 772

I have a Ubuntu 12.04 server which sometimes dies completely - no SSH, no ping, nothing until it is physically rebooted.

After the reboot, I see in syslog that the oom-killer killed, well, pretty much everything.

There's a lot of detailed memory usage information in them. How do I read these logs to see what caused the OOM issue? The server has far more memory than it needs, so it shouldn't be running out of memory.


Oct 25 07:28:04 nldedip4k031 kernel: [87946.529511] oom_kill_process: 9 callbacks suppressed
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529514] irqbalance invoked oom-killer: gfp_mask=0x80d0, order=0, oom_adj=0, oom_score_adj=0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529516] irqbalance cpuset=/ mems_allowed=0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529518] Pid: 948, comm: irqbalance Not tainted 3.2.0-55-generic-pae #85-Ubuntu
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529519] Call Trace:
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529525]  [] dump_header.isra.6+0x85/0xc0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529528]  [] oom_kill_process+0x5c/0x80
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529530]  [] out_of_memory+0xc5/0x1c0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529532]  [] __alloc_pages_nodemask+0x72c/0x740
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529535]  [] __get_free_pages+0x1c/0x30
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529537]  [] get_zeroed_page+0x12/0x20
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529541]  [] fill_read_buffer.isra.8+0xaa/0xd0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529543]  [] sysfs_read_file+0x7d/0x90
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529546]  [] vfs_read+0x8c/0x160
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529548]  [] ? fill_read_buffer.isra.8+0xd0/0xd0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529550]  [] sys_read+0x3d/0x70
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529554]  [] sysenter_do_call+0x12/0x28
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529555] Mem-Info:
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529556] DMA per-cpu:
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529557] CPU    0: hi:    0, btch:   1 usd:   0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529558] CPU    1: hi:    0, btch:   1 usd:   0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529560] CPU    2: hi:    0, btch:   1 usd:   0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529561] CPU    3: hi:    0, btch:   1 usd:   0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529562] CPU    4: hi:    0, btch:   1 usd:   0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529563] CPU    5: hi:    0, btch:   1 usd:   0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529564] CPU    6: hi:    0, btch:   1 usd:   0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529565] CPU    7: hi:    0, btch:   1 usd:   0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529566] Normal per-cpu:
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529567] CPU    0: hi:  186, btch:  31 usd: 179
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529568] CPU    1: hi:  186, btch:  31 usd: 182
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529569] CPU    2: hi:  186, btch:  31 usd: 132
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529570] CPU    3: hi:  186, btch:  31 usd: 175
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529571] CPU    4: hi:  186, btch:  31 usd:  91
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529572] CPU    5: hi:  186, btch:  31 usd: 173
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529573] CPU    6: hi:  186, btch:  31 usd: 159
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529574] CPU    7: hi:  186, btch:  31 usd: 164
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529575] HighMem per-cpu:
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529576] CPU    0: hi:  186, btch:  31 usd: 165
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529577] CPU    1: hi:  186, btch:  31 usd: 183
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529578] CPU    2: hi:  186, btch:  31 usd: 185
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529579] CPU    3: hi:  186, btch:  31 usd: 138
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529580] CPU    4: hi:  186, btch:  31 usd: 155
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529581] CPU    5: hi:  186, btch:  31 usd: 104
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529582] CPU    6: hi:  186, btch:  31 usd: 133
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529583] CPU    7: hi:  186, btch:  31 usd: 170
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529586] active_anon:5523 inactive_anon:354 isolated_anon:0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529586]  active_file:2815 inactive_file:6849119 isolated_file:0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529587]  unevictable:0 dirty:449 writeback:10 unstable:0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529587]  free:1304125 slab_reclaimable:104672 slab_unreclaimable:3419
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529588]  mapped:2661 shmem:138 pagetables:313 bounce:0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529591] DMA free:4252kB min:780kB low:972kB high:1168kB active_anon:0kB inactive_anon:0kB active_file:4kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15756kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:11564kB slab_unreclaimable:4kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:1 all_unreclaimable? yes
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529594] lowmem_reserve[]: 0 869 32460 32460
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529599] Normal free:44052kB min:44216kB low:55268kB high:66324kB active_anon:0kB inactive_anon:0kB active_file:616kB inactive_file:568kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:890008kB mlocked:0kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:407124kB slab_unreclaimable:13672kB kernel_stack:992kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:2083 all_unreclaimable? yes
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529602] lowmem_reserve[]: 0 0 252733 252733
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529606] HighMem free:5168196kB min:512kB low:402312kB high:804112kB active_anon:22092kB inactive_anon:1416kB active_file:10640kB inactive_file:27395920kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:32349872kB mlocked:0kB dirty:1796kB writeback:40kB mapped:10640kB shmem:552kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:1252kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529609] lowmem_reserve[]: 0 0 0 0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529611] DMA: 6*4kB 6*8kB 6*16kB 5*32kB 5*64kB 4*128kB 2*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 4232kB
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529616] Normal: 297*4kB 180*8kB 119*16kB 73*32kB 67*64kB 47*128kB 35*256kB 13*512kB 5*1024kB 1*2048kB 1*4096kB = 44052kB
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529622] HighMem: 1*4kB 6*8kB 27*16kB 11*32kB 2*64kB 1*128kB 0*256kB 0*512kB 4*1024kB 1*2048kB 1260*4096kB = 5168196kB
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529627] 6852076 total pagecache pages
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529628] 0 pages in swap cache
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529629] Swap cache stats: add 0, delete 0, find 0/0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529630] Free swap  = 3998716kB
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529631] Total swap = 3998716kB
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571914] 8437743 pages RAM
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571916] 8209409 pages HighMem
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571917] 159556 pages reserved
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571917] 6862034 pages shared
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571918] 123540 pages non-shared
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571919] [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571927] [  421]     0   421      709      152   3       0             0 upstart-udev-br
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571929] [  429]     0   429      773      326   5     -17         -1000 udevd
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571931] [  567]     0   567      772      224   4     -17         -1000 udevd
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571932] [  568]     0   568      772      231   7     -17         -1000 udevd
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571934] [  764]     0   764      712      103   1       0             0 upstart-socket-
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571936] [  772]   103   772      815      164   5       0             0 dbus-daemon
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571938] [  785]     0   785     1671      600   1     -17         -1000 sshd
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571940] [  809]   101   809     7766      380   1       0             0 rsyslogd
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571942] [  869]     0   869     1158      213   3       0             0 getty
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571943] [  873]     0   873     1158      214   6       0             0 getty
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571945] [  911]     0   911     1158      215   3       0             0 getty
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571947] [  912]     0   912     1158      214   2       0             0 getty
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571949] [  914]     0   914     1158      213   1       0             0 getty
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571950] [  916]     0   916      618       86   1       0             0 atd
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571952] [  917]     0   917      655      226   3       0             0 cron
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571954] [  948]     0   948      902      159   3       0             0 irqbalance
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571956] [  993]     0   993     1145      363   3       0             0 master
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571957] [ 1002]   104  1002     1162      333   1       0             0 qmgr
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571959] [ 1016]     0  1016      730      149   2       0             0 mdadm
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571961] [ 1057]     0  1057     6066     2160   3       0             0 /usr/sbin/apach
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571963] [ 1086]     0  1086     1158      213   3       0             0 getty
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571965] [ 1088]    33  1088     6191     1517   0       0             0 /usr/sbin/apach
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571967] [ 1089]    33  1089     6191     1451   1       0             0 /usr/sbin/apach
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571969] [ 1090]    33  1090     6175     1451   3       0             0 /usr/sbin/apach
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571971] [ 1091]    33  1091     6191     1451   1       0             0 /usr/sbin/apach
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571972] [ 1092]    33  1092     6191     1451   0       0             0 /usr/sbin/apach
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571974] [ 1109]    33  1109     6191     1517   0       0             0 /usr/sbin/apach
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571976] [ 1151]    33  1151     6191     1451   1       0             0 /usr/sbin/apach
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571978] [ 1201]   104  1201     1803      652   1       0             0 tlsmgr
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571980] [ 2475]     0  2475     2435      812   0       0             0 sshd
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571982] [ 2494]     0  2494     1745      839   1       0             0 bash
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571984] [ 2573]     0  2573     3394     1689   0       0             0 sshd
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571986] [ 2589]     0  2589     5014      457   3       0             0 rsync
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571988] [ 2590]     0  2590     7970      522   1       0             0 rsync
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571990] [ 2652]   104  2652     1150      326   5       0             0 pickup
Oct 25 07:28:04 nldedip4k031 kernel: [87946.571992] Out of memory: Kill process 421 (upstart-udev-br) score 1 or sacrifice child
Oct 25 07:28:04 nldedip4k031 kernel: [87946.572407] Killed process 421 (upstart-udev-br) total-vm:2836kB, anon-rss:156kB, file-rss:452kB
Oct 25 07:28:04 nldedip4k031 kernel: [87946.573107] init: upstart-udev-bridge main process (421) killed by KILL signal
Oct 25 07:28:04 nldedip4k031 kernel: [87946.573126] init: upstart-udev-bridge main process ended, respawning
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461570] irqbalance invoked oom-killer: gfp_mask=0x80d0, order=0, oom_adj=0, oom_score_adj=0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461573] irqbalance cpuset=/ mems_allowed=0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461576] Pid: 948, comm: irqbalance Not tainted 3.2.0-55-generic-pae #85-Ubuntu
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461578] Call Trace:
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461585]  [] dump_header.isra.6+0x85/0xc0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461588]  [] oom_kill_process+0x5c/0x80
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461591]  [] out_of_memory+0xc5/0x1c0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461595]  [] __alloc_pages_nodemask+0x72c/0x740
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461599]  [] __get_free_pages+0x1c/0x30
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461602]  [] get_zeroed_page+0x12/0x20
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461606]  [] fill_read_buffer.isra.8+0xaa/0xd0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461609]  [] sysfs_read_file+0x7d/0x90
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461613]  [] vfs_read+0x8c/0x160
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461616]  [] ? fill_read_buffer.isra.8+0xd0/0xd0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461619]  [] sys_read+0x3d/0x70
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461624]  [] sysenter_do_call+0x12/0x28
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461626] Mem-Info:
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461628] DMA per-cpu:
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461629] CPU    0: hi:    0, btch:   1 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461631] CPU    1: hi:    0, btch:   1 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461633] CPU    2: hi:    0, btch:   1 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461634] CPU    3: hi:    0, btch:   1 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461636] CPU    4: hi:    0, btch:   1 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461638] CPU    5: hi:    0, btch:   1 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461639] CPU    6: hi:    0, btch:   1 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461641] CPU    7: hi:    0, btch:   1 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461642] Normal per-cpu:
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461644] CPU    0: hi:  186, btch:  31 usd:  61
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461646] CPU    1: hi:  186, btch:  31 usd:  49
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461647] CPU    2: hi:  186, btch:  31 usd:   8
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461649] CPU    3: hi:  186, btch:  31 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461651] CPU    4: hi:  186, btch:  31 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461652] CPU    5: hi:  186, btch:  31 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461654] CPU    6: hi:  186, btch:  31 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461656] CPU    7: hi:  186, btch:  31 usd:  30
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461657] HighMem per-cpu:
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461658] CPU    0: hi:  186, btch:  31 usd:   4
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461660] CPU    1: hi:  186, btch:  31 usd: 204
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461662] CPU    2: hi:  186, btch:  31 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461663] CPU    3: hi:  186, btch:  31 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461665] CPU    4: hi:  186, btch:  31 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461667] CPU    5: hi:  186, btch:  31 usd:  31
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461668] CPU    6: hi:  186, btch:  31 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461670] CPU    7: hi:  186, btch:  31 usd:   0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461674] active_anon:5441 inactive_anon:412 isolated_anon:0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461674]  active_file:2668 inactive_file:6922842 isolated_file:0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461675]  unevictable:0 dirty:836 writeback:0 unstable:0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461676]  free:1231664 slab_reclaimable:105781 slab_unreclaimable:3399
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461677]  mapped:2649 shmem:138 pagetables:313 bounce:0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461682] DMA free:4248kB min:780kB low:972kB high:1168kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:4kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15756kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:11560kB slab_unreclaimable:4kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:5687 all_unreclaimable? yes
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461686] lowmem_reserve[]: 0 869 32460 32460
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461693] Normal free:44184kB min:44216kB low:55268kB high:66324kB active_anon:0kB inactive_anon:0kB active_file:20kB inactive_file:1096kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:890008kB mlocked:0kB dirty:4kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:411564kB slab_unreclaimable:13592kB kernel_stack:992kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:1816 all_unreclaimable? yes
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461697] lowmem_reserve[]: 0 0 252733 252733
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461703] HighMem free:4878224kB min:512kB low:402312kB high:804112kB active_anon:21764kB inactive_anon:1648kB active_file:10652kB inactive_file:27690268kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:32349872kB mlocked:0kB dirty:3340kB writeback:0kB mapped:10592kB shmem:552kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:1252kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461708] lowmem_reserve[]: 0 0 0 0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461711] DMA: 8*4kB 7*8kB 6*16kB 5*32kB 5*64kB 4*128kB 2*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 4248kB
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461719] Normal: 272*4kB 178*8kB 76*16kB 52*32kB 42*64kB 36*128kB 23*256kB 20*512kB 7*1024kB 2*2048kB 1*4096kB = 44176kB
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461727] HighMem: 1*4kB 45*8kB 31*16kB 24*32kB 5*64kB 3*128kB 1*256kB 2*512kB 4*1024kB 2*2048kB 1188*4096kB = 4877852kB
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461736] 6925679 total pagecache pages
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461737] 0 pages in swap cache
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461739] Swap cache stats: add 0, delete 0, find 0/0
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461740] Free swap  = 3998716kB
Oct 25 07:28:34 nldedip4k031 kernel: [87976.461741] Total swap = 3998716kB
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524951] 8437743 pages RAM
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524953] 8209409 pages HighMem
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524954] 159556 pages reserved
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524955] 6936141 pages shared
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524956] 124602 pages non-shared
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524957] [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524966] [  429]     0   429      773      326   5     -17         -1000 udevd
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524968] [  567]     0   567      772      224   4     -17         -1000 udevd
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524971] [  568]     0   568      772      231   7     -17         -1000 udevd
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524973] [  764]     0   764      712      103   3       0             0 upstart-socket-
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524976] [  772]   103   772      815      164   2       0             0 dbus-daemon
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524979] [  785]     0   785     1671      600   1     -17         -1000 sshd
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524981] [  809]   101   809     7766      380   1       0             0 rsyslogd
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524983] [  869]     0   869     1158      213   3       0             0 getty
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524986] [  873]     0   873     1158      214   6       0             0 getty
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524988] [  911]     0   911     1158      215   3       0             0 getty
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524990] [  912]     0   912     1158      214   2       0             0 getty
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524992] [  914]     0   914     1158      213   1       0             0 getty
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524995] [  916]     0   916      618       86   1       0             0 atd
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524997] [  917]     0   917      655      226   3       0             0 cron
Oct 25 07:28:34 nldedip4k031 kernel: [87976.524999] [  948]     0   948      902      159   5       0             0 irqbalance
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525002] [  993]     0   993     1145      363   3       0             0 master
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525004] [ 1002]   104  1002     1162      333   1       0             0 qmgr
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525007] [ 1016]     0  1016      730      149   2       0             0 mdadm
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525009] [ 1057]     0  1057     6066     2160   3       0             0 /usr/sbin/apach
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525012] [ 1086]     0  1086     1158      213   3       0             0 getty
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525014] [ 1088]    33  1088     6191     1517   0       0             0 /usr/sbin/apach
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525017] [ 1089]    33  1089     6191     1451   1       0             0 /usr/sbin/apach
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525019] [ 1090]    33  1090     6175     1451   1       0             0 /usr/sbin/apach
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525021] [ 1091]    33  1091     6191     1451   1       0             0 /usr/sbin/apach
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525024] [ 1092]    33  1092     6191     1451   0       0             0 /usr/sbin/apach
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525026] [ 1109]    33  1109     6191     1517   0       0             0 /usr/sbin/apach
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525029] [ 1151]    33  1151     6191     1451   1       0             0 /usr/sbin/apach
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525031] [ 1201]   104  1201     1803      652   1       0             0 tlsmgr
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525033] [ 2475]     0  2475     2435      812   0       0             0 sshd
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525036] [ 2494]     0  2494     1745      839   1       0             0 bash
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525038] [ 2573]     0  2573     3394     1689   3       0             0 sshd
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525040] [ 2589]     0  2589     5014      457   3       0             0 rsync
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525043] [ 2590]     0  2590     7970      522   1       0             0 rsync
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525045] [ 2652]   104  2652     1150      326   5       0             0 pickup
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525048] [ 2847]     0  2847      709       89   0       0             0 upstart-udev-br
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525050] Out of memory: Kill process 764 (upstart-socket-) score 1 or sacrifice child
Oct 25 07:28:34 nldedip4k031 kernel: [87976.525484] Killed process 764 (upstart-socket-) total-vm:2848kB, anon-rss:204kB, file-rss:208kB
Oct 25 07:28:34 nldedip4k031 kernel: [87976.526161] init: upstart-socket-bridge main process (764) killed by KILL signal
Oct 25 07:28:34 nldedip4k031 kernel: [87976.526180] init: upstart-socket-bridge main process ended, respawning
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439671] irqbalance invoked oom-killer: gfp_mask=0x80d0, order=0, oom_adj=0, oom_score_adj=0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439674] irqbalance cpuset=/ mems_allowed=0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439676] Pid: 948, comm: irqbalance Not tainted 3.2.0-55-generic-pae #85-Ubuntu
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439678] Call Trace:
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439684]  [] dump_header.isra.6+0x85/0xc0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439686]  [] oom_kill_process+0x5c/0x80
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439688]  [] out_of_memory+0xc5/0x1c0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439691]  [] __alloc_pages_nodemask+0x72c/0x740
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439694]  [] __get_free_pages+0x1c/0x30
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439696]  [] get_zeroed_page+0x12/0x20
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439699]  [] fill_read_buffer.isra.8+0xaa/0xd0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439702]  [] sysfs_read_file+0x7d/0x90
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439704]  [] vfs_read+0x8c/0x160
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439707]  [] ? fill_read_buffer.isra.8+0xd0/0xd0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439709]  [] sys_read+0x3d/0x70
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439712]  [] sysenter_do_call+0x12/0x28
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439714] Mem-Info:
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439714] DMA per-cpu:
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439716] CPU    0: hi:    0, btch:   1 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439717] CPU    1: hi:    0, btch:   1 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439718] CPU    2: hi:    0, btch:   1 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439719] CPU    3: hi:    0, btch:   1 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439720] CPU    4: hi:    0, btch:   1 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439721] CPU    5: hi:    0, btch:   1 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439722] CPU    6: hi:    0, btch:   1 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439723] CPU    7: hi:    0, btch:   1 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439724] Normal per-cpu:
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439725] CPU    0: hi:  186, btch:  31 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439726] CPU    1: hi:  186, btch:  31 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439727] CPU    2: hi:  186, btch:  31 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439728] CPU    3: hi:  186, btch:  31 usd:   0
Oct 25 07:28:44 nldedip4k031 kernel: [87986.439729] CPU    4: hi:  186, btch:  31 usd:   0
Oct 25 07:33:48 nldedip4k031 kernel: imklog 5.8.6, log source = /proc/kmsg started.
Oct 25 07:33:48 nldedip4k031 rsyslogd: [origin software="rsyslogd" swVersion="5.8.6" x-pid="2880" x-info="http://www.rsyslog.com"] start
Oct 25 07:33:48 nldedip4k031 rsyslogd: rsyslogd's groupid changed to 103
Oct 25 07:33:48 nldedip4k031 rsyslogd: rsyslogd's userid changed to 101
Oct 25 07:33:48 nldedip4k031 rsyslogd-2039: Could not open output pipe '/dev/xconsole' [try http://www.rsyslog.com/e/2039 ]
linux

2 Answers

  1. Best Answer

    The OOM killer suggests that in fact, you've run out of memory.

    If you say it's got more memory than it needs then maybe some system event is creating a memory leak somewhere, but the OOM killer will not tell why there is a memory leak, only that it's run out of memory and now tries to kill the least important things (based on oom_score).

    And if the case is that there is a memory leak, then maybe the oom-killer will only kill procs so that the rouge one can allocate more and more memory.

    So what I would do in case, is

    1. Configure kdump, which will create a crash dump vmcore after a kernel panic. (it's described more here)
    2. Setting vm.panic_on_oom=1 kernel parameter. This will cause a kernel panic should the machine run out of memory.
    3. Next time you get a panic, you can open up the vmcore file created by kdump, and look at the process table, and it will reveal the culprit.
    • 22

  2. The question is pretty old but reading the log suggests that this is a VFS or some filesystem bug. The system still has 4 GB of free swap and OOM Killer is activated!

    The interesting part is at the start:

    Oct 25 07:28:04 nldedip4k031 kernel: [87946.529519] Call Trace:
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529525]  [] dump_header.isra.6+0x85/0xc0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529528]  [] oom_kill_process+0x5c/0x80
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529530]  [] out_of_memory+0xc5/0x1c0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529532]  [] __alloc_pages_nodemask+0x72c/0x740
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529535]  [] __get_free_pages+0x1c/0x30
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529537]  [] get_zeroed_page+0x12/0x20
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529541]  [] fill_read_buffer.isra.8+0xaa/0xd0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529543]  [] sysfs_read_file+0x7d/0x90
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529546]  [] vfs_read+0x8c/0x160
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529548]  [] ? fill_read_buffer.isra.8+0xd0/0xd0
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529550]  [] sys_read+0x3d/0x70
Oct 25 07:28:04 nldedip4k031 kernel: [87946.529554]  [] sysenter_do_call+0x12/0x28

    So some process was trying to read file (from sysfs?) and the system run out of memory while doing that.

    Note that before the OOM Killer lines the system also says free:1304125 so it really doesn't make any sense to start killing processes to execute a filesystem read.

    If you're not using any rare filesystems or unstable kernel, I'd guess the hardware has memory corruption. Otherwise, stick to something stable (e.g. ext4 filesystem) and use latest stable kernel available for the distribution you have.

    • 1