Take the 2-minute tour ×
Unix & Linux Stack Exchange is a question and answer site for users of Linux, FreeBSD and other Un*x-like operating systems.. It's 100% free, no registration required.

This might be a basic question, but I am getting hard time finding an answer to it. I am using RHEL6. After running any process that takes significant cpu time, I get a line that tells (I guess) the run-time and IO usage automatically. It reads like:

77410.101u 124.968s 1:42:43.49 657.9%    0+0k 0+1353384io 0pf+0w

I have the following questions:

  1. How do I interpret each field in this message? I can guess some time,IO usage and may be CPU usage ... but I am not sure.
  2. What actually prints this line? Is it the shell? Is it the terminal emulator? Is there a running daemon taking care of that? What is the name of this feature/service/whatever it is.
  3. Is it possible to control this message? Like set the cpu usage threshold for printing it?
  4. Can I add extra information to it? Like the absolute path of the process, peak memory usage, peak disk usage, etc ...
share|improve this question
add comment

1 Answer

up vote 5 down vote accepted

Tip for debugging what's going on

I would suggest turning on the debug facility of your shell, assuming you're using Bash.

$ set -x

This output will show you what's happening behind the scenes when you run a command that produces this output.

The output

That output is from the time /usr/bin/time command being prefixed to every command you run. In order to get that output, I'm guessing you're using either C-shell (csh) or Turbo C-shell (tcsh).

Example

$ tcsh
$ time sleep 2
0.000u 0.000s 0:02.00 0.0%  0+0k 0+0io 0pf+0w

The reason I suspect this is a tcsh shell is that when I run the command /usr/bin/time in a Bash shell the output looks like this:

$ /usr/bin/time sleep 2
0.00user 0.00system 0:02.02elapsed 0%CPU (0avgtext+0avgdata 580maxresident)k
0inputs+0outputs (0major+180minor)pagefaults 0swaps

The output can be controlled using the -f or --format switch, so the output you're seeing could be achieved in Bash as well, but would have to be done intentionally.

Meaning of output

If you run the command /usr/bin/time in verbose mode, (-v) you'll get all the details about each field like this:

$ /usr/bin/time -v sleep 2
    Command being timed: "sleep 2"
    User time (seconds): 0.00
    System time (seconds): 0.00
    Percent of CPU this job got: 0%
    Elapsed (wall clock) time (h:mm:ss or m:ss): 0:02.00
    Average shared text size (kbytes): 0
    Average unshared data size (kbytes): 0
    Average stack size (kbytes): 0
    Average total size (kbytes): 0
    Maximum resident set size (kbytes): 584
    Average resident set size (kbytes): 0
    Major (requiring I/O) page faults: 0
    Minor (reclaiming a frame) page faults: 184
    Voluntary context switches: 2
    Involuntary context switches: 4
    Swaps: 0
    File system inputs: 0
    File system outputs: 0
    Socket messages sent: 0
    Socket messages received: 0
    Signals delivered: 0
    Page size (bytes): 4096
    Exit status: 0

If you line up the original output:

77410.101u 124.968s 1:42:43.49 657.9%    0+0k 0+1353384io 0pf+0w
^^^^^^^^^^ ^^^^^^^^ ^^^^^^^^^^ ^^^^^^    ^^^^ ^^^^^^^^^^^ ^^^^^^
     1        2         3       4         5        6        7
  1. User time (seconds)
  2. System time (seconds)
  3. Elapsed (wall clock) time (h:mm:ss or m:ss)
  4. Percent of CPU this job got
  5. Average shared text size (kbytes) + Average unshared data size (kbytes)
  6. Number of file system inputs by the process + Number of file system outputs by the process
  7. Number of major page faults that occurred while the process was running. These are faults where the page has to be read in from disk + Number of times the process was swapped out of main memory

You can manually do the same format like this:

$ /usr/bin/time -f '%Uu %Ss %E %P %X+%Dk %I+%Oio %Fpf+%Ww' sleep 2
0.00u 0.00s 0:02.00 0% 0+0k 0+0io 0pf+0w

Customizing the output

Once you're able to determine where the call to /usr/bin/time is being made you can customize the output by taking a peak at the man page for time. There are lots of options that can be included in this output.

$ man time

excerpt

   Time
   %E     Elapsed real time (in [hours:]minutes:seconds).
   %e     (Not in tcsh.) Elapsed real time (in seconds).
   %S     Total number of CPU-seconds that the process spent in kernel mode.
   %U     Total number of CPU-seconds that the process spent in user mode.
   %P     Percentage of the CPU that this job got, computed as (%U + %S) / %E.

   Memory
   %M     Maximum resident set size of the process during its lifetime, in Kbytes.
   %t     (Not in tcsh.) Average resident set size of the process, in Kbytes.
   %K     Average total (data+stack+text) memory use of the process, in Kbytes.
   %D     Average size of the process's unshared data area, in Kbytes.
   %p     (Not in tcsh.) Average size of the process's unshared stack space, in Kbytes.
   %X     Average size of the process's shared text space, in Kbytes.
   %Z     (Not in tcsh.) System's page size, in bytes.  This is a per-system constant, but varies between systems.
   %F     Number  of major page faults that occurred while the process was running.  These are faults where the page has to be read
          in from disk.
   %R     Number of minor, or recoverable, page faults.  These are faults for pages that are not valid but which have not yet  been
          claimed by other virtual pages.  Thus the data in the page is still valid but the system tables must be updated.
   %W     Number of times the process was swapped out of main memory.
   %c     Number of times the process was context-switched involuntarily (because the time slice expired).
   %w     Number of waits: times that the program was context-switched voluntarily, for instance while waiting for an I/O operation
          to complete.

   I/O
   %I     Number of file system inputs by the process.
   %O     Number of file system outputs by the process.
   %r     Number of socket messages received by the process.
   %s     Number of socket messages sent by the process.
   %k     Number of signals delivered to the process.
   %C     (Not in tcsh.) Name and command-line arguments of the command being timed.
   %x     (Not in tcsh.) Exit status of the command.

See the man page for more details.

EDIT #1: Your issue

Turns out your question about the output being shown automatically is being caused by the setting of this environment variable in csh/tcsh.

from the tcsh man page

   The time shell variable can be set to execute the time builtin command 
     after the completion of any process that takes more  than a given number 
     of CPU seconds.

Example

Set the time to 5 seconds.

$ set time=5

Confirm:

$ set|grep time
time    5

Test it out:

$ bash -c "while [ 1 ];do echo hi; done"
hi
hi
...
...waited ~5 seconds, then Ctrl-C to stop it

5.650u 1.471s 0:09.68 73.5% 0+0k 0+0io 0pf+0w

The output will only show up if the task you're running consumes more than the number of seconds of the CPU time set by the variable $time.

References

share|improve this answer
    
Just for completeness: time is a builtin in bash as well, and its output differs from /usr/bin/time (real, user,sys over three lines). –  Ulrich Schwarz Oct 14 '13 at 5:11
    
@Bichoy - take a look at the update. Figured out what was printing your time outout. –  slm Oct 15 '13 at 1:12
    
Thanks @slm for thorough explanation and the edit. Indeed this perfectly answered my question. Thanks! –  Bichoy Oct 15 '13 at 2:17
    
@Bichoy - you're quite welcome. Thanks for the Q. I didn't know any of this before so your Q actually taught me something new too 8-). –  slm Oct 15 '13 at 2:21
add comment

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.