BUG: soft lockup - CPU#1 stuck for 61s! [unlink:13830]

[Brian J. Murrell]

I got a soft lockup while trying to delete files from an ext4 filesystem on 2.6.28-8.28:

[94007.172003] BUG: soft lockup - CPU#0 stuck for 61s! [rm:11764]
[94007.173005] BUG: soft lockup - CPU#1 stuck for 61s! [unlink:13830]
[94072.669004] BUG: soft lockup - CPU#1 stuck for 61s! [unlink:13830]
[94072.672004] BUG: soft lockup - CPU#0 stuck for 61s! [rm:11764]

There were two processes doing deletes on that filesystem, an "rm" and an "unlink".

Here's a stack trace of the unlink process:

[94271.313004] BUG: soft lockup - CPU#1 stuck for 61s! [unlink:13830]
[94271.313005] Modules linked in: xt_multiport binfmt_misc bridge stp bnep vboxnetflt vboxdrv tun des_generic cbc autofs4 video output input_polldev rpcsec_gss_krb5 nfsd auth_rpcgss exportfs nfs lockd nfs_acl sunrpc nf_conntrack_ipv6 ip6t_hl ipt_LOG xt_limit ipt_REJECT xt_tcpudp xt_state ipt_addrtype ip6table_filter ip6_tables nf_nat_irc nf_conntrack_irc nf_nat_ftp nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack_ftp nf_conntrack iptable_filter ip_tables x_tables it87 hwmon_vid eeprom lp snd_usb_audio snd_emu10k1_synth snd_emux_synth snd_seq_virmidi snd_seq_midi_emul tuner_simple tuner_types tea5767 tuner msp3400 snd_usb_lib snd_seq_dummy snd_emu10k1 bttv snd_seq_oss ir_common snd_bt87x snd_hda_intel snd_ac97_codec i2c_algo_bit snd_seq_midi v4l2_common snd_rawmidi ac97_bus snd_pcm_oss snd_mixer_oss videobuf_dma_sg videobuf_core btcx_risc emu10k1_gp ppdev snd_pcm parport_pc snd_seq_midi_event snd_util_mem tveeprom snd_seq serio_raw k8temp gameport snd_hwdep snd_timer snd_seq_device parport uvcvideo nvidia(P) snd compat_ioctl32 psmouse usblp agpgart videodev i2c_nforce2 pcspkr v4l1_compat soundcore snd_page_alloc forcedeth ohci1394 ieee1394 ohci_hcd ehci_hcd raid10 raid456 async_xor async_memcpy async_tx xor raid1 raid0 multipath linear fbcon tileblit font bitblit softcursor fuse
[94271.313005]
[94271.313005] Pid: 13830, comm: unlink Tainted: P (2.6.28-8-generic #27-Ubuntu) System Product Name
[94271.313005] EIP: 0060:[<c0122ba3>] EFLAGS: 00000293 CPU: 1
[94271.313005] EIP is at __ticket_spin_lock+0x13/0x20
[94271.313005] EAX: f4040af4 EBX: f4040af4 ECX: c78a6c40 EDX: 00002a28
[94271.313005] ESI: ee080c80 EDI: c78a6c40 EBP: ee5cde14 ESP: ee5cde14
[94271.313005] DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
[94271.313005] CR0: 8005003b CR2: b7ffd9c0 CR3: 06317000 CR4: 00000690
[94271.313005] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[94271.313005] DR6: ffff0ff0 DR7: 00000400
[94271.313005] Call Trace:
[94271.313005] [<c04eb338>] _spin_lock+0x8/0x10
[94271.313005] [<c0250d46>] do_get_write_access+0x3d6/0x4b0
[94271.313005] [<c01dd615>] ? ll_rw_block+0x75/0x120
[94271.313005] [<c0250f93>] jbd2_journal_get_write_access+0x23/0x40
[94271.313005] [<c023cc6f>] __ext4_journal_get_write_access+0x1f/0x50
[94271.313005] [<c022d420>] ext4_delete_entry+0xb0/0x130
[94271.313005] [<c022f4c5>] ext4_unlink+0x145/0x220
[94271.313005] [<c029fbb1>] ? apparmor_inode_unlink+0x41/0x50
[94271.313005] [<c01c60e7>] vfs_unlink+0xa7/0xf0
[94271.313005] [<c04eb338>] ? _spin_lock+0x8/0x10
[94271.313005] [<c01c8248>] do_unlinkat+0x138/0x150
[94271.313005] [<c01bb389>] ? filp_close+0x49/0x70
[94271.313005] [<c01c8270>] sys_unlink+0x10/0x20
[94271.313005] [<c0103f6b>] sysenter_do_call+0x12/0x2f

The stack trace of the "rm" process:

[94191.856007] Modules linked in: xt_multiport binfmt_misc bridge stp bnep vboxnetflt vboxdrv tun des_generic cbc autofs4 video output input_polldev rpcsec_gss_krb5 nfsd auth_rpcgss exportfs nfs lockd nfs_acl sunrpc nf_conntrack_ipv6 ip6t_hl ipt_LOG xt_limit ipt_REJECT xt_tcpudp xt_state ipt_addrtype ip6table_filter ip6_tables nf_nat_irc nf_conntrack_irc nf_nat_ftp nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack_ftp nf_conntrack iptable_filter ip_tables x_tables it87 hwmon_vid eeprom lp snd_usb_audio snd_emu10k1_synth snd_emux_synth snd_seq_virmidi snd_seq_midi_emul tuner_simple tuner_types tea5767 tuner msp3400 snd_usb_lib snd_seq_dummy snd_emu10k1 bttv snd_seq_oss ir_common snd_bt87x snd_hda_intel snd_ac97_codec i2c_algo_bit snd_seq_midi v4l2_common snd_rawmidi ac97_bus snd_pcm_oss snd_mixer_oss videobuf_dma_sg videobuf_core btcx_risc emu10k1_gp ppdev snd_pcm parport_pc snd_seq_midi_event snd_util_mem tveeprom snd_seq serio_raw k8temp gameport snd_hwdep snd_timer snd_seq_device parport uvcvideo nvidia(P) snd compat_ioctl32 psmouse usblp agpgart videodev i2c_nforce2 pcspkr v4l1_compat soundcore snd_page_alloc forcedeth ohci1394 ieee1394 ohci_hcd ehci_hcd raid10 raid456 async_xor async_memcpy async_tx xor raid1 raid0 multipath linear fbcon tileblit font bitblit softcursor fuse
[94191.856007]
[94191.856007] Pid: 11764, comm: rm Tainted: P (2.6.28-8-generic #27-Ubuntu) System Product Name
[94191.856007] EIP: 0060:[<c0122ba3>] EFLAGS: 00000297 CPU: 0
[94191.856007] EIP is at __ticket_spin_lock+0x13/0x20
[94191.856007] EAX: f4040af4 EBX: f4040af4 ECX: c6a63cb0 EDX: 00002928
[94191.856007] ESI: ee080c80 EDI: c6a63cb0 EBP: f4bc7e1c ESP: f4bc7e1c
[94191.856007] DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
[94191.856007] CR0: 8005003b CR2: b3f8f000 CR3: 0a367000 CR4: 00000690
[94191.856007] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[94191.856007] DR6: ffff0ff0 DR7: 00000400
[94191.856007] Call Trace:
[94191.856007] [<c04eb338>] _spin_lock+0x8/0x10
[94191.856007] [<c0250d46>] do_get_write_access+0x3d6/0x4b0
[94191.856007] [<c02c3fe6>] ? copy_to_user+0x36/0x120
[94191.856007] [<c0255989>] ? jbd2_journal_add_journal_head+0x69/0x130
[94191.856007] [<c0254544>] ? __jbd2_log_space_left+0x14/0x40
[94191.856007] [<c0250f93>] jbd2_journal_get_write_access+0x23/0x40
[94191.856007] [<c023cc6f>] __ext4_journal_get_write_access+0x1f/0x50
[94191.856007] [<c02281ce>] ext4_reserve_inode_write+0x5e/0x80
[94191.856007] [<c022822b>] ext4_mark_inode_dirty+0x3b/0x160
[94191.856007] [<c024fbcb>] ? jbd2_journal_start+0x8b/0xd0
[94191.856007] [<c0228469>] ext4_dirty_inode+0x49/0x80
[94191.856007] [<c01d916c>] __mark_inode_dirty+0x2c/0x190
[94191.856007] [<c04eb338>] ? _spin_lock+0x8/0x10
[94191.856007] [<c01cf54c>] touch_atime+0xbc/0x110
[94191.856007] [<c01caccb>] vfs_readdir+0x9b/0xa0
[94191.856007] [<c01ca990>] ? filldir64+0x0/0xf0
[94191.856007] [<c01cad38>] sys_getdents64+0x68/0xb0
[94191.856007] [<c0103f6b>] sysenter_do_call+0x12/0x2f
[94140.361005] c04ea5b2 0000c350
[94140.361005] Call Trace:
[94140.361005] [<c04ea5b2>] do_nanosleep+0x92/0xc0
[94140.361005] [<c0152fe3>] hrtimer_nanosleep+0xf3/0x180
[94140.361005] [<c01523a0>] ? hrtimer_wakeup+0x0/0x20
[94140.361005] [<c04ea59f>] ? do_nanosleep+0x7f/0xc0
[94140.361005] [<c01530d0>] sys_nanosleep+0x60/0x70
[94140.361005] [<c0103f6b>] sysenter_do_call+0x12/0x2f

[dnyaga (daniel-nyaga)]

This seems to be https://bugs.launchpad.net/ubuntu/+source/linux/+bug/330824. Similar behavior has been reported here (https://bugs.launchpad.net/ubuntu/+source/subversion/+bug/342164) and here (https://bugs.launchpad.net/ubuntu/+bug/334581).

Did you convert your ext4 filesystem from ext3 or is it a new/fresh filesystem?

[Brian J. Murrell (brian-interlinx)]

On Sun, 2009-03-15 at 20:13 +0000, dnyaga wrote:
> This seems to be
> https://bugs.launchpad.net/ubuntu/+source/linux/+bug/330824. Similar
> behavior has been reported here
> (https://bugs.launchpad.net/ubuntu/+source/subversion/+bug/342164) and
> here (https://bugs.launchpad.net/ubuntu/+bug/334581).

Without having looked at these other bugs yet...

> Did you convert your ext4 filesystem from ext3 or is it a new/fresh
> filesystem?

This was a new/fresh created ext4dev from Intrepid.