This message generated a parse failure. Raw output follows here. Please use 'back' to navigate. From devnull@lkml.org Fri May 10 01:58:37 2024 Delivery-date: Fri, 16 Feb 2007 22:36:22 +0000 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1946263AbXBPWfr (ORCPT ); Fri, 16 Feb 2007 17:35:47 -0500 Received: from nz-out-0506.google.com ([64.233.162.230]:34734 "EHLO nz-out-0506.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1946251AbXBPWfq (ORCPT ); Fri, 16 Feb 2007 17:35:46 -0500 Received: by nz-out-0506.google.com with SMTP id s1so1019766nze for ; Fri, 16 Feb 2007 14:35:45 -0800 (PST) DomainKey-Signature: a=rsa-sha1; c=nofws; d=gmail.com; s=beta; h=received:message-id:date:user-agent:mime-version:to:subject:x-enigmail-version:content-type:content-transfer-encoding:from; b=MAJlS2S0H80BZTQ32ycOB46eXCOxWVCACT7b3lCU6LPFXEQtNd4igFSxbY3DB1c Received: by 10.65.43.17 with SMTP id v17mr5832817qbj.1171665344670; Fri, 16 Feb 2007 14:35:44 -0800 (PST) Received: from ?192.168.1.70? ( [217.97.160.3]) by mx.google.com with ESMTP id p32sm4178549ugc.2007.02.16.14.35.42; Fri, 16 Feb 2007 14:35:44 -0800 (PST) Message-Id: <45D631BA.6010709@googlemail.com> Date: Fri, 16 Feb 2007 23:35:38 +0100 User-Agent: Thunderbird 1.5.0.9 (X11/20070212) Mime-Version: 1.0 To: Ingo Molnar , LKML Subject: 2.6.20-rt8 X-Enigmail-Version: 0.94.1.1 Content-Type: text/plain; charset=ISO-8859-2 Content-Transfer-Encoding: 7bit From: Michal Piotrowski Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org Hi Ingo, Test scenario: - normal boot - echo shutdown > /sys/power/disk; echo disk > /sys/power/state - echo platform > /sys/power/disk; echo disk > /sys/power/state ====================================================== [ INFO: hard-safe -> hard-unsafe lock order detected ] [ 2.6.20-rt8 #1 ------------------------------------------------------ softirq-timer/0/5 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: ((raw_spinlock_t *)(&lock->wait_lock)){--..}, at: [] rt_spin_lock_slowlock+0x21/0x18f and this task is already holding: (xtime_lock){+...}, at: [] run_timer_softirq+0x47/0x9ad which would create a new lock dependency: (xtime_lock){+...} -> ((raw_spinlock_t *)(&lock->wait_lock)){--..} but this new dependency connects a hard-irq-safe lock: (xtime_lock){+...} ... which became hard-irq-safe at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x3b3/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] tick_periodic+0x15/0x68 [] tick_handle_periodic+0x18/0x66 [] timer_interrupt+0x31/0x38 [] handle_IRQ_event+0x63/0x101 [] handle_level_irq+0xa7/0xf0 [] do_IRQ+0xc0/0xea [] common_interrupt+0x2e/0x34 [] __spin_unlock_irqrestore+0x42/0x59 [] setup_irq+0x170/0x1e0 [] time_init_hook+0x19/0x1b [] hpet_time_init+0xd/0xf [] start_kernel+0x276/0x42f [] 0xffffffff to a hard-irq-unsafe lock: ((raw_spinlock_t *)(&lock->wait_lock)){--..} ... which became hard-irq-unsafe at: ... [] mark_lock+0x6b/0x40b [] mark_held_locks+0x4a/0x67 [] trace_hardirqs_on+0x10d/0x150 [] __spin_unlock_irqrestore+0x40/0x59 [] task_blocks_on_rt_mutex+0x1c4/0x20a [] rt_spin_lock_slowlock+0xb9/0x18f [] rt_spin_lock+0xe/0x38 [] complete+0x14/0x57 [] migration_thread+0x1a4/0x1e5 [] kthread+0xb5/0xe1 [] kernel_thread_helper+0x7/0x10 [] 0xffffffff other info that might help us debug this: 1 lock held by softirq-timer/0/5: #0: (xtime_lock){+...}, at: [] run_timer_softirq+0x47/0x9ad the hard-irq-safe lock's dependencies: -> (xtime_lock){+...} ops: 9269 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] timekeeping_init+0x25/0x143 [] start_kernel+0x1c8/0x42f [] 0xffffffff in-hardirq-W at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x3b3/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] tick_periodic+0x15/0x68 [] tick_handle_periodic+0x18/0x66 [] timer_interrupt+0x31/0x38 [] handle_IRQ_event+0x63/0x101 [] handle_level_irq+0xa7/0xf0 [] do_IRQ+0xc0/0xea [] common_interrupt+0x2e/0x34 [] __spin_unlock_irqrestore+0x42/0x59 [] setup_irq+0x170/0x1e0 [] time_init_hook+0x19/0x1b [] hpet_time_init+0xd/0xf [] start_kernel+0x276/0x42f [] 0xffffffff } ... key at: [] xtime_lock+0x18/0x80 -> (clocksource_lock){....} ops: 4435 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] clocksource_get_next+0xd/0x43 [] timekeeping_init+0x35/0x143 [] start_kernel+0x1c8/0x42f [] 0xffffffff } ... key at: [] clocksource_lock+0x14/0x80 ... acquired at: [] add_lock_to_list+0x65/0x89 [] __lock_acquire+0xa12/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] clocksource_get_next+0xd/0x43 [] timekeeping_init+0x35/0x143 [] start_kernel+0x1c8/0x42f [] 0xffffffff -> (logbuf_lock){....} ops: 1563 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] release_console_sem+0x3c/0x1c5 [] vprintk+0x2cd/0x330 [] printk+0x1b/0x1d [] start_kernel+0x60/0x42f [] 0xffffffff } ... key at: [] logbuf_lock+0x14/0x80 ... acquired at: [] add_lock_to_list+0x65/0x89 [] __lock_acquire+0xa12/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] release_console_sem+0x3c/0x1c5 [] vprintk+0x2cd/0x330 [] printk+0x1b/0x1d [] run_timer_softirq+0x670/0x9ad [] ksoftirqd+0x121/0x205 [] kthread+0xb5/0xe1 [] kernel_thread_helper+0x7/0x10 [] 0xffffffff the hard-irq-unsafe lock's dependencies: -> ((raw_spinlock_t *)(&lock->wait_lock)){--..} ops: 151167 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] rt_spin_lock_slowlock+0x21/0x18f [] rt_spin_lock+0xe/0x38 [] lock_timer_base+0x18/0x35 [] __mod_timer+0x20/0x9f [] mod_timer+0x21/0x27 [] con_init+0xb9/0x203 [] console_init+0x1e/0x2c [] start_kernel+0x1f5/0x42f [] 0xffffffff softirq-on-W at: [] mark_lock+0x6b/0x40b [] mark_held_locks+0x4a/0x67 [] trace_hardirqs_on+0x125/0x150 [] __spin_unlock_irqrestore+0x40/0x59 [] task_blocks_on_rt_mutex+0x1c4/0x20a [] rt_spin_lock_slowlock+0xb9/0x18f [] rt_spin_lock+0xe/0x38 [] complete+0x14/0x57 [] migration_thread+0x1a4/0x1e5 [] kthread+0xb5/0xe1 [] kernel_thread_helper+0x7/0x10 [] 0xffffffff hardirq-on-W at: [] mark_lock+0x6b/0x40b [] mark_held_locks+0x4a/0x67 [] trace_hardirqs_on+0x10d/0x150 [] __spin_unlock_irqrestore+0x40/0x59 [] task_blocks_on_rt_mutex+0x1c4/0x20a [] rt_spin_lock_slowlock+0xb9/0x18f [] rt_spin_lock+0xe/0x38 [] complete+0x14/0x57 [] migration_thread+0x1a4/0x1e5 [] kthread+0xb5/0xe1 [] kernel_thread_helper+0x7/0x10 [] 0xffffffff } ... key at: [] __key.11113+0x0/0x8 -> ((raw_spinlock_t *)(&p->pi_lock)){....} ops: 571 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] sched_setscheduler+0x13f/0x22e [] posix_cpu_thread_call+0x88/0xff [] posix_cpu_thread_init+0x1c/0x3c [] init+0x4d/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff } ... key at: [] __key.24601+0x0/0x8 -> (&rq->rq_lock_key){+...} ops: 34146 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] init_idle+0x5c/0x7a [] sched_init+0x1a9/0x1b0 [] start_kernel+0x120/0x42f [] 0xffffffff in-hardirq-W at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x3b3/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] task_running_tick+0x2a/0x23d [] scheduler_tick+0x92/0xee [] update_process_times+0x3e/0x63 [] tick_periodic+0x66/0x68 [] tick_handle_periodic+0x18/0x66 [] timer_interrupt+0x31/0x38 [] handle_IRQ_event+0x63/0x101 [] handle_level_irq+0xa7/0xf0 [] do_IRQ+0xc0/0xea [] common_interrupt+0x2e/0x34 [] serial_in+0x69/0x6f [] serial8250_console_write+0xa6/0x11e [] __call_console_drivers+0x66/0x79 [] _call_console_drivers+0x57/0x5b [] release_console_sem+0x14d/0x1c5 [] vprintk+0x2cd/0x330 [] printk+0x1b/0x1d [] smp_prepare_cpus+0x46/0x5eb [] init+0x3e/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff } ... key at: [] 0xc60686cc -> (&rq->rq_lock_key#2){+...} ops: 33028 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] init_idle+0x5c/0x7a [] fork_idle+0x4f/0x58 [] do_boot_cpu+0x3c/0x547 [] smp_prepare_cpus+0x477/0x5eb [] init+0x3e/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff in-hardirq-W at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x3b3/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] task_rq_lock+0x36/0x5d [] try_to_wake_up+0x35/0x41a [] wake_up_process+0x19/0x1b [] wakeup_softirqd+0x30/0x34 [] raise_softirq+0x33/0x51 [] run_local_timers+0xd/0x14 [] update_process_times+0x43/0x63 [] tick_periodic+0x66/0x68 [] tick_handle_periodic+0x18/0x66 [] smp_apic_timer_interrupt+0xb5/0xc7 [] apic_timer_interrupt+0x33/0x38 [] default_idle+0x49/0x62 [] cpu_idle+0xd4/0x11e [] start_secondary+0x35a/0x362 [] 0xffffffff } ... key at: [] 0xc60e86cc ... acquired at: [] add_lock_to_list+0x65/0x89 [] __lock_acquire+0xa12/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] double_rq_lock+0x33/0x37 [] __migrate_task+0x58/0x131 [] migration_thread+0x196/0x1e5 [] kthread+0xb5/0xe1 [] kernel_thread_helper+0x7/0x10 [] 0xffffffff ... acquired at: [] add_lock_to_list+0x65/0x89 [] __lock_acquire+0xa12/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] sched_setscheduler+0x15d/0x22e [] posix_cpu_thread_call+0x88/0xff [] posix_cpu_thread_init+0x1c/0x3c [] init+0x4d/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff -> (&rq->rq_lock_key#2){+...} ops: 33028 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] init_idle+0x5c/0x7a [] fork_idle+0x4f/0x58 [] do_boot_cpu+0x3c/0x547 [] smp_prepare_cpus+0x477/0x5eb [] init+0x3e/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff in-hardirq-W at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x3b3/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] task_rq_lock+0x36/0x5d [] try_to_wake_up+0x35/0x41a [] wake_up_process+0x19/0x1b [] wakeup_softirqd+0x30/0x34 [] raise_softirq+0x33/0x51 [] run_local_timers+0xd/0x14 [] update_process_times+0x43/0x63 [] tick_periodic+0x66/0x68 [] tick_handle_periodic+0x18/0x66 [] smp_apic_timer_interrupt+0xb5/0xc7 [] apic_timer_interrupt+0x33/0x38 [] default_idle+0x49/0x62 [] cpu_idle+0xd4/0x11e [] start_secondary+0x35a/0x362 [] 0xffffffff } ... key at: [] 0xc60e86cc ... acquired at: [] add_lock_to_list+0x65/0x89 [] __lock_acquire+0xa12/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] sched_setscheduler+0x15d/0x22e [] posix_cpu_thread_call+0x88/0xff [] notifier_call_chain+0x20/0x31 [] raw_notifier_call_chain+0x8/0xa [] _cpu_up+0x3d/0xbf [] cpu_up+0x26/0x38 [] init+0x91/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff ... acquired at: [] add_lock_to_list+0x65/0x89 [] __lock_acquire+0xa12/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] task_blocks_on_rt_mutex+0x25/0x20a [] rt_spin_lock_slowlock+0xb9/0x18f [] rt_spin_lock+0xe/0x38 [] complete+0x14/0x57 [] migration_thread+0x1a4/0x1e5 [] kthread+0xb5/0xe1 [] kernel_thread_helper+0x7/0x10 [] 0xffffffff -> (&rq->rq_lock_key){+...} ops: 34146 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] init_idle+0x5c/0x7a [] sched_init+0x1a9/0x1b0 [] start_kernel+0x120/0x42f [] 0xffffffff in-hardirq-W at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x3b3/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] task_running_tick+0x2a/0x23d [] scheduler_tick+0x92/0xee [] update_process_times+0x3e/0x63 [] tick_periodic+0x66/0x68 [] tick_handle_periodic+0x18/0x66 [] timer_interrupt+0x31/0x38 [] handle_IRQ_event+0x63/0x101 [] handle_level_irq+0xa7/0xf0 [] do_IRQ+0xc0/0xea [] common_interrupt+0x2e/0x34 [] serial_in+0x69/0x6f [] serial8250_console_write+0xa6/0x11e [] __call_console_drivers+0x66/0x79 [] _call_console_drivers+0x57/0x5b [] release_console_sem+0x14d/0x1c5 [] vprintk+0x2cd/0x330 [] printk+0x1b/0x1d [] smp_prepare_cpus+0x46/0x5eb [] init+0x3e/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff } ... key at: [] 0xc60686cc -> (&rq->rq_lock_key#2){+...} ops: 33028 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] init_idle+0x5c/0x7a [] fork_idle+0x4f/0x58 [] do_boot_cpu+0x3c/0x547 [] smp_prepare_cpus+0x477/0x5eb [] init+0x3e/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff in-hardirq-W at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x3b3/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] task_rq_lock+0x36/0x5d [] try_to_wake_up+0x35/0x41a [] wake_up_process+0x19/0x1b [] wakeup_softirqd+0x30/0x34 [] raise_softirq+0x33/0x51 [] run_local_timers+0xd/0x14 [] update_process_times+0x43/0x63 [] tick_periodic+0x66/0x68 [] tick_handle_periodic+0x18/0x66 [] smp_apic_timer_interrupt+0xb5/0xc7 [] apic_timer_interrupt+0x33/0x38 [] default_idle+0x49/0x62 [] cpu_idle+0xd4/0x11e [] start_secondary+0x35a/0x362 [] 0xffffffff } ... key at: [] 0xc60e86cc ... acquired at: [] add_lock_to_list+0x65/0x89 [] __lock_acquire+0xa12/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] double_rq_lock+0x33/0x37 [] __migrate_task+0x58/0x131 [] migration_thread+0x196/0x1e5 [] kthread+0xb5/0xe1 [] kernel_thread_helper+0x7/0x10 [] 0xffffffff ... acquired at: [] add_lock_to_list+0x65/0x89 [] __lock_acquire+0xa12/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] task_rq_lock+0x36/0x5d [] try_to_wake_up+0x35/0x41a [] wake_up_process_mutex+0x19/0x1b [] wakeup_next_waiter+0x1d0/0x1e1 [] rt_spin_lock_slowunlock+0x46/0x5e [] rt_spin_unlock+0x1d/0x20 [] wait_for_completion+0x69/0x93 [] set_cpus_allowed+0x82/0xa2 [] measure_one+0x98/0x163 [] build_sched_domains+0x546/0xb5c [] arch_init_sched_domains+0x1b/0x1d [] sched_init_smp+0x15/0x5a [] init+0xd0/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff -> (&rq->rq_lock_key#2){+...} ops: 33028 { initial-use at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x487/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] init_idle+0x5c/0x7a [] fork_idle+0x4f/0x58 [] do_boot_cpu+0x3c/0x547 [] smp_prepare_cpus+0x477/0x5eb [] init+0x3e/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff in-hardirq-W at: [] mark_lock+0x6b/0x40b [] __lock_acquire+0x3b3/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] task_rq_lock+0x36/0x5d [] try_to_wake_up+0x35/0x41a [] wake_up_process+0x19/0x1b [] wakeup_softirqd+0x30/0x34 [] raise_softirq+0x33/0x51 [] run_local_timers+0xd/0x14 [] update_process_times+0x43/0x63 [] tick_periodic+0x66/0x68 [] tick_handle_periodic+0x18/0x66 [] smp_apic_timer_interrupt+0xb5/0xc7 [] apic_timer_interrupt+0x33/0x38 [] default_idle+0x49/0x62 [] cpu_idle+0xd4/0x11e [] start_secondary+0x35a/0x362 [] 0xffffffff } ... key at: [] 0xc60e86cc ... acquired at: [] add_lock_to_list+0x65/0x89 [] __lock_acquire+0xa12/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock+0x35/0x42 [] task_rq_lock+0x36/0x5d [] try_to_wake_up+0x35/0x41a [] wake_up_process_mutex+0x19/0x1b [] wakeup_next_waiter+0x1d0/0x1e1 [] rt_spin_lock_slowunlock+0x46/0x5e [] rt_spin_unlock+0x1d/0x20 [] wait_for_completion+0x69/0x93 [] set_cpus_allowed+0x82/0xa2 [] measure_one+0x34/0x163 [] build_sched_domains+0x546/0xb5c [] arch_init_sched_domains+0x1b/0x1d [] sched_init_smp+0x15/0x5a [] init+0xd0/0x3be [] kernel_thread_helper+0x7/0x10 [] 0xffffffff stack backtrace: [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] check_usage+0x241/0x24b [] __lock_acquire+0x91f/0xb94 [] lock_acquire+0x68/0x82 [] __spin_lock_irqsave+0x3e/0x4e [] rt_spin_lock_slowlock+0x21/0x18f [] rt_spin_lock+0xe/0x38 [] serial8250_console_write+0x4a/0x11e [] __call_console_drivers+0x66/0x79 [] _call_console_drivers+0x57/0x5b [] release_console_sem+0x113/0x1c5 [] vprintk+0x2cd/0x330 [] printk+0x1b/0x1d [] run_timer_softirq+0x670/0x9ad [] ksoftirqd+0x121/0x205 [] kthread+0xb5/0xe1 [] kernel_thread_helper+0x7/0x10 ======================= --------------------------- | preempt count: 00000002 ] | 2-level deep critical section nesting: ---------------------------------------- .. [] .... __spin_lock+0x13/0x42 .....[] .. ( <= run_timer_softirq+0x47/0x9ad) .. [] .... __spin_lock_irqsave+0x1c/0x4e .....[] .. ( <= rt_spin_lock_slowlock+0x21/0x18f) 0xc0314dd9 is in __spin_lock (kernel/spinlock.c:218). 213 EXPORT_SYMBOL(__write_lock_bh); 214 215 void __lockfunc __spin_lock(raw_spinlock_t *lock) 216 { 217 preempt_disable(); 218 spin_acquire(&lock->dep_map, 0, 0, _RET_IP_); 219 _raw_spin_lock(lock); 220 } 221 222 EXPORT_SYMBOL(__spin_lock); 0xc012aa40 is in run_timer_softirq (include/linux/seqlock.h:148). 143 } 144 145 static __always_inline void __write_seqlock_raw(raw_seqlock_t *sl) 146 { 147 spin_lock(&sl->lock); 148 ++sl->sequence; 149 smp_wmb(); 150 } 151 152 static __always_inline void __write_sequnlock_raw(raw_seqlock_t *sl) 0xc0315046 is in __spin_lock_irqsave (kernel/spinlock.c:122). 117 { 118 unsigned long flags; 119 120 local_irq_save(flags); 121 preempt_disable(); 122 spin_acquire(&lock->dep_map, 0, 0, _RET_IP_); 123 /* 124 * On lockdep we dont want the hand-coded irq-enable of 125 * _raw_spin_lock_flags() code, because lockdep assumes 126 * that interrupts are not re-enabled during lock-acquire: 0xc031404f is in rt_spin_lock_slowlock (kernel/rtmutex.c:640). 635 unsigned long saved_state, state, flags; 636 637 debug_rt_mutex_init_waiter(&waiter); 638 waiter.task = NULL; 639 640 spin_lock_irqsave(&lock->wait_lock, flags); 641 init_lists(lock); 642 643 /* Try to acquire the lock again: */ 644 if (try_to_take_rt_mutex(lock)) { ======================================== echo shutdown > /sys/power/disk; echo disk > /sys/power/state Disabling non-boot CPUs ... CPU1 playing dead [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] cpu_idle+0x8d/0x11e [] start_secondary+0x35a/0x362 ======================= --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [] .... cpu_idle+0x113/0x11e .....[] .. ( <= start_secondary+0x35a/0x362) 0xc010142b is in cpu_idle (arch/i386/kernel/process.c:204). 199 tick_nohz_restart_sched_tick(); 200 local_irq_disable(); 201 __preempt_enable_no_resched(); 202 __schedule(); 203 preempt_disable(); 204 local_irq_enable(); 205 } 206 } 207 208 void cpu_idle_wait(void) 0xc0112d11 is in start_secondary (arch/i386/kernel/smpboot.c:432). 427 /* We can take interrupts now: we're officially "up". */ 428 local_irq_enable(); 429 430 wmb(); 431 cpu_idle(); 432 } 433 434 /* 435 * Everything has been set up for the secondary 436 * CPUs - they just need to reload everything CPU 1 is now offline lockdep: not fixing up alternatives. CPU1 is down Stopping tasks ... done. Shrinking memory... -\|done (13953 pages freed) Freed 55812 kbytes in 0.42 seconds (132.88 MB/s) Suspending console(s) lapic suspend on CPU#0 [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] lapic_suspend+0xd8/0x101 [] sysdev_suspend+0x8d/0x1ee [] device_power_down+0x119/0x152 [] swsusp_suspend+0x17/0x67 [] pm_suspend_disk+0x9a/0x161 [] enter_state+0x52/0x1bb [] state_store+0x86/0x9c [] subsys_attr_store+0x20/0x25 [] sysfs_write_file+0xa1/0xc2 [] vfs_write+0xaf/0x163 [] sys_write+0x40/0x67 [] syscall_call+0x7/0xb [] 0xb7f73410 ======================= --------------------------- | preempt count: 00000000 ] | 0-level deep critical section nesting: ---------------------------------------- swsusp: critical section: swsusp: Need to copy 126290 pages BUG: sleeping function called from invalid context swsusp_shutdown(3247) at arch/i386/mm/highmem.c:8 in_atomic():1 [00000001], irqs_disabled():1 no locks held by swsusp_shutdown/3247. irq event stamp: 0 hardirqs last enabled at (0): [<00000000>] 0x0 hardirqs last disabled at (0): [] copy_process+0x526/0x1343 softirqs last enabled at (0): [] copy_process+0x544/0x1343 softirqs last disabled at (0): [<00000000>] 0x0 [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] __might_sleep+0x10d/0x114 [] kmap+0x3b/0x46 [] swsusp_save+0x2a9/0x3a8 [] swsusp_arch_suspend+0x2a/0x2c DWARF2 unwinder stuck at swsusp_arch_suspend+0x2a/0x2c Leftover inexact backtrace: [] pm_suspend_disk+0x9a/0x161 [] enter_state+0x52/0x1bb [] state_store+0x86/0x9c [] subsys_attr_store+0x20/0x25 [] sysfs_write_file+0xa1/0xc2 [] vfs_write+0xaf/0x163 [] sys_write+0x40/0x67 [] syscall_call+0x7/0xb ======================= --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [] .... kernel_fpu_begin+0x16/0x49 .....[] .. ( <= __save_processor_state+0xb/0x3d) 0xc0120a00 is in copy_process (kernel/fork.c:1121). 1116 #else 1117 p->hardirqs_enabled = 0; 1118 #endif 1119 p->hardirq_enable_ip = 0; 1120 p->hardirq_enable_event = 0; 1121 p->hardirq_disable_ip = _THIS_IP_; 1122 p->hardirq_disable_event = 0; 1123 p->softirqs_enabled = 1; 1124 p->softirq_enable_ip = _THIS_IP_; 1125 p->softirq_enable_event = 0; 0xc0120a1e is in copy_process (kernel/fork.c:1124). 1119 p->hardirq_enable_ip = 0; 1120 p->hardirq_enable_event = 0; 1121 p->hardirq_disable_ip = _THIS_IP_; 1122 p->hardirq_disable_event = 0; 1123 p->softirqs_enabled = 1; 1124 p->softirq_enable_ip = _THIS_IP_; 1125 p->softirq_enable_event = 0; 1126 p->softirq_disable_ip = 0; 1127 p->softirq_disable_event = 0; 1128 p->hardirq_context = 0; 0xc0108538 is in kernel_fpu_begin (arch/i386/kernel/i387.c:76). 71 void kernel_fpu_begin(void) 72 { 73 struct thread_info *thread = current_thread_info(); 74 75 preempt_disable(); 76 if (thread->status & TS_USEDFPU) { 77 __save_init_fpu(thread->task); 78 return; 79 } 80 clts(); 0xc02bfd85 is in __save_processor_state (arch/i386/power/cpu.c:29). 24 kernel_fpu_begin(); 25 26 /* 27 * descriptor tables 28 */ 29 store_gdt(&ctxt->gdt); 30 store_idt(&ctxt->idt); 31 store_tr(ctxt->tr); 32 33 /* swsusp: critical section/: done (126290 pages copied) BUG: using smp_processor_id() in preemptible [00000000] code: swsusp_shutdown/3247 caller is intel_p4_mcheck_init+0x7b/0x18e [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] debug_smp_processor_id+0x9f/0xac [] intel_p4_mcheck_init+0x7b/0x18e [] mcheck_init+0x57/0x6b [] __restore_processor_state+0x1b5/0x1bb [] restore_processor_state+0xd/0xf [] swsusp_suspend+0x50/0x67 [] pm_suspend_disk+0x9a/0x161 [] enter_state+0x52/0x1bb [] state_store+0x86/0x9c [] subsys_attr_store+0x20/0x25 [] sysfs_write_file+0xa1/0xc2 [] vfs_write+0xaf/0x163 [] sys_write+0x40/0x67 [] syscall_call+0x7/0xb [] 0xb7f73410 ======================= --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [] .... debug_smp_processor_id+0x50/0xac .....[] .. ( <= intel_p4_mcheck_init+0x7b/0x18e) 0xc010c440 is in intel_p4_mcheck_init (arch/i386/kernel/cpu/mcheck/p4.c:226). 221 wrmsr (MSR_IA32_MCG_STATUS,mcgstl, mcgsth); 222 } 223 224 225 void intel_p4_mcheck_init(struct cpuinfo_x86 *c) 226 { 227 u32 l, h; 228 int i; 229 230 machine_check_vector = intel_machine_check; 0xc01f832c is in debug_smp_processor_id (lib/smp_processor_id.c:42). 37 /* 38 * Avoid recursion: 39 */ 40 preempt_disable(); 41 42 if (!printk_ratelimit()) 43 goto out_enable; 44 45 printk(KERN_ERR "BUG: using smp_processor_id() in preemptible [%08x] code: %s/%d\n", preempt_count()-1, current->comm, current->pid); 46 print_symbol("caller is %s\n", (long)__builtin_return_address(0)); 0xc010c4bb is in intel_p4_mcheck_init (arch/i386/kernel/cpu/mcheck/p4.c:245). 240 wrmsr (MSR_IA32_MC0_CTL+4*i, 0xffffffff, 0xffffffff); 241 wrmsr (MSR_IA32_MC0_STATUS+4*i, 0x0, 0x0); 242 } 243 244 set_in_cr4 (X86_CR4_MCE); 245 printk (KERN_INFO "Intel machine check reporting enabled on CPU#%d.\n", 246 smp_processor_id()); 247 248 /* Check for P4/Xeon extended MCE MSRs */ 249 rdmsr (MSR_IA32_MCG_CAP, l, h); BUG: swsusp_shutdown:3247 task might have lost a preemption check! [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] preempt_enable_no_resched+0x5a/0x5c [] debug_smp_processor_id+0xa4/0xac [] intel_p4_mcheck_init+0x7b/0x18e [] mcheck_init+0x57/0x6b [] __restore_processor_state+0x1b5/0x1bb [] restore_processor_state+0xd/0xf [] swsusp_suspend+0x50/0x67 [] pm_suspend_disk+0x9a/0x161 [] enter_state+0x52/0x1bb [] state_store+0x86/0x9c [] subsys_attr_store+0x20/0x25 [] sysfs_write_file+0xa1/0xc2 [] vfs_write+0xaf/0x163 [] sys_write+0x40/0x67 [] syscall_call+0x7/0xb [] 0xb7f73410 ======================= --------------------------- | preempt count: 00000000 ] | 0-level deep critical section nesting: ---------------------------------------- BUG: using smp_processor_id() in preemptible [00000000] code: swsusp_shutdown/3247 caller is intel_p4_mcheck_init+0xac/0x18e [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] debug_smp_processor_id+0x9f/0xac [] intel_p4_mcheck_init+0xac/0x18e [] mcheck_init+0x57/0x6b [] __restore_processor_state+0x1b5/0x1bb [] restore_processor_state+0xd/0xf [] swsusp_suspend+0x50/0x67 [] pm_suspend_disk+0x9a/0x161 [] enter_state+0x52/0x1bb [] state_store+0x86/0x9c [] subsys_attr_store+0x20/0x25 [] sysfs_write_file+0xa1/0xc2 [] vfs_write+0xaf/0x163 [] sys_write+0x40/0x67 [] syscall_call+0x7/0xb [] 0xb7f73410 ======================= --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [] .... debug_smp_processor_id+0x50/0xac .....[] .. ( <= intel_p4_mcheck_init+0xac/0x18e) BUG: using smp_processor_id() in preemptible [00000000] code: swsusp_shutdown/3247 caller is intel_p4_mcheck_init+0xc5/0x18e [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] debug_smp_processor_id+0x9f/0xac [] intel_p4_mcheck_init+0xc5/0x18e [] mcheck_init+0x57/0x6b [] __restore_processor_state+0x1b5/0x1bb [] restore_processor_state+0xd/0xf [] swsusp_suspend+0x50/0x67 [] pm_suspend_disk+0x9a/0x161 [] enter_state+0x52/0x1bb [] state_store+0x86/0x9c [] subsys_attr_store+0x20/0x25 [] sysfs_write_file+0xa1/0xc2 [] vfs_write+0xaf/0x163 [] sys_write+0x40/0x67 [] syscall_call+0x7/0xb [] 0xb7f73410 ======================= --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [] .... debug_smp_processor_id+0x50/0xac .....[] .. ( <= intel_p4_mcheck_init+0xc5/0x18e) lapic resume on CPU#0 [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] lapic_resume+0x31/0x1c3 [] __sysdev_resume+0x14/0x57 [] sysdev_resume+0x19/0x54 [] device_power_up+0x8/0xf [] swsusp_suspend+0x5a/0x67 [] pm_suspend_disk+0x9a/0x161 [] enter_state+0x52/0x1bb [] state_store+0x86/0x9c [] subsys_attr_store+0x20/0x25 [] sysfs_write_file+0xa1/0xc2 [] vfs_write+0xaf/0x163 [] sys_write+0x40/0x67 [] syscall_call+0x7/0xb [] 0xb7f73410 ======================= --------------------------- | preempt count: 00000000 ] | 0-level deep critical section nesting: ---------------------------------------- ============================================ Resume swsusp: Resume From Partition /dev/sda2 PM: Checking swsusp image. swsusp: Signature found, resuming PM: Preparing processes for restore. Disabling non-boot CPUs ... CPU1 playing dead [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] cpu_idle+0x8d/0x11e [] start_secondary+0x35a/0x362 ======================= --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [] .... cpu_idle+0x113/0x11e .....[] .. ( <= start_secondary+0x35a/0x362) etc... =================================== echo platform > /sys/power/disk; echo disk > /sys/power/state CPU1 playing dead [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] cpu_idle+0x8d/0x11e [] start_secondary+0x35a/0x362 ======================= --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [] .... cpu_idle+0x113/0x11e .....[] .. ( <= start_secondary+0x35a/0x362) etc.../ ======================================= Resume CPU1 playing dead [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] cpu_idle+0x8d/0x11e [] start_secondary+0x35a/0x362 ======================= --------------------------- | preempt count: 00000001 ] | 1-level deep critical section nesting: ---------------------------------------- .. [] .... cpu_idle+0x113/0x11e .....[] .. ( <= start_secondary+0x35a/0x362) fb0: PM: suspend 0->1, parent 0000:01:00.0 already 1 i2c_adapter i2c-2: PM: suspend 0->1, parent 0000:01:00.0 already 1 i2c_adapter i2c-1: PM: suspend 0->1, parent 0000:01:00.0 already 1 i2c_adapter i2c-0: PM: suspend 0->1, parent 0000:01:00.0 already 1 lapic suspend on CPU#0 [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] lapic_suspend+0xd8/0x101 [] sysdev_suspend+0x8d/0x1ee [] device_power_down+0x119/0x152 [] swsusp_suspend+0x17/0x67 [] pm_suspend_disk+0x9a/0x161 [] enter_state+0x52/0x1bb [] state_store+0x86/0x9c [] subsys_attr_store+0x20/0x25 [] sysfs_write_file+0xa1/0xc2 [] vfs_write+0xaf/0x163 [] sys_write+0x40/0x67 [] syscall_call+0x7/0xb [] 0xb7f8c410 ======================= --------------------------- | preempt count: 00000000 ] | 0-level deep critical section nesting: ---------------------------------------- swsusp: critical section: swsusp: Need to copy 126417 pages lapic resume on CPU#0 [] dump_trace+0x63/0x1eb [] show_trace_log_lvl+0x1d/0x3a [] show_trace+0x12/0x14 [] dump_stack+0x16/0x18 [] lapic_resume+0x31/0x1c3 [] __sysdev_resume+0x14/0x57 [] sysdev_resume+0x19/0x54 [] device_power_up+0x8/0xf [] swsusp_suspend+0x5a/0x67 [] pm_suspend_disk+0x9a/0x161 [] enter_state+0x52/0x1bb [] state_store+0x86/0x9c [] subsys_attr_store+0x20/0x25 My system hangs here. http://www.stardust.webpages.pl/files/tbf/euridica/2.6.20-rt8/boot2.log http://www.stardust.webpages.pl/files/tbf/euridica/2.6.20-rt8/rt-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@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/