nnpfs_readdir problem

[Jean-Damien Durand]

Just catched the following loop: pressed tab to have completion in my zsh and it got very cpu
consuming. fs arladebug showed nothing relevant:

Apr  4 12:24:29 pcitds04 arla[7348]: sending wakeup: seq = 28427, error = 0
Apr  4 12:24:29 pcitds04 arla[7348]: Send message: opcode = 1 (wakeup), size = 24
Apr  4 12:24:29 pcitds04 arla[7348]: worker 0: done
Apr  4 12:24:29 pcitds04 arla[7348]: worker 0 waiting
Apr  4 12:24:52 pcitds04 arla[7348]: worker 0: processing
Apr  4 12:24:52 pcitds04 arla[7348]: Rec message: opcode = 22 (pioctl), size = 2104
Apr  4 12:24:52 pcitds04 arla[7348]: sending wakeup: seq = 28428, error = 0
Apr  4 12:24:52 pcitds04 arla[7348]: Send message: opcode = 23 (wakeup_data), size = 2080
Apr  4 12:24:52 pcitds04 arla[7348]: worker 0: done
Apr  4 12:24:52 pcitds04 arla[7348]: worker 0 waiting
Apr  4 12:24:54 pcitds04 arla[7348]: worker 0: processing
Apr  4 12:24:54 pcitds04 arla[7348]: Rec message: opcode = 22 (pioctl), size = 2104
Apr  4 12:24:54 pcitds04 arla[7348]: sending wakeup: seq = 28429, error = 0
Apr  4 12:24:54 pcitds04 arla[7348]: Send message: opcode = 23 (wakeup_data), size = 2080
Apr  4 12:24:54 pcitds04 arla[7348]: worker 0: done
Apr  4 12:24:54 pcitds04 arla[7348]: worker 0 waiting
Apr  4 12:25:20 pcitds04 arla[7348]: poller waiting
Apr  4 12:25:20 pcitds04 arla[7348]: running poller
Apr  4 12:25:20 pcitds04 arla[7348]: poller done
Apr  4 12:25:20 pcitds04 arla[7348]: poller waiting

but fs nnpfsdebug, that I switched after, showed weird behaviour:


Apr  4 12:26:01 pcitds04 kernel: nnpfs_syscall returns error: 0
Apr  4 12:26:01 pcitds04 kernel: BUG: using smp_processor_id() in preemptible [00000001] code: fs/20020
Apr  4 12:26:01 pcitds04 kernel: caller is sys_afs_int+0x654/0x673 [nnpfs]
Apr  4 12:26:01 pcitds04 kernel:  [debug_smp_processor_id+117/136] debug_smp_processor_id+0x75/0x88
Apr  4 12:26:01 pcitds04 kernel:  [pg0+281864749/1067545600] sys_afs_int+0x654/0x673 [nnpfs]
Apr  4 12:26:01 pcitds04 kernel:  [pg0+281864749/1067545600] sys_afs_int+0x654/0x673 [nnpfs]
Apr  4 12:26:01 pcitds04 kernel:  [avc_has_perm_noaudit+901/1061] avc_has_perm_noaudit+0x385/0x425
Apr  4 12:26:01 pcitds04 kernel:  [avc_has_perm+57/69] avc_has_perm+0x39/0x45
Apr  4 12:26:01 pcitds04 kernel:  [__do_page_cache_readahead+148/538] __do_page_cache_readahead+0x94/0x21a
Apr  4 12:26:01 pcitds04 kernel:  [_read_unlock_irq+14/34] _read_unlock_irq+0xe/0x22
Apr  4 12:26:01 pcitds04 kernel:  [__do_page_cache_readahead+304/538] __do_page_cache_readahead+0x130/0x21a
Apr  4 12:26:01 pcitds04 kernel:  [slice+11/43] slice+0xb/0x2b
Apr  4 12:26:01 pcitds04 kernel:  [effective_prio+166/203] effective_prio+0xa6/0xcb
Apr  4 12:26:01 pcitds04 kernel:  [avc_has_perm_noaudit+901/1061] avc_has_perm_noaudit+0x385/0x425
Apr  4 12:26:01 pcitds04 kernel:  [resched_task+63/99] resched_task+0x3f/0x63
Apr  4 12:26:01 pcitds04 kernel:  [avc_has_perm+57/69] avc_has_perm+0x39/0x45
Apr  4 12:26:01 pcitds04 kernel:  [do_gettimeofday+27/157] do_gettimeofday+0x1b/0x9d
Apr  4 12:26:01 pcitds04 kernel:  [getnstimeofday+15/37] getnstimeofday+0xf/0x25
Apr  4 12:26:01 pcitds04 kernel:  [ktime_get_ts+71/77] ktime_get_ts+0x47/0x4d
Apr  4 12:26:01 pcitds04 kernel:  [_spin_unlock_irq+14/34] _spin_unlock_irq+0xe/0x22
Apr  4 12:26:01 pcitds04 kernel:  [avc_has_perm_noaudit+901/1061] avc_has_perm_noaudit+0x385/0x425
Apr  4 12:26:01 pcitds04 kernel:  [kzalloc+16/55] kzalloc+0x10/0x37
Apr  4 12:26:01 pcitds04 kernel:  [kzalloc+16/55] kzalloc+0x10/0x37
Apr  4 12:26:01 pcitds04 kernel:  [selinux_inode_alloc_security+34/139] selinux_inode_alloc_security+0x22/0x8b
Apr  4 12:26:01 pcitds04 kernel:  [alloc_inode+245/381] alloc_inode+0xf5/0x17d
Apr  4 12:26:01 pcitds04 kernel:  [_spin_unlock+13/33] _spin_unlock+0xd/0x21
Apr  4 12:26:01 pcitds04 last message repeated 2 times
Apr  4 12:26:01 pcitds04 kernel:  [proc_lookup+101/138] proc_lookup+0x65/0x8a
Apr  4 12:26:01 pcitds04 kernel:  [avc_has_perm_noaudit+901/1061] avc_has_perm_noaudit+0x385/0x425
Apr  4 12:26:01 pcitds04 kernel:  [dput+27/289] dput+0x1b/0x121
Apr  4 12:26:01 pcitds04 kernel:  [avc_has_perm+57/69] avc_has_perm+0x39/0x45
Apr  4 12:26:01 pcitds04 kernel:  [avc_has_perm_noaudit+901/1061] avc_has_perm_noaudit+0x385/0x425
Apr  4 12:26:01 pcitds04 kernel:  [inode_has_perm+82/90] inode_has_perm+0x52/0x5a
Apr  4 12:26:01 pcitds04 kernel:  [avc_has_perm+57/69] avc_has_perm+0x39/0x45
Apr  4 12:26:01 pcitds04 kernel:  [inode_has_perm+82/90] inode_has_perm+0x52/0x5a
Apr  4 12:26:01 pcitds04 kernel:  [pg0+281864844/1067545600] sys_afs+0x40/0x4c [nnpfs]
Apr  4 12:26:01 pcitds04 kernel:  [pg0+281864926/1067545600] nnpfs_procfs_ioctl+0x46/0x54 [nnpfs]
Apr  4 12:26:01 pcitds04 kernel:  [do_ioctl+72/95] do_ioctl+0x48/0x5f
Apr  4 12:26:01 pcitds04 kernel:  [vfs_ioctl+592/611] vfs_ioctl+0x250/0x263
Apr  4 12:26:01 pcitds04 kernel:  [sys_ioctl+70/98] sys_ioctl+0x46/0x62
Apr  4 12:26:01 pcitds04 kernel:  [syscall_call+7/11] syscall_call+0x7/0xb
Apr  4 12:26:01 pcitds04 kernel: sys_afs kernel unlock; cpu: 0
Apr  4 12:26:01 pcitds04 kernel: offset2: 2595
Apr  4 12:26:01 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595
Apr  4 12:26:01 pcitds04 last message repeated 1341 times
Apr  4 12:26:01 pcitds04 kernel: offset2: 2595
Apr  4 12:26:01 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595
Apr  4 12:26:01 pcitds04 last message repeated 617 times
Apr  4 12:26:02 pcitds04 kernel: offset2: 2595
Apr  4 12:26:02 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595
Apr  4 12:26:02 pcitds04 last message repeated 2028 times
Apr  4 12:26:02 pcitds04 kernel: offset2: 2595
Apr  4 12:26:02 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595
Apr  4 12:26:02 pcitds04 last message repeated 2002 times
Apr  4 12:26:02 pcitds04 kernel: offset2: 2595
Apr  4 12:26:02 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595
Apr  4 12:26:02 pcitds04 last message repeated 617 times
Apr  4 12:26:02 pcitds04 kernel: offset2: 2595
Apr  4 12:26:02 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595
Apr  4 12:26:02 pcitds04 last message repeated 1721 times
Apr  4 12:26:03 pcitds04 kernel: offset2: 2595
Apr  4 12:26:03 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595
Apr  4 12:26:03 pcitds04 last message repeated 2358 times
Apr  4 12:26:03 pcitds04 kernel: offset2: 2595
Apr  4 12:26:03 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595
Apr  4 12:26:03 pcitds04 last message repeated 2311 times
Apr  4 12:26:04 pcitds04 kernel: offset2: 2595
Apr  4 12:26:04 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595

including once the following log overlap:

Apr  4 12:26:33 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 25offset2: 2595
Apr  4 12:26:33 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595
Apr  4 12:26:33 pcitds04 last message repeated 84 times
Apr  4 12:26:33 pcitds04 kernel: noffset2: 2595
Apr  4 12:26:33 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595
Apr  4 12:26:33 pcitds04 last message repeated 67 times
Apr  4 12:26:33 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2offset2: 2595
Apr  4 12:26:33 pcitds04 kernel: nnpfs_readdir offset: 547 namlen: 0 offset2: 2595

Then I could not stop fs nnpfsdebug.

Cheers, JD.