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

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 | 497 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 lib/stopwatch.h |  41 +++++
 3 files changed, 540 insertions(+)
 create mode 100644 lib/stopwatch.c
 create mode 100644 lib/stopwatch.h

On Wed, Mar 7, 2018 at 9:01 AM, Mark Michelson <mmichels@redhat.com> wrote:
>
> 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 | 497
++++++++++++++++++++++++++++++++++++++++++++++++++++++++
>  lib/stopwatch.h |  41 +++++
>  3 files changed, 540 insertions(+)
>  create mode 100644 lib/stopwatch.c
>  create mode 100644 lib/stopwatch.h
>
> diff --git a/lib/automake.mk b/lib/automake.mk
> index 5c26e0f33..7784057c9 100644
> --- a/lib/automake.mk
> +++ b/lib/automake.mk
> @@ -222,6 +222,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..9b7847bf5
> --- /dev/null
> +++ b/lib/stopwatch.c
> @@ -0,0 +1,497 @@
> +/* 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 bool
> +stopwatch_start_sample_protected(const struct stopwatch_packet *pkt)
> +{
> +    struct stopwatch *sw = shash_find_data(&stopwatches, pkt->name);
> +    if (!sw) {
> +        return false;
> +    }
> +
> +    /* We already started sampling. Need an end before
> +     * we start another sample
> +     */
> +    if (sw->sample_in_progress) {
> +        return false;
> +    }
> +
> +    sw->sample_start = pkt->time;
> +    sw->sample_in_progress = true;
> +    return true;
> +}
> +
> +static bool
The return value is not used. Any consideration of using it in the future
to report error when start/stop doesn't match? Or just not needed, and
return void?
> +stopwatch_end_sample_protected(const struct stopwatch_packet *pkt)
> +{
> +    struct stopwatch *sw = shash_find_data(&stopwatches, pkt->name);
> +    if (!sw) {
> +        return false;
> +    }
> +
> +    /* We can't end a sample if we haven't started one */
> +    if (!sw->sample_in_progress) {
> +        return false;
> +    }
> +
> +    add_sample(sw, pkt->time - sw->sample_start);
> +    sw->sample_in_progress = false;
> +    return true;
> +}
> +
> +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 */
> --
> 2.14.3
>
> _______________________________________________
> dev mailing list
> dev@openvswitch.org
> https://mail.openvswitch.org/mailman/listinfo/ovs-dev

Acked-by: Han Zhou <hzhou8@ebay.com>