Bug 76268 - lastcomm does not provide accurate information compared to /usr/bin/time
lastcomm does not provide accurate information compared to /usr/bin/time
Status: CLOSED ERRATA
Product: Red Hat Linux
Classification: Retired
Component: kernel (Show other bugs)
7.3
i686 Linux
medium Severity medium
: ---
: ---
Assigned To: Arjan van de Ven
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2002-10-18 18:21 EDT by Bob Manson
Modified: 2007-04-18 12:47 EDT (History)
1 user (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2004-01-01 04:46:36 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)

  None (edit)
Description Bob Manson 2002-10-18 18:21:20 EDT
From Bugzilla Helper:
User-Agent: Mozilla/4.77 [en] (X11; U; Linux 2.2.19-6.2.7 i686)

Description of problem:
I wrote a small progam that has nothing but loops in it
and used /usr/bin/time to see how long it ran, then used
lastcomm to check the accounting information.  The lastcomm
time is just over 5 times (perhaps 5.12 times?) larger than that
shown by /usr/bin/time

Version-Release number of selected component (if applicable):


How reproducible:
Always

Steps to Reproduce:
1.run almost any program using /usr/bin/time
2.run lastcomm and look for the entry for the program that was run
3.compare the results
	

Actual Results:  [bob@sps spin_my_wheels]$ cat spinning.c
#include <stdio.h>

main()
{
        int i,j,k;
        for(i=0; i < 10; i++)
        {
                fprintf(stderr,"iter=%d\n", i);
                for(j=0; j < 1000; j++)
                {
                        for(k=0; k < 100000; k++)
                                ;
                }
        }
}
------------------------------------------------------
[bob@sps spin_my_wheels]$ /usr/bin/time ./spinning
iter=0
iter=1
iter=2
iter=3
iter=4
iter=5
iter=6
iter=7
iter=8
iter=9
Command exited with non-zero status 100
2.33user 0.00system 0:02.34elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (85major+9minor)pagefaults 0swaps
-------------------------------------------------------
[bob@sps spin_my_wheels]$ lastcomm | grep spinning
spinning                bob      stdin     11.98 secs Fri Oct 18 18:12

[bob@sps spin_my_wheels]$ uname -a
Linux sps.ecf 2.4.18-17.7.x #1 Tue Oct 8 13:33:14 EDT 2002 i686 unknown




Expected Results:  I expected the lastcomm time to be closer to 2.3 seconds.

Additional info:

Running on a Dell Optiplex GX260.

I'm always suspicious when something wierd happens and I see something
so close to a magic number (i.e. looks like 512/100):

[bob@sps spin_my_wheels]$ dc
5k
11.98 2.34 / p
5.11965
Comment 1 Mike A. Harris 2002-10-18 19:51:24 EDT
What CPU do you have?  Also, what kernel arch is running?

rpm -q $(rpm -qa | grep ^kernel) --qf '%{name}-%{version}-%{release}.%{arch}\n'

Also, what does this show:  cat /proc/version
Comment 2 Mike A. Harris 2002-10-18 20:56:41 EDT
I believe this is an issue occuring due to the kernel using
Hz=512, and the program likely assuming Hz=100.  I still need
the information requested above however.

So, it's either a bug in the app making a bad assumption, or
else the kernel not scaling the data to Hz before spewing to
logfiles.

CC'ing Arjan for comment.
Comment 3 Bob Manson 2002-10-19 10:05:38 EDT
You'll noticed that I previously installed a rawhide kernel on this machine (to
overcome the dma problems with this machine) and I wonder if something I else I
installed at the same time as that kernel could be causing this?

From dmesg:
CPU: Intel(R) Pentium(R) 4 CPU 1.80GHz stepping 04

bash-2.05a$ rpm -q $(rpm -qa | grep ^kernel) --qf
'%{name}-%{version}-%{release}.%{arch}\n'
kernel-doc-2.4.18-10.i386
kernel-2.4.18-17.7.x.i686
kernel-2.4.18-10.98.i686
kernel-2.4.18-14.i686
kernel-source-2.4.18-10.i386

bash-2.05a$ cat /proc/version
Linux version 2.4.18-17.7.x (bhcompile@daffy.perf.redhat.com) (gcc version 2.96
20000731 (Red Hat Linux 7.3 2.96-11
2)) #1 Tue Oct 8 13:33:14 EDT 2002

bash-2.05a$ rpm -q psacct
psacct-6.3.2-19
Comment 4 Mike A. Harris 2002-11-13 16:30:54 EST
This looks like a kernel Hz bug.  Reassigning to kernel component.

Note You need to log in before you can comment on or make changes to this bug.