Created attachment 397391 [details] messages.1.log showing 94cpufreq/25179 is trying to acquire lock Description of problem: 94cpufreq kernel stack backtrace in /var/log/messages. I have been seeing these on screen during shutdown before restarting, although this one may have happened while suspending to RAM. Version-Release number of selected component (if applicable): kernel: Linux version 2.6.33-1.fc13.x86_64 How reproducible: Happens frequently. Steps to Reproduce: 1. Install F13 (13-Alpha-RC4 net install on a CDRW). 2. Restart F13 off hard drive. 2. Restart or sleep. Actual results: kernel stack backtrace flashes by on screen or is written to /var/log/messages Expected results: No kernel stack backtrace Additional info: Mar 2 07:04:51 spruce kernel: ============================================= Mar 2 07:04:51 spruce kernel: [ INFO: possible recursive locking detected ] Mar 2 07:04:51 spruce kernel: 2.6.33-1.fc13.x86_64 #1 Mar 2 07:04:51 spruce kernel: --------------------------------------------- Mar 2 07:04:51 spruce kernel: 94cpufreq/25179 is trying to acquire lock: Mar 2 07:04:51 spruce kernel: (s_active){++++.+}, at: [<ffffffff81176f02>] sysfs_addrm_finish+0 x36/0x55 Mar 2 07:04:51 spruce kernel: Mar 2 07:04:51 spruce kernel: but task is already holding lock: Mar 2 07:04:51 spruce kernel: (s_active){++++.+}, at: [<ffffffff811770bd>] sysfs_get_active_two
Created attachment 397392 [details] dmesg.old.1.log
Created attachment 397393 [details] dmesg.1.log
Created attachment 397403 [details] messages.2.log showing K99cpuspeed/3406 is trying to acquire lock Correction: when shutting down to restart, I see a kernel stack backtrace about K99cpuspeed flash by on the screen, and it is recorded in /var/log/messages. Mar 2 11:51:02 spruce cpuspeed: Disabling ondemand cpu frequency scaling governor Mar 2 11:51:02 spruce kernel: Mar 2 11:51:02 spruce kernel: ============================================= Mar 2 11:51:02 spruce kernel: [ INFO: possible recursive locking detected ] Mar 2 11:51:02 spruce kernel: 2.6.33-1.fc13.x86_64 #1 Mar 2 11:51:02 spruce kernel: --------------------------------------------- Mar 2 11:51:02 spruce kernel: K99cpuspeed/3406 is trying to acquire lock: Mar 2 11:51:02 spruce kernel: (s_active){++++.+}, at: [<ffffffff81176f02>] sysfs_addrm_finish+0 x36/0x55 Mar 2 11:51:02 spruce kernel: Mar 2 11:51:02 spruce kernel: but task is already holding lock: Mar 2 11:51:02 spruce kernel: (s_active){++++.+}, at: [<ffffffff811770bd>] sysfs_get_active_two +0x24/0x48
The K99cpuspeed kernel backtrace while restarting is reliably reproduced with the Live ISO on a USB stick. http://serverbeach1.fedoraproject.org/pub/alt/stage/13-Alpha.RC4/F13-Alpha-x86_64-Live/F13-Alpha-x86_64-Live.iso
I see a similar message when shutting down: Mar 13 19:52:19 t500 auditd[1099]: The audit daemon is exiting. Mar 13 19:52:19 t500 kernel: type=1305 audit(1268538739.816:17): audit_pid=0 old=1099 auid=4294967295 ses=4294967295 subj=system_u:system_r:auditd_t:s0 res=1 Mar 13 19:52:20 t500 cpuspeed: Disabling ondemand cpu frequency scaling governor Mar 13 19:52:20 t500 kernel: Mar 13 19:52:20 t500 kernel: ============================================= Mar 13 19:52:20 t500 kernel: [ INFO: possible recursive locking detected ] Mar 13 19:52:20 t500 kernel: 2.6.33-1.fc13.x86_64 #1 Mar 13 19:52:20 t500 kernel: --------------------------------------------- Mar 13 19:52:20 t500 kernel: K99cpuspeed/2705 is trying to acquire lock: Mar 13 19:52:20 t500 kernel: (s_active){++++.+}, at: [<ffffffff81176f02>] sysfs_addrm_finish+0x36/0x55 Mar 13 19:52:20 t500 kernel: Mar 13 19:52:20 t500 kernel: but task is already holding lock: Mar 13 19:52:20 t500 kernel: (s_active){++++.+}, at: [<ffffffff811770bd>] sysfs_get_active_two+0x24/0x48 Mar 13 19:52:20 t500 kernel: Mar 13 19:52:20 t500 kernel: other info that might help us debug this: Mar 13 19:52:20 t500 kernel: 4 locks held by K99cpuspeed/2705: Mar 13 19:52:20 t500 kernel: #0: (&buffer->mutex){+.+.+.}, at: [<ffffffff81175b9f>] sysfs_write_file+0x3c/0x144 Mar 13 19:52:20 t500 kernel: #1: (s_active){++++.+}, at: [<ffffffff811770bd>] sysfs_get_active_two+0x24/0x48 Mar 13 19:52:20 t500 kernel: #2: (s_active){++++.+}, at: [<ffffffff811770ca>] sysfs_get_active_two+0x31/0x48 Mar 13 19:52:20 t500 kernel: #3: (dbs_mutex){+.+.+.}, at: [<ffffffffa03f8da2>] cpufreq_governor_dbs+0x2a0/0x352 [cpufreq_ondemand] Mar 13 19:52:20 t500 kernel: Mar 13 19:52:20 t500 kernel: stack backtrace: Mar 13 19:52:20 t500 kernel: Pid: 2705, comm: K99cpuspeed Not tainted 2.6.33-1.fc13.x86_64 #1 Mar 13 19:52:20 t500 kernel: Call Trace: Mar 13 19:52:20 t500 kernel: [<ffffffff8107e94f>] __lock_acquire+0xcb5/0xd2c Mar 13 19:52:20 t500 kernel: [<ffffffff8107cf48>] ? mark_held_locks+0x52/0x70 Mar 13 19:52:20 t500 kernel: [<ffffffff8107d329>] ? debug_check_no_locks_freed+0x12e/0x145 Mar 13 19:52:20 t500 kernel: [<ffffffff8107d1c8>] ? trace_hardirqs_on_caller+0x111/0x135 Mar 13 19:52:20 t500 kernel: [<ffffffff8107eaa2>] lock_acquire+0xdc/0x102 Mar 13 19:52:20 t500 kernel: [<ffffffff81176f02>] ? sysfs_addrm_finish+0x36/0x55 Mar 13 19:52:20 t500 kernel: [<ffffffff8107c300>] ? lockdep_init_map+0x9e/0x113 Mar 13 19:52:20 t500 kernel: [<ffffffff8117690f>] sysfs_deactivate+0x9a/0x103 Mar 13 19:52:20 t500 kernel: [<ffffffff81176f02>] ? sysfs_addrm_finish+0x36/0x55 Mar 13 19:52:20 t500 kernel: [<ffffffff8107120a>] ? sched_clock_cpu+0xc3/0xce Mar 13 19:52:20 t500 kernel: [<ffffffff81476e44>] ? __mutex_unlock_slowpath+0x120/0x132 Mar 13 19:52:20 t500 kernel: [<ffffffff81176f02>] sysfs_addrm_finish+0x36/0x55 Mar 13 19:52:20 t500 kernel: [<ffffffff81175254>] sysfs_hash_and_remove+0x53/0x6a Mar 13 19:52:20 t500 kernel: [<ffffffff811782f9>] sysfs_remove_group+0x91/0xca Mar 13 19:52:20 t500 kernel: [<ffffffffa03f8db6>] cpufreq_governor_dbs+0x2b4/0x352 [cpufreq_ondemand] Mar 13 19:52:20 t500 kernel: [<ffffffff8107d1f9>] ? trace_hardirqs_on+0xd/0xf Mar 13 19:52:20 t500 kernel: [<ffffffff813a289b>] __cpufreq_governor+0x9b/0xde Mar 13 19:52:20 t500 kernel: [<ffffffff813a36e7>] __cpufreq_set_policy+0x1ce/0x275 Mar 13 19:52:20 t500 kernel: [<ffffffff813a3c0b>] store_scaling_governor+0x1a7/0x1fb Mar 13 19:52:20 t500 kernel: [<ffffffff813a3f14>] ? handle_update+0x0/0x39 Mar 13 19:52:20 t500 kernel: [<ffffffff8147775f>] ? down_write+0x7a/0x81 Mar 13 19:52:20 t500 kernel: [<ffffffff813a34f4>] store+0x61/0x86 Mar 13 19:52:20 t500 kernel: [<ffffffff81175c6b>] sysfs_write_file+0x108/0x144 Mar 13 19:52:20 t500 kernel: [<ffffffff8111ed9d>] vfs_write+0xae/0x10b Mar 13 19:52:20 t500 kernel: [<ffffffff8107d1c8>] ? trace_hardirqs_on_caller+0x111/0x135 Mar 13 19:52:20 t500 kernel: [<ffffffff8111eeba>] sys_write+0x4a/0x6e Mar 13 19:52:20 t500 kernel: [<ffffffff81009c72>] system_call_fastpath+0x16/0x1b Mar 13 19:52:20 t500 kernel: Kernel logging (proc) stopped. I also have general instability/crashes/slowness on this kernel, but I don't have any particular reason to suspect that it's related to this message.
I'm seeing this as well. Cpuspeed gets locked to the lowest speed and the laptop becomes slow and unresponsive. Reverting to the original kernel see cpuspeed work normally. SELinux: initialized (dev fuse, type fuse), uses genfs_contexts ============================================= [ INFO: possible recursive locking detected ] 2.6.33-1.fc13.i686 #1 --------------------------------------------- cpufreq-selecto/1846 is trying to acquire lock: (s_active){++++.+}, at: [<c05244e0>] sysfs_hash_and_remove+0x42/0x54 but task is already holding lock: (s_active){++++.+}, at: [<c0525de8>] sysfs_get_active_two+0x1b/0x39 other info that might help us debug this: 4 locks held by cpufreq-selecto/1846: #0: (&buffer->mutex){+.+.+.}, at: [<c0524c94>] sysfs_write_file+0x2a/0xf0 #1: (s_active){++++.+}, at: [<c0525de8>] sysfs_get_active_two+0x1b/0x39 #2: (s_active){++++.+}, at: [<c0525df3>] sysfs_get_active_two+0x26/0x39 #3: (dbs_mutex){+.+.+.}, at: [<e2b46c35>] cpufreq_governor_dbs+0x24b/0x2da [cpufreq_ondemand] Possibly SELinux related? Setting selinux to permissive and changing the frequency throws up a denial. Summary: SELinux is preventing /usr/bin/cpufreq-selector "read" access on /usr/share/locale/locale.alias. Raw Audit Messages node=shrike.example.com type=AVC msg=audit(1269125288.858:20): avc: denied { read } for pid=1962 comm="cpufreq-selecto" name="locale.alias" dev=dm-0 ino=5919 scontext=system_u:system_r:cpufreqselector_t:s0-s0:c0.c1023 tcontext=system_u:object_r:locale_t:s0 tclass=file node=shrike.example.com type=AVC msg=audit(1269125288.858:20): avc: denied { open } for pid=1962 comm="cpufreq-selecto" name="locale.alias" dev=dm-0 ino=5919 scontext=system_u:system_r:cpufreqselector_t:s0-s0:c0.c1023 tcontext=system_u:object_r:locale_t:s0 tclass=file node=shrike.example.com type=SYSCALL msg=audit(1269125288.858:20): arch=40000003 syscall=5 success=yes exit=3 a0=4e11ec a1=8000 a2=1b6 a3=4a4d28 items=0 ppid=1961 pid=1962 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="cpufreq-selecto" exe="/usr/bin/cpufreq-selector" subj=system_u:system_r:cpufreqselector_t:s0-s0:c0.c1023 key=(null)
*** This bug has been marked as a duplicate of bug 571969 ***