Bug 527276 - time reports ?%CPU on a faster machine
Summary: time reports ?%CPU on a faster machine
Keywords:
Status: CLOSED RAWHIDE
Alias: None
Product: Fedora
Classification: Fedora
Component: time
Version: 14
Hardware: All
OS: Linux
low
medium
Target Milestone: ---
Assignee: Petr Pisar
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2009-10-05 17:21 UTC by H.J. Lu
Modified: 2011-05-11 16:15 UTC (History)
1 user (show)

Fixed In Version: time-1.7-39.fc16
Clone Of:
Environment:
Last Closed: 2011-05-11 16:15:41 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)
A patch (1.74 KB, patch)
2009-10-05 17:25 UTC, H.J. Lu
no flags Details | Diff

Description H.J. Lu 2009-10-05 17:21:03 UTC
On a very fast machine, I got

[hjl@gnu-34 simple]$ /usr/bin/time ./simple

Hello world
0.00user 0.00system 0:00.00elapsed ?%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+29minor)pagefaults 0swaps

resp->ru reports:

$10 = {ru_utime = {tv_sec = 0, tv_usec = 0}, ru_stime = {tv_sec = 0, 
    tv_usec = 999}, ru_maxrss = 0, ru_ixrss = 0, ru_idrss = 0, ru_isrss = 0, 
  ru_minflt = 23, ru_majflt = 0, ru_nswap = 0, ru_inblock = 0, ru_oublock = 0, 
  ru_msgsnd = 0, ru_msgrcv = 0, ru_nsignals = 0, ru_nvcsw = 1, ru_nivcsw = 6}
(gdb) c

and resp->elapsed reports:

$7 = {tv_sec = 0, tv_usec = 318}

Since summarize in time.c has:

  r = resp->elapsed.tv_sec * 1000 + resp->elapsed.tv_usec / 1000;

  v = resp->ru.ru_utime.tv_sec * 1000 + resp->ru.ru_utime.TV_MSEC +
    resp->ru.ru_stime.tv_sec * 1000 + resp->ru.ru_stime.TV_MSEC;

we get r == 0 and v == 0. Later,

            case 'P':           /* Percent of CPU this job got.  */
              /* % cpu is (total cpu time)/(elapsed time).  */
              if (r > 0)
                fprintf (fp, "%lu%%", (v * 100 / r));
              else
                fprintf (fp, "?%%");
              break;

Comment 1 H.J. Lu 2009-10-05 17:25:15 UTC
Created attachment 363719 [details]
A patch

Comment 2 Bug Zapper 2010-04-28 10:42:37 UTC
This message is a reminder that Fedora 11 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 11.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '11'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 11's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 11 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 3 Fedora Admin XMLRPC Client 2010-07-19 15:34:24 UTC
This package has changed ownership in the Fedora Package Database.  Reassigning to the new owner of this component.

Comment 4 Bug Zapper 2010-07-30 10:44:54 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 14 development cycle.
Changing version to '14'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 5 Petr Pisar 2011-05-11 16:00:38 UTC
This patch does not help pretty much because getrusage() returns time usage in 1000 us precision. See patched version:

 $ ./time -f %P ../a.out 800
elapsed.tv_sec = 0, elapsed.tv_usec=959
utime.tv_sec = 0, utime.tv_usec=0
stime.tv_sec = 0, stime.tv_usec=0
ru = 959, vu=0
0%
petr@dhcp-0-146:~/time/time-1.7-fedora $ ./time -f %P ../a.out 800
elapsed.tv_sec = 0, elapsed.tv_usec=1130
utime.tv_sec = 0, utime.tv_usec=0
stime.tv_sec = 0, stime.tv_usec=999
0%

The upper case hits proposed microsecond recalculation but because of Linux/glibc it always (ok., almost) returns 0.

The bottom case shows old milisecond path. You can also see how the ratio is inaccurate (shows 0%, should be much higher). There is more work needed to get better values (e.g. use microsecond resolution if it would not overflow long int variable types).

Also division near to zero introduces rounding errors per se and the question mark is good signal for that.

Despite that I will merge the patch into F16 because it does not make things worse.


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