diff mbox series

[ovs-dev,v7,1/5] Add stopwatch timing API

Message ID 20180328213510.16037-2-mmichels@redhat.com
State Accepted
Headers show
Series Stopwatch Library | expand

Commit Message

Mark Michelson March 28, 2018, 9:35 p.m. UTC
This is similar to the existing coverage and perf-counter APIs in OVS.
However, rather than keeping counters, this is aimed at timing how long
operations take to perform. "Operations" in this case can be anything
from a loop iteration, to a function, to something more complex.

The library allows for named stopwatches to be created. From there, the
stopwatch can be started and stopped via stopwatch_start() and
stopwatch_stop(). After each run, statistics for the stopwatch will be
calculated.

Statistics for a particular stopwatch can be queried from the command
line by using ovs-appctl -t <target> stopwatch/show <stopwatch name>.

Statistics can be reset from the command line using
ovs-appctl -t <target> stopwatch/reset <stopwatch name>

Signed-off-by: Mark Michelson <mmichels@redhat.com>
---
 lib/automake.mk |   2 +
 lib/stopwatch.c | 483 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 lib/stopwatch.h |  41 +++++
 3 files changed, 526 insertions(+)
 create mode 100644 lib/stopwatch.c
 create mode 100644 lib/stopwatch.h
diff mbox series

Patch

diff --git a/lib/automake.mk b/lib/automake.mk
index c7eda6e31..0161a946b 100644
--- a/lib/automake.mk
+++ b/lib/automake.mk
@@ -224,6 +224,8 @@  lib_libopenvswitch_la_SOURCES = \
 	lib/pcap-file.h \
 	lib/perf-counter.h \
 	lib/perf-counter.c \
+	lib/stopwatch.h \
+	lib/stopwatch.c \
 	lib/poll-loop.c \
 	lib/process.c \
 	lib/process.h \
diff --git a/lib/stopwatch.c b/lib/stopwatch.c
new file mode 100644
index 000000000..d33976c28
--- /dev/null
+++ b/lib/stopwatch.c
@@ -0,0 +1,483 @@ 
+/* Copyright (c) 2017 Red Hat, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at:
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#include <config.h>
+
+#include "stopwatch.h"
+#include "openvswitch/shash.h"
+#include "openvswitch/vlog.h"
+#include "unixctl.h"
+#include "openvswitch/dynamic-string.h"
+#include "openvswitch/poll-loop.h"
+#include "ovs-thread.h"
+#include <unistd.h>
+#include "socket-util.h"
+
+VLOG_DEFINE_THIS_MODULE(stopwatch);
+
+struct average {
+    double average; /* Moving average */
+    double alpha;   /* Weight given to new samples */
+};
+
+#define MARKERS 5
+
+/* Number of samples to collect before reporting P-square calculated
+ * percentile
+ */
+#define P_SQUARE_MIN 50
+
+/* The naming of these fields is based on the naming used in the
+ * P-square algorithm paper.
+ */
+struct percentile {
+    int n[MARKERS];
+    double n_prime[MARKERS];
+    double q[MARKERS];
+    double dn[MARKERS];
+    unsigned long long samples[P_SQUARE_MIN];
+    double percentile;
+};
+
+struct stopwatch {
+    enum stopwatch_units units;
+    unsigned long long n_samples;
+    unsigned long long max;
+    unsigned long long min;
+    struct percentile pctl;
+    struct average short_term;
+    struct average long_term;
+    unsigned long long sample_start;
+    bool sample_in_progress;
+};
+
+enum stopwatch_op {
+    OP_START_SAMPLE,
+    OP_END_SAMPLE,
+    OP_RESET,
+    OP_SHUTDOWN,
+};
+
+struct stopwatch_packet {
+    enum stopwatch_op op;
+    char name[32];
+    unsigned long long time;
+};
+
+static struct shash stopwatches = SHASH_INITIALIZER(&stopwatches);
+static struct ovs_mutex stopwatches_lock = OVS_MUTEX_INITIALIZER;
+
+static int stopwatch_pipe[2];
+static pthread_t stopwatch_thread_id;
+
+static const char *unit_name[] = {
+    [SW_MS] = "msec",
+    [SW_US] = "usec",
+    [SW_NS] = "nsec",
+};
+
+/* Percentile value we are calculating */
+#define P 0.95
+
+static int
+comp_samples(const void *left, const void *right)
+{
+    const double *left_d = left;
+    const double *right_d = right;
+
+    return (int) *right_d - *left_d;
+}
+
+/* Calculate the percentile using the P-square algorithm. For more
+ * information, see https://www1.cse.wustl.edu/~jain/papers/ftp/psqr.pdf
+ */
+static void
+calc_percentile(unsigned long long n_samples, struct percentile *pctl,
+                unsigned long long new_sample)
+{
+
+    if (n_samples < P_SQUARE_MIN) {
+        pctl->samples[n_samples - 1] = new_sample;
+    }
+
+    /* For the first MARKERS samples, we calculate the percentile
+     * in the traditional way in the pct->q array.
+     */
+    if (n_samples <= MARKERS) {
+        pctl->q[n_samples - 1] = new_sample;
+        qsort(pctl->q, n_samples, sizeof *pctl->q, comp_samples);
+        if (n_samples == MARKERS) {
+            pctl->n[0] = 0;
+            pctl->n[1] = 1;
+            pctl->n[2] = 2;
+            pctl->n[3] = 3;
+            pctl->n[4] = 4;
+
+            pctl->n_prime[0] = 0;
+            pctl->n_prime[1] = 2 * P;
+            pctl->n_prime[2] = 4 * P;
+            pctl->n_prime[3] = 2 + 2 * P;
+            pctl->n_prime[4] = 4;
+
+            pctl->dn[0] = 0;
+            pctl->dn[1] = P / 2;
+            pctl->dn[2] = P;
+            pctl->dn[3] = (1 + P) / 2;
+            pctl->dn[4] = 1;
+        }
+        pctl->percentile = pctl->q[(int) P * n_samples];
+        return;
+    }
+
+    /* From here on, update the markers using quadratic spline calculations */
+    int k;
+    if (new_sample < pctl->q[0]) {
+        k = 0;
+        pctl->q[0] = new_sample;
+    } else if (new_sample < pctl->q[1]) {
+        k = 0;
+    } else if (new_sample < pctl->q[2]) {
+        k = 1;
+    } else if (new_sample < pctl->q[3]) {
+        k = 2;
+    } else if (new_sample <= pctl->q[4]) {
+        k = 3;
+    } else {
+        k = 3;
+        pctl->q[4] = new_sample;
+    }
+
+    for (int i = k + 1; i < MARKERS; i++) {
+        pctl->n[i]++;
+    }
+
+    for (int i = 0; i < MARKERS; i++) {
+        pctl->n_prime[i] += pctl->dn[i];
+    }
+
+    for (int i = 1; i < MARKERS - 1; i++) {
+        double d = pctl->n_prime[i] - pctl->n[i];
+
+        if ((d >= 1 && pctl->n[i + 1] - pctl->n[i] > 1) ||
+            (d <= -1 && pctl->n[i - 1] - pctl->n[i] < -1)) {
+            d = d >= 0 ? 1 : -1;
+
+            double a = d / (pctl->n[i + 1] - pctl->n[i - 1]);
+            double b = (pctl->n[i] - pctl->n[i - 1] + d) *
+                (pctl->q[i + 1] - pctl->q[i]) / (pctl->n[i + 1] - pctl->n[i]);
+            double c = (pctl->n[i + 1] - pctl->n[i] - d) *
+                (pctl->q[i] - pctl->q[i - 1]) / (pctl->n[i] - pctl->n[i - 1]);
+
+            double candidate = pctl->q[i] + a * (b + c);
+            if (pctl->q[i - 1] < candidate && candidate < pctl->q[i + 1]) {
+                pctl->q[i] = candidate;
+            } else {
+                pctl->q[i] = pctl->q[i] +
+                    (d * (pctl->q[i + (int)d] - pctl->q[i]) /
+                    (pctl->n[i +(int)d] - pctl->n[i]));
+            }
+
+            pctl->n[i] += d;
+        }
+    }
+
+    /* Without enough samples, P-square is not very accurate. Until we reach
+     * P_SQUARE_MIN, use a traditional calculation for the percentile.
+     */
+    if (n_samples < P_SQUARE_MIN) {
+        qsort(pctl->samples, n_samples, sizeof *pctl->samples, comp_samples);
+        pctl->percentile = pctl->samples[(int) (P * n_samples)];
+    } else {
+        pctl->percentile = pctl->q[2];
+    }
+}
+
+static void
+calc_average(struct average *avg, double new_sample)
+{
+    avg->average = new_sample * avg->alpha + (1 - avg->alpha) * avg->average;
+}
+
+static void
+add_sample(struct stopwatch *sw, unsigned long long new_sample)
+{
+    if (new_sample > sw->max) {
+        sw->max = new_sample;
+    }
+
+    if (new_sample < sw->min || sw->n_samples == 0) {
+        sw->min = new_sample;
+    }
+
+    calc_percentile(sw->n_samples, &sw->pctl, new_sample);
+
+    if (sw->n_samples++ == 0) {
+        sw->short_term.average = sw->long_term.average = new_sample;
+        return;
+    }
+
+    calc_average(&sw->short_term, new_sample);
+    calc_average(&sw->long_term, new_sample);
+}
+
+static void
+stopwatch_print(struct stopwatch *sw, const char *name,
+                  struct ds *s)
+{
+    ds_put_format(s, "Statistics for '%s'\n", name);
+
+    const char *units = unit_name[sw->units];
+    ds_put_format(s, "\t Total samples: %llu\n", sw->n_samples);
+    ds_put_format(s, "\t Maximum: %llu %s\n", sw->max, units);
+    ds_put_format(s, "\t Minimum: %llu %s\n", sw->min, units);
+    ds_put_format(s, "\t 95th percentile: %f %s\n",
+                  sw->pctl.percentile, units);
+    ds_put_format(s, "\t Short term average: %f %s\n",
+                  sw->short_term.average, units);
+    ds_put_format(s, "\t Long term average: %f %s\n",
+                  sw->long_term.average, units);
+}
+
+static bool
+stopwatch_show_protected(int argc, const char *argv[], struct ds *s)
+{
+    struct stopwatch *sw;
+
+    if (argc > 1) {
+        sw = shash_find_data(&stopwatches, argv[1]);
+        if (!sw) {
+            ds_put_cstr(s, "No such stopwatch");
+            return false;
+        }
+        stopwatch_print(sw, argv[1], s);
+    } else {
+        struct shash_node *node;
+        SHASH_FOR_EACH (node, &stopwatches) {
+            sw = node->data;
+            stopwatch_print(sw, node->name, s);
+        }
+    }
+
+    return true;
+}
+
+static void
+stopwatch_show(struct unixctl_conn *conn, int argc OVS_UNUSED,
+        const char *argv[], void *ignore OVS_UNUSED)
+{
+    struct ds s = DS_EMPTY_INITIALIZER;
+    bool success;
+
+    ovs_mutex_lock(&stopwatches_lock);
+    success = stopwatch_show_protected(argc, argv, &s);
+    ovs_mutex_unlock(&stopwatches_lock);
+
+    if (success) {
+        unixctl_command_reply(conn, ds_cstr(&s));
+    } else {
+        unixctl_command_reply_error(conn, ds_cstr(&s));
+    }
+    ds_destroy(&s);
+}
+
+static void
+stopwatch_reset(struct unixctl_conn *conn, int argc OVS_UNUSED,
+        const char *argv[], void *ignore OVS_UNUSED)
+{
+    struct stopwatch_packet pkt = {
+        .op = OP_RESET,
+    };
+    if (argc > 1) {
+        ovs_strlcpy(pkt.name, argv[1], sizeof(pkt.name));
+    }
+    write(stopwatch_pipe[1], &pkt, sizeof(pkt));
+    unixctl_command_reply(conn, "");
+}
+
+static void
+stopwatch_start_sample_protected(const struct stopwatch_packet *pkt)
+{
+    struct stopwatch *sw = shash_find_data(&stopwatches, pkt->name);
+    if (!sw || sw->sample_in_progress) {
+        return;
+    }
+
+    sw->sample_start = pkt->time;
+    sw->sample_in_progress = true;
+}
+
+static void
+stopwatch_end_sample_protected(const struct stopwatch_packet *pkt)
+{
+    struct stopwatch *sw = shash_find_data(&stopwatches, pkt->name);
+    if (!sw || !sw->sample_in_progress) {
+        return;
+    }
+
+    add_sample(sw, pkt->time - sw->sample_start);
+    sw->sample_in_progress = false;
+}
+
+static void reset_stopwatch(struct stopwatch *sw)
+{
+    sw->short_term.average = 0;
+    sw->long_term.average = 0;
+    sw->pctl.percentile = 0;
+    sw->n_samples = 0;
+    sw->max = 0;
+    sw->min = 0;
+    /* Don't reset sw->sample_start or sw->sample_in_progress.
+     * This way, if a sample was currently in progress, it can be
+     * concluded properly after the reset.
+     */
+}
+
+static void
+stopwatch_reset_protected(const struct stopwatch_packet *pkt)
+{
+    if (pkt->name[0]) {
+        struct stopwatch *sw = shash_find_data(&stopwatches, pkt->name);
+        if (!sw) {
+            return;
+        }
+        reset_stopwatch(sw);
+        return;
+    }
+
+    struct shash_node *node;
+    SHASH_FOR_EACH (node, &stopwatches) {
+        struct stopwatch *sw = node->data;
+        reset_stopwatch(sw);
+    }
+}
+
+static void *
+stopwatch_thread(void *ign OVS_UNUSED)
+{
+    bool should_exit = false;
+
+    while (!should_exit) {
+        struct stopwatch_packet pkt;
+        while (read(stopwatch_pipe[0], &pkt, sizeof(pkt)) > 0) {
+            ovs_mutex_lock(&stopwatches_lock);
+            switch (pkt.op) {
+            case OP_START_SAMPLE:
+                stopwatch_start_sample_protected(&pkt);
+                break;
+            case OP_END_SAMPLE:
+                stopwatch_end_sample_protected(&pkt);
+                break;
+            case OP_RESET:
+                stopwatch_reset_protected(&pkt);
+                break;
+            case OP_SHUTDOWN:
+                should_exit = true;
+                break;
+            }
+            ovs_mutex_unlock(&stopwatches_lock);
+        }
+
+        if (!should_exit) {
+            poll_fd_wait(stopwatch_pipe[0], POLLIN);
+            poll_block();
+        }
+    }
+
+    return NULL;
+}
+
+static void
+stopwatch_exit(void)
+{
+    struct shash_node *node, *node_next;
+    struct stopwatch_packet pkt = {
+        .op = OP_SHUTDOWN,
+    };
+
+    write(stopwatch_pipe[1], &pkt, sizeof pkt);
+    xpthread_join(stopwatch_thread_id, NULL);
+
+    /* Process is exiting and we have joined the only
+     * other competing thread. We are now the sole owners
+     * of all data in the file.
+     */
+    SHASH_FOR_EACH_SAFE (node, node_next, &stopwatches) {
+        struct stopwatch *sw = node->data;
+        shash_delete(&stopwatches, node);
+        free(sw);
+    }
+    shash_destroy(&stopwatches);
+    ovs_mutex_destroy(&stopwatches_lock);
+}
+
+static void
+do_init_stopwatch(void)
+{
+    unixctl_command_register("stopwatch/show", "[NAME]", 0, 1,
+                             stopwatch_show, NULL);
+    unixctl_command_register("stopwatch/reset", "[NAME]", 0, 1,
+                             stopwatch_reset, NULL);
+    xpipe_nonblocking(stopwatch_pipe);
+    stopwatch_thread_id = ovs_thread_create(
+        "stopwatch", stopwatch_thread, NULL);
+    atexit(stopwatch_exit);
+}
+
+static void
+stopwatch_init(void)
+{
+    static struct ovsthread_once once = OVSTHREAD_ONCE_INITIALIZER;
+    if (ovsthread_once_start(&once)) {
+        do_init_stopwatch();
+        ovsthread_once_done(&once);
+    }
+}
+
+void
+stopwatch_create(const char *name, enum stopwatch_units units)
+{
+    stopwatch_init();
+
+    struct stopwatch *sw = xzalloc(sizeof *sw);
+    sw->units = units;
+    sw->short_term.alpha = 0.50;
+    sw->long_term.alpha = 0.01;
+
+    ovs_mutex_lock(&stopwatches_lock);
+    shash_add(&stopwatches, name, sw);
+    ovs_mutex_unlock(&stopwatches_lock);
+}
+
+void
+stopwatch_start(const char *name, unsigned long long ts)
+{
+    struct stopwatch_packet pkt = {
+        .op = OP_START_SAMPLE,
+        .time = ts,
+    };
+    ovs_strlcpy(pkt.name, name, sizeof(pkt.name));
+    write(stopwatch_pipe[1], &pkt, sizeof(pkt));
+}
+
+void
+stopwatch_stop(const char *name, unsigned long long ts)
+{
+    struct stopwatch_packet pkt = {
+        .op = OP_END_SAMPLE,
+        .time = ts,
+    };
+    ovs_strlcpy(pkt.name, name, sizeof(pkt.name));
+    write(stopwatch_pipe[1], &pkt, sizeof(pkt));
+}
diff --git a/lib/stopwatch.h b/lib/stopwatch.h
new file mode 100644
index 000000000..61f814523
--- /dev/null
+++ b/lib/stopwatch.h
@@ -0,0 +1,41 @@ 
+/* Copyright (c) 2017 Red Hat, Inc.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at:
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef STOPWATCH_H
+#define STOPWATCH_H 1
+
+#include <stdbool.h>
+
+enum stopwatch_units {
+    SW_MS,
+    SW_US,
+    SW_NS,
+};
+
+/* Create a new stopwatch.
+ * The "units" are not used for any calculations but are printed when
+ * statistics are requested.
+ */
+void stopwatch_create(const char *name, enum stopwatch_units units);
+
+/* Start a stopwatch. */
+void stopwatch_start(const char *name, unsigned long long ts);
+
+/* Stop a stopwatch. The elapsed time will be used for updating statistics
+ * for this stopwatch.
+ */
+void stopwatch_stop(const char *name, unsigned long long ts);
+
+#endif /* stopwatch.h */