top incorrectly reporting process time

[Mel]

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- S    582: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.