Hello,
While I was testing my filesystem module on 2.6.27-rc1-mm1, I got this
message from oprofile. Is this a known problem, or did I miss something?
sync_buffer() is the one in drivers/oprofile/buffer_sync.c instead of
fs/buffer.c.
Junjiro R. Okajima
----------------------------------------------------------------------
+ sudo opcontrol --setup --vmlinux=/home/jro/transparent/linux-2.6.27-rc1-mm1/D/vmlinux
+ sudo opcontrol --reset
+ sudo opcontrol --start
Using default event: GLOBAL_POWER_EVENTS:100000:1:1:1
Using 2.6+ OProfile kernel interface.
Reading module info.
Daemon started.
=======================================================
[ INFO: possible circular locking dependency detected ]
2.6.27-rc1-mm1jrousD #1
-------------------------------------------------------
events/0/7 is trying to acquire lock:
(&mm->mmap_sem){----}, at: [<c02d6500>] sync_buffer+0xe7/0x3c9
but task is already holding lock:
(buffer_mutex){--..}, at: [<c02d6445>] sync_buffer+0x2c/0x3c9
which lock already depends on the new lock.
the existing dependency chain (in reverse order) is:
-> #3 (buffer_mutex){--..}:
[<c01427d7>] __lock_acquire+0x1195/0x128d
[<c014296e>] lock_acquire+0x9f/0xb9
[<c0369f33>] mutex_lock_nested+0xbd/0x39f
[<c02d6445>] sync_buffer+0x2c/0x3c9
[<c02d6170>] wq_sync_buffer+0x3e/0x5c
[<c012ff4a>] run_workqueue+0x128/0x226
[<c0130b0c>] worker_thread+0x72/0xa7
[<c0133217>] kthread+0x37/0x59
[<c0103e37>] kernel_thread_helper+0x7/0x10
[<ffffffff>] 0xffffffff
-> #2 (&(&b->work)->work){--..}:
[<c01427d7>] __lock_acquire+0x1195/0x128d
[<c014296e>] lock_acquire+0x9f/0xb9
[<c012ff45>] run_workqueue+0x123/0x226
[<c0130b0c>] worker_thread+0x72/0xa7
[<c0133217>] kthread+0x37/0x59
[<c0103e37>] kernel_thread_helper+0x7/0x10
[<ffffffff>] 0xffffffff
-> #1 (events){--..}:
[<c01427d7>] __lock_acquire+0x1195/0x128d
[<c014296e>] lock_acquire+0x9f/0xb9
[<c01306ac>] flush_work+0x51/0xd2
[<c0130bda>] schedule_on_each_cpu+0x99/0xbf
[<c0166266>] lru_add_drain_all+0xd/0xf
[<c01703a6>] __mlock_vma_pages_range+0x44/0x294
[<c01706eb>] mlock_fixup+0xf5/0x1c3
[<c0170832>] do_mlockall+0x79/0x8d
[<c0170b7d>] sys_mlockall+0x74/0x9e
[<c0103151>] sysenter_do_call+0x12/0x31
[<ffffffff>] 0xffffffff
-> #0 (&mm->mmap_sem){----}:
[<c01425fa>] __lock_acquire+0xfb8/0x128d
[<c014296e>] lock_acquire+0x9f/0xb9
[<c036a77e>] down_read+0x3d/0x74
[<c02d6500>] sync_buffer+0xe7/0x3c9
[<c02d6170>] wq_sync_buffer+0x3e/0x5c
[<c012ff4a>] run_workqueue+0x128/0x226
[<c0130b0c>] worker_thread+0x72/0xa7
[<c0133217>] kthread+0x37/0x59
[<c0103e37>] kernel_thread_helper+0x7/0x10
[<ffffffff>] 0xffffffff
other info that might help us debug this:
3 locks held by events/0/7:
#0: (events){--..}, at: [<c012fefc>] run_workqueue+0xda/0x226
#1: (&(&b->work)->work){--..}, at: [<c012ff22>] run_workqueue+0x100/0x226
#2: (buffer_mutex){--..}, at: [<c02d6445>] sync_buffer+0x2c/0x3c9
stack backtrace:
Pid: 7, comm: events/0 Not tainted 2.6.27-rc1-mm1jrousD #1
[<c013fb3b>] print_circular_bug_tail+0x68/0x71
[<c013f1ce>] ? print_circular_bug_entry+0x43/0x4b
[<c01425fa>] __lock_acquire+0xfb8/0x128d
[<c0236cc4>] ? debug_smp_processor_id+0x28/0xdc
[<c013e7ed>] ? trace_hardirqs_off+0xb/0xd
[<c014296e>] lock_acquire+0x9f/0xb9
[<c02d6500>] ? sync_buffer+0xe7/0x3c9
[<c036a77e>] down_read+0x3d/0x74
[<c02d6500>] ? sync_buffer+0xe7/0x3c9
[<c02d6500>] sync_buffer+0xe7/0x3c9
[<c02d6170>] wq_sync_buffer+0x3e/0x5c
[<c012ff22>] ? run_workqueue+0x100/0x226
[<c012ff4a>] run_workqueue+0x128/0x226
[<c012ff22>] ? run_workqueue+0x100/0x226
[<c02d6132>] ? wq_sync_buffer+0x0/0x5c
[<c0130b0c>] worker_thread+0x72/0xa7
[<c01334d6>] ? autoremove_wake_function+0x0/0x3a
[<c0130a9a>] ? worker_thread+0x0/0xa7
[<c0133217>] kthread+0x37/0x59
[<c01331e0>] ? kthread+0x0/0x59
[<c0103e37>] kernel_thread_helper+0x7/0x10
=======================
Using log file /var/lib/oprofile/oprofiled.log
Profiler running.
Robert Richter:
> this is new to me. I will take a look at this.
Thanks.
Here is another message at shutdown time.
Junjiro R. Okajima
----------------------------------------------------------------------
BUG: sleeping function called from invalid context at /home/jro/transparent/linux-2.6.27-rc1-mm1/kernel/sched.c:4613
in_atomic():1, irqs_disabled():0
1 lock held by oprofiled/1843:
#0: (start_mutex){--..}, at: [<c02d5c77>] oprofile_shutdown+0xf/0x5a
Pid: 1843, comm: oprofiled Not tainted 2.6.27-rc1-mm1jrousD #1
[<c011ac79>] __might_sleep+0xdf/0x103
[<c03688a8>] wait_for_common+0x1f/0x140
[<c036e602>] ? sub_preempt_count+0x62/0xb0
[<c036bf14>] ? _spin_unlock_irqrestore+0x53/0x69
[<c0368a4b>] wait_for_completion+0x12/0x14
[<c01314fe>] synchronize_rcu+0x2d/0x33
[<c013154b>] ? wakeme_after_rcu+0x0/0xd
[<c0137cc5>] atomic_notifier_chain_unregister+0x2b/0x32
[<c0137cdb>] unregister_die_notifier+0xf/0x14
[<c02d787c>] nmi_shutdown+0x44/0x84
[<c02d5c94>] oprofile_shutdown+0x2c/0x5a
[<c02d697c>] event_buffer_release+0x10/0x3c
[<c01849a8>] __fput+0xc7/0x1b8
[<c0184e43>] fput+0x22/0x3b
[<c0181c32>] filp_close+0x43/0x69
[<c012266f>] ? exit_files+0x30/0x3c
[<c012261a>] put_files_struct+0xb1/0xd6
[<c0122676>] exit_files+0x37/0x3c
[<c0123b21>] do_exit+0x292/0x909
[<c013e854>] ? put_lock_stats+0x27/0x3a
[<c013e8b9>] ? lock_release_holdtime+0x52/0x6b
[<c0173114>] ? sys_munmap+0x3b/0x42
[<c01241dd>] do_group_exit+0x45/0x9d
[<c0124244>] sys_exit_group+0xf/0x11
[<c0103151>] sysenter_do_call+0x12/0x31
=======================
On 05.08.08 20:29:06, [email protected] wrote:
>
> Robert Richter:
> > this is new to me. I will take a look at this.
>
> Thanks.
> Here is another message at shutdown time.
Junjiro,
I reworked the code around this bug and it is upstream in
v2.6.29-rc1. Could you test with this version and look if the problem
still exists, please?
Thanks,
-Robert
>
>
> Junjiro R. Okajima
>
> ----------------------------------------------------------------------
> BUG: sleeping function called from invalid context at /home/jro/transparent/linux-2.6.27-rc1-mm1/kernel/sched.c:4613
> in_atomic():1, irqs_disabled():0
> 1 lock held by oprofiled/1843:
> #0: (start_mutex){--..}, at: [<c02d5c77>] oprofile_shutdown+0xf/0x5a
> Pid: 1843, comm: oprofiled Not tainted 2.6.27-rc1-mm1jrousD #1
> [<c011ac79>] __might_sleep+0xdf/0x103
> [<c03688a8>] wait_for_common+0x1f/0x140
> [<c036e602>] ? sub_preempt_count+0x62/0xb0
> [<c036bf14>] ? _spin_unlock_irqrestore+0x53/0x69
> [<c0368a4b>] wait_for_completion+0x12/0x14
> [<c01314fe>] synchronize_rcu+0x2d/0x33
> [<c013154b>] ? wakeme_after_rcu+0x0/0xd
> [<c0137cc5>] atomic_notifier_chain_unregister+0x2b/0x32
> [<c0137cdb>] unregister_die_notifier+0xf/0x14
> [<c02d787c>] nmi_shutdown+0x44/0x84
> [<c02d5c94>] oprofile_shutdown+0x2c/0x5a
> [<c02d697c>] event_buffer_release+0x10/0x3c
> [<c01849a8>] __fput+0xc7/0x1b8
> [<c0184e43>] fput+0x22/0x3b
> [<c0181c32>] filp_close+0x43/0x69
> [<c012266f>] ? exit_files+0x30/0x3c
> [<c012261a>] put_files_struct+0xb1/0xd6
> [<c0122676>] exit_files+0x37/0x3c
> [<c0123b21>] do_exit+0x292/0x909
> [<c013e854>] ? put_lock_stats+0x27/0x3a
> [<c013e8b9>] ? lock_release_holdtime+0x52/0x6b
> [<c0173114>] ? sys_munmap+0x3b/0x42
> [<c01241dd>] do_group_exit+0x45/0x9d
> [<c0124244>] sys_exit_group+0xf/0x11
> [<c0103151>] sysenter_do_call+0x12/0x31
> =======================
>
--
Advanced Micro Devices, Inc.
Operating System Research Center
email: [email protected]
Robert Richter:
> I reworked the code around this bug and it is upstream in
> v2.6.29-rc1. Could you test with this version and look if the problem
> still exists, please?
Unfortunately, I cannot test it soon. I am afraid it will take a few
months. When I become to be able to test it, I will let you know.
J. R. Okajima