miscutils/time.c

   1 /* vi: set sw=4 ts=4: */
   2 /* 'time' utility to display resource usage of processes.
   3    Copyright (C) 1990, 91, 92, 93, 96 Free Software Foundation, Inc.
   4
   5    Licensed under GPLv2, see file LICENSE in this source tree.
   6 */
   7 /* Originally written by David Keppel <pardo@cs.washington.edu>.
   8    Heavily modified by David MacKenzie <djm@gnu.ai.mit.edu>.
   9    Heavily modified for busybox by Erik Andersen <andersen@codepoet.org>
  10 */
  11 //config:config TIME
  12 //config:       bool "time"
  13 //config:       default y
  14 //config:       help
  15 //config:         The time command runs the specified program with the given arguments.
  16 //config:         When the command finishes, time writes a message to standard output
  17 //config:         giving timing statistics about this program run.
  18
  19 //usage:#define time_trivial_usage
  20 //usage:       "[-v] PROG ARGS"
  21 //usage:#define time_full_usage "\n\n"
  22 //usage:       "Run PROG, display resource usage when it exits\n"
  23 //usage:     "\n        -v      Verbose"
  24
  25 #include "libbb.h"
  26 #include <sys/resource.h> /* getrusage */
  27
  28 /* Information on the resources used by a child process.  */
  29 typedef struct {
  30         int waitstatus;
  31         struct rusage ru;
  32         unsigned elapsed_ms;    /* Wallclock time of process.  */
  33 } resource_t;
  34
  35 /* msec = milliseconds = 1/1,000 (1*10e-3) second.
  36    usec = microseconds = 1/1,000,000 (1*10e-6) second.  */
  37
  38 #define UL unsigned long
  39
  40 static const char default_format[] ALIGN1 = "real\t%E\nuser\t%u\nsys\t%T";
  41
  42 /* The output format for the -p option .*/
  43 static const char posix_format[] ALIGN1 = "real %e\nuser %U\nsys %S";
  44
  45 /* Format string for printing all statistics verbosely.
  46    Keep this output to 24 lines so users on terminals can see it all.*/
  47 static const char long_format[] ALIGN1 =
  48         "\tCommand being timed: \"%C\"\n"
  49         "\tUser time (seconds): %U\n"
  50         "\tSystem time (seconds): %S\n"
  51         "\tPercent of CPU this job got: %P\n"
  52         "\tElapsed (wall clock) time (h:mm:ss or m:ss): %E\n"
  53         "\tAverage shared text size (kbytes): %X\n"
  54         "\tAverage unshared data size (kbytes): %D\n"
  55         "\tAverage stack size (kbytes): %p\n"
  56         "\tAverage total size (kbytes): %K\n"
  57         "\tMaximum resident set size (kbytes): %M\n"
  58         "\tAverage resident set size (kbytes): %t\n"
  59         "\tMajor (requiring I/O) page faults: %F\n"
  60         "\tMinor (reclaiming a frame) page faults: %R\n"
  61         "\tVoluntary context switches: %w\n"
  62         "\tInvoluntary context switches: %c\n"
  63         "\tSwaps: %W\n"
  64         "\tFile system inputs: %I\n"
  65         "\tFile system outputs: %O\n"
  66         "\tSocket messages sent: %s\n"
  67         "\tSocket messages received: %r\n"
  68         "\tSignals delivered: %k\n"
  69         "\tPage size (bytes): %Z\n"
  70         "\tExit status: %x";
  71
  72 /* Wait for and fill in data on child process PID.
  73    Return 0 on error, 1 if ok.  */
  74 /* pid_t is short on BSDI, so don't try to promote it.  */
  75 static void resuse_end(pid_t pid, resource_t *resp)
  76 {
  77         pid_t caught;
  78
  79         /* Ignore signals, but don't ignore the children.  When wait3
  80          * returns the child process, set the time the command finished. */
  81         while ((caught = wait3(&resp->waitstatus, 0, &resp->ru)) != pid) {
  82                 if (caught == -1 && errno != EINTR) {
  83                         bb_perror_msg("wait");
  84                         return;
  85                 }
  86         }
  87         resp->elapsed_ms = monotonic_ms() - resp->elapsed_ms;
  88 }
  89
  90 static void printargv(char *const *argv)
  91 {
  92         const char *fmt = " %s" + 1;
  93         do {
  94                 printf(fmt, *argv);
  95                 fmt = " %s";
  96         } while (*++argv);
  97 }
  98
  99 /* Return the number of kilobytes corresponding to a number of pages PAGES.
 100    (Actually, we use it to convert pages*ticks into kilobytes*ticks.)
 101
 102    Try to do arithmetic so that the risk of overflow errors is minimized.
 103    This is funky since the pagesize could be less than 1K.
 104    Note: Some machines express getrusage statistics in terms of K,
 105    others in terms of pages.  */
 106 static unsigned long ptok(const unsigned pagesize, const unsigned long pages)
 107 {
 108         unsigned long tmp;
 109
 110         /* Conversion.  */
 111         if (pages > (LONG_MAX / pagesize)) { /* Could overflow.  */
 112                 tmp = pages / 1024;     /* Smaller first, */
 113                 return tmp * pagesize;  /* then larger.  */
 114         }
 115         /* Could underflow.  */
 116         tmp = pages * pagesize; /* Larger first, */
 117         return tmp / 1024;      /* then smaller.  */
 118 }
 119
 120 /* summarize: Report on the system use of a command.
 121
 122    Print the FMT argument except that `%' sequences
 123    have special meaning, and `\n' and `\t' are translated into
 124    newline and tab, respectively, and `\\' is translated into `\'.
 125
 126    The character following a `%' can be:
 127    (* means the tcsh time builtin also recognizes it)
 128    % == a literal `%'
 129    C == command name and arguments
 130 *  D == average unshared data size in K (ru_idrss+ru_isrss)
 131 *  E == elapsed real (wall clock) time in [hour:]min:sec
 132 *  F == major page faults (required physical I/O) (ru_majflt)
 133 *  I == file system inputs (ru_inblock)
 134 *  K == average total mem usage (ru_idrss+ru_isrss+ru_ixrss)
 135 *  M == maximum resident set size in K (ru_maxrss)
 136 *  O == file system outputs (ru_oublock)
 137 *  P == percent of CPU this job got (total cpu time / elapsed time)
 138 *  R == minor page faults (reclaims; no physical I/O involved) (ru_minflt)
 139 *  S == system (kernel) time (seconds) (ru_stime)
 140 *  T == system time in [hour:]min:sec
 141 *  U == user time (seconds) (ru_utime)
 142 *  u == user time in [hour:]min:sec
 143 *  W == times swapped out (ru_nswap)
 144 *  X == average amount of shared text in K (ru_ixrss)
 145    Z == page size
 146 *  c == involuntary context switches (ru_nivcsw)
 147    e == elapsed real time in seconds
 148 *  k == signals delivered (ru_nsignals)
 149    p == average unshared stack size in K (ru_isrss)
 150 *  r == socket messages received (ru_msgrcv)
 151 *  s == socket messages sent (ru_msgsnd)
 152    t == average resident set size in K (ru_idrss)
 153 *  w == voluntary context switches (ru_nvcsw)
 154    x == exit status of command
 155
 156    Various memory usages are found by converting from page-seconds
 157    to kbytes by multiplying by the page size, dividing by 1024,
 158    and dividing by elapsed real time.
 159
 160    FMT is the format string, interpreted as described above.
 161    COMMAND is the command and args that are being summarized.
 162    RESP is resource information on the command.  */
 163
 164 #ifndef TICKS_PER_SEC
 165 #define TICKS_PER_SEC 100
 166 #endif
 167
 168 static void summarize(const char *fmt, char **command, resource_t *resp)
 169 {
 170         unsigned vv_ms;     /* Elapsed virtual (CPU) milliseconds */
 171         unsigned cpu_ticks; /* Same, in "CPU ticks" */
 172         unsigned pagesize = getpagesize();
 173
 174         /* Impossible: we do not use WUNTRACED flag in wait()...
 175         if (WIFSTOPPED(resp->waitstatus))
 176                 printf("Command stopped by signal %u\n",
 177                                 WSTOPSIG(resp->waitstatus));
 178         else */
 179         if (WIFSIGNALED(resp->waitstatus))
 180                 printf("Command terminated by signal %u\n",
 181                                 WTERMSIG(resp->waitstatus));
 182         else if (WIFEXITED(resp->waitstatus) && WEXITSTATUS(resp->waitstatus))
 183                 printf("Command exited with non-zero status %u\n",
 184                                 WEXITSTATUS(resp->waitstatus));
 185
 186         vv_ms = (resp->ru.ru_utime.tv_sec + resp->ru.ru_stime.tv_sec) * 1000
 187               + (resp->ru.ru_utime.tv_usec + resp->ru.ru_stime.tv_usec) / 1000;
 188
 189 #if (1000 / TICKS_PER_SEC) * TICKS_PER_SEC == 1000
 190         /* 1000 is exactly divisible by TICKS_PER_SEC (typical) */
 191         cpu_ticks = vv_ms / (1000 / TICKS_PER_SEC);
 192 #else
 193         cpu_ticks = vv_ms * (unsigned long long)TICKS_PER_SEC / 1000;
 194 #endif
 195         if (!cpu_ticks) cpu_ticks = 1; /* we divide by it, must be nonzero */
 196
 197         while (*fmt) {
 198                 /* Handle leading literal part */
 199                 int n = strcspn(fmt, "%\\");
 200                 if (n) {
 201                         printf("%.*s", n, fmt);
 202                         fmt += n;
 203                         continue;
 204                 }
 205
 206                 switch (*fmt) {
 207 #ifdef NOT_NEEDED
 208                 /* Handle literal char */
 209                 /* Usually we optimize for size, but there is a limit
 210                  * for everything. With this we do a lot of 1-byte writes */
 211                 default:
 212                         bb_putchar(*fmt);
 213                         break;
 214 #endif
 215
 216                 case '%':
 217                         switch (*++fmt) {
 218 #ifdef NOT_NEEDED_YET
 219                 /* Our format strings do not have these */
 220                 /* and we do not take format str from user */
 221                         default:
 222                                 bb_putchar('%');
 223                                 /*FALLTHROUGH*/
 224                         case '%':
 225                                 if (!*fmt) goto ret;
 226                                 bb_putchar(*fmt);
 227                                 break;
 228 #endif
 229                         case 'C':       /* The command that got timed.  */
 230                                 printargv(command);
 231                                 break;
 232                         case 'D':       /* Average unshared data size.  */
 233                                 printf("%lu",
 234                                         (ptok(pagesize, (UL) resp->ru.ru_idrss) +
 235                                          ptok(pagesize, (UL) resp->ru.ru_isrss)) / cpu_ticks);
 236                                 break;
 237                         case 'E': {     /* Elapsed real (wall clock) time.  */
 238                                 unsigned seconds = resp->elapsed_ms / 1000;
 239                                 if (seconds >= 3600)    /* One hour -> h:m:s.  */
 240                                         printf("%uh %um %02us",
 241                                                         seconds / 3600,
 242                                                         (seconds % 3600) / 60,
 243                                                         seconds % 60);
 244                                 else
 245                                         printf("%um %u.%02us",  /* -> m:s.  */
 246                                                         seconds / 60,
 247                                                         seconds % 60,
 248                                                         (unsigned)(resp->elapsed_ms / 10) % 100);
 249                                 break;
 250                         }
 251                         case 'F':       /* Major page faults.  */
 252                                 printf("%lu", resp->ru.ru_majflt);
 253                                 break;
 254                         case 'I':       /* Inputs.  */
 255                                 printf("%lu", resp->ru.ru_inblock);
 256                                 break;
 257                         case 'K':       /* Average mem usage == data+stack+text.  */
 258                                 printf("%lu",
 259                                         (ptok(pagesize, (UL) resp->ru.ru_idrss) +
 260                                          ptok(pagesize, (UL) resp->ru.ru_isrss) +
 261                                          ptok(pagesize, (UL) resp->ru.ru_ixrss)) / cpu_ticks);
 262                                 break;
 263                         case 'M':       /* Maximum resident set size.  */
 264                                 printf("%lu", ptok(pagesize, (UL) resp->ru.ru_maxrss));
 265                                 break;
 266                         case 'O':       /* Outputs.  */
 267                                 printf("%lu", resp->ru.ru_oublock);
 268                                 break;
 269                         case 'P':       /* Percent of CPU this job got.  */
 270                                 /* % cpu is (total cpu time)/(elapsed time).  */
 271                                 if (resp->elapsed_ms > 0)
 272                                         printf("%u%%", (unsigned)(vv_ms * 100 / resp->elapsed_ms));
 273                                 else
 274                                         printf("?%%");
 275                                 break;
 276                         case 'R':       /* Minor page faults (reclaims).  */
 277                                 printf("%lu", resp->ru.ru_minflt);
 278                                 break;
 279                         case 'S':       /* System time.  */
 280                                 printf("%u.%02u",
 281                                                 (unsigned)resp->ru.ru_stime.tv_sec,
 282                                                 (unsigned)(resp->ru.ru_stime.tv_usec / 10000));
 283                                 break;
 284                         case 'T':       /* System time.  */
 285                                 if (resp->ru.ru_stime.tv_sec >= 3600) /* One hour -> h:m:s.  */
 286                                         printf("%uh %um %02us",
 287                                                         (unsigned)(resp->ru.ru_stime.tv_sec / 3600),
 288                                                         (unsigned)(resp->ru.ru_stime.tv_sec % 3600) / 60,
 289                                                         (unsigned)(resp->ru.ru_stime.tv_sec % 60));
 290                                 else
 291                                         printf("%um %u.%02us",  /* -> m:s.  */
 292                                                         (unsigned)(resp->ru.ru_stime.tv_sec / 60),
 293                                                         (unsigned)(resp->ru.ru_stime.tv_sec % 60),
 294                                                         (unsigned)(resp->ru.ru_stime.tv_usec / 10000));
 295                                 break;
 296                         case 'U':       /* User time.  */
 297                                 printf("%u.%02u",
 298                                                 (unsigned)resp->ru.ru_utime.tv_sec,
 299                                                 (unsigned)(resp->ru.ru_utime.tv_usec / 10000));
 300                                 break;
 301                         case 'u':       /* User time.  */
 302                                 if (resp->ru.ru_utime.tv_sec >= 3600) /* One hour -> h:m:s.  */
 303                                         printf("%uh %um %02us",
 304                                                         (unsigned)(resp->ru.ru_utime.tv_sec / 3600),
 305                                                         (unsigned)(resp->ru.ru_utime.tv_sec % 3600) / 60,
 306                                                         (unsigned)(resp->ru.ru_utime.tv_sec % 60));
 307                                 else
 308                                         printf("%um %u.%02us",  /* -> m:s.  */
 309                                                         (unsigned)(resp->ru.ru_utime.tv_sec / 60),
 310                                                         (unsigned)(resp->ru.ru_utime.tv_sec % 60),
 311                                                         (unsigned)(resp->ru.ru_utime.tv_usec / 10000));
 312                                 break;
 313                         case 'W':       /* Times swapped out.  */
 314                                 printf("%lu", resp->ru.ru_nswap);
 315                                 break;
 316                         case 'X':       /* Average shared text size.  */
 317                                 printf("%lu", ptok(pagesize, (UL) resp->ru.ru_ixrss) / cpu_ticks);
 318                                 break;
 319                         case 'Z':       /* Page size.  */
 320                                 printf("%u", pagesize);
 321                                 break;
 322                         case 'c':       /* Involuntary context switches.  */
 323                                 printf("%lu", resp->ru.ru_nivcsw);
 324                                 break;
 325                         case 'e':       /* Elapsed real time in seconds.  */
 326                                 printf("%u.%02u",
 327                                                 (unsigned)resp->elapsed_ms / 1000,
 328                                                 (unsigned)(resp->elapsed_ms / 10) % 100);
 329                                 break;
 330                         case 'k':       /* Signals delivered.  */
 331                                 printf("%lu", resp->ru.ru_nsignals);
 332                                 break;
 333                         case 'p':       /* Average stack segment.  */
 334                                 printf("%lu", ptok(pagesize, (UL) resp->ru.ru_isrss) / cpu_ticks);
 335                                 break;
 336                         case 'r':       /* Incoming socket messages received.  */
 337                                 printf("%lu", resp->ru.ru_msgrcv);
 338                                 break;
 339                         case 's':       /* Outgoing socket messages sent.  */
 340                                 printf("%lu", resp->ru.ru_msgsnd);
 341                                 break;
 342                         case 't':       /* Average resident set size.  */
 343                                 printf("%lu", ptok(pagesize, (UL) resp->ru.ru_idrss) / cpu_ticks);
 344                                 break;
 345                         case 'w':       /* Voluntary context switches.  */
 346                                 printf("%lu", resp->ru.ru_nvcsw);
 347                                 break;
 348                         case 'x':       /* Exit status.  */
 349                                 printf("%u", WEXITSTATUS(resp->waitstatus));
 350                                 break;
 351                         }
 352                         break;
 353
 354 #ifdef NOT_NEEDED_YET
 355                 case '\\':              /* Format escape.  */
 356                         switch (*++fmt) {
 357                         default:
 358                                 bb_putchar('\\');
 359                                 /*FALLTHROUGH*/
 360                         case '\\':
 361                                 if (!*fmt) goto ret;
 362                                 bb_putchar(*fmt);
 363                                 break;
 364                         case 't':
 365                                 bb_putchar('\t');
 366                                 break;
 367                         case 'n':
 368                                 bb_putchar('\n');
 369                                 break;
 370                         }
 371                         break;
 372 #endif
 373                 }
 374                 ++fmt;
 375         }
 376  /* ret: */
 377         bb_putchar('\n');
 378 }
 379
 380 /* Run command CMD and return statistics on it.
 381    Put the statistics in *RESP.  */
 382 static void run_command(char *const *cmd, resource_t *resp)
 383 {
 384         pid_t pid;
 385         void (*interrupt_signal)(int);
 386         void (*quit_signal)(int);
 387
 388         resp->elapsed_ms = monotonic_ms();
 389         pid = xvfork();
 390         if (pid == 0) {
 391                 /* Child */
 392                 BB_EXECVP_or_die((char**)cmd);
 393         }
 394
 395         /* Have signals kill the child but not self (if possible).  */
 396 //TODO: just block all sigs? and reenable them in the very end in main?
 397         interrupt_signal = signal(SIGINT, SIG_IGN);
 398         quit_signal = signal(SIGQUIT, SIG_IGN);
 399
 400         resuse_end(pid, resp);
 401
 402         /* Re-enable signals.  */
 403         signal(SIGINT, interrupt_signal);
 404         signal(SIGQUIT, quit_signal);
 405 }
 406
 407 int time_main(int argc, char **argv) MAIN_EXTERNALLY_VISIBLE;
 408 int time_main(int argc UNUSED_PARAM, char **argv)
 409 {
 410         resource_t res;
 411         const char *output_format = default_format;
 412         int opt;
 413
 414         opt_complementary = "-1"; /* at least one arg */
 415         /* "+": stop on first non-option */
 416         opt = getopt32(argv, "+vp");
 417         argv += optind;
 418         if (opt & 1)
 419                 output_format = long_format;
 420         if (opt & 2)
 421                 output_format = posix_format;
 422
 423         run_command(argv, &res);
 424
 425         /* Cheat. printf's are shorter :) */
 426         xdup2(STDERR_FILENO, STDOUT_FILENO);
 427         summarize(output_format, argv, &res);
 428
 429         if (WIFSTOPPED(res.waitstatus))
 430                 return WSTOPSIG(res.waitstatus);
 431         if (WIFSIGNALED(res.waitstatus))
 432                 return WTERMSIG(res.waitstatus);
 433         if (WIFEXITED(res.waitstatus))
 434                 return WEXITSTATUS(res.waitstatus);
 435         fflush_stdout_and_exit(EXIT_SUCCESS);
 436 }