Re: 2.6.21-rc4-mm1

From: Michal Piotrowski
Date: Tue Mar 20 2007 - 03:56:12 EST

Andrew Morton napisaÅ(a):
> Temporarily at
>
> http://userweb.kernel.org/~akpm/2.6.21-rc4-mm1/
>

Some new details about
http://www.ussg.iu.edu/hypermail/linux/kernel/0703.2/1367.html

I can reproduce it by running this on AutoTest

for profiler in ('oprofile', ):
try:
print "Testing profiler %s ..." % profiler
job.profilers.add(profiler)
job.run_test('aiostress',)
job.profilers.delete(profiler)
except:
print "Test of profiler %s failed" % profiler
raise

I guess that oprofile triggers it.

BUG: using smp_processor_id() in preemptible [00000001] code: mount/4934
caller is avail_to_resrv_perfctr_nmi_bit+0x2b/0x43
[<c0105256>] show_trace_log_lvl+0x1a/0x2f
[<c010597b>] show_trace+0x12/0x14
[<c0105a3d>] dump_stack+0x16/0x18
[<c0212f43>] debug_smp_processor_id+0xb3/0xc8
[<c0116a26>] avail_to_resrv_perfctr_nmi_bit+0x2b/0x43
[<fdc829b9>] nmi_create_files+0x2a/0x10e [oprofile]
[<fdc81f52>] oprofile_create_files+0xe6/0xec [oprofile]
[<fdc82157>] oprofilefs_fill_super+0x78/0x7e [oprofile]
[<c018296e>] get_sb_single+0x59/0x9f
[<fdc8208f>] oprofilefs_get_sb+0x1c/0x1e [oprofile]
[<c01823d2>] vfs_kern_mount+0x81/0xf1
[<c0182492>] do_kern_mount+0x38/0xde
[<c01962b1>] do_mount+0x605/0x693
[<c01963bf>] sys_mount+0x80/0xb5
[<c0104270>] syscall_call+0x7/0xb
=======================

l *avail_to_resrv_perfctr_nmi_bit+0x2b/0x43
0xc01169fb is in avail_to_resrv_perfctr_nmi_bit (/mnt/md0/devel/linux-mm/arch/i386/kernel/nmi.c:124).
119 return 0;
120 }
121
122 /* checks for a bit availability (hack for oprofile) */
123 int avail_to_resrv_perfctr_nmi_bit(unsigned int counter)
124 {
125 BUG_ON(counter > NMI_MAX_COUNTER_BITS);
126
127 return (!test_bit(counter, &__get_cpu_var(perfctr_nmi_owner)));
128 }


BUG: using smp_processor_id() in preemptible [00000001] code: mount/4934
caller is avail_to_resrv_perfctr_nmi_bit+0x2b/0x43
[<c0105256>] show_trace_log_lvl+0x1a/0x2f
[<c010597b>] show_trace+0x12/0x14
[<c0105a3d>] dump_stack+0x16/0x18
[<c0212f43>] debug_smp_processor_id+0xb3/0xc8
[<c0116a26>] avail_to_resrv_perfctr_nmi_bit+0x2b/0x43
[<fdc829b9>] nmi_create_files+0x2a/0x10e [oprofile]
[<fdc81f52>] oprofile_create_files+0xe6/0xec [oprofile]
[<fdc82157>] oprofilefs_fill_super+0x78/0x7e [oprofile]
[<c018296e>] get_sb_single+0x59/0x9f
[<fdc8208f>] oprofilefs_get_sb+0x1c/0x1e [oprofile]
[<c01823d2>] vfs_kern_mount+0x81/0xf1
[<c0182492>] do_kern_mount+0x38/0xde
[<c01962b1>] do_mount+0x605/0x693
[<c01963bf>] sys_mount+0x80/0xb5
[<c0104270>] syscall_call+0x7/0xb
=======================
BUG: using smp_processor_id() in preemptible [00000001] code: mount/4934
caller is avail_to_resrv_perfctr_nmi_bit+0x2b/0x43
[<c0105256>] show_trace_log_lvl+0x1a/0x2f
[<c010597b>] show_trace+0x12/0x14
[<c0105a3d>] dump_stack+0x16/0x18
[<c0212f43>] debug_smp_processor_id+0xb3/0xc8
[<c0116a26>] avail_to_resrv_perfctr_nmi_bit+0x2b/0x43
[<fdc829b9>] nmi_create_files+0x2a/0x10e [oprofile]
[<fdc81f52>] oprofile_create_files+0xe6/0xec [oprofile]
[<fdc82157>] oprofilefs_fill_super+0x78/0x7e [oprofile]
[<c018296e>] get_sb_single+0x59/0x9f
[<fdc8208f>] oprofilefs_get_sb+0x1c/0x1e [oprofile]
[<c01823d2>] vfs_kern_mount+0x81/0xf1
[<c0182492>] do_kern_mount+0x38/0xde
[<c01962b1>] do_mount+0x605/0x693
[<c01963bf>] sys_mount+0x80/0xb5
[<c0104270>] syscall_call+0x7/0xb
=======================
BUG: using smp_processor_id() in preemptible [00000001] code: mount/4934
caller is avail_to_resrv_perfctr_nmi_bit+0x2b/0x43
[<c0105256>] show_trace_log_lvl+0x1a/0x2f
[<c010597b>] show_trace+0x12/0x14
[<c0105a3d>] dump_stack+0x16/0x18
[<c0212f43>] debug_smp_processor_id+0xb3/0xc8
[<c0116a26>] avail_to_resrv_perfctr_nmi_bit+0x2b/0x43
[<fdc829b9>] nmi_create_files+0x2a/0x10e [oprofile]
[<fdc81f52>] oprofile_create_files+0xe6/0xec [oprofile]
[<fdc82157>] oprofilefs_fill_super+0x78/0x7e [oprofile]
[<c018296e>] get_sb_single+0x59/0x9f
[<fdc8208f>] oprofilefs_get_sb+0x1c/0x1e [oprofile]
[<c01823d2>] vfs_kern_mount+0x81/0xf1
[<c0182492>] do_kern_mount+0x38/0xde
[<c01962b1>] do_mount+0x605/0x693
[<c01963bf>] sys_mount+0x80/0xb5
[<c0104270>] syscall_call+0x7/0xb
=======================
SELinux: initialized (dev oprofilefs, type oprofilefs), uses genfs_contexts

=================================
[ INFO: inconsistent lock state ]
2.6.21-rc4-mm1 #5
---------------------------------
inconsistent {hardirq-on-W} -> {in-hardirq-W} usage.
init/1 [HC1[1]:SC0[0]:HE0:SE1] takes:
(oprofilefs_lock){+-..}, at: [<fdc82b6e>] nmi_cpu_setup+0x15/0x4f [oprofile]
{hardirq-on-W} state was registered at:
[<c0140c15>] __lock_acquire+0x4e8/0xceb
[<c0141491>] lock_acquire+0x79/0x93
[<c033eb3f>] _spin_lock+0x35/0x42
[<fdc82347>] oprofilefs_ulong_from_user+0x4e/0x74 [oprofile]
[<fdc81fc7>] depth_write+0x27/0x43 [oprofile]
[<c0180afa>] vfs_write+0xd1/0x15a
[<c018112a>] sys_write+0x3d/0x72
[<c0104270>] syscall_call+0x7/0xb
[<ffffffff>] 0xffffffff
irq event stamp: 1022800
hardirqs last enabled at (1022799): [<c01042b8>] restore_nocheck+0x12/0x15
hardirqs last disabled at (1022800): [<c0104cf1>] call_function_interrupt+0x29/0x38
softirqs last enabled at (1022784): [<c0128eb4>] __do_softirq+0xe4/0xea
softirqs last disabled at (1022779): [<c0128ef3>] do_softirq+0x39/0x55

l *0xc01042b8
0xc01042b8 is at include2/asm/bitops.h:246.
241 static int test_bit(int nr, const volatile void * addr);
242 #endif
243
244 static __always_inline int constant_test_bit(int nr, const volatile unsigned long *addr)
245 {
246 return ((1UL << (nr & 31)) & (addr[nr >> 5])) != 0;
247 }
248
249 static inline int variable_test_bit(int nr, const volatile unsigned long * addr)
250 {

l *0xc0104cf1
0xc0104cf1 is at include2/asm/bitops.h:246.
241 static int test_bit(int nr, const volatile void * addr);
242 #endif
243
244 static __always_inline int constant_test_bit(int nr, const volatile unsigned long *addr)
245 {
246 return ((1UL << (nr & 31)) & (addr[nr >> 5])) != 0;
247 }
248
249 static inline int variable_test_bit(int nr, const volatile unsigned long * addr)
250 {

l *0xc0128eb4
0xc0128eb4 is in __do_softirq (/mnt/md0/devel/linux-mm/kernel/softirq.c:252).
247
248 trace_softirq_exit();
249
250 account_system_vtime(current);
251 _local_bh_enable();
252 }
253
254 #ifndef __ARCH_HAS_DO_SOFTIRQ
255
256 asmlinkage void do_softirq(void)

l *0xc0128ef3
0xc0128ef3 is in do_softirq (/mnt/md0/devel/linux-mm/kernel/softirq.c:271).
266 pending = local_softirq_pending();
267
268 if (pending)
269 __do_softirq();
270
271 local_irq_restore(flags);
272 }
273
274 EXPORT_SYMBOL(do_softirq);
275


other info that might help us debug this:
2 locks held by init/1:
#0: (tasklist_lock){..??}, at: [<c01261b6>] do_wait+0x54/0xba4
#1: (policy_rwlock){..??}, at: [<c01ef326>] security_compute_av+0x4f/0xbf

l *0xc01261b6
0xc01261b6 is in do_wait (include2/asm/current.h:11).
6
7 struct task_struct;
8
9 static __always_inline struct task_struct *get_current(void)
10 {
11 return read_pda(pcurrent);
12 }
13
14 #define current get_current()
15

l *0xc01ef326
0xc01ef326 is in security_compute_av (/mnt/md0/devel/linux-mm/security/selinux/ss/services.c:527).
522 return 0;
523 }
524
525 POLICY_RDLOCK;
526
527 scontext = sidtab_search(&sidtab, ssid);
528 if (!scontext) {
529 printk(KERN_ERR "security_compute_av: unrecognized SID %d\n",
530 ssid);
531 rc = -EINVAL;


stack backtrace:
[<c0105256>] show_trace_log_lvl+0x1a/0x2f
[<c010597b>] show_trace+0x12/0x14
[<c0105a3d>] dump_stack+0x16/0x18
[<c013f327>] print_usage_bug+0x140/0x14a
[<c013fbbf>] mark_lock+0xc9/0x510
[<c0140b86>] __lock_acquire+0x459/0xceb
[<c0141491>] lock_acquire+0x79/0x93
[<c033eb3f>] _spin_lock+0x35/0x42
[<fdc82b6e>] nmi_cpu_setup+0x15/0x4f [oprofile]
[<c0113b63>] smp_call_function_interrupt+0x3a/0x56
[<c0104cfb>] call_function_interrupt+0x33/0x38
[<c01ef380>] security_compute_av+0xa9/0xbf
[<c01e2649>] avc_has_perm_noaudit+0x1cf/0x490
[<c01e34da>] avc_has_perm+0x28/0x58
[<c01e3cd7>] task_has_perm+0x2d/0x2f
[<c01e6e74>] selinux_task_wait+0x2f/0x31
[<c0126295>] do_wait+0x133/0xba4
[<c0126d36>] sys_wait4+0x30/0x32
[<c0126d5f>] sys_waitpid+0x27/0x29
[<c01041e6>] sysenter_past_esp+0x5f/0x99
=======================

http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.21-rc4-mm1/mm-dmesg
http://www.stardust.webpages.pl/files/tbf/bitis-gabonica/2.6.21-rc4-mm1/mm-config

Regards,
Michal

--
Michal K. K. Piotrowski
LTG - Linux Testers Group (PL)
(http://www.stardust.webpages.pl/ltg/)
LTG - Linux Testers Group (EN)
(http://www.stardust.webpages.pl/linux_testers_group_en/)
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/