miscutils/time.c

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