Bug 569945

Summary:

94cpufreq/25179 is trying to acquire lock with Linux version 2.6.33-1.fc13.x86_64

Product:

[Fedora] Fedora

Reporter:

Steve Tyler <stephent98>

Component:

kernel

Assignee:

Kernel Maintainer List <kernel-maint>

Status:

CLOSED DUPLICATE

QA Contact:

Fedora Extras Quality Assurance <extras-qa>

Severity:

medium

Docs Contact:

Priority:

low

Version:

CC:

anton, dougsland, evan, gansalmon, itamar, jonathan, jon.dufresne, kernel-maint, kraekan, rderooy

Target Milestone:

---

Target Release:

---

Hardware:

x86_64

OS:

Linux

Whiteboard:

Fixed In Version:

Doc Type:

Bug Fix

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2010-03-26 11:39:56 UTC

Type:

---

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

---

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
messages.1.log showing 94cpufreq/25179 is trying to acquire lock	none
dmesg.old.1.log	none
dmesg.1.log	none
messages.2.log showing K99cpuspeed/3406 is trying to acquire lock	none

Description Steve Tyler 2010-03-02 18:58:55 UTC

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

Comment 1 Steve Tyler 2010-03-02 19:01:02 UTC

Created attachment 397392 [details]
dmesg.old.1.log

Comment 2 Steve Tyler 2010-03-02 19:01:58 UTC

Created attachment 397393 [details]
dmesg.1.log

Comment 3 Steve Tyler 2010-03-02 20:02:45 UTC

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

Comment 4 Steve Tyler 2010-03-02 20:48:54 UTC

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

Comment 5 Evan Klitzke 2010-03-15 01:30:21 UTC

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.

Comment 6 Robert 2010-03-20 22:52:57 UTC

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)

Comment 7 Robert de Rooy 2010-03-26 11:39:56 UTC


*** This bug has been marked as a duplicate of bug 571969 ***