From 846e20cb655dd255e4caec2d1fe2628af35639e8 Mon Sep 17 00:00:00 2001 From: Karl Vogel Date: Wed, 17 Jan 2018 12:13:15 +0100 Subject: [PATCH] procd: add timing to start/stop logging Shows how long an initd task took, for example: procd: stop /etc/init.d/dropbear running - took 0.088824s procd: Update service dnsmasq procd: Update instance dnsmasq::dnsmasq procd: running /etc/init.d/dnsmasq running procd: start /etc/init.d/dnsmasq running procd: stop /etc/init.d/dnsmasq running - took 0.092586s v2: rename variables, correct time unit v3: use CLOCK_MONOTONIC_RAW to prevent issues with NTP and adjtime Signed-off-by: Karl Vogel --- rcS.c | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/rcS.c b/rcS.c index dd3b76d..c2e1abb 100644 --- a/rcS.c +++ b/rcS.c @@ -37,6 +37,7 @@ static struct runqueue q, r; struct initd { struct ustream_fd fd; struct runqueue_process proc; + struct timespec ts_start; char *file; char *param; }; @@ -70,6 +71,7 @@ static void q_initd_run(struct runqueue *q, struct runqueue_task *t) int pipefd[2]; pid_t pid; + clock_gettime(CLOCK_MONOTONIC_RAW, &s->ts_start); DEBUG(2, "start %s %s \n", s->file, s->param); if (pipe(pipefd) == -1) { ERROR("Failed to create pipe: %m\n"); @@ -106,8 +108,17 @@ static void q_initd_run(struct runqueue *q, struct runqueue_task *t) static void q_initd_complete(struct runqueue *q, struct runqueue_task *p) { struct initd *s = container_of(p, struct initd, proc.task); + struct timespec ts_stop, ts_res; + + clock_gettime(CLOCK_MONOTONIC_RAW, &ts_stop); + ts_res.tv_sec = ts_stop.tv_sec - s->ts_start.tv_sec; + ts_res.tv_nsec = ts_stop.tv_nsec - s->ts_start.tv_nsec; + if (ts_res.tv_nsec < 0) { + --ts_res.tv_sec; + ts_res.tv_nsec += 1000000000; + } - DEBUG(2, "stop %s %s \n", s->file, s->param); + DEBUG(2, "stop %s %s - took %lu.%09lus\n", s->file, s->param, ts_res.tv_sec, ts_res.tv_nsec); ustream_free(&s->fd.stream); close(s->fd.fd.fd); free(s); -- 2.30.2