From owner-freebsd-users-jp@FreeBSD.ORG Sun Jul 6 13:36:44 2014 Return-Path: Delivered-To: freebsd-users-jp@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id 2293428D for ; Sun, 6 Jul 2014 13:36:44 +0000 (UTC) Received: from mail1.asahi-net.or.jp (mail1.asahi-net.or.jp [202.224.39.197]) by mx1.freebsd.org (Postfix) with ESMTP id DCF3F228B for ; Sun, 6 Jul 2014 13:36:42 +0000 (UTC) Received: from flu.if0.org (x239189.ppp.asahi-net.or.jp [122.249.239.189]) by mail1.asahi-net.or.jp (Postfix) with ESMTP id 8EAB718CBA for ; Sun, 6 Jul 2014 22:36:35 +0900 (JST) Received: from localhost (localhost.if0.org [127.0.0.1]) by flu.if0.org (8.14.9/8.14.5) with ESMTP id s66DaY1O077402 for ; Sun, 6 Jul 2014 22:36:34 +0900 (JST) (envelope-from ka@flu.if0.org) X-Authentication-Warning: flu.if0.org: Host localhost.if0.org [127.0.0.1] claimed to be localhost Resent-Date: Sun, 06 Jul 2014 22:36:34 +0900 (JST) Resent-Message-Id: <20140706.223634.15252722.ka@flu.if0.org> Resent-To: freebsd-users-jp@freebsd.org Resent-From: Kazumaro Aoki Date: Sun, 06 Jul 2014 21:44:34 +0900 (JST) Message-Id: <20140706.214434.28800521.ka@flu.if0.org> To: freebsd-users-jp@freebsd.org From: Kazumaro Aoki In-Reply-To: <20140703.224248.250136926.ka@flu.if0.org> References: <20140702.225753.74551033.ka@flu.if0.org> <20140703.224248.250136926.ka@flu.if0.org> X-Mailer: Mew version 6.6 on Emacs 22.3 / Mule 5.0 (SAKAKI) Mime-Version: 1.0 Content-Type: Multipart/Mixed; boundary="--Next_Part(Sun_Jul__6_21_44_34_2014_960)--" Content-Transfer-Encoding: 7bit Subject: [FreeBSD-users-jp 95226] Re: powerd with high frequency when idling X-BeenThere: freebsd-users-jp@freebsd.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: Discussion relevant to FreeBSD communities in Japan List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 06 Jul 2014 13:36:44 -0000 ----Next_Part(Sun_Jul__6_21_44_34_2014_960)-- Content-Type: Text/Plain; charset=iso-2022-jp Content-Transfer-Encoding: 7bit 青木＠国分寺市在住です From: Kazumaro Aoki 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(Sun_Jul__6_21_44_34_2014_960)-- Content-Type: Text/Plain; charset=us-ascii Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename=log 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(Sun_Jul__6_21_44_34_2014_960)-- Content-Type: Text/Plain; charset=us-ascii Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename=messages 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 ----Next_Part(Sun_Jul__6_21_44_34_2014_960)----