From mboxrd@z Thu Jan 1 00:00:00 1970 From: leandro Costantino Subject: Question about warning and later oops slub/jbd2 Date: Sat, 20 Jun 2009 15:54:52 -0400 Message-ID: Mime-Version: 1.0 Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit To: linux-fsdevel@vger.kernel.org Return-path: Received: from yw-out-2324.google.com ([74.125.46.30]:56752 "EHLO yw-out-2324.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751636AbZFTTyu (ORCPT ); Sat, 20 Jun 2009 15:54:50 -0400 Received: by yw-out-2324.google.com with SMTP id 5so1404502ywb.1 for ; Sat, 20 Jun 2009 12:54:52 -0700 (PDT) Sender: linux-fsdevel-owner@vger.kernel.org List-ID: Hi, i just wanted to know from people that know about mm/fs subject, if the follow "oops" its an expected behavior (kinda feature ) or not, since i was just touching some files and suddenly started to happen. Please CC me since i am not subscribed to the list. I consider myself ignorant about this subject to make any asumption, so i'll try to explain what's going on. Using lastest git kernel (2.6.30-6701-g4b67c5d), and also tested on 2.6.28-rc2 both smp. (Modules: jbd2 ) No "oops" reported when: Booting with slub_debug=ZPU , the caches are not merged, so doing something like this # modprobe jbd2 ( or ext4 ) # ls -la /sys/kernel/slab|grep jbd2 ... drwxr-xr-x 2 root root 0 Jun 20 20:50 jbd2_journal_handle drwxr-xr-x 2 root root 0 Jun 20 20:50 jbd2_journal_head drwxr-xr-x 2 root root 0 Jun 20 20:50 jbd2_revoke_record drwxr-xr-x 2 root root 0 Jun 20 20:50 jbd2_revoke_table .... Next, when removing the module: (rmmod jbd2 or modprobe -r ext4 ), the jbd2_* files are removed from sys. But, when booting with slub_debug=- ( or disabling slub debug directly from kernel ), the caches are merged , so after modprobe ext4 (or jbd2) /sys/kernel/slab|grep jbd2 reports something like: lrwxrwxrwx 1 root root 0 Jun 20 21:00 jbd2_journal_handle -> :at-0000040 lrwxrwxrwx 1 root root 0 Jun 20 21:00 jbd2_journal_head -> :at-0000064 lrwxrwxrwx 1 root root 0 Jun 20 21:00 jbd2_revoke_record -> :at-0000032 lrwxrwxrwx 1 root root 0 Jun 20 21:00 jbd2_revoke_table -> :at-0000016 slabinfo -a reports: ------------------------------- :at-0000016 <- revoke_record revoke_table jbd2_revoke_table :at-0000040 <- jbd2_journal_handle journal_handle ext4_free_block_extents :at-0000048 <- ext3_xattr ext2_xattr ext4_xattr :at-0000064 <- journal_head jbd2_journal_head :t-0000008 <- kmalloc-8 dm_rq_clone_bio_info :t-0000016 <- inotify_event_private_data kmalloc-16 ip_fib_alias dm_target_io dm_snap_tracked_chunk fsnotify_event_holder fasync_cache :t-0000024 <- Acpi-Namespace dm_io debug_objects_cache dm_snap_exception dnotify_struct scsi_data_buffer nsproxy :t-0000032 <- kmalloc-32 fib6_nodes tcp_bind_bucket uhci_urb_priv secpath_cache Acpi-Parse :t-0000040 <- Acpi-Operand ip_fib_hash eventpoll_pwq :t-0000048 <- Acpi-ParseExt sysfs_dir_cache Acpi-State :t-0000064 <- inet_peer_cache dm_snap_pending_exception uid_cache pid nfs_page kmalloc-64 :t-0000080 <- blkdev_ioc flow_cache :t-0000096 <- inotify_inode_mark_entry cfq_io_context fsnotify_event kmalloc-96 dnotify_mark_entry :t-0000128 <- request_sock_TCP ip_mrt_cache mnt_cache cred_jar bio-0 scsi_sense_cache eventpoll_epi request_sock_TCPv6 kmalloc-128 :t-0000192 <- kiocb biovec-16 skbuff_head_cache kmalloc-192 scsi_cmd_cache filp key_jar rpc_tasks sgpool-8 :t-0000256 <- arp_cache kmalloc-256 ndisc_cache ip6_dst_cache ip_dst_cache :t-0000320 <- sgpool-16 xfrm_dst_cache :t-0000384 <- kioctx nfs_read_data skbuff_fclone_cache :t-0000768 <- biovec-64 RAW :t-0002048 <- kmalloc-2048 rpc_buffers :t-0004096 <- names_cache kmalloc-4096 -------[eof]------- Now , when modprobe -r ext4 ( or rmmod jbd2), the jbd2_* files are still listed on /sys/kernel/slab and slabinfo start to report some alias errors. I suppose they are not remove if they have been merged on some cache that's still being used by some "alias" or if they have persistent in-kernel storage. Since the "alias" or files are still listed, when doing: # echo 1 > /sys/kernel/slab/jbd2_journal_handle/poison # modprobe ext4 ( or modprobe jbd2 ) this oops appears and later a bunch of another oops, making the system unresponsive. [ 65.132850] ------------[ cut here ]------------ [ 65.132925] WARNING: at fs/sysfs/dir.c:487 sysfs_add_one+0xf6/0x120() [ 65.132989] Hardware name: Extensa 5420 [ 65.133069] sysfs: cannot create duplicate filename '/kernel/slab/:at-0000040' [ 65.133154] Modules linked in: jbd2(+) crc16 loop snd_hda_codec_realtek snd_hda_intel snd_hda_codec arc4 ecb snd_hwdep cryptomgr aead snd_pcm_oss snd_pcm pcompress crypto_blkcipher snd_mixer_oss crypto_hash crypto_algapi snd_seq_oss $ [ 65.135932] Pid: 4507, comm: modprobe Tainted: G B 2.6.30-obelisco-generic #29 [ 65.136026] Call Trace: [ 65.136087] [] ? sysfs_add_one+0xf6/0x120 [ 65.136151] [] warn_slowpath_common+0x7d/0xe0 [ 65.136215] [] ? sysfs_add_one+0xf6/0x120 [ 65.136278] [] warn_slowpath_fmt+0x33/0x50 [ 65.136341] [] sysfs_add_one+0xf6/0x120 [ 65.136403] [] create_dir+0x5a/0xb0 [ 65.136465] [] sysfs_create_dir+0x36/0x60 [ 65.136530] [] ? _spin_unlock+0x2b/0x50 [ 65.136595] [] kobject_add_internal+0xd4/0x1d0 [ 65.136659] [] kobject_add_varg+0x3d/0x70 [ 65.136721] [] kobject_init_and_add+0x3e/0x60 [ 65.136785] [] sysfs_slab_add+0x82/0x220 [ 65.136849] [] kmem_cache_create+0xe8/0x2f0 [ 65.137716] [] ? journal_init+0x0/0xd5 [jbd2] [ 65.137782] [] journal_init+0x9e/0xd5 [jbd2] [ 65.137845] [] do_one_initcall+0x35/0x180 [ 65.137909] [] ? up_read+0x24/0x50 [ 65.137972] [] ? __blocking_notifier_call_chain+0x63/0x90 [ 65.138047] [] ? blocking_notifier_call_chain+0x27/0x50 [ 65.138111] [] sys_init_module+0xc2/0x210 [ 65.138175] [] sysenter_do_call+0x12/0x3c [ 65.138237] ---[ end trace 16c86c85e40c183d ]--- [ 65.138301] kobject_add_internal failed for :at-0000040 with -EEXIST, don't try to register things with the same name in the same directory. [ 65.138390] Pid: 4507, comm: modprobe Tainted: G B W 2.6.30-obelisco-generic #29 [ 65.138474] Call Trace: [ 65.138534] [] ? printk+0x23/0x40 [ 65.138596] [] kobject_add_internal+0x118/0x1d0 [ 65.138660] [] kobject_add_varg+0x3d/0x70 [ 65.138722] [] kobject_init_and_add+0x3e/0x60 [ 65.138786] [] sysfs_slab_add+0x82/0x220 [ 65.138848] [] kmem_cache_create+0xe8/0x2f0 [ 65.138913] [] ? journal_init+0x0/0xd5 [jbd2] [ 65.138979] [] journal_init+0x9e/0xd5 [ 65.139243] [] ? blocking_notifier_call_chain+0x27/0x50 [ 65.139307] [] sys_init_module+0xc2/0x210 [ 65.139369] [] sysenter_do_call+0x12/0x3c [ 65.141247] BUG: unable to handle kernel NULL pointer dereference at (null) [ 65.141396] IP: [] list_del+0x17/0xb0 [ 65.141500] *pde = 00000000 [ 65.141597] Oops: 0000 [#1] SMP [ 65.141732] last sysfs file: /sys/kernel/slab/:at-0000040/poison [ 65.141795] Modules linked in: jbd2(+) crc16 loop snd_hda_codec_realtek snd_hda_intel snd_hda_codec arc4 ecb snd_hwdep cryptomgr aead snd_pcm_oss snd_pcm pcompress crypto_blkcipher snd_mixer_oss crypto_hash crypto_algapi snd_seq_oss $ [ 65.142015] [ 65.142015] Pid: 4507, comm: modprobe Tainted: G B W (2.6.30-obelisco-generic #29) Extensa 5420 [ 65.142015] EIP: 0060:[] EFLAGS: 00010246 CPU: 0 [ 65.142015] EIP is at list_del+0x17/0xb0 [ 65.142015] EAX: 00000000 EBX: f7374df8 ECX: 00000000 EDX: 00000000 [ 65.142015] ESI: f7374d80 EDI: f8ae0416 EBP: c3633ea0 ESP: c3633e84 [ 65.142015] DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 [ 65.142015] Process modprobe (pid: 4507, ti=c3632000 task=c3a0c060 task.ti=c3632000) [ 65.142015] Stack: [ 65.142015] 00000002 00000000 c10e1b46 fc41b58e f7374d80 fc41b58e f7374d80 c3633ef0 [ 65.142015] <0> c10e1b4e 00000028 00000000 00020000 00000000 00000000 00020000 00000000 [ 65.142015] <0> 00000028 f7374df8 00000000 00000005 0000002b fffffff8 00020000 fc41b58e [ 65.142015] Call Trace: [ 65.142015] [] ? kmem_cache_create+0xf6/0x2f0 [ 65.142015] [] ? kmem_cache_create+0xfe/0x2f0 [ 65.142015] [] ? journal_init+0x0/0xd5 [jbd2] [ 65.142015] [] ? journal_init+0x9e/0xd5 [jbd2] [ 65.142015] [] ? do_one_initcall+0x35/0x180 [ 65.142015] [] ? up_read+0x24/0x50 [ 65.142015] [] ? __blocking_notifier_call_chain+0x63/0x90 [ 65.142015] [] ? blocking_notifier_call_chain+0x27/0x50 [ 65.142015] [] ? sys_init_module+0xc2/0x210 [ 65.142015] [] ? sysenter_do_call+0x12/0x3c [ 65.142015] Code: 75 fc 89 ec 5d c3 e8 f9 e7 e6 ff 90 90 90 90 90 90 90 90 90 55 89 e5 53 89 c3 83 ec 18 65 a1 14 00 00 00 89 45 f8 31 c0 8b 43 04 <8b> 00 39 d8 75 5d 8b 13 8b 42 04 39 d8 75 2c 8b 43 04 89 42 04 [ 65.142015] EIP: [] list_del+0x17/0xb0 SS:ESP 0068:c3633e84 [ 65.142015] CR2: 0000000000000000 [ 65.149731] ---[ end trace 16c86c85e40c183e ]--- [jbd2] [ 65.139053] [] do_one_initcall+0x35/0x180 [ 65.139116] [] ? up_read+0x24/0x50 [ 65.139179] [] ? __blocking_notifier_call_chain+0x63/0x90 [more oops, related to other operations] So to resume all the wrong assumptions i wrote, this is reproducible in my case doing: #modprobe jbd2 ( or any dependent module) #rmmod jbd2 ( or any dependent module, [-r] in that case ) #echo 1 > /sys/kernel/slab/jbd2_journal_handle/poison #modprobe jbd2 Is this "behavior" expected since the caches are merged? or i am just writing bs and its related to another thing? Best Rgds Sorry if i make some ppl loose time reading this. Costantino Leandro