Bug 283108 – mount invokes oom-killer while mount the dvd drive sometimes

• Product: Gentoo Linux
• Status: RESOLVED NEEDINFO

[Description Jimmy Kloss 2009-08-29 11:12:26 UTC]

While copying some data from various backup dvds via a mount-copy-eject-loop-shellscript, my machine crashed several times on the mount action. most of the time oom-killer was invoked, which killed almost all processes, but a login on the text console was still possible. pstree showed something like 5 processes left. So I just rebooted and continued. Happens in KDE4 and Fluxbox.
Once I could only hard resett the machine.

I remeber that some time ago a had the some problem while using the pmount command, which "just" killed my KDE session and let me re-login instantly.

$ emerge --info
Portage 2.1.6.13 (default/linux/amd64/2008.0, gcc-4.3.2, glibc-2.9_p20081201-r2, 2.6.30-gentoo-r5 x86_64)

---Snippet of syslog---
Aug 29 11:44:04 HyperBel mount invoked oom-killer: gfp_mask=0x40d1, order=0, oomkilladj=0
Aug 29 11:44:04 HyperBel Pid: 6369, comm: mount Tainted: P           2.6.30-gentoo-r5 #2
Aug 29 11:44:04 HyperBel Call Trace:
Aug 29 11:44:04 HyperBel [<ffffffff802a23d3>] oom_kill_process+0x81/0x212
Aug 29 11:44:04 HyperBel [<ffffffff802a2950>] ? badness+0x176/0x1b9
Aug 29 11:44:04 HyperBel [<ffffffff802a29d2>] __out_of_memory+0x3f/0x146
Aug 29 11:44:04 HyperBel [<ffffffff802a2b47>] out_of_memory+0x6e/0x99
Aug 29 11:44:04 HyperBel [<ffffffff802a55fc>] __alloc_pages_internal+0x363/0x423
Aug 29 11:44:04 HyperBel [<ffffffff802c7747>] __slab_alloc+0x17d/0x4d3
Aug 29 11:44:04 HyperBel [<ffffffff804da552>] ? sr_cd_check+0x40/0x196
Aug 29 11:44:04 HyperBel [<ffffffff804da552>] ? sr_cd_check+0x40/0x196
Aug 29 11:44:04 HyperBel [<ffffffff802c8465>] __kmalloc+0xfb/0x163
Aug 29 11:44:04 HyperBel [<ffffffff804da552>] sr_cd_check+0x40/0x196
Aug 29 11:44:04 HyperBel [<ffffffff804d8a9d>] ? sr_test_unit_ready+0x60/0xc7
Aug 29 11:44:04 HyperBel [<ffffffff804d8deb>] sr_media_change+0xfc/0x286
Aug 29 11:44:04 HyperBel [<ffffffff804fce79>] media_changed+0x4e/0x83
Aug 29 11:44:04 HyperBel [<ffffffff804fceda>] cdrom_media_changed+0x2c/0x32
Aug 29 11:44:04 HyperBel [<ffffffff804d8b57>] sr_block_media_changed+0x14/0x16
Aug 29 11:44:04 HyperBel [<ffffffff802ef37a>] check_disk_change+0x24/0x56
Aug 29 11:44:04 HyperBel [<ffffffff805014e7>] cdrom_open+0x8a4/0x921
Aug 29 11:44:04 HyperBel [<ffffffff802dc685>] ? dput+0x2d/0x149
Aug 29 11:44:04 HyperBel [<ffffffff802d5da2>] ? __link_path_walk+0xc77/0xda0
Aug 29 11:44:04 HyperBel [<ffffffff802e0f23>] ? mntput_no_expire+0x2a/0x130
Aug 29 11:44:04 HyperBel [<ffffffff802d38fb>] ? path_put+0x2c/0x30
Aug 29 11:44:04 HyperBel [<ffffffff802d6128>] ? path_walk+0xc7/0xd4
Aug 29 11:44:04 HyperBel [<ffffffff804517d8>] ? kobject_get+0x1a/0x22
Aug 29 11:44:04 HyperBel [<ffffffff80447a79>] ? get_disk+0x4a/0x66
Aug 29 11:44:04 HyperBel [<ffffffff804517d8>] ? kobject_get+0x1a/0x22
Aug 29 11:44:04 HyperBel [<ffffffff804d8cd6>] sr_block_open+0x8b/0xa4
Aug 29 11:44:04 HyperBel [<ffffffff802f013d>] __blkdev_get+0xa4/0x330
Aug 29 11:44:04 HyperBel [<ffffffff802d38fb>] ? path_put+0x2c/0x30
Aug 29 11:44:04 HyperBel [<ffffffff802f03d4>] blkdev_get+0xb/0xd
Aug 29 11:44:04 HyperBel [<ffffffff802f04a8>] open_bdev_exclusive+0x2c/0x79
Aug 29 11:44:04 HyperBel [<ffffffff802ce6ae>] get_sb_bdev+0x43/0x162
Aug 29 11:44:04 HyperBel [<ffffffffa0c1f02e>] ? isofs_fill_super+0x0/0xa7e [isofs]
Aug 29 11:44:04 HyperBel [<ffffffff802aeee8>] ? kstrdup+0x2f/0x4b
Aug 29 11:44:04 HyperBel [<ffffffffa0c1e699>] isofs_get_sb+0x13/0x15 [isofs]
Aug 29 11:44:04 HyperBel [<ffffffff802ce3b4>] vfs_kern_mount+0x99/0x11d
Aug 29 11:44:04 HyperBel [<ffffffff802ce495>] do_kern_mount+0x47/0xe8
Aug 29 11:44:04 HyperBel [<ffffffff802e2b7f>] do_mount+0x74f/0x79d
Aug 29 11:44:04 HyperBel [<ffffffff802a572a>] ? __get_free_pages+0x17/0x56
Aug 29 11:44:04 HyperBel [<ffffffff802e2c56>] sys_mount+0x89/0xcf
Aug 29 11:44:04 HyperBel [<ffffffff80264233>] ? sys_rt_sigprocmask+0x54/0xce
Aug 29 11:44:04 HyperBel [<ffffffff80227aab>] system_call_fastpath+0x16/0x1b
Aug 29 11:44:04 HyperBel Mem-Info:
Aug 29 11:44:04 HyperBel DMA per-cpu:
Aug 29 11:44:04 HyperBel CPU    0: hi:    0, btch:   1 usd:   0
Aug 29 11:44:04 HyperBel CPU    1: hi:    0, btch:   1 usd:   0
Aug 29 11:44:04 HyperBel DMA32 per-cpu:
Aug 29 11:44:04 HyperBel CPU    0: hi:  186, btch:  31 usd:   0
Aug 29 11:44:04 HyperBel CPU    1: hi:  186, btch:  31 usd:   0
Aug 29 11:44:04 HyperBel Normal per-cpu:
Aug 29 11:44:04 HyperBel CPU    0: hi:  186, btch:  31 usd:   0
Aug 29 11:44:04 HyperBel CPU    1: hi:  186, btch:  31 usd:   0
Aug 29 11:44:04 HyperBel Active_anon:11145 active_file:4819 inactive_anon:10270
Aug 29 11:44:04 HyperBel inactive_file:463433 unevictable:0 dirty:79879 writeback:0 unstable:0
Aug 29 11:44:04 HyperBel free:473219 slab:37558 mapped:4068 pagetables:994 bounce:0
Aug 29 11:44:04 HyperBel DMA free:12kB min:12kB low:12kB high:16kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB present:6732kB pages_scanned:0 all_unreclaimable? yes
Aug 29 11:44:04 HyperBel lowmem_reserve[]: 0 3255 4012 4012
Aug 29 11:44:04 HyperBel DMA32 free:1579408kB min:6568kB low:8208kB high:9852kB active_anon:6328kB inactive_anon:1296kB active_file:2992kB inactive_file:1529400kB unevictable:0kB present:3333216kB pages_scanned:0 all_unreclaimable? no
Aug 29 11:44:04 HyperBel lowmem_reserve[]: 0 0 757 757
Aug 29 11:44:04 HyperBel Normal free:313456kB min:1528kB low:1908kB high:2292kB active_anon:38252kB inactive_anon:39784kB active_file:16284kB inactive_file:324332kB unevictable:0kB present:775680kB pages_scanned:0 all_unreclaimable? no
Aug 29 11:44:04 HyperBel lowmem_reserve[]: 0 0 0 0
Aug 29 11:44:04 HyperBel DMA: 1*4kB 1*8kB 0*16kB 0*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 12kB
Aug 29 11:44:04 HyperBel DMA32: 53773*4kB 48646*8kB 32371*16kB 11802*32kB 1086*64kB 19*128kB 2*256kB 2*512kB 2*1024kB 0*2048kB 1*4096kB = 1579476kB
Aug 29 11:44:04 HyperBel Normal: 15655*4kB 12466*8kB 5920*16kB 1531*32kB 95*64kB 3*128kB 0*256kB 2*512kB 0*1024kB 0*2048kB 0*4096kB = 313548kB
Aug 29 11:44:04 HyperBel 468433 total pagecache pages
Aug 29 11:44:04 HyperBel 0 pages in swap cache
Aug 29 11:44:04 HyperBel Swap cache stats: add 0, delete 0, find 0/0
Aug 29 11:44:04 HyperBel Free swap  = 0kB
Aug 29 11:44:04 HyperBel Total swap = 0kB
Aug 29 11:44:04 HyperBel 1245168 pages RAM
Aug 29 11:44:04 HyperBel 234468 pages reserved
Aug 29 11:44:04 HyperBel 472405 pages shared
Aug 29 11:44:04 HyperBel 71215 pages non-shared
Aug 29 11:44:04 HyperBel Out of memory: kill process 5942 (urxvtd) score 19264 or a child
Aug 29 11:44:04 HyperBel Killed process 6031 (bash)
---Snippet---

Reproducible: Sometimes

Steps to Reproduce:
1. Put a disc into the optical disc drive
2. use mount (or pmount) to mount it
3. watch your screens turn black :(

Actual Results:  
A memory leak? fills up all ram: mount invokes oom-killer
X sessions get killed, always
Several other processes get killed, often
Total machine lockup, sometimes

Expected Results:  
simply mount the disc.

[Comment 1 Jimmy Kloss 2009-08-29 11:13:54 UTC]

Created attachment 202589 [details]
emerge --info

[Comment 2 Jimmy Kloss 2009-08-29 11:14:36 UTC]

Created attachment 202590 [details]
syslog output

[Comment 3 Jimmy Kloss 2009-08-29 11:24:46 UTC]

Created attachment 202592 [details]
syslog output (this time with content)

[Comment 4 Samuli Suominen (RETIRED) 2009-09-14 08:27:11 UTC]

So.. stop using this custom script and use mount(8) ?

[Comment 5 Jimmy Kloss 2009-09-14 09:59:25 UTC]

(In reply to comment #4)
> So.. stop using this custom script and use mount(8) ?
> 

The script uses mount(8) it's just a for-loop to be faster. And yes, it also happened by typing it manually in a terminal with mount(8) and pmount(1). The deal i recognized it while using the script simply boils down to the fact that it happens rarely and the script is intended to copy alot of CDs/DVDs in a role. So the probability to hit the bug raises and every now and then... KABOOM.

[Comment 6 Jimmy Kloss 2009-09-14 10:04:48 UTC]

Created attachment 204006 [details]
the "evil" mount script

I attach the script so everyone has the chance to blame a specific line in it.

[Comment 7 Peter Alfredsen (RETIRED) 2009-10-23 21:10:06 UTC]

Anyone have any good ideas for debugging this problem?

[Comment 8 Jimmy Kloss 2009-10-24 13:58:18 UTC]

It seems that hal is involved here somehow. The following commands give similar result.

hal-disable-polling --device /dev/scd0
hal-disable-polling --enable-polling --device /dev/scd0

[Comment 9 SpanKY 2009-10-25 05:23:51 UTC]

i dont imagine the OOM is immediate.  why not start a new terminal and run:
while ps auxOR | tail ; do :; done

then run your test mount command and go back to the terminal and see what sucks up the memory

btw, you might want to enable magic sysrq in your kernel.  that makes it easy to kill all processes and remount disks safely with a few key strokes.