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