ksh patch to add execution time tracking in interactive shells
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 - 1.201
+++ ksh.1 27 Nov 2018 05:20:00 -
@@ -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 - 1.78
+++ lex.c 27 Nov 2018 05:20:00 -
@@ -9,6 +9,7 @@
#include
#include
#include
+#include
#include
#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)
+{
+ longnanos = cmd_exec_time.tv_nsec % 1000;
+ longmicros =
Re: wdc polling lead to unclean fs and panics
Hi,
Was anybody able to reproduce the bug I am running into?
Did these changes also help?
Thanks,
mbuhl
> On 4. Oct 2018, at 13:16, Moritz Buhl wrote:
>
> Hi,
>
> when rebooting a PowerBook G4, the kernel sometimes paniced while
> detaching the disk.
> Additionallly, during boot it was noted that / is not clean.
> The following patch special cases polling to not return early anymore
> and adds polling to all previous elements in the queue.
> Please tell me if this is not the right way to address the problem.
>
> Thanks,
> mbuhl
>
> Index: dev/ic/wdc.c
> ===
> RCS file: /cvs/src/sys/dev/ic/wdc.c,v
> retrieving revision 1.134
> diff -u -p -r1.134 wdc.c
> --- dev/ic/wdc.c 30 Dec 2017 23:08:29 - 1.134
> +++ dev/ic/wdc.c 2 Oct 2018 14:01:04 -
> @@ -888,7 +888,8 @@ wdcstart(struct channel_softc *chp)
> /* adjust chp, in case we have a shared queue */
> chp = xfer->chp;
>
> - if ((chp->ch_flags & WDCF_ACTIVE) != 0 ) {
> + if ((chp->ch_flags & WDCF_ACTIVE) != 0 &&
> + (xfer->c_flags & C_POLL) == 0) {
> return; /* channel already active */
> }
> #ifdef DIAGNOSTIC
> @@ -1905,6 +1906,7 @@ wdccommandshort(struct channel_softc *ch
> void
> wdc_exec_xfer(struct channel_softc *chp, struct wdc_xfer *xfer)
> {
> + struct wdc_xfer *iter;
> WDCDEBUG_PRINT(("wdc_exec_xfer %p flags 0x%x channel %d drive %d\n",
> xfer, xfer->c_flags, chp->channel, xfer->drive), DEBUG_XFERS);
>
> @@ -1918,7 +1920,8 @@ wdc_exec_xfer(struct channel_softc *chp,
>*/
> if ((xfer->c_flags & C_POLL) != 0 &&
> !TAILQ_EMPTY(>ch_queue->sc_xfer)) {
> - TAILQ_INIT(>ch_queue->sc_xfer);
> + TAILQ_FOREACH(iter, >ch_queue->sc_xfer, c_xferchain)
> + iter->c_flags |= C_POLL;
> }
> /* insert at the end of command list */
> TAILQ_INSERT_TAIL(>ch_queue->sc_xfer,xfer , c_xferchain);
>
Re: option kcov + GENERIC.MP -> silent crash
On Mon, Nov 26, 2018 at 08:43:12AM -0800, Greg Steuck wrote:
> Thanks for the patch, I'll give it a go. Should I make up a patch reporting
> #error when trying to build kcov with MP in the meantime? The next person
> won't have to find it the hard way...
Please try out the diff first. I'd rather try coming up with a proper
fix before adding any #error directives.
>
> On Sun, Nov 25, 2018 at 11:21 PM Anton Lindqvist wrote:
>
> > Hi Greg,
> >
> > On Sun, Nov 25, 2018 at 10:13:52AM -0800, Greg Steuck wrote:
> > > Hi Anton,
> > >
> > > I tried to boot a kernel with kcov based on GENERIC.MP and the machine
> > > reboots without a peep immediately after
> > >
> > > vmm0 at mainbus0: VMX (using slow L1TF mitigation)
> > >
> > > Switching off either of kcov or MP results in normally working kernels.
> > I'm
> > > attaching two concatenated dmesgs. The effect is reproducible on real HW
> > > and on GCE VM. Broken config is just:
> > > $ cat /sys/arch/amd64/conf/SYZKALLER
> > > include "arch/amd64/conf/GENERIC.MP"
> > > pseudo-device kcov 1
> > >
> > > Disabling either vmm or kcov in broken kernel UKC doesn't prevent
> > crashes.
> >
> > Known limitation, I haven't spent much time on making kcov MP-safe.
> > Especially since it's primarily used inside a VM through vmm which
> > currently is limited to a single CPU.
> >
> > However, I did some investigation before and concluded that the problem
> > resides in the trace routine which is called from
> > cpu_boot_secondary_processors() before the secondary CPU is accessible
> > through curcpu(). I came up with a hackish solution to this problem (see
> > diff below) that got rejected; kettenis@ mentioned that we instead
> > should set MSR_GSBASE earlier in cpu_hatch() but I never managed to get
> > the right people involved with knowledge in this area. I might take a
> > look myself.
> >
> > In the meantime, you could give the diff a try. It might be the case
> > that more functions are not eligible for tracing. OpenBSD as no method
> > of turning of tracing for a given source file like Linux does. This
> > might become necessary since I fear many more functions will not cope
> > with tracing.
> >
> > Index: dev/kcov.c
> > ===
> > RCS file: /cvs/src/sys/dev/kcov.c,v
> > retrieving revision 1.4
> > diff -u -p -r1.4 kcov.c
> > --- dev/kcov.c 27 Aug 2018 15:57:39 - 1.4
> > +++ dev/kcov.c 8 Sep 2018 21:51:20 -
> > @@ -49,6 +49,7 @@ struct kcov_dev {
> > };
> >
> > void kcovattach(int);
> > +void kcov_attachhook(struct device *);
> >
> > int kd_alloc(struct kcov_dev *, unsigned long);
> > void kd_free(struct kcov_dev *);
> > @@ -57,6 +58,7 @@ struct kcov_dev *kd_lookup(int);
> > static inline int inintr(void);
> >
> > TAILQ_HEAD(, kcov_dev) kd_list = TAILQ_HEAD_INITIALIZER(kd_list);
> > +int kcov_attached = 0;
> >
> > #ifdef KCOV_DEBUG
> > int kcov_debug = 1;
> > @@ -76,12 +78,11 @@ int kcov_debug = 1;
> > void
> > __sanitizer_cov_trace_pc(void)
> > {
> > - extern int cold;
> > struct kcov_dev *kd;
> > uint64_t idx;
> >
> > - /* Do not trace during boot. */
> > - if (cold)
> > + /* Do not trace before the root file system is mounted. */
> > + if (!kcov_attached)
> > return;
> >
> > /* Do not trace in interrupts to prevent noisy coverage. */
> > @@ -102,6 +103,13 @@ __sanitizer_cov_trace_pc(void)
> > void
> > kcovattach(int count)
> > {
> > + config_mountroot(NULL, kcov_attachhook);
> > +}
> > +
> > +void
> > +kcov_attachhook(struct device *dev)
> > +{
> > + kcov_attached = 1;
> > }
> >
> > int
> >
>
>
> --
> nest.cx is Gmail hosted, use PGP for anything private. Key:
> http://goo.gl/6dMsr
> Fingerprint: 5E2B 2D0E 1E03 2046 BEC3 4D50 0B15 42BD 8DF5 A1B0
Re: xidle: parse options once, simplify code
On Sun, Nov 11, 2018 at 06:07:10PM +0100, Klemens Nanni wrote:
> There's no point in parsing `-display' separately, just do it once and
> simplify the code while here.
>
> This addresses two of cheloha's comments from my strtonum diff.
Ping.
Feedback? OK?
Index: xidle.c
===
RCS file: /cvs/xenocara/app/xidle/xidle.c,v
retrieving revision 1.8
diff -u -p -r1.8 xidle.c
--- xidle.c 11 Nov 2018 16:10:37 - 1.8
+++ xidle.c 26 Nov 2018 17:37:30 -
@@ -75,13 +75,10 @@ struct xinfo {
struct xinfo x;
-static XrmOptionDescRec fopts[] = {
- { "-display", ".display", XrmoptionSepArg,(caddr_t)NULL },
-};
-
static XrmOptionDescRec opts[] = {
{ "-area", ".area",XrmoptionSepArg,(caddr_t)NULL },
{ "-delay", ".delay", XrmoptionSepArg,(caddr_t)NULL },
+ { "-display", ".display", XrmoptionSepArg,(caddr_t)NULL },
{ "-program", ".program", XrmoptionSepArg,(caddr_t)NULL },
{ "-timeout", ".timeout", XrmoptionSepArg,(caddr_t)NULL },
@@ -263,37 +260,25 @@ parse_opts(int argc, char **argv, Displa
XrmInitialize();
- /* Get display to open. */
- XrmParseCommand(, fopts, sizeof(fopts) / sizeof(fopts[0]),
+ /* Get command line values. */
+ XrmParseCommand(, opts, sizeof(opts) / sizeof(opts[0]),
__progname, , argv);
+ if (argc > 1)
+ usage();
- display = (getres(, rdb, "display", "Display") == True) ?
- (char *)value.addr : NULL;
+ display = getres(, rdb, "display", "Display") ? value.addr : NULL;
- *dpy = XOpenDisplay(display);
- if (!*dpy) {
+ if (!(*dpy = XOpenDisplay(display)))
errx(1, "Unable to open display %s", XDisplayName(display));
- }
- /* Get server resources database. */
- p = XResourceManagerString(*dpy);
- if (!p) {
- /* Get screen resources database. */
- p = XScreenResourceString(ScreenOfDisplay(*dpy,
- DefaultScreen(*dpy)));
- }
-
- if (p) {
+ /* Get resources database. */
+ if ((p = XResourceManagerString(*dpy)) ||
+ (p = XScreenResourceString(ScreenOfDisplay(*dpy,
+ DefaultScreen(*dpy) {
tdb = XrmGetStringDatabase(p);
XrmMergeDatabases(tdb, );
}
- /* Get remaining command line values. */
- XrmParseCommand(, opts, sizeof(opts) / sizeof(opts[0]),
- __progname, , argv);
- if (argc > 1) {
- usage();
- }
if (getres(, rdb, "area", "Area")) {
*area = strtonum(value.addr, 1, INT_MAX, );
if (errstr)
===
Stats: --- 26 lines 719 chars
Stats: +++ 11 lines 451 chars
Stats: -15 lines
Stats: -268 chars
Re: option kcov + GENERIC.MP -> silent crash
Thanks for the patch, I'll give it a go. Should I make up a patch reporting
#error when trying to build kcov with MP in the meantime? The next person
won't have to find it the hard way...
On Sun, Nov 25, 2018 at 11:21 PM Anton Lindqvist wrote:
> Hi Greg,
>
> On Sun, Nov 25, 2018 at 10:13:52AM -0800, Greg Steuck wrote:
> > Hi Anton,
> >
> > I tried to boot a kernel with kcov based on GENERIC.MP and the machine
> > reboots without a peep immediately after
> >
> > vmm0 at mainbus0: VMX (using slow L1TF mitigation)
> >
> > Switching off either of kcov or MP results in normally working kernels.
> I'm
> > attaching two concatenated dmesgs. The effect is reproducible on real HW
> > and on GCE VM. Broken config is just:
> > $ cat /sys/arch/amd64/conf/SYZKALLER
> > include "arch/amd64/conf/GENERIC.MP"
> > pseudo-device kcov 1
> >
> > Disabling either vmm or kcov in broken kernel UKC doesn't prevent
> crashes.
>
> Known limitation, I haven't spent much time on making kcov MP-safe.
> Especially since it's primarily used inside a VM through vmm which
> currently is limited to a single CPU.
>
> However, I did some investigation before and concluded that the problem
> resides in the trace routine which is called from
> cpu_boot_secondary_processors() before the secondary CPU is accessible
> through curcpu(). I came up with a hackish solution to this problem (see
> diff below) that got rejected; kettenis@ mentioned that we instead
> should set MSR_GSBASE earlier in cpu_hatch() but I never managed to get
> the right people involved with knowledge in this area. I might take a
> look myself.
>
> In the meantime, you could give the diff a try. It might be the case
> that more functions are not eligible for tracing. OpenBSD as no method
> of turning of tracing for a given source file like Linux does. This
> might become necessary since I fear many more functions will not cope
> with tracing.
>
> Index: dev/kcov.c
> ===
> RCS file: /cvs/src/sys/dev/kcov.c,v
> retrieving revision 1.4
> diff -u -p -r1.4 kcov.c
> --- dev/kcov.c 27 Aug 2018 15:57:39 - 1.4
> +++ dev/kcov.c 8 Sep 2018 21:51:20 -
> @@ -49,6 +49,7 @@ struct kcov_dev {
> };
>
> void kcovattach(int);
> +void kcov_attachhook(struct device *);
>
> int kd_alloc(struct kcov_dev *, unsigned long);
> void kd_free(struct kcov_dev *);
> @@ -57,6 +58,7 @@ struct kcov_dev *kd_lookup(int);
> static inline int inintr(void);
>
> TAILQ_HEAD(, kcov_dev) kd_list = TAILQ_HEAD_INITIALIZER(kd_list);
> +int kcov_attached = 0;
>
> #ifdef KCOV_DEBUG
> int kcov_debug = 1;
> @@ -76,12 +78,11 @@ int kcov_debug = 1;
> void
> __sanitizer_cov_trace_pc(void)
> {
> - extern int cold;
> struct kcov_dev *kd;
> uint64_t idx;
>
> - /* Do not trace during boot. */
> - if (cold)
> + /* Do not trace before the root file system is mounted. */
> + if (!kcov_attached)
> return;
>
> /* Do not trace in interrupts to prevent noisy coverage. */
> @@ -102,6 +103,13 @@ __sanitizer_cov_trace_pc(void)
> void
> kcovattach(int count)
> {
> + config_mountroot(NULL, kcov_attachhook);
> +}
> +
> +void
> +kcov_attachhook(struct device *dev)
> +{
> + kcov_attached = 1;
> }
>
> int
>
--
nest.cx is Gmail hosted, use PGP for anything private. Key:
http://goo.gl/6dMsr
Fingerprint: 5E2B 2D0E 1E03 2046 BEC3 4D50 0B15 42BD 8DF5 A1B0
simple MH_ALIGN -> m_align transformations
Since M_ALIGN and MH_ALIGN are not streight calls to m_align() convert the
users to call directly m_align() so that the macros can be removed at a
later stage.
This diff has the streight forward bits in it.
There is one extra bit in revarprequest() where I make the function
more like arprequest() by setting m->m_pkthdr.ph_rtableid. This is a bit
more correct like this.
OK?
--
:wq Claudio
Index: kern/uipc_mbuf.c
===
RCS file: /cvs/src/sys/kern/uipc_mbuf.c,v
retrieving revision 1.261
diff -u -p -r1.261 uipc_mbuf.c
--- kern/uipc_mbuf.c12 Nov 2018 07:45:52 - 1.261
+++ kern/uipc_mbuf.c12 Nov 2018 08:13:49 -
@@ -618,7 +618,7 @@ m_prepend(struct mbuf *m, int len, int h
M_MOVE_PKTHDR(mn, m);
mn->m_next = m;
m = mn;
- MH_ALIGN(m, len);
+ m_align(m, len);
m->m_len = len;
}
if (m->m_flags & M_PKTHDR)
@@ -1057,7 +1057,7 @@ m_split(struct mbuf *m0, int len0, int w
goto extpacket;
if (remain > MHLEN) {
/* m can't be the lead packet */
- MH_ALIGN(n, 0);
+ m_align(n, 0);
n->m_next = m_split(m, len, wait);
if (n->m_next == NULL) {
(void) m_free(n);
@@ -1068,7 +1068,7 @@ m_split(struct mbuf *m0, int len0, int w
return (n);
}
} else
- MH_ALIGN(n, remain);
+ m_align(n, remain);
} else if (remain == 0) {
n = m->m_next;
m->m_next = NULL;
@@ -1077,7 +1077,7 @@ m_split(struct mbuf *m0, int len0, int w
MGET(n, wait, m->m_type);
if (n == NULL)
return (NULL);
- M_ALIGN(n, remain);
+ m_align(n, remain);
}
extpacket:
if (m->m_flags & M_EXT) {
Index: kern/uipc_socket.c
===
RCS file: /cvs/src/sys/kern/uipc_socket.c,v
retrieving revision 1.229
diff -u -p -r1.229 uipc_socket.c
--- kern/uipc_socket.c 21 Nov 2018 16:50:49 - 1.229
+++ kern/uipc_socket.c 22 Nov 2018 08:56:32 -
@@ -577,7 +577,7 @@ nopages:
* for protocol headers in first mbuf.
*/
if (atomic && m == top && len < mlen - max_hdr)
- MH_ALIGN(m, len);
+ m_align(m, len);
}
error = uiomove(mtod(m, caddr_t), len, uio);
Index: net80211/ieee80211_output.c
===
RCS file: /cvs/src/sys/net80211/ieee80211_output.c,v
retrieving revision 1.122
diff -u -p -r1.122 ieee80211_output.c
--- net80211/ieee80211_output.c 14 Dec 2017 18:52:17 - 1.122
+++ net80211/ieee80211_output.c 12 Nov 2018 08:15:11 -
@@ -1262,7 +1262,7 @@ ieee80211_get_auth(struct ieee80211com *
MGETHDR(m, M_DONTWAIT, MT_DATA);
if (m == NULL)
return NULL;
- MH_ALIGN(m, 2 * 3);
+ m_align(m, 2 * 3);
m->m_pkthdr.len = m->m_len = 2 * 3;
frm = mtod(m, u_int8_t *);
@@ -1286,9 +1286,9 @@ ieee80211_get_deauth(struct ieee80211com
MGETHDR(m, M_DONTWAIT, MT_DATA);
if (m == NULL)
return NULL;
- MH_ALIGN(m, 2);
-
+ m_align(m, 2);
m->m_pkthdr.len = m->m_len = 2;
+
*mtod(m, u_int16_t *) = htole16(reason);
return m;
@@ -1446,9 +1446,9 @@ ieee80211_get_disassoc(struct ieee80211c
MGETHDR(m, M_DONTWAIT, MT_DATA);
if (m == NULL)
return NULL;
- MH_ALIGN(m, 2);
-
+ m_align(m, 2);
m->m_pkthdr.len = m->m_len = 2;
+
*mtod(m, u_int16_t *) = htole16(reason);
return m;
Index: netinet/if_ether.c
===
RCS file: /cvs/src/sys/netinet/if_ether.c,v
retrieving revision 1.236
diff -u -p -r1.236 if_ether.c
--- netinet/if_ether.c 11 Jun 2018 08:48:54 - 1.236
+++ netinet/if_ether.c 12 Nov 2018 09:16:01 -
@@ -246,7 +246,7 @@ arprequest(struct ifnet *ifp, u_int32_t
m->m_pkthdr.len = sizeof(*ea);
m->m_pkthdr.ph_rtableid = ifp->if_rdomain;
m->m_pkthdr.pf.prio = ifp->if_llprio;
- MH_ALIGN(m, sizeof(*ea));
+ m_align(m, sizeof(*ea));
ea = mtod(m, struct ether_arp *);
eh = (struct ether_header *)sa.sa_data;
memset(ea, 0, sizeof(*ea));
@@ -873,8 +873,9 @@ revarprequest(struct ifnet *ifp)
return;
m->m_len = sizeof(*ea);
m->m_pkthdr.len = sizeof(*ea);
+ m->m_pkthdr.ph_rtableid = ifp->if_rdomain;
m->m_pkthdr.pf.prio = ifp->if_llprio;
-
