mir/ovs
2
0
Fork 0
mirror of https://github.com/openvswitch/ovs synced 2025-08-22 18:07:40 +00:00
Code Issues Releases Wiki Activity
ovs/lib/dpif-netdev-perf.c
Kevin Traynor 3beff0a6b0 dpif-netdev-perf: Add metric averages when no iterations. 
pmd-perf-show with pmd-perf-metrics=true displays a histogram
with averages. However, averages were not displayed when there
is no iterations.

They will be all zero so it is not hiding useful information
but the stats look incomplete without them, especially when
they are displayed for some PMD thread cores and not others.

The histogram print is large and this is just an extra couple
of lines, so might as well print them all the time to ensure
that the user does not think there is something missing from
the display.

Before patch:
  Histograms
     cycles/it
     499       0
     716       0
     1025      0
     1469      0
  <snip>

After patch:
  Histograms
     cycles/it
     499       0
     716       0
     1025      0
     1469      0
  <snip>
  ---------------
     cycles/it
     0

Acked-by: Mike Pattrick <mkp@redhat.com>
Signed-off-by: Kevin Traynor <ktraynor@redhat.com>
Signed-off-by: Ilya Maximets <i.maximets@ovn.org>
2023-01-27 16:57:27 +01:00

806 lines
28 KiB
C
Raw Blame History

/*
* Copyright (c) 2017 Ericsson AB.
*
* 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 <stdint.h>
#include "dpdk.h"
#include "dpif-netdev-perf.h"
#include "openvswitch/dynamic-string.h"
#include "openvswitch/vlog.h"
#include "ovs-numa.h"
#include "ovs-thread.h"
#include "timeval.h"
VLOG_DEFINE_THIS_MODULE(pmd_perf);
#define ITER_US_THRESHOLD 250 /* Warning threshold for iteration duration
in microseconds. */
#define VHOST_QUEUE_FULL 128 /* Size of the virtio TX queue. */
#define LOG_IT_BEFORE 5 /* Number of iterations to log before
suspicious iteration. */
#define LOG_IT_AFTER 5 /* Number of iterations to log after
suspicious iteration. */
bool log_enabled = false;
bool log_extend = false;
static uint32_t log_it_before = LOG_IT_BEFORE;
static uint32_t log_it_after = LOG_IT_AFTER;
static uint32_t log_us_thr = ITER_US_THRESHOLD;
uint32_t log_q_thr = VHOST_QUEUE_FULL;
uint64_t iter_cycle_threshold;
static struct vlog_rate_limit latency_rl = VLOG_RATE_LIMIT_INIT(600, 600);
static uint64_t tsc_hz = 1;
void
pmd_perf_estimate_tsc_frequency(void)
{
#ifdef DPDK_NETDEV
if (dpdk_available()) {
tsc_hz = rte_get_tsc_hz();
}
if (tsc_hz > 1) {
VLOG_INFO("DPDK provided TSC frequency: %"PRIu64" KHz", tsc_hz / 1000);
return;
}
#endif
struct ovs_numa_dump *affinity;
struct pmd_perf_stats s;
uint64_t start, stop;
/* DPDK is not available or returned unreliable value.
* Trying to estimate. */
affinity = ovs_numa_thread_getaffinity_dump();
if (affinity) {
const struct ovs_numa_info_core *core;
FOR_EACH_CORE_ON_DUMP (core, affinity) {
/* Setting affinity to a single core from the affinity mask to
* avoid re-scheduling to another core while sleeping. */
ovs_numa_thread_setaffinity_core(core->core_id);
break;
}
}
memset(&s, 0, sizeof s);
start = cycles_counter_update(&s);
/* Using xnanosleep as it's interrupt resistant.
* Sleeping only 100 ms to avoid holding the main thread for too long. */
xnanosleep(1E8);
stop = cycles_counter_update(&s);
if (affinity) {
/* Restoring previous affinity. */
ovs_numa_thread_setaffinity_dump(affinity);
ovs_numa_dump_destroy(affinity);
}
if (stop <= start) {
VLOG_WARN("TSC source is unreliable.");
tsc_hz = 1;
} else {
tsc_hz = (stop - start) * 10;
}
VLOG_INFO("Estimated TSC frequency: %"PRIu64" KHz", tsc_hz / 1000);
}
/* Histogram functions. */
static void
histogram_walls_set_lin(struct histogram *hist, uint32_t min, uint32_t max)
{
int i;
ovs_assert(min < max);
for (i = 0; i < NUM_BINS-1; i++) {
hist->wall[i] = min + (i * (max - min)) / (NUM_BINS - 2);
}
hist->wall[NUM_BINS-1] = UINT32_MAX;
}
static void
histogram_walls_set_log(struct histogram *hist, uint32_t min, uint32_t max)
{
int i, start, bins, wall;
double log_min, log_max;
ovs_assert(min < max);
if (min > 0) {
log_min = log(min);
log_max = log(max);
start = 0;
bins = NUM_BINS - 1;
} else {
hist->wall[0] = 0;
log_min = log(1);
log_max = log(max);
start = 1;
bins = NUM_BINS - 2;
}
wall = start;
for (i = 0; i < bins; i++) {
/* Make sure each wall is monotonically increasing. */
wall = MAX(wall, exp(log_min + (i * (log_max - log_min)) / (bins-1)));
hist->wall[start + i] = wall++;
}
if (hist->wall[NUM_BINS-2] < max) {
hist->wall[NUM_BINS-2] = max;
}
hist->wall[NUM_BINS-1] = UINT32_MAX;
}
uint64_t
histogram_samples(const struct histogram *hist)
{
uint64_t samples = 0;
for (int i = 0; i < NUM_BINS; i++) {
samples += hist->bin[i];
}
return samples;
}
static void
histogram_clear(struct histogram *hist)
{
int i;
for (i = 0; i < NUM_BINS; i++) {
hist->bin[i] = 0;
}
}
static void
history_init(struct history *h)
{
memset(h, 0, sizeof(*h));
}
void
pmd_perf_stats_init(struct pmd_perf_stats *s)
{
memset(s, 0, sizeof(*s));
ovs_mutex_init(&s->stats_mutex);
ovs_mutex_init(&s->clear_mutex);
/* Logarithmic histogram for cycles/it ranging from 500 to 24M
* (corresponding to 200 ns to 9.6 ms at 2.5 GHz TSC clock). */
histogram_walls_set_log(&s->cycles, 500, 24000000);
/* Logarithmic histogram for pkts/it ranging from 0 to 1000. */
histogram_walls_set_log(&s->pkts, 0, 1000);
/* Linear histogram for cycles/pkt ranging from 100 to 30K. */
histogram_walls_set_lin(&s->cycles_per_pkt, 100, 30000);
/* Linear histogram for pkts/rx batch ranging from 0 to 32,
* the maximum rx batch size in OVS. */
histogram_walls_set_lin(&s->pkts_per_batch, 0, 32);
/* Linear histogram for upcalls/it ranging from 0 to 30. */
histogram_walls_set_lin(&s->upcalls, 0, 30);
/* Logarithmic histogram for cycles/upcall ranging from 1000 to 1M
* (corresponding to 400 ns to 400 us at 2.5 GHz TSC clock). */
histogram_walls_set_log(&s->cycles_per_upcall, 1000, 1000000);
/* Log. histogram for max vhostuser queue fill level from 0 to 512.
* 512 is the maximum fill level for a virtio queue with 1024
* descriptors (maximum configurable length in Qemu), with the
* DPDK 17.11 virtio PMD in the guest. */
histogram_walls_set_log(&s->max_vhost_qfill, 0, 512);
s->iteration_cnt = 0;
s->start_ms = time_msec();
s->log_susp_it = UINT32_MAX;
s->log_begin_it = UINT32_MAX;
s->log_end_it = UINT32_MAX;
s->log_reason = NULL;
}
void
pmd_perf_format_overall_stats(struct ds *str, struct pmd_perf_stats *s,
double duration)
{
uint64_t stats[PMD_N_STATS];
double us_per_cycle = 1000000.0 / tsc_hz;
if (duration == 0) {
return;
}
pmd_perf_read_counters(s, stats);
uint64_t tot_cycles = stats[PMD_CYCLES_ITER_IDLE] +
stats[PMD_CYCLES_ITER_BUSY];
uint64_t rx_packets = stats[PMD_STAT_RECV];
uint64_t tx_packets = stats[PMD_STAT_SENT_PKTS];
uint64_t tx_batches = stats[PMD_STAT_SENT_BATCHES];
uint64_t passes = stats[PMD_STAT_RECV] +
stats[PMD_STAT_RECIRC];
uint64_t upcalls = stats[PMD_STAT_MISS];
uint64_t upcall_cycles = stats[PMD_CYCLES_UPCALL];
uint64_t tot_iter = histogram_samples(&s->pkts);
uint64_t idle_iter = s->pkts.bin[0];
uint64_t busy_iter = tot_iter >= idle_iter ? tot_iter - idle_iter : 0;
uint64_t sleep_iter = stats[PMD_SLEEP_ITER];
uint64_t tot_sleep_cycles = stats[PMD_CYCLES_SLEEP];
ds_put_format(str,
" Iterations: %12"PRIu64" (%.2f us/it)\n"
" - Used TSC cycles: %12"PRIu64" (%5.1f %% of total cycles)\n"
" - idle iterations: %12"PRIu64" (%5.1f %% of used cycles)\n"
" - busy iterations: %12"PRIu64" (%5.1f %% of used cycles)\n"
" - sleep iterations: %12"PRIu64" (%5.1f %% of iterations)\n"
" Sleep time (us): %12.0f (%3.0f us/iteration avg.)\n",
tot_iter,
tot_iter
? (tot_cycles + tot_sleep_cycles) * us_per_cycle / tot_iter
: 0,
tot_cycles, 100.0 * (tot_cycles / duration) / tsc_hz,
idle_iter,
tot_cycles ? 100.0 * stats[PMD_CYCLES_ITER_IDLE] / tot_cycles : 0,
busy_iter,
tot_cycles ? 100.0 * stats[PMD_CYCLES_ITER_BUSY] / tot_cycles : 0,
sleep_iter, tot_iter ? 100.0 * sleep_iter / tot_iter : 0,
tot_sleep_cycles * us_per_cycle,
sleep_iter ? (tot_sleep_cycles * us_per_cycle) / sleep_iter : 0);
if (rx_packets > 0) {
ds_put_format(str,
" Rx packets: %12"PRIu64" (%.0f Kpps, %.0f cycles/pkt)\n"
" Datapath passes: %12"PRIu64" (%.2f passes/pkt)\n"
" - PHWOL hits: %12"PRIu64" (%5.1f %%)\n"
" - MFEX Opt hits: %12"PRIu64" (%5.1f %%)\n"
" - Simple Match hits:%12"PRIu64" (%5.1f %%)\n"
" - EMC hits: %12"PRIu64" (%5.1f %%)\n"
" - SMC hits: %12"PRIu64" (%5.1f %%)\n"
" - Megaflow hits: %12"PRIu64" (%5.1f %%, %.2f "
"subtbl lookups/hit)\n"
" - Upcalls: %12"PRIu64" (%5.1f %%, %.1f us/upcall)\n"
" - Lost upcalls: %12"PRIu64" (%5.1f %%)\n",
rx_packets, (rx_packets / duration) / 1000,
1.0 * stats[PMD_CYCLES_ITER_BUSY] / rx_packets,
passes, rx_packets ? 1.0 * passes / rx_packets : 0,
stats[PMD_STAT_PHWOL_HIT],
100.0 * stats[PMD_STAT_PHWOL_HIT] / passes,
stats[PMD_STAT_MFEX_OPT_HIT],
100.0 * stats[PMD_STAT_MFEX_OPT_HIT] / passes,
stats[PMD_STAT_SIMPLE_HIT],
100.0 * stats[PMD_STAT_SIMPLE_HIT] / passes,
stats[PMD_STAT_EXACT_HIT],
100.0 * stats[PMD_STAT_EXACT_HIT] / passes,
stats[PMD_STAT_SMC_HIT],
100.0 * stats[PMD_STAT_SMC_HIT] / passes,
stats[PMD_STAT_MASKED_HIT],
100.0 * stats[PMD_STAT_MASKED_HIT] / passes,
stats[PMD_STAT_MASKED_HIT]
? 1.0 * stats[PMD_STAT_MASKED_LOOKUP] / stats[PMD_STAT_MASKED_HIT]
: 0,
upcalls, 100.0 * upcalls / passes,
upcalls ? (upcall_cycles * us_per_cycle) / upcalls : 0,
stats[PMD_STAT_LOST],
100.0 * stats[PMD_STAT_LOST] / passes);
} else {
ds_put_format(str,
" Rx packets: %12d\n", 0);
}
if (tx_packets > 0) {
ds_put_format(str,
" Tx packets: %12"PRIu64" (%.0f Kpps)\n"
" Tx batches: %12"PRIu64" (%.2f pkts/batch)\n",
tx_packets, (tx_packets / duration) / 1000,
tx_batches, 1.0 * tx_packets / tx_batches);
} else {
ds_put_format(str,
" Tx packets: %12d\n\n", 0);
}
}
void
pmd_perf_format_histograms(struct ds *str, struct pmd_perf_stats *s)
{
int i;
ds_put_cstr(str, "Histograms\n");
ds_put_format(str,
" %-21s %-21s %-21s %-21s %-21s %-21s %-21s\n",
"cycles/it", "packets/it", "cycles/pkt", "pkts/batch",
"max vhost qlen", "upcalls/it", "cycles/upcall");
for (i = 0; i < NUM_BINS-1; i++) {
ds_put_format(str,
" %-9d %-11"PRIu64" %-9d %-11"PRIu64" %-9d %-11"PRIu64
" %-9d %-11"PRIu64" %-9d %-11"PRIu64" %-9d %-11"PRIu64
" %-9d %-11"PRIu64"\n",
s->cycles.wall[i], s->cycles.bin[i],
s->pkts.wall[i],s->pkts.bin[i],
s->cycles_per_pkt.wall[i], s->cycles_per_pkt.bin[i],
s->pkts_per_batch.wall[i], s->pkts_per_batch.bin[i],
s->max_vhost_qfill.wall[i], s->max_vhost_qfill.bin[i],
s->upcalls.wall[i], s->upcalls.bin[i],
s->cycles_per_upcall.wall[i], s->cycles_per_upcall.bin[i]);
}
ds_put_format(str,
" %-9s %-11"PRIu64" %-9s %-11"PRIu64" %-9s %-11"PRIu64
" %-9s %-11"PRIu64" %-9s %-11"PRIu64" %-9s %-11"PRIu64
" %-9s %-11"PRIu64"\n",
">", s->cycles.bin[i],
">", s->pkts.bin[i],
">", s->cycles_per_pkt.bin[i],
">", s->pkts_per_batch.bin[i],
">", s->max_vhost_qfill.bin[i],
">", s->upcalls.bin[i],
">", s->cycles_per_upcall.bin[i]);
ds_put_cstr(str,
"-----------------------------------------------------"
"-----------------------------------------------------"
"------------------------------------------------\n");
ds_put_format(str,
" %-21s %-21s %-21s %-21s %-21s %-21s %-21s\n",
"cycles/it", "packets/it", "cycles/pkt", "pkts/batch",
"vhost qlen", "upcalls/it", "cycles/upcall");
ds_put_format(str,
" %-21"PRIu64" %-21.5f %-21"PRIu64
" %-21.5f %-21.5f %-21.5f %-21"PRIu32"\n",
s->totals.iterations
? s->totals.cycles / s->totals.iterations : 0,
s->totals.iterations
? 1.0 * s->totals.pkts / s->totals.iterations : 0,
s->totals.pkts
? s->totals.busy_cycles / s->totals.pkts : 0,
s->totals.batches
? 1.0 * s->totals.pkts / s->totals.batches : 0,
s->totals.iterations
? 1.0 * s->totals.max_vhost_qfill / s->totals.iterations
: 0,
s->totals.iterations
? 1.0 * s->totals.upcalls / s->totals.iterations : 0,
s->totals.upcalls
? s->totals.upcall_cycles / s->totals.upcalls : 0);
}
void
pmd_perf_format_iteration_history(struct ds *str, struct pmd_perf_stats *s,
int n_iter)
{
struct iter_stats *is;
size_t index;
int i;
if (n_iter == 0) {
return;
}
ds_put_format(str, " %-17s %-10s %-10s %-10s %-10s "
"%-10s %-10s %-10s\n",
"iter", "cycles", "packets", "cycles/pkt", "pkts/batch",
"vhost qlen", "upcalls", "cycles/upcall");
for (i = 1; i <= n_iter; i++) {
index = history_sub(s->iterations.idx, i);
is = &s->iterations.sample[index];
ds_put_format(str,
" %-17"PRIu64" %-11"PRIu64" %-11"PRIu32
" %-11"PRIu64" %-11"PRIu32" %-11"PRIu32
" %-11"PRIu32" %-11"PRIu32"\n",
is->timestamp,
is->cycles,
is->pkts,
is->pkts ? is->cycles / is->pkts : 0,
is->batches ? is->pkts / is->batches : 0,
is->max_vhost_qfill,
is->upcalls,
is->upcalls ? is->upcall_cycles / is->upcalls : 0);
}
}
void
pmd_perf_format_ms_history(struct ds *str, struct pmd_perf_stats *s, int n_ms)
{
struct iter_stats *is;
size_t index;
int i;
if (n_ms == 0) {
return;
}
ds_put_format(str,
" %-12s %-10s %-10s %-10s %-10s"
" %-10s %-10s %-10s %-10s\n",
"ms", "iterations", "cycles/it", "Kpps", "cycles/pkt",
"pkts/batch", "vhost qlen", "upcalls", "cycles/upcall");
for (i = 1; i <= n_ms; i++) {
index = history_sub(s->milliseconds.idx, i);
is = &s->milliseconds.sample[index];
ds_put_format(str,
" %-12"PRIu64" %-11"PRIu32" %-11"PRIu64
" %-11"PRIu32" %-11"PRIu64" %-11"PRIu32
" %-11"PRIu32" %-11"PRIu32" %-11"PRIu32"\n",
is->timestamp,
is->iterations,
is->iterations ? is->cycles / is->iterations : 0,
is->pkts,
is->pkts ? is->busy_cycles / is->pkts : 0,
is->batches ? is->pkts / is->batches : 0,
is->iterations
? is->max_vhost_qfill / is->iterations : 0,
is->upcalls,
is->upcalls ? is->upcall_cycles / is->upcalls : 0);
}
}
void
pmd_perf_read_counters(struct pmd_perf_stats *s,
uint64_t stats[PMD_N_STATS])
{
uint64_t val;
/* These loops subtracts reference values (.zero[*]) from the counters.
* Since loads and stores are relaxed, it might be possible for a .zero[*]
* value to be more recent than the current value we're reading from the
* counter. This is not a big problem, since these numbers are not
* supposed to be 100% accurate, but we should at least make sure that
* the result is not negative. */
for (int i = 0; i < PMD_N_STATS; i++) {
atomic_read_relaxed(&s->counters.n[i], &val);
if (val > s->counters.zero[i]) {
stats[i] = val - s->counters.zero[i];
} else {
stats[i] = 0;
}
}
}
/* This function clears the PMD performance counters from within the PMD
* thread or from another thread when the PMD thread is not executing its
* poll loop. */
void
pmd_perf_stats_clear_lock(struct pmd_perf_stats *s)
OVS_REQUIRES(s->stats_mutex)
{
ovs_mutex_lock(&s->clear_mutex);
for (int i = 0; i < PMD_N_STATS; i++) {
atomic_read_relaxed(&s->counters.n[i], &s->counters.zero[i]);
}
/* The following stats are only applicable in PMD thread and */
memset(&s->current, 0 , sizeof(struct iter_stats));
memset(&s->totals, 0 , sizeof(struct iter_stats));
histogram_clear(&s->cycles);
histogram_clear(&s->pkts);
histogram_clear(&s->cycles_per_pkt);
histogram_clear(&s->upcalls);
histogram_clear(&s->cycles_per_upcall);
histogram_clear(&s->pkts_per_batch);
histogram_clear(&s->max_vhost_qfill);
history_init(&s->iterations);
history_init(&s->milliseconds);
s->start_ms = time_msec();
s->milliseconds.sample[0].timestamp = s->start_ms;
s->log_susp_it = UINT32_MAX;
s->log_begin_it = UINT32_MAX;
s->log_end_it = UINT32_MAX;
s->log_reason = NULL;
/* Clearing finished. */
s->clear = false;
ovs_mutex_unlock(&s->clear_mutex);
}
/* This function can be called from the anywhere to clear the stats
* of PMD and non-PMD threads. */
void
pmd_perf_stats_clear(struct pmd_perf_stats *s)
{
if (ovs_mutex_trylock(&s->stats_mutex) == 0) {
/* Locking successful. PMD not polling. */
pmd_perf_stats_clear_lock(s);
ovs_mutex_unlock(&s->stats_mutex);
} else {
/* Request the polling PMD to clear the stats. There is no need to
* block here as stats retrieval is prevented during clearing. */
s->clear = true;
}
}
/* Functions recording PMD metrics per iteration. */
void
pmd_perf_start_iteration(struct pmd_perf_stats *s)
OVS_REQUIRES(s->stats_mutex)
{
if (s->clear) {
/* Clear the PMD stats before starting next iteration. */
pmd_perf_stats_clear_lock(s);
}
s->iteration_cnt++;
/* Initialize the current interval stats. */
memset(&s->current, 0, sizeof(struct iter_stats));
if (OVS_LIKELY(s->last_tsc)) {
/* We assume here that last_tsc was updated immediately prior at
* the end of the previous iteration, or just before the first
* iteration. */
s->start_tsc = s->last_tsc;
} else {
/* In case last_tsc has never been set before. */
s->start_tsc = cycles_counter_update(s);
}
}
void
pmd_perf_end_iteration(struct pmd_perf_stats *s, int rx_packets,
int tx_packets, uint64_t sleep_cycles,
bool full_metrics)
{
uint64_t now_tsc = cycles_counter_update(s);
struct iter_stats *cum_ms;
uint64_t cycles, cycles_per_pkt = 0;
char *reason = NULL;
cycles = now_tsc - s->start_tsc - sleep_cycles;
s->current.timestamp = s->iteration_cnt;
s->current.cycles = cycles;
s->current.pkts = rx_packets;
if (rx_packets + tx_packets > 0) {
pmd_perf_update_counter(s, PMD_CYCLES_ITER_BUSY, cycles);
} else {
pmd_perf_update_counter(s, PMD_CYCLES_ITER_IDLE, cycles);
}
/* Add iteration samples to histograms. */
histogram_add_sample(&s->cycles, cycles);
histogram_add_sample(&s->pkts, rx_packets);
if (sleep_cycles) {
pmd_perf_update_counter(s, PMD_SLEEP_ITER, 1);
pmd_perf_update_counter(s, PMD_CYCLES_SLEEP, sleep_cycles);
}
if (!full_metrics) {
return;
}
s->counters.n[PMD_CYCLES_UPCALL] += s->current.upcall_cycles;
if (rx_packets > 0) {
cycles_per_pkt = cycles / rx_packets;
histogram_add_sample(&s->cycles_per_pkt, cycles_per_pkt);
}
histogram_add_sample(&s->upcalls, s->current.upcalls);
histogram_add_sample(&s->max_vhost_qfill, s->current.max_vhost_qfill);
/* Add iteration samples to millisecond stats. */
cum_ms = history_current(&s->milliseconds);
cum_ms->iterations++;
cum_ms->cycles += cycles;
if (rx_packets > 0) {
cum_ms->busy_cycles += cycles;
}
cum_ms->pkts += s->current.pkts;
cum_ms->upcalls += s->current.upcalls;
cum_ms->upcall_cycles += s->current.upcall_cycles;
cum_ms->batches += s->current.batches;
cum_ms->max_vhost_qfill += s->current.max_vhost_qfill;
if (log_enabled) {
/* Log suspicious iterations. */
if (cycles > iter_cycle_threshold) {
reason = "Excessive total cycles";
} else if (s->current.max_vhost_qfill >= log_q_thr) {
reason = "Vhost RX queue full";
}
if (OVS_UNLIKELY(reason)) {
pmd_perf_set_log_susp_iteration(s, reason);
cycles_counter_update(s);
}
/* Log iteration interval around suspicious iteration when reaching
* the end of the range to be logged. */
if (OVS_UNLIKELY(s->log_end_it == s->iterations.idx)) {
pmd_perf_log_susp_iteration_neighborhood(s);
cycles_counter_update(s);
}
}
/* Store in iteration history. This advances the iteration idx and
* clears the next slot in the iteration history. */
history_store(&s->iterations, &s->current);
if (now_tsc > s->next_check_tsc) {
/* Check if ms is completed and store in milliseconds history. */
uint64_t now = time_msec();
if (now != cum_ms->timestamp) {
/* Add ms stats to totals. */
s->totals.iterations += cum_ms->iterations;
s->totals.cycles += cum_ms->cycles;
s->totals.busy_cycles += cum_ms->busy_cycles;
s->totals.pkts += cum_ms->pkts;
s->totals.upcalls += cum_ms->upcalls;
s->totals.upcall_cycles += cum_ms->upcall_cycles;
s->totals.batches += cum_ms->batches;
s->totals.max_vhost_qfill += cum_ms->max_vhost_qfill;
cum_ms = history_next(&s->milliseconds);
cum_ms->timestamp = now;
}
/* Do the next check after 4 us (10K cycles at 2.5 GHz TSC clock). */
s->next_check_tsc = cycles_counter_update(s) + tsc_hz / 250000;
}
}
/* Delay logging of the suspicious iteration and the range of iterations
* around it until after the last iteration in the range to be logged.
* This avoids any distortion of the measurements through the cost of
* logging itself. */
void
pmd_perf_set_log_susp_iteration(struct pmd_perf_stats *s,
char *reason)
{
if (s->log_susp_it == UINT32_MAX) {
/* No logging scheduled yet. */
s->log_susp_it = s->iterations.idx;
s->log_reason = reason;
s->log_begin_it = history_sub(s->iterations.idx, log_it_before);
s->log_end_it = history_add(s->iterations.idx, log_it_after + 1);
} else if (log_extend) {
/* Logging was initiated earlier, we log the previous suspicious
* iteration now and extend the logging interval, if possible. */
struct iter_stats *susp = &s->iterations.sample[s->log_susp_it];
uint32_t new_end_it, old_range, new_range;
VLOG_WARN_RL(&latency_rl,
"Suspicious iteration (%s): iter=%"PRIu64
" duration=%"PRIu64" us\n",
s->log_reason,
susp->timestamp,
(1000000L * susp->cycles) / tsc_hz);
new_end_it = history_add(s->iterations.idx, log_it_after + 1);
new_range = history_sub(new_end_it, s->log_begin_it);
old_range = history_sub(s->log_end_it, s->log_begin_it);
if (new_range < old_range) {
/* Extended range exceeds history length. */
new_end_it = s->log_begin_it;
}
s->log_susp_it = s->iterations.idx;
s->log_reason = reason;
s->log_end_it = new_end_it;
}
}
void
pmd_perf_log_susp_iteration_neighborhood(struct pmd_perf_stats *s)
{
ovs_assert(s->log_reason != NULL);
ovs_assert(s->log_susp_it != UINT32_MAX);
struct ds log = DS_EMPTY_INITIALIZER;
struct iter_stats *susp = &s->iterations.sample[s->log_susp_it];
uint32_t range = history_sub(s->log_end_it, s->log_begin_it);
VLOG_WARN_RL(&latency_rl,
"Suspicious iteration (%s): iter=%"PRIu64
" duration=%"PRIu64" us\n",
s->log_reason,
susp->timestamp,
(1000000L * susp->cycles) / tsc_hz);
pmd_perf_format_iteration_history(&log, s, range);
VLOG_WARN_RL(&latency_rl,
"Neighborhood of suspicious iteration:\n"
"%s", ds_cstr(&log));
ds_destroy(&log);
s->log_susp_it = s->log_end_it = s->log_begin_it = UINT32_MAX;
s->log_reason = NULL;
if (range > 100) {
/* Reset to safe default values to avoid disturbance. */
log_it_before = LOG_IT_BEFORE;
log_it_after = LOG_IT_AFTER;
log_extend = false;
}
}
void
pmd_perf_log_set_cmd(struct unixctl_conn *conn,
int argc, const char *argv[],
void *aux OVS_UNUSED)
{
unsigned int it_before, it_after, us_thr, q_thr;
bool on, extend;
bool usage = false;
on = log_enabled;
extend = log_extend;
it_before = log_it_before;
it_after = log_it_after;
q_thr = log_q_thr;
us_thr = log_us_thr;
while (argc > 1) {
if (!strcmp(argv[1], "on")) {
on = true;
argc--;
argv++;
} else if (!strcmp(argv[1], "off")) {
on = false;
argc--;
argv++;
} else if (!strcmp(argv[1], "-e")) {
extend = true;
argc--;
argv++;
} else if (!strcmp(argv[1], "-ne")) {
extend = false;
argc--;
argv++;
} else if (!strcmp(argv[1], "-a") && argc > 2) {
if (str_to_uint(argv[2], 10, &it_after)) {
if (it_after > HISTORY_LEN - 2) {
it_after = HISTORY_LEN - 2;
}
} else {
usage = true;
break;
}
argc -= 2;
argv += 2;
} else if (!strcmp(argv[1], "-b") && argc > 2) {
if (str_to_uint(argv[2], 10, &it_before)) {
if (it_before > HISTORY_LEN - 2) {
it_before = HISTORY_LEN - 2;
}
} else {
usage = true;
break;
}
argc -= 2;
argv += 2;
} else if (!strcmp(argv[1], "-q") && argc > 2) {
if (!str_to_uint(argv[2], 10, &q_thr)) {
usage = true;
break;
}
argc -= 2;
argv += 2;
} else if (!strcmp(argv[1], "-us") && argc > 2) {
if (!str_to_uint(argv[2], 10, &us_thr)) {
usage = true;
break;
}
argc -= 2;
argv += 2;
} else {
usage = true;
break;
}
}
if (it_before + it_after > HISTORY_LEN - 2) {
it_after = HISTORY_LEN - 2 - it_before;
}
if (usage) {
unixctl_command_reply_error(conn,
"Usage: ovs-appctl dpif-netdev/pmd-perf-log-set "
"[on|off] [-b before] [-a after] [-e|-ne] "
"[-us usec] [-q qlen]");
return;
}
VLOG_INFO("pmd-perf-log-set: %s, before=%d, after=%d, extend=%s, "
"us_thr=%d, q_thr=%d\n",
on ? "on" : "off", it_before, it_after,
extend ? "true" : "false", us_thr, q_thr);
log_enabled = on;
log_extend = extend;
log_it_before = it_before;
log_it_after = it_after;
log_q_thr = q_thr;
log_us_thr = us_thr;
iter_cycle_threshold = (log_us_thr * tsc_hz) / 1000000L;
unixctl_command_reply(conn, "");
}
Reference in New Issue View Git Blame Copy Permalink