From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1758071Ab0GTRmf (ORCPT ); Tue, 20 Jul 2010 13:42:35 -0400 Received: from mail.candelatech.com ([208.74.158.172]:45303 "EHLO ns3.lanforge.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751982Ab0GTRmd (ORCPT ); Tue, 20 Jul 2010 13:42:33 -0400 Message-ID: <4C45E007.4050100@candelatech.com> Date: Tue, 20 Jul 2010 10:42:31 -0700 From: Ben Greear Organization: Candela Technologies User-Agent: Mozilla/5.0 (X11; U; Linux x86_64; en-US; rv:1.9.1.9) Gecko/20100430 Fedora/3.0.4-2.fc11 Thunderbird/3.0.4 MIME-Version: 1.0 To: linux-kernel Subject: 2.6.34.1+hacks: stopping oprofile locked system for several minutes. Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org This is on my custom-compiled kernel, with my proprietary module included, (ie, tainted), so feel free to ignore. OS is Fedora 11, 64-bit. I was running oprofile on a system under heavy network load. Once, the machine rebooted when I clicked 'Stop' in oprof_start. I added serial console and did some more testing. Normally stop works fine, but one time, the whole system was totally locked (as far as I could tell) for several minutes..then miraculously recovered. I noticed this in 'dmesg': INFO: task events/1:28 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. events/1 D ffff88033096b480 0 28 2 0x00000000 ffff88033213bce0 0000000000000046 ffff88033213bcb0 ffff880332128f40 ffff88032ab39e80 ffff880332129200 0000000000000002 0000000000000001 ffff88033213bce0 ffff88033213bfd8 ffffffffa02650c0 0000000000000246 Call Trace: [] __mutex_lock_common+0x242/0x3ac [] __mutex_lock_slowpath+0x14/0x16 [] mutex_lock+0x27/0x3e [] sync_buffer+0x2d/0x3fe [oprofile] [] ? _raw_spin_unlock_irq+0x34/0x3f [] ? finish_task_switch+0x4a/0xa1 [] ? need_resched+0x1e/0x28 [] ? schedule+0x4cf/0x4e6 [] ? wq_sync_buffer+0x0/0x84 [oprofile] [] wq_sync_buffer+0x64/0x84 [oprofile] [] worker_thread+0x112/0x1ba [] ? autoremove_wake_function+0x0/0x38 [] ? worker_thread+0x0/0x1ba [] kthread+0x69/0x71 [] kernel_thread_helper+0x4/0x10 [] ? kthread+0x0/0x71 [] ? kernel_thread_helper+0x0/0x10 INFO: task events/2:29 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. events/2 D 0000000000000002 0 29 2 0x00000000 ffff88033213dce0 0000000000000046 ffff880001a8fee0 ffff8803321296e0 ffff88033209db80 ffff8803321299a0 0000000000000000 0000000000004158 0000000100000c00 ffff88033213dfd8 ffffffffa02650c0 0000000000000246 Call Trace: [] __mutex_lock_common+0x242/0x3ac [] __mutex_lock_slowpath+0x14/0x16 [] mutex_lock+0x27/0x3e [] sync_buffer+0x2d/0x3fe [oprofile] [] ? _raw_spin_unlock_irq+0x34/0x3f [] ? finish_task_switch+0x7f/0xa1 [] ? need_resched+0x1e/0x28 [] ? schedule+0x4cf/0x4e6 [] ? wq_sync_buffer+0x0/0x84 [oprofile] [] wq_sync_buffer+0x64/0x84 [oprofile] [] worker_thread+0x112/0x1ba [] ? autoremove_wake_function+0x0/0x38 [] ? worker_thread+0x0/0x1ba [] kthread+0x69/0x71 [] kernel_thread_helper+0x4/0x10 [] ? kthread+0x0/0x71 [] ? kernel_thread_helper+0x0/0x10 INFO: task events/3:30 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. events/3 D 0000000000000003 0 30 2 0x00000000 ffff88033213fce0 0000000000000046 ffff880001acfee0 ffff880332129e80 ffff8803320d8000 ffff88033212a140 0000000000000000 0000000000004158 0000000100000c00 ffff88033213ffd8 ffffffffa02650c0 0000000000000246 Call Trace: [] __mutex_lock_common+0x242/0x3ac [] __mutex_lock_slowpath+0x14/0x16 [] mutex_lock+0x27/0x3e [] sync_buffer+0x2d/0x3fe [oprofile] [] ? _raw_spin_unlock_irq+0x34/0x3f [] ? finish_task_switch+0x7f/0xa1 [] ? need_resched+0x1e/0x28 [] ? schedule+0x4cf/0x4e6 [] ? wq_sync_buffer+0x0/0x84 [oprofile] [] wq_sync_buffer+0x64/0x84 [oprofile] [] worker_thread+0x112/0x1ba [] ? autoremove_wake_function+0x0/0x38 [] ? worker_thread+0x0/0x1ba [] kthread+0x69/0x71 [] kernel_thread_helper+0x4/0x10 [] ? kthread+0x0/0x71 [] ? kernel_thread_helper+0x0/0x10 INFO: task events/4:31 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. events/4 D ffff880322448000 0 31 2 0x00000000 ffff880332141ce0 0000000000000046 ffff880332128000 ffff88033212a620 ffff88032ab387a0 ffff88033212a8e0 ffff880332141cc0 0000000000000046 ffff880332141cd0 ffff880332141fd8 ffffffffa02650c0 0000000000000246 Call Trace: [] __mutex_lock_common+0x242/0x3ac [] __mutex_lock_slowpath+0x14/0x16 [] mutex_lock+0x27/0x3e [] sync_buffer+0x2d/0x3fe [oprofile] [] ? _raw_spin_unlock_irq+0x34/0x3f [] ? finish_task_switch+0x4a/0xa1 [] ? need_resched+0x1e/0x28 [] ? schedule+0x4cf/0x4e6 [] ? wq_sync_buffer+0x0/0x84 [oprofile] [] wq_sync_buffer+0x64/0x84 [oprofile] [] worker_thread+0x112/0x1ba [] ? autoremove_wake_function+0x0/0x38 [] ? worker_thread+0x0/0x1ba [] kthread+0x69/0x71 [] kernel_thread_helper+0x4/0x10 [] ? kthread+0x0/0x71 [] ? kernel_thread_helper+0x0/0x10 INFO: task events/5:32 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. events/5 D 0000000000000005 0 32 2 0x00000000 ffff880332143ce0 0000000000000046 ffff880001b4fee0 ffff88033212adc0 ffff8803320dbd00 ffff88033212b080 ffff880332143cc0 0000000000000046 0000000132143cd0 ffff880332143fd8 ffffffffa02650c0 0000000000000246 Call Trace: [] __mutex_lock_common+0x242/0x3ac [] __mutex_lock_slowpath+0x14/0x16 [] mutex_lock+0x27/0x3e [] sync_buffer+0x2d/0x3fe [oprofile] [] ? _raw_spin_unlock_irq+0x34/0x3f [] ? finish_task_switch+0x7f/0xa1 [] ? need_resched+0x1e/0x28 [] ? schedule+0x4cf/0x4e6 [] ? wq_sync_buffer+0x0/0x84 [oprofile] [] wq_sync_buffer+0x64/0x84 [oprofile] [] worker_thread+0x112/0x1ba [] ? autoremove_wake_function+0x0/0x38 [] ? worker_thread+0x0/0x1ba [] kthread+0x69/0x71 [] kernel_thread_helper+0x4/0x10 [] ? kthread+0x0/0x71 [] ? kernel_thread_helper+0x0/0x10 INFO: task events/6:33 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. events/6 D 0000000000000006 0 33 2 0x00000000 ffff880332145ce0 0000000000000046 ffff880001b8fee0 ffff88033212b560 ffff8803320ddb80 ffff88033212b820 ffff880332145cc0 0000000000000046 0000000132145cd0 ffff880332145fd8 ffffffffa02650c0 0000000000000246 Call Trace: [] __mutex_lock_common+0x242/0x3ac [] __mutex_lock_slowpath+0x14/0x16 [] mutex_lock+0x27/0x3e [] sync_buffer+0x2d/0x3fe [oprofile] [] ? refresh_cpu_vm_stats+0x105/0x146 [] ? mod_timer+0x1e/0x20 [] ? add_timer+0x17/0x19 [] ? queue_delayed_work_on+0x91/0xa1 [] ? wq_sync_buffer+0x0/0x84 [oprofile] [] wq_sync_buffer+0x64/0x84 [oprofile] [] worker_thread+0x112/0x1ba [] ? autoremove_wake_function+0x0/0x38 [] ? worker_thread+0x0/0x1ba [] kthread+0x69/0x71 [] kernel_thread_helper+0x4/0x10 [] ? kthread+0x0/0x71 [] ? kernel_thread_helper+0x0/0x10 INFO: task events/7:34 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. events/7 D 0000000000000007 0 34 2 0x00000000 ffff880332147ce0 0000000000000046 ffff880001bcfee0 ffff88033212bd00 ffff880332128000 ffff88033212bfc0 0000000000000000 0000000000004041 0000000100000800 ffff880332147fd8 ffffffffa02650c0 0000000000000246 Call Trace: [] __mutex_lock_common+0x242/0x3ac [] __mutex_lock_slowpath+0x14/0x16 [] mutex_lock+0x27/0x3e [] sync_buffer+0x2d/0x3fe [oprofile] [] ? _raw_spin_unlock_irq+0x34/0x3f [] ? finish_task_switch+0x7f/0xa1 [] ? need_resched+0x1e/0x28 [] ? schedule+0x4cf/0x4e6 [] ? wq_sync_buffer+0x0/0x84 [oprofile] [] wq_sync_buffer+0x64/0x84 [oprofile] [] worker_thread+0x112/0x1ba [] ? autoremove_wake_function+0x0/0x38 [] ? worker_thread+0x0/0x1ba [] kthread+0x69/0x71 [] kernel_thread_helper+0x4/0x10 [] ? kthread+0x0/0x71 [] ? kernel_thread_helper+0x0/0x10 INFO: task rsyslogd:8499 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. rsyslogd D 0000000000000007 0 8499 1 0x00000080 ffff8803186c9cc8 0000000000000082 ffffffff8141b2c0 ffff880322535b80 ffff880332128000 ffff880322535e40 0000000000000050 0000000000000000 0000000100000000 ffff8803186c9fd8 ffffffffa02650c0 0000000000000246 Call Trace: [] __mutex_lock_common+0x242/0x3ac [] __mutex_lock_slowpath+0x14/0x16 [] mutex_lock+0x27/0x3e [] sync_buffer+0x2d/0x3fe [oprofile] [] ? generic_file_aio_write+0x85/0xa1 [] ? ext4_file_write+0x90/0xa0 [] task_exit_notify+0x11/0x15 [oprofile] [] notifier_call_chain+0x33/0x5b [] __blocking_notifier_call_chain+0x4d/0x6a [] blocking_notifier_call_chain+0xf/0x11 [] profile_task_exit+0x15/0x17 [] do_exit+0x25/0x679 [] ? path_put+0x1d/0x22 [] ? audit_syscall_entry+0xfe/0x12a [] complete_and_exit+0x0/0x1e [] system_call_fastpath+0x16/0x1b INFO: task ip:8931 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. ip D 0000000000000007 0 8931 8930 0x00000080 ffff880318351c98 0000000000000082 ffff880318351c58 ffff88031e1f8f40 ffff880332128000 ffff88031e1f9200 0000000000000000 0000000000000000 0000000100000000 ffff880318351fd8 ffffffffa02650c0 0000000000000246 Call Trace: [] __mutex_lock_common+0x242/0x3ac [] __mutex_lock_slowpath+0x14/0x16 [] mutex_lock+0x27/0x3e [] sync_buffer+0x2d/0x3fe [oprofile] [] ? wake_up_page+0x20/0x25 [] ? unlock_page+0xf/0x11 [] ? __do_fault+0x34b/0x388 [] ? __sys_recvmsg+0x18d/0x226 [] task_exit_notify+0x11/0x15 [oprofile] [] notifier_call_chain+0x33/0x5b [] __blocking_notifier_call_chain+0x4d/0x6a [] blocking_notifier_call_chain+0xf/0x11 [] profile_task_exit+0x15/0x17 [] do_exit+0x25/0x679 [] ? do_page_fault+0x278/0x287 [] sys_exit_group+0x0/0x16 [] sys_exit_group+0x12/0x16 [] system_call_fastpath+0x16/0x1b INFO: task ps:8933 blocked for more than 120 seconds. "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. ps D 0000000000000001 0 8933 8932 0x00000080 ffff88030e871c98 0000000000000086 ffff88030e871c58 ffff88031e1f9e80 ffff88033209bd00 ffff88031e1fa140 ffff88030e871c68 ffffffff81034fb4 000000010e871cb8 ffff88030e871fd8 ffffffffa02650c0 0000000000000246 Call Trace: [] ? task_rq_unlock+0xc/0xe [] __mutex_lock_common+0x242/0x3ac [] ? autoremove_wake_function+0x11/0x38 [] __mutex_lock_slowpath+0x14/0x16 [] mutex_lock+0x27/0x3e [] sync_buffer+0x2d/0x3fe [oprofile] [] ? wake_up_page+0x20/0x25 [] ? unlock_page+0xf/0x11 [] ? __do_fault+0x34b/0x388 [] task_exit_notify+0x11/0x15 [oprofile] [] notifier_call_chain+0x33/0x5b [] __blocking_notifier_call_chain+0x4d/0x6a [] blocking_notifier_call_chain+0xf/0x11 [] profile_task_exit+0x15/0x17 [] do_exit+0x25/0x679 [] ? do_page_fault+0x278/0x287 [] sys_exit_group+0x0/0x16 [] sys_exit_group+0x12/0x16 [] system_call_fastpath+0x16/0x1b Thanks, Ben -- Ben Greear Candela Technologies Inc http://www.candelatech.com