Re: top incorrectly reporting process time
Kris Kennaway wrote: Ott Köstner wrote: Kris Kennaway wrote: Ott Köstner wrote: Jeremy Chadwick wrote: On Sun, Nov 16, 2008 at 04:34:01PM +0200, Ott Köstner wrote: On several FreeBSD machines I have the following problem: What FreeBSD version? (It matters) 7.1-PRERELEASE FreeBSD But I can experience it also on a 7.0 machine. Seems that top reports incorrectly processes with multiple threads. $ top -bUbind last pid: 21635; load averages: 0.73, 0.46, 0.29 up 1+00:17:18 16:48:10 54 processes: 1 running, 53 sleeping Mem: 66M Active, 1174M Inact, 204M Wired, 36K Cache, 112M Buf, 555M Free Swap: 2048M Total, 2048M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind8 440 40288K 32916K select 0 0:16 0.00% named $ ps -ax|grep 979 979 ?? Ss 1:11.26 /usr/sbin/named -n 5 -t /var/named -u bind Check top -H to display the statistics for individual threads. Kris # top -bUmysql last pid: 8336; load averages: 0.33, 0.30, 0.24 up 13+22:36:2908:47:07 157 processes: 1 running, 156 sleeping Mem: 1163M Active, 2058M Inact, 555M Wired, 160M Cache, 214M Buf, 22M Free Swap: 4096M Total, 432K Used, 4095M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 9 200 92316K 70472K sigwai 1 0:04 0.00% mysqld 1015 mysql 1 80 7056K 1332K wait 1 0:00 0.00% sh - # top -bHUmysql last pid: 8497; load averages: 0.36, 0.32, 0.25 up 13+22:37:4308:48:21 148 processes: 4 running, 144 sleeping Mem: 1147M Active, 2068M Inact, 554M Wired, 156M Cache, 214M Buf, 32M Free Swap: 4096M Total, 432K Used, 4095M Free PID USERNAME PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 440 92316K 70472K select 0 4:10 0.00% mysqld 1079 mysql 440 92316K 70472K select 0 3:12 0.00% mysqld 1079 mysql 440 92316K 70472K select 1 1:59 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 0 0:47 0.00% mysqld 1079 mysql 440 92316K 70472K select 0 0:26 0.00% mysqld 1079 mysql 200 92316K 70472K sigwai 1 0:04 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 0 0:04 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 1 0:01 0.00% mysqld 1015 mysql 80 7056K 1332K wait 1 0:00 0.00% sh 1079 mysql 440 92316K 70472K ucond 0 0:00 0.00% mysqld -- This seems to be the only inconsistent one: # ps -ax|grep 1079 1079 con- S576:13.90 [mysqld] Check that your ps binary is in sync with your kernel, i.e. rebuild world with the same sources you used to build your kernel. Kris I did that. First, downloaded source with csup, built world, kernel, installed kernel and world. Then rebuilt kernel once again and installed it. On another machine (w/ 32bit kernel): # top -bU bind; top -bHU bind last pid: 21738; load averages: 0.02, 0.20, 0.27 up 12+18:08:53 10:39:45 56 processes: 1 running, 55 sleeping Mem: 207M Active, 1494M Inact, 223M Wired, 70M Cache, 112M Buf, 4700K Free Swap: 2048M Total, 12K Used, 2048M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind8 440 52576K 44652K select 1 9:42 0.00% named last pid: 21739; load averages: 0.02, 0.20, 0.27 up 12+18:08:53 10:39:45 56 processes: 1 running, 55 sleeping Mem: 207M Active, 1494M Inact, 223M Wired, 70M Cache, 112M Buf, 4712K Free Swap: 2048M Total, 12K Used, 2048M Free PID USERNAME PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind 440 52576K 44652K select 1 9:42 0.00% named 979 bind 440 52576K 44652K ucond 1 5:52 0.00% named 979 bind 440 52576K 44652K ucond 0 5:51 0.00% named 979 bind 440 52576K 44652K ucond 0 5:50 0.00% named 979 bind 440 52576K 44652K ucond 1 5:49 0.00% named 979 bind 440 52576K 44652K ucond 1 5:48 0.00% named 979 bind 440 52576K 44652K ucond 1 0:16 0.00% named 979 bind 200 52576K 44652K sigwai 1 0:00 0.00% named # ps -aHx | grep 979; echo ;ps -ax | grep 979 979 ?? Is 0:00.01 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:49.41 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:50.73 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:50.36 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:52.14 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:48.15 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 0:15.69 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 9:41.68 /usr/sbin/named -n 5 -t /var/named -u bind 21761 p0 R+
Re: top incorrectly reporting process time
Ott Köstner wrote: Kris Kennaway wrote: Ott Köstner wrote: Kris Kennaway wrote: Ott Köstner wrote: Jeremy Chadwick wrote: On Sun, Nov 16, 2008 at 04:34:01PM +0200, Ott Köstner wrote: On several FreeBSD machines I have the following problem: What FreeBSD version? (It matters) 7.1-PRERELEASE FreeBSD But I can experience it also on a 7.0 machine. Seems that top reports incorrectly processes with multiple threads. $ top -bUbind last pid: 21635; load averages: 0.73, 0.46, 0.29 up 1+00:17:18 16:48:10 54 processes: 1 running, 53 sleeping Mem: 66M Active, 1174M Inact, 204M Wired, 36K Cache, 112M Buf, 555M Free Swap: 2048M Total, 2048M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind8 440 40288K 32916K select 0 0:16 0.00% named $ ps -ax|grep 979 979 ?? Ss 1:11.26 /usr/sbin/named -n 5 -t /var/named -u bind Check top -H to display the statistics for individual threads. Kris # top -bUmysql last pid: 8336; load averages: 0.33, 0.30, 0.24 up 13+22:36:2908:47:07 157 processes: 1 running, 156 sleeping Mem: 1163M Active, 2058M Inact, 555M Wired, 160M Cache, 214M Buf, 22M Free Swap: 4096M Total, 432K Used, 4095M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 9 200 92316K 70472K sigwai 1 0:04 0.00% mysqld 1015 mysql 1 80 7056K 1332K wait 1 0:00 0.00% sh - # top -bHUmysql last pid: 8497; load averages: 0.36, 0.32, 0.25 up 13+22:37:4308:48:21 148 processes: 4 running, 144 sleeping Mem: 1147M Active, 2068M Inact, 554M Wired, 156M Cache, 214M Buf, 32M Free Swap: 4096M Total, 432K Used, 4095M Free PID USERNAME PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 440 92316K 70472K select 0 4:10 0.00% mysqld 1079 mysql 440 92316K 70472K select 0 3:12 0.00% mysqld 1079 mysql 440 92316K 70472K select 1 1:59 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 0 0:47 0.00% mysqld 1079 mysql 440 92316K 70472K select 0 0:26 0.00% mysqld 1079 mysql 200 92316K 70472K sigwai 1 0:04 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 0 0:04 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 1 0:01 0.00% mysqld 1015 mysql 80 7056K 1332K wait 1 0:00 0.00% sh 1079 mysql 440 92316K 70472K ucond 0 0:00 0.00% mysqld -- This seems to be the only inconsistent one: # ps -ax|grep 1079 1079 con- S576:13.90 [mysqld] Check that your ps binary is in sync with your kernel, i.e. rebuild world with the same sources you used to build your kernel. Kris I did that. First, downloaded source with csup, built world, kernel, installed kernel and world. Then rebuilt kernel once again and installed it. On another machine (w/ 32bit kernel): # top -bU bind; top -bHU bind last pid: 21738; load averages: 0.02, 0.20, 0.27 up 12+18:08:53 10:39:45 56 processes: 1 running, 55 sleeping Mem: 207M Active, 1494M Inact, 223M Wired, 70M Cache, 112M Buf, 4700K Free Swap: 2048M Total, 12K Used, 2048M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind8 440 52576K 44652K select 1 9:42 0.00% named last pid: 21739; load averages: 0.02, 0.20, 0.27 up 12+18:08:53 10:39:45 56 processes: 1 running, 55 sleeping Mem: 207M Active, 1494M Inact, 223M Wired, 70M Cache, 112M Buf, 4712K Free Swap: 2048M Total, 12K Used, 2048M Free PID USERNAME PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind 440 52576K 44652K select 1 9:42 0.00% named 979 bind 440 52576K 44652K ucond 1 5:52 0.00% named 979 bind 440 52576K 44652K ucond 0 5:51 0.00% named 979 bind 440 52576K 44652K ucond 0 5:50 0.00% named 979 bind 440 52576K 44652K ucond 1 5:49 0.00% named 979 bind 440 52576K 44652K ucond 1 5:48 0.00% named 979 bind 440 52576K 44652K ucond 1 0:16 0.00% named 979 bind 200 52576K 44652K sigwai 1 0:00 0.00% named # ps -aHx | grep 979; echo ;ps -ax | grep 979 979 ?? Is 0:00.01 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:49.41 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:50.73 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:50.36 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:52.14 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:48.15 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 0:15.69 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 9:41.68 /usr/sbin/named -n 5 -t /var/named -u bind
Re: top incorrectly reporting process time
Kris Kennaway wrote: Ott Köstner wrote: Kris Kennaway wrote: Ott Köstner wrote: Kris Kennaway wrote: Ott Köstner wrote: Jeremy Chadwick wrote: On Sun, Nov 16, 2008 at 04:34:01PM +0200, Ott Köstner wrote: On several FreeBSD machines I have the following problem: What FreeBSD version? (It matters) 7.1-PRERELEASE FreeBSD But I can experience it also on a 7.0 machine. Seems that top reports incorrectly processes with multiple threads. $ top -bUbind last pid: 21635; load averages: 0.73, 0.46, 0.29 up 1+00:17:18 16:48:10 54 processes: 1 running, 53 sleeping Mem: 66M Active, 1174M Inact, 204M Wired, 36K Cache, 112M Buf, 555M Free Swap: 2048M Total, 2048M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind8 440 40288K 32916K select 0 0:16 0.00% named $ ps -ax|grep 979 979 ?? Ss 1:11.26 /usr/sbin/named -n 5 -t /var/named -u bind Check top -H to display the statistics for individual threads. Kris # top -bUmysql last pid: 8336; load averages: 0.33, 0.30, 0.24 up 13+22:36:2908:47:07 157 processes: 1 running, 156 sleeping Mem: 1163M Active, 2058M Inact, 555M Wired, 160M Cache, 214M Buf, 22M Free Swap: 4096M Total, 432K Used, 4095M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 9 200 92316K 70472K sigwai 1 0:04 0.00% mysqld 1015 mysql 1 80 7056K 1332K wait 1 0:00 0.00% sh - # top -bHUmysql last pid: 8497; load averages: 0.36, 0.32, 0.25 up 13+22:37:4308:48:21 148 processes: 4 running, 144 sleeping Mem: 1147M Active, 2068M Inact, 554M Wired, 156M Cache, 214M Buf, 32M Free Swap: 4096M Total, 432K Used, 4095M Free PID USERNAME PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 440 92316K 70472K select 0 4:10 0.00% mysqld 1079 mysql 440 92316K 70472K select 0 3:12 0.00% mysqld 1079 mysql 440 92316K 70472K select 1 1:59 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 0 0:47 0.00% mysqld 1079 mysql 440 92316K 70472K select 0 0:26 0.00% mysqld 1079 mysql 200 92316K 70472K sigwai 1 0:04 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 0 0:04 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 1 0:01 0.00% mysqld 1015 mysql 80 7056K 1332K wait 1 0:00 0.00% sh 1079 mysql 440 92316K 70472K ucond 0 0:00 0.00% mysqld -- This seems to be the only inconsistent one: # ps -ax|grep 1079 1079 con- S576:13.90 [mysqld] Check that your ps binary is in sync with your kernel, i.e. rebuild world with the same sources you used to build your kernel. Kris I did that. First, downloaded source with csup, built world, kernel, installed kernel and world. Then rebuilt kernel once again and installed it. On another machine (w/ 32bit kernel): # top -bU bind; top -bHU bind last pid: 21738; load averages: 0.02, 0.20, 0.27 up 12+18:08:5310:39:45 56 processes: 1 running, 55 sleeping Mem: 207M Active, 1494M Inact, 223M Wired, 70M Cache, 112M Buf, 4700K Free Swap: 2048M Total, 12K Used, 2048M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind8 440 52576K 44652K select 1 9:42 0.00% named ==^^ last pid: 21739; load averages: 0.02, 0.20, 0.27 up 12+18:08:5310:39:45 56 processes: 1 running, 55 sleeping Mem: 207M Active, 1494M Inact, 223M Wired, 70M Cache, 112M Buf, 4712K Free Swap: 2048M Total, 12K Used, 2048M Free PID USERNAME PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind 440 52576K 44652K select 1 9:42 0.00% named 979 bind 440 52576K 44652K ucond 1 5:52 0.00% named 979 bind 440 52576K 44652K ucond 0 5:51 0.00% named 979 bind 440 52576K 44652K ucond 0 5:50 0.00% named 979 bind 440 52576K 44652K ucond 1 5:49 0.00% named 979 bind 440 52576K 44652K ucond 1 5:48 0.00% named 979 bind 440 52576K 44652K ucond 1 0:16 0.00% named 979 bind 200 52576K 44652K sigwai 1 0:00 0.00% named # ps -aHx | grep 979; echo ;ps -ax | grep 979 979 ?? Is 0:00.01 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:49.41 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:50.73 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:50.36 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:52.14 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 5:48.15 /usr/sbin/named -n 5 -t /var/named -u bind 979 ?? Ss 0:15.69 /usr/sbin/named -n 5 -t
Re: top incorrectly reporting process time
Kris Kennaway wrote: Ott Köstner wrote: Here is the problem. top returns only 9:42 -- the time of the first thread. ps returns the sum of the thread times, which is correct. OK, I thought you were claiming the numbers were completely unrelated. Yeah, top and ps are just reporting different things (runtime of one thread vs total runtime of all threads). top may have a configuration option about aggregating the thread runtimes, or it may require a source code change. Kris Now I understand -- there are actually 2 separate problems -- one with top code, which is the same on all systems and another porblem wihth ps on two amd64 machines I am running: First computer FreeBSD 7.1-PRERELEASE #2 (exact copy / paste) : # ps -ax|grep mysql; echo; ps -axH|grep mysql 981 con- IW 0:00.00 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.c 1019 con- S 98:00.87 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 12266 p0 S+ 0:00.00 grep mysql 981 con- IW 0:00.00 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.c 1019 con- S 0:01.21 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 1019 con- S 0:00.11 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 1019 con- I 3:13.38 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 1019 con- I 0:00.08 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 1019 con- S 0:00.02 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 12268 p0 R+ 0:00.00 grep mysql 3.xx minutes seems to be correct here, not 98. Second computer FreeBSD 7.1-PRERELEASE #3 (exact copy / paste): # ps -ax|grep mysql; echo; ps -axH|grep mysql 1015 con- I 0:00.01 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.c 1079 con- S582:49.60 [mysqld] 1015 con- I 0:00.01 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.c 1079 con- S 2:00.40 [mysqld] 1079 con- I 0:00.00 [mysqld] 1079 con- I 0:01.32 [mysqld] 1079 con- I 0:47.04 [mysqld] 1079 con- I 0:03.56 [mysqld] 1079 con- S 0:26.43 [mysqld] 1079 con- S 3:13.97 [mysqld] 1079 con- S 4:12.72 [mysqld] 1079 con- S 0:03.72 [mysqld] 582 minutes is clearly wrong. Sincerely, O.K. -- Testi oma Interneti kiirust / Test Your Internet speed: http://speedtest.zzz.ee/ ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
Re: top incorrectly reporting process time
Mel wrote: On Friday 28 November 2008 11:52:26 Ott Köstner wrote: Second computer FreeBSD 7.1-PRERELEASE #3 (exact copy / paste): # ps -ax|grep mysql; echo; ps -axH|grep mysql 1015 con- I 0:00.01 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.c 1079 con- S582:49.60 [mysqld] 1015 con- I 0:00.01 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.c 1079 con- S 2:00.40 [mysqld] 1079 con- I 0:00.00 [mysqld] 1079 con- I 0:01.32 [mysqld] 1079 con- I 0:47.04 [mysqld] 1079 con- I 0:03.56 [mysqld] 1079 con- S 0:26.43 [mysqld] 1079 con- S 3:13.97 [mysqld] 1079 con- S 4:12.72 [mysqld] 1079 con- S 0:03.72 [mysqld] 582 minutes is clearly wrong. Not if it's the sum of all threads that lived and died during the lifetime of the process. It's value is taken from the kernel's idea of the runtime. With KERN_PROC_INC_THREAD set, it will look at the thread storage for active threads, including the 'main()' thread. I haven't looked into detail, but I suspect when a thread dies it gets added to process runtime, and is stored nowhere else. I see. Thank You! Aside from the different machines, you also took 2 different daemons, which fits this: named uses a static thread pool, by design, sum(nthreads) will equal the process time mysqld uses a dynamic thread pool, sum(nthreads) is really sum(nthreads_active). I haven't looked into detail I see. Regards, O.K. ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
Re: top incorrectly reporting process time
Ott Köstner wrote: Here is the problem. top returns only 9:42 -- the time of the first thread. ps returns the sum of the thread times, which is correct. OK, I thought you were claiming the numbers were completely unrelated. Yeah, top and ps are just reporting different things (runtime of one thread vs total runtime of all threads). top may have a configuration option about aggregating the thread runtimes, or it may require a source code change. Kris ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
Re: top incorrectly reporting process time
On Friday 28 November 2008 11:52:26 Ott Köstner wrote: Kris Kennaway wrote: Ott Köstner wrote: Here is the problem. top returns only 9:42 -- the time of the first thread. ps returns the sum of the thread times, which is correct. OK, I thought you were claiming the numbers were completely unrelated. Yeah, top and ps are just reporting different things (runtime of one thread vs total runtime of all threads). top may have a configuration option about aggregating the thread runtimes, or it may require a source code change. Kris Now I understand -- there are actually 2 separate problems -- one with top code, which is the same on all systems and another porblem wihth ps on two amd64 machines I am running: First computer FreeBSD 7.1-PRERELEASE #2 (exact copy / paste) : # ps -ax|grep mysql; echo; ps -axH|grep mysql 981 con- IW 0:00.00 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.c 1019 con- S 98:00.87 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 12266 p0 S+ 0:00.00 grep mysql 981 con- IW 0:00.00 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.c 1019 con- S 0:01.21 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 1019 con- S 0:00.11 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 1019 con- I 3:13.38 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 1019 con- I 0:00.08 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 1019 con- S 0:00.02 /usr/local/libexec/mysqld --defaults-extra-file=/var/db/mysql/my.cnf --base 12268 p0 R+ 0:00.00 grep mysql 3.xx minutes seems to be correct here, not 98. Second computer FreeBSD 7.1-PRERELEASE #3 (exact copy / paste): # ps -ax|grep mysql; echo; ps -axH|grep mysql 1015 con- I 0:00.01 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.c 1079 con- S582:49.60 [mysqld] 1015 con- I 0:00.01 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.c 1079 con- S 2:00.40 [mysqld] 1079 con- I 0:00.00 [mysqld] 1079 con- I 0:01.32 [mysqld] 1079 con- I 0:47.04 [mysqld] 1079 con- I 0:03.56 [mysqld] 1079 con- S 0:26.43 [mysqld] 1079 con- S 3:13.97 [mysqld] 1079 con- S 4:12.72 [mysqld] 1079 con- S 0:03.72 [mysqld] 582 minutes is clearly wrong. Not if it's the sum of all threads that lived and died during the lifetime of the process. It's value is taken from the kernel's idea of the runtime. With KERN_PROC_INC_THREAD set, it will look at the thread storage for active threads, including the 'main()' thread. I haven't looked into detail, but I suspect when a thread dies it gets added to process runtime, and is stored nowhere else. Aside from the different machines, you also took 2 different daemons, which fits this: named uses a static thread pool, by design, sum(nthreads) will equal the process time mysqld uses a dynamic thread pool, sum(nthreads) is really sum(nthreads_active). I haven't looked into detail -- Mel Problem with today's modular software: they start with the modules and never get to the software part. ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
Re: top incorrectly reporting process time
Ott Köstner wrote: Jeremy Chadwick wrote: On Sun, Nov 16, 2008 at 04:34:01PM +0200, Ott Köstner wrote: On several FreeBSD machines I have the following problem: What FreeBSD version? (It matters) 7.1-PRERELEASE FreeBSD But I can experience it also on a 7.0 machine. Seems that top reports incorrectly processes with multiple threads. $ top -bUbind last pid: 21635; load averages: 0.73, 0.46, 0.29 up 1+00:17:18 16:48:10 54 processes: 1 running, 53 sleeping Mem: 66M Active, 1174M Inact, 204M Wired, 36K Cache, 112M Buf, 555M Free Swap: 2048M Total, 2048M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind8 440 40288K 32916K select 0 0:16 0.00% named $ ps -ax|grep 979 979 ?? Ss 1:11.26 /usr/sbin/named -n 5 -t /var/named -u bind Check top -H to display the statistics for individual threads. Kris ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
Re: top incorrectly reporting process time
Kris Kennaway wrote: Ott Köstner wrote: Jeremy Chadwick wrote: On Sun, Nov 16, 2008 at 04:34:01PM +0200, Ott Köstner wrote: On several FreeBSD machines I have the following problem: What FreeBSD version? (It matters) 7.1-PRERELEASE FreeBSD But I can experience it also on a 7.0 machine. Seems that top reports incorrectly processes with multiple threads. $ top -bUbind last pid: 21635; load averages: 0.73, 0.46, 0.29 up 1+00:17:18 16:48:10 54 processes: 1 running, 53 sleeping Mem: 66M Active, 1174M Inact, 204M Wired, 36K Cache, 112M Buf, 555M Free Swap: 2048M Total, 2048M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind8 440 40288K 32916K select 0 0:16 0.00% named $ ps -ax|grep 979 979 ?? Ss 1:11.26 /usr/sbin/named -n 5 -t /var/named -u bind Check top -H to display the statistics for individual threads. Kris # top -bUmysql last pid: 8336; load averages: 0.33, 0.30, 0.24 up 13+22:36:29 08:47:07 157 processes: 1 running, 156 sleeping Mem: 1163M Active, 2058M Inact, 555M Wired, 160M Cache, 214M Buf, 22M Free Swap: 4096M Total, 432K Used, 4095M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 9 200 92316K 70472K sigwai 1 0:04 0.00% mysqld 1015 mysql 1 80 7056K 1332K wait 1 0:00 0.00% sh - # top -bHUmysql last pid: 8497; load averages: 0.36, 0.32, 0.25 up 13+22:37:43 08:48:21 148 processes: 4 running, 144 sleeping Mem: 1147M Active, 2068M Inact, 554M Wired, 156M Cache, 214M Buf, 32M Free Swap: 4096M Total, 432K Used, 4095M Free PID USERNAME PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 440 92316K 70472K select 0 4:10 0.00% mysqld 1079 mysql 440 92316K 70472K select 0 3:12 0.00% mysqld 1079 mysql 440 92316K 70472K select 1 1:59 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 0 0:47 0.00% mysqld 1079 mysql 440 92316K 70472K select 0 0:26 0.00% mysqld 1079 mysql 200 92316K 70472K sigwai 1 0:04 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 0 0:04 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 1 0:01 0.00% mysqld 1015 mysql 80 7056K 1332K wait 1 0:00 0.00% sh 1079 mysql 440 92316K 70472K ucond 0 0:00 0.00% mysqld -- # ps -ax|grep 1079 1079 con- S576:13.90 [mysqld] -- # ps -aHx|grep 1079 1079 con- S 1:58.71 [mysqld] 1079 con- I 0:00.00 [mysqld] 1079 con- S 0:01.30 [mysqld] 1079 con- I 0:46.72 [mysqld] 1079 con- S 0:03.51 [mysqld] 1079 con- S 0:26.05 [mysqld] 1079 con- S 3:11.80 [mysqld] 1079 con- S 4:09.88 [mysqld] 1079 con- S 0:03.67 [mysqld] Strange? Greetings, O.K. ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
Re: top incorrectly reporting process time
Ott Köstner wrote: Kris Kennaway wrote: Ott Köstner wrote: Jeremy Chadwick wrote: On Sun, Nov 16, 2008 at 04:34:01PM +0200, Ott Köstner wrote: On several FreeBSD machines I have the following problem: What FreeBSD version? (It matters) 7.1-PRERELEASE FreeBSD But I can experience it also on a 7.0 machine. Seems that top reports incorrectly processes with multiple threads. $ top -bUbind last pid: 21635; load averages: 0.73, 0.46, 0.29 up 1+00:17:18 16:48:10 54 processes: 1 running, 53 sleeping Mem: 66M Active, 1174M Inact, 204M Wired, 36K Cache, 112M Buf, 555M Free Swap: 2048M Total, 2048M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind8 440 40288K 32916K select 0 0:16 0.00% named $ ps -ax|grep 979 979 ?? Ss 1:11.26 /usr/sbin/named -n 5 -t /var/named -u bind Check top -H to display the statistics for individual threads. Kris # top -bUmysql last pid: 8336; load averages: 0.33, 0.30, 0.24 up 13+22:36:29 08:47:07 157 processes: 1 running, 156 sleeping Mem: 1163M Active, 2058M Inact, 555M Wired, 160M Cache, 214M Buf, 22M Free Swap: 4096M Total, 432K Used, 4095M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 9 200 92316K 70472K sigwai 1 0:04 0.00% mysqld 1015 mysql 1 80 7056K 1332K wait 1 0:00 0.00% sh - # top -bHUmysql last pid: 8497; load averages: 0.36, 0.32, 0.25 up 13+22:37:43 08:48:21 148 processes: 4 running, 144 sleeping Mem: 1147M Active, 2068M Inact, 554M Wired, 156M Cache, 214M Buf, 32M Free Swap: 4096M Total, 432K Used, 4095M Free PID USERNAME PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 440 92316K 70472K select 0 4:10 0.00% mysqld 1079 mysql 440 92316K 70472K select 0 3:12 0.00% mysqld 1079 mysql 440 92316K 70472K select 1 1:59 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 0 0:47 0.00% mysqld 1079 mysql 440 92316K 70472K select 0 0:26 0.00% mysqld 1079 mysql 200 92316K 70472K sigwai 1 0:04 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 0 0:04 0.00% mysqld 1079 mysql 440 92316K 70472K ucond 1 0:01 0.00% mysqld 1015 mysql 80 7056K 1332K wait 1 0:00 0.00% sh 1079 mysql 440 92316K 70472K ucond 0 0:00 0.00% mysqld -- This seems to be the only inconsistent one: # ps -ax|grep 1079 1079 con- S576:13.90 [mysqld] Check that your ps binary is in sync with your kernel, i.e. rebuild world with the same sources you used to build your kernel. Kris -- # ps -aHx|grep 1079 1079 con- S 1:58.71 [mysqld] 1079 con- I 0:00.00 [mysqld] 1079 con- S 0:01.30 [mysqld] 1079 con- I 0:46.72 [mysqld] 1079 con- S 0:03.51 [mysqld] 1079 con- S 0:26.05 [mysqld] 1079 con- S 3:11.80 [mysqld] 1079 con- S 4:09.88 [mysqld] 1079 con- S 0:03.67 [mysqld] Strange? Greetings, O.K. ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED] ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
top incorrectly reporting process time
Hello, On several FreeBSD machines I have the following problem: # top -bUmysql last pid: 99112; load averages: 0.22, 0.12, 0.09 up 2+06:07:05 16:17:43 132 processes: 1 running, 131 sleeping Mem: 718M Active, 2494M Inact, 455M Wired, 77M Cache, 214M Buf, 213M Free Swap: 4096M Total, 4096M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 9 200 81564K 60268K sigwai 1 0:01 0.00% mysqld ^^^ 1015 mysql 1 80 7056K 1368K wait 1 0:00 0.00% sh However mysqld time is actually # ps -ax|grep mysql 1015 con- I 0:00.01 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.cnf 1079 con- S 70:03.64 [mysqld] ^^^ 99156 p0 S+ 0:00.00 grep mysql Anyone who can explain this? With greetings, Ott Köstner ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
top incorrectly reporting process time
Hello, On several FreeBSD machines I have the following problem: # top -bUmysql last pid: 99112; load averages: 0.22, 0.12, 0.09 up 2+06:07:05 16:17:43 132 processes: 1 running, 131 sleeping Mem: 718M Active, 2494M Inact, 455M Wired, 77M Cache, 214M Buf, 213M Free Swap: 4096M Total, 4096M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 9 200 81564K 60268K sigwai 1 0:01 0.00% mysqld ^^^ 1015 mysql 1 80 7056K 1368K wait 1 0:00 0.00% sh However mysqld time is actually # ps -ax|grep mysql 1015 con- I 0:00.01 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.cnf 1079 con- S 70:03.64 [mysqld] ^^^ 99156 p0 S+ 0:00.00 grep mysql Anyone who can explain this? With greetings, Ott Köstner ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
Re: top incorrectly reporting process time
On Sun, Nov 16, 2008 at 04:34:01PM +0200, Ott Köstner wrote: On several FreeBSD machines I have the following problem: What FreeBSD version? (It matters) # top -bUmysql last pid: 99112; load averages: 0.22, 0.12, 0.09 up 2+06:07:05 16:17:43 132 processes: 1 running, 131 sleeping Mem: 718M Active, 2494M Inact, 455M Wired, 77M Cache, 214M Buf, 213M Free Swap: 4096M Total, 4096M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 9 200 81564K 60268K sigwai 1 0:01 0.00% mysqld ^^^ 1015 mysql 1 80 7056K 1368K wait 1 0:00 0.00% sh However mysqld time is actually # ps -ax|grep mysql 1015 con- I 0:00.01 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.cnf 1079 con- S 70:03.64 [mysqld] ^^^ 99156 p0 S+ 0:00.00 grep mysql Anyone who can explain this? Does the behaviour change if you mount /proc? (This would mainly apply to RELENG_6 and earlier only) -- | Jeremy Chadwickjdc at parodius.com | | Parodius Networking http://www.parodius.com/ | | UNIX Systems Administrator Mountain View, CA, USA | | Making life hard for others since 1977. PGP: 4BD6C0CB | ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
Re: top incorrectly reporting process time
Jeremy Chadwick wrote: On Sun, Nov 16, 2008 at 04:34:01PM +0200, Ott Köstner wrote: On several FreeBSD machines I have the following problem: What FreeBSD version? (It matters) 7.1-PRERELEASE FreeBSD But I can experience it also on a 7.0 machine. Seems that top reports incorrectly processes with multiple threads. $ top -bUbind last pid: 21635; load averages: 0.73, 0.46, 0.29 up 1+00:17:18 16:48:10 54 processes: 1 running, 53 sleeping Mem: 66M Active, 1174M Inact, 204M Wired, 36K Cache, 112M Buf, 555M Free Swap: 2048M Total, 2048M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 979 bind8 440 40288K 32916K select 0 0:16 0.00% named $ ps -ax|grep 979 979 ?? Ss 1:11.26 /usr/sbin/named -n 5 -t /var/named -u bind # top -bUmysql last pid: 99112; load averages: 0.22, 0.12, 0.09 up 2+06:07:05 16:17:43 132 processes: 1 running, 131 sleeping Mem: 718M Active, 2494M Inact, 455M Wired, 77M Cache, 214M Buf, 213M Free Swap: 4096M Total, 4096M Free PID USERNAME THR PRI NICE SIZERES STATE C TIME WCPU COMMAND 1079 mysql 9 200 81564K 60268K sigwai 1 0:01 0.00% mysqld ^^^ 1015 mysql 1 80 7056K 1368K wait 1 0:00 0.00% sh However mysqld time is actually # ps -ax|grep mysql 1015 con- I 0:00.01 /bin/sh /usr/local/bin/mysqld_safe --defaults-extra-file=/var/db/mysql/my.cnf 1079 con- S 70:03.64 [mysqld] ^^^ 99156 p0 S+ 0:00.00 grep mysql Anyone who can explain this? Does the behaviour change if you mount /proc? (This would mainly apply to RELENG_6 and earlier only) procfs on /proc (procfs, local) No. ___ freebsd-questions@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-questions To unsubscribe, send any mail to [EMAIL PROTECTED]
