Hi,
This patch adds tracking of total execution (real) time for all commands
executed in an interactive ksh instance. I find it useful as an automatic,
simple poor-man's means of profiling as-i-go (and just informative). I
personally have a couple ksh functions to toggle showing this info in my prompt.
It works by calling clock_gettime(2) before/after each command line is executed
(encompassing pipes/&&'s/etc), using a monotonic clock. This is for interactive
shells only. See the first caveat below about the impact of this.
The information collected is exposed in two ways:
1. A new parameter named $NANOSECONDS, exposing the number of nanoseconds for
the previous commands (0 on startup). An interactive ksh can just display
this, or format it as desired (in the prompt or otherwise).
2. A new escape character supported in prompts/PS1, "\x". This sequence is
expanded to a human-readable form, showing the two most significant units
measured (where the units are, in decreasing order of significance: minutes,
seconds, milliseconds, microseconds, nanoseconds). See caveat 2 below for
comments on this.
I've tested by running on my laptop and a couple home machines (all amd64) for
a couple weeks now, and tested batch scripts to ensure the behavior isn't
present there (this only impacts interactive shells).
Caveats:
1. This type of tracking can still delay commands roughly 10 msec according to
documentation and some rudimentary tests. I'd prefer using getnanotime(9),
since absolute accuracy isn't required for this case, but that's not exposed
outside the kernel. None the less, the impact isn't noticeable on the
machines I've tested, including a 15 year old laptop.
2. The current format of "\x" is debatable, and I'm open to suggestions. Or even
removing it. Exposing this info via $NANOSECONDS is sufficient for most
cases, allowing a user to customize it.
Any interest in adopting this?
Feedback welcome.
-Ryan
Index: ksh.1
===================================================================
RCS file: /cvs/src/bin/ksh/ksh.1,v
retrieving revision 1.201
diff -u -p -u -p -r1.201 ksh.1
--- ksh.1 18 Jun 2018 17:03:58 -0000 1.201
+++ ksh.1 27 Nov 2018 05:20:00 -0000
@@ -1499,6 +1499,13 @@ The index of the next argument to be pro
Assigning 1 to this parameter causes
.Ic getopts
to process arguments from the beginning the next time it is invoked.
+.It Ev NANOSECONDS
+The number of nanoseconds spent executing the previously executed command in
+an interactive shell.
+This time is measured by calling
+.Xr clock_gettime 2
+with a monotonic clock, before and after each command execution, and
+measuring the difference.
.It Ev PATH
A colon separated list of directories that are searched when looking for
commands and files sourced using the
@@ -1581,6 +1588,13 @@ Insert a carriage return character.
The name of the shell.
.It Li \et
The current time, in 24-hour HH:MM:SS format.
+.It Li \ex
+The execution time of the previous command, including the 2 most significant
+units of measurement (in order: minutes (m), seconds(s), milliseconds (ms),
+microseconds (µs), and nanoseconds (ns).
+The parameter
+.Ev NANOSECONDS
+can be leveraged to customize this display.
.It Li \eT
The current time, in 12-hour HH:MM:SS format.
.It Li \e@
Index: lex.c
===================================================================
RCS file: /cvs/src/bin/ksh/lex.c,v
retrieving revision 1.78
diff -u -p -u -p -r1.78 lex.c
--- lex.c 15 Jan 2018 14:58:05 -0000 1.78
+++ lex.c 27 Nov 2018 05:20:00 -0000
@@ -9,6 +9,7 @@
#include <libgen.h>
#include <stdio.h>
#include <string.h>
+#include <time.h>
#include <unistd.h>
#include "sh.h"
@@ -102,6 +103,8 @@ char **history; /* saved commands */
char **histptr; /* last history item */
uint32_t histsize; /* history size */
+extern struct timespec cmd_start_time, cmd_end_time, cmd_exec_time;
+
/* optimized getsc_bn() */
#define getsc() (*source->str != '\0' && *source->str != '\\' \
&& !backslash_skip ? *source->str++ : getsc_bn())
@@ -1373,6 +1376,9 @@ dopprompt(const char *sp, int ntruncate,
} else
strlcpy(strbuf, basename(p), sizeof
strbuf);
break;
+ case 'x': /* '\' 'x' execution time */
+ expand_execution_time(strbuf, sizeof strbuf);
+ break;
case '!': /* '\' '!' history line number */
snprintf(strbuf, sizeof strbuf, "%d",
source->line + 1);
@@ -1665,4 +1671,25 @@ pop_state_(State_info *si, Lex_state *ol
afree(old_base, ATEMP);
return si->base + STATE_BSIZE - 1;
+}
+
+void
+expand_execution_time(char *buf, int bufsz)
+{
+ long nanos = cmd_exec_time.tv_nsec % 1000;
+ long micros = cmd_exec_time.tv_nsec / 1000 % 1000;
+ long millis = cmd_exec_time.tv_nsec / 1000000;
+ time_t seconds = cmd_exec_time.tv_sec % 60;
+ time_t minutes = cmd_exec_time.tv_sec / 60;
+
+ if (minutes > 0)
+ snprintf(buf, bufsz, "%llum %llus", minutes, seconds);
+ else if (seconds > 0)
+ snprintf(buf, bufsz, "%llus %ldms", seconds, millis);
+ else if (millis > 0)
+ snprintf(buf, bufsz, "%ldms %ldµs", millis, micros);
+ else if (micros > 0)
+ snprintf(buf, bufsz, "%ldµs %ldns", micros, nanos);
+ else
+ snprintf(buf, bufsz, "%ldns", nanos);
}
Index: lex.h
===================================================================
RCS file: /cvs/src/bin/ksh/lex.h,v
retrieving revision 1.21
diff -u -p -u -p -r1.21 lex.h
--- lex.h 15 Jan 2018 14:58:05 -0000 1.21
+++ lex.h 27 Nov 2018 05:20:00 -0000
@@ -117,3 +117,4 @@ void yyerror(const char *, ...)
Source * pushs(int, Area *);
void set_prompt(int);
void pprompt(const char *, int);
+void expand_execution_time(char *, int);
Index: main.c
===================================================================
RCS file: /cvs/src/bin/ksh/main.c,v
retrieving revision 1.96
diff -u -p -u -p -r1.96 main.c
--- main.c 20 Nov 2018 07:02:23 -0000 1.96
+++ main.c 27 Nov 2018 05:20:00 -0000
@@ -13,6 +13,7 @@
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
+#include <time.h>
#include <unistd.h>
#include "sh.h"
@@ -71,6 +72,8 @@ int current_wd_size;
int x_cols = 80;
+struct timespec cmd_start_time, cmd_end_time, cmd_exec_time;
+
/*
* shell initialization
*/
@@ -548,8 +551,16 @@ shell(Source *volatile s, volatile int t
int i;
newenv(E_PARSE);
- if (interactive)
+ if (interactive) {
really_exit = 0;
+
+ /* Initialize command execution timers to all zero */
+ timespecclear(&cmd_start_time);
+ timespecclear(&cmd_end_time);
+ timespecclear(&cmd_exec_time);
+ setint(global("NANOSECONDS"), 0);
+ }
+
i = sigsetjmp(genv->jbuf, 0);
if (i) {
switch (i) {
@@ -631,8 +642,27 @@ shell(Source *volatile s, volatile int t
}
}
- if (t && (!Flag(FNOEXEC) || (s->flags & SF_TTY)))
+ if (t && (!Flag(FNOEXEC) || (s->flags & SF_TTY))) {
+ if (interactive)
+ clock_gettime(CLOCK_MONOTONIC, &cmd_start_time);
+
exstat = execute(t, 0, NULL);
+
+ if (interactive) {
+ /*
+ * Calculate the time spent executing the
+ * command and updat ehte NANOSECONDS parameter
+ * accordingly. Note rollover could happen if
+ * the command took > 292 years to execute.
+ */
+ clock_gettime(CLOCK_MONOTONIC, &cmd_end_time);
+ timespecsub(&cmd_end_time, &cmd_start_time,
+ &cmd_exec_time);
+ setint(global("NANOSECONDS"),
+ cmd_exec_time.tv_sec * 1e9
+ + cmd_exec_time.tv_nsec);
+ }
+ }
if (t != NULL && t->type != TEOF && interactive && really_exit)
really_exit = 0;
Index: table.h
===================================================================
RCS file: /cvs/src/bin/ksh/table.h,v
retrieving revision 1.15
diff -u -p -u -p -r1.15 table.h
--- table.h 18 Jun 2018 17:03:58 -0000 1.15
+++ table.h 27 Nov 2018 05:20:00 -0000
@@ -171,6 +171,7 @@ extern const struct builtin shbuiltins [
#define V_TMPDIR 17
#define V_LINENO 18
#define V_TERM 19
+#define V_NANOSECONDS 20
/* values for set_prompt() */
#define PS1 0 /* command */
