[FreeBSD-users-jp 95226] Re: powerd with high frequency when idling

Sun Jul 6 13:36:44 UTC 2014

青木＠国分寺市在住です

From: Kazumaro Aoki <ka at flu.if0.org>
Subject: [FreeBSD-users-jp 95225] Re: powerd with high frequency when idling
Date: Thu, 03 Jul 2014 22:42:48 +0900 (JST)

>> 8-stable には入らないようなので、同じ問題ならですが、
>> http://svnweb.freebsd.org/base?view=revision&revision=263022
>> と
>> http://svnweb.freebsd.org/base?view=revision&revision=267883
>> をもってきて、src/sys/dev/acpica/acpi.c にマージすればよさそうです。
> 
> ちょっと差分が大きそうなのでmergeは手間がかかりそうですがやってみたいと
> 思います。

手間が大きいということもあり、acpi.cだけを問題が起きていなかったと思わ
れる8.3Rか、確実に問題が起きていなかった8.2Rのものに置き換えてkernel
makeしたら問題なく通ったので、そのkernelで運用したのですが、残念ながら
問題は解消しませんでした。

実は、そのkernelに入れ換える直前、動作周波数が最低である100MHzに何故か
なっていました。
その時の状態をもう少し解析すればよかったのですが、次の計算が始まる前に
kernelを入れ換えねば…との気持ちが強く気がつかず。
その時は、100%の自信はありませんがshutdown中に実行される
/etc/rc.d/powerd stopでの「sysctl: dev.cpu.0.freq=1600: Operation not
permitted」は表示されなかったように思います。
ということで、何かの条件が揃えば動作周波数を変えられる状態になっている
ようです。

そもそもpowerdというよりは、
sysctl dev.cpu.0.freq=100
とか、周波数変更を受け付けなくなってしまっているのが問題と考えています。

何か、他のOIDとかでenableとかdisableとかされているとかを疑っているので
すが、この辺のdriverの知識なしにkey wordをgrepして、出てきたsource
codeを斜め読みするだけでは全然答えにいきついていません。

役にたつ情報かどうかわかりませんが、powerdを止めた状態で
truss sysctl dev.cpu.0.freq=400
とした結果と、
sysctl dev.cpu.0.freq=400
をsysctl debug.cpufreq.verbose=1の状態で実行したlogを添付します。

どういう時にEPERMになっているのか気になっていますが、全然追えていませ
ん。引続き情報を待ってます。

＃とりあえずOSを9系列にあげるというのもありかなぁ。

青木和麻呂＠国分寺市在住
-------------- next part --------------
Script started on Sun Jul  6 21:33:55 2014
truss sysctl dev.cpu.0.freq=400
__sysctl(0x7fffffffe1c0,0x2,0x7fffffffe1dc,0x7fffffffe1d0,0x0,0x0) = 0 (0x0)
mmap(0x0,688,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 34365190144 (0x800533000)
munmap(0x800533000,688)				 = 0 (0x0)
__sysctl(0x7fffffffe230,0x2,0x80063d408,0x7fffffffe228,0x0,0x0) = 0 (0x0)
mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34365190144 (0x800533000)
issetugid(0x800534015,0x80052e664,0x800649b10,0x800649ae0,0x59b1,0x0) = 0 (0x0)
open("/etc/libmap.conf",O_RDONLY,0666)		 ERR#2 'No such file or directory'
open("/var/run/ld-elf.so.hints",O_RDONLY,057)	 = 3 (0x3)
read(3,"Ehnt\^A\0\0\0\M^@\0\0\0\M^E\0\0"...,128) = 128 (0x80)
lseek(3,0x80,SEEK_SET)				 = 128 (0x80)
read(3,"/lib:/usr/lib:/usr/lib/compat:/u"...,133) = 133 (0x85)
close(3)					 = 0 (0x0)
access("/lib/libc.so.7",0)			 = 0 (0x0)
open("/lib/libc.so.7",O_RDONLY,030751340)	 = 3 (0x3)
fstat(3,{ mode=-r--r--r-- ,inode=94283,size=1299824,blksize=16384 }) = 0 (0x0)
pread(0x3,0x80063c2c0,0x1000,0x0,0x101010101010101,0x8080808080808080) = 4096 (0x1000)
mmap(0x0,2371584,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 34366332928 (0x80064a000)
mmap(0x80064a000,1085440,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE,3,0x0) = 34366332928 (0x80064a000)
mmap(0x800853000,126976,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED,3,0x109000) = 34368466944 (0x800853000)
mmap(0x800872000,110592,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) = 34368593920 (0x800872000)
close(3)					 = 0 (0x0)
mmap(0x0,768,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 34365222912 (0x80053b000)
munmap(0x80053b000,768)				 = 0 (0x0)
mmap(0x0,43904,PROT_READ|PROT_WRITE,MAP_ANON,-1,0x0) = 34365222912 (0x80053b000)
munmap(0x80053b000,43904)			 = 0 (0x0)
sysarch(0x81,0x7fffffffe2b0,0x800538088,0x0,0xffffffffffcdb550,0x8080808080808080) = 0 (0x0)
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
__sysctl(0x7fffffffe240,0x2,0x503980,0x7fffffffe238,0x0,0x0) = 0 (0x0)
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
__sysctl(0x7fffffffe110,0x2,0x7fffffffe0a0,0x7fffffffe108,0x7fffffffe550,0xe) = 0 (0x0)
__sysctl(0x7fffffffdbd0,0x6,0x7fffffffdc40,0x7fffffffdc38,0x0,0x0) = 0 (0x0)
__sysctl(0x7fffffffd7b0,0x6,0x7fffffffd830,0x7fffffffd820,0x0,0x0) = 0 (0x0)
__sysctl(0x7fffffffe0a0,0x4,0x0,0x7fffffffd820,0x0,0x0) = 0 (0x0)
__sysctl(0x7fffffffd2a0,0x2,0x800877dc8,0x7fffffffd298,0x0,0x0) = 0 (0x0)
__sysctl(0x7fffffffd1c0,0x2,0x7fffffffd150,0x7fffffffd1b8,0x800745880,0xc) = 0 (0x0)
__sysctl(0x7fffffffd150,0x2,0x800877fd0,0x7fffffffd218,0x0,0x0) = 0 (0x0)
readlink("/etc/malloc.conf",0x7fffffffd2c0,1024) ERR#2 'No such file or directory'
issetugid(0x800744541,0x7fffffffd2c0,0xffffffffffffffff,0x0,0x2,0x0) = 0 (0x0)
break(0x600000)					 = 0 (0x0)
__sysctl(0x7fffffffd580,0x2,0x7fffffffd59c,0x7fffffffd590,0x0,0x0) = 0 (0x0)
mmap(0x0,2097152,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34368704512 (0x80088d000)
mmap(0x800a8d000,1519616,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 34370801664 (0x800a8d000)
munmap(0x80088d000,1519616)			 = 0 (0x0)
__sysctl(0x7fffffffe0a0,0x4,0x800a04040,0x7fffffffd818,0x0,0x0) = 0 (0x0)
__sysctl(0x7fffffffd2d0,0x6,0x7fffffffd340,0x7fffffffd338,0x0,0x0) = 0 (0x0)
dev.cpu.0.freq: write(1,"dev.cpu.0.freq: ",16)			 = 16 (0x10)
960write(1,"960",3)				 = 3 (0x3)
__sysctl(0x7fffffffe0a0,0x4,0x0,0x0,0x7fffffffe14c,0x4) ERR#1 'Operation not permitted'

write(1,"\n",1)					 = 1 (0x1)
sysctl: write(2,"sysctl: ",8)				 = 8 (0x8)
dev.cpu.0.freq=400write(2,"dev.cpu.0.freq=400",18)		 = 18 (0x12)
: write(2,": ",2)					 = 2 (0x2)
stat("/usr/share/nls/C/libc.cat",0x7fffffffda20) ERR#2 'No such file or directory'
stat("/usr/share/nls/libc/C",0x7fffffffda20)	 ERR#2 'No such file or directory'
stat("/usr/local/share/nls/C/libc.cat",0x7fffffffda20) ERR#2 'No such file or directory'
stat("/usr/local/share/nls/libc/C",0x7fffffffda20) ERR#2 'No such file or directory'
Operation not permitted
write(2,"Operation not permitted\n",24)		 = 24 (0x18)
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
process exit, rval = 1

Script done on Sun Jul  6 21:33:55 2014
-------------- next part --------------
cpufreq: get returning known freq 960
cpufreq: get returning known freq 960
cpufreq: skipping info-only driver acpi_perf0
cpufreq: adding 8 relative settings
cpufreq: adding abs setting 1600 at head
cpufreq: adding abs setting 1280 after 1600
cpufreq: adding abs setting 800 after 1280
cpufreq: expand set added rel setting 100% to 800 level
cpufreq: dup set considering derived setting 700
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup done, inserting new level 700 after 800
cpufreq: expand set added rel setting 87% to 700 level
cpufreq: dup set considering derived setting 600
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup done, inserting new level 600 after 700
cpufreq: expand set added rel setting 75% to 600 level
cpufreq: dup set considering derived setting 500
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup done, inserting new level 500 after 600
cpufreq: expand set added rel setting 62% to 500 level
cpufreq: dup set considering derived setting 400
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup done, inserting new level 400 after 500
cpufreq: expand set added rel setting 50% to 400 level
cpufreq: dup set considering derived setting 300
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup done, inserting new level 300 after 400
cpufreq: expand set added rel setting 37% to 300 level
cpufreq: dup set considering derived setting 200
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup done, inserting new level 200 after 300
cpufreq: expand set added rel setting 25% to 200 level
cpufreq: dup set considering derived setting 100
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup done, inserting new level 100 after 200
cpufreq: expand set added rel setting 12% to 100 level
cpufreq: expand set added rel setting 100% to 1280 level
cpufreq: dup set considering derived setting 1120
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup done, inserting new level 1120 after 1280
cpufreq: expand set added rel setting 87% to 1120 level
cpufreq: dup set considering derived setting 960
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup done, inserting new level 960 after 1120
cpufreq: expand set added rel setting 75% to 960 level
cpufreq: dup set considering derived setting 800
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup set rejecting 800 (dupe)
cpufreq: dup set freeing new level 800 (not optimal)
cpufreq: expand set added rel setting 100% to 1600 level
cpufreq: dup set considering derived setting 1400
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup done, inserting new level 1400 after 1600
cpufreq: expand set added rel setting 87% to 1400 level
cpufreq: dup set considering derived setting 1200
cpufreq: removed last relative driver: acpi_throttle0
cpufreq: dup set rejecting 1200 (abs too big)
cpufreq: dup set freeing new level 1200 (not optimal)
cpufreq: ignoring, curr prio 100 less than 1000