lib/dpif-netdev-perf.c

   1 /*
   2  * Copyright (c) 2017 Ericsson AB.
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at:
   7  *
   8  *     http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16
  17 #include <config.h>
  18 #include <stdint.h>
  19
  20 #include "dpif-netdev-perf.h"
  21 #include "openvswitch/dynamic-string.h"
  22 #include "openvswitch/vlog.h"
  23 #include "ovs-thread.h"
  24 #include "timeval.h"
  25
  26 VLOG_DEFINE_THIS_MODULE(pmd_perf);
  27
  28 #define ITER_US_THRESHOLD 250   /* Warning threshold for iteration duration
  29                                    in microseconds. */
  30 #define VHOST_QUEUE_FULL 128    /* Size of the virtio TX queue. */
  31 #define LOG_IT_BEFORE 5         /* Number of iterations to log before
  32                                    suspicious iteration. */
  33 #define LOG_IT_AFTER 5          /* Number of iterations to log after
  34                                    suspicious iteration. */
  35
  36 bool log_enabled = false;
  37 bool log_extend = false;
  38 static uint32_t log_it_before = LOG_IT_BEFORE;
  39 static uint32_t log_it_after = LOG_IT_AFTER;
  40 static uint32_t log_us_thr = ITER_US_THRESHOLD;
  41 uint32_t log_q_thr = VHOST_QUEUE_FULL;
  42 uint64_t iter_cycle_threshold;
  43
  44 static struct vlog_rate_limit latency_rl = VLOG_RATE_LIMIT_INIT(600, 600);
  45
  46 #ifdef DPDK_NETDEV
  47 static uint64_t
  48 get_tsc_hz(void)
  49 {
  50     return rte_get_tsc_hz();
  51 }
  52 #else
  53 /* This function is only invoked from PMD threads which depend on DPDK.
  54  * A dummy function is sufficient when building without DPDK_NETDEV. */
  55 static uint64_t
  56 get_tsc_hz(void)
  57 {
  58     return 1;
  59 }
  60 #endif
  61
  62 /* Histogram functions. */
  63
  64 static void
  65 histogram_walls_set_lin(struct histogram *hist, uint32_t min, uint32_t max)
  66 {
  67     int i;
  68
  69     ovs_assert(min < max);
  70     for (i = 0; i < NUM_BINS-1; i++) {
  71         hist->wall[i] = min + (i * (max - min)) / (NUM_BINS - 2);
  72     }
  73     hist->wall[NUM_BINS-1] = UINT32_MAX;
  74 }
  75
  76 static void
  77 histogram_walls_set_log(struct histogram *hist, uint32_t min, uint32_t max)
  78 {
  79     int i, start, bins, wall;
  80     double log_min, log_max;
  81
  82     ovs_assert(min < max);
  83     if (min > 0) {
  84         log_min = log(min);
  85         log_max = log(max);
  86         start = 0;
  87         bins = NUM_BINS - 1;
  88     } else {
  89         hist->wall[0] = 0;
  90         log_min = log(1);
  91         log_max = log(max);
  92         start = 1;
  93         bins = NUM_BINS - 2;
  94     }
  95     wall = start;
  96     for (i = 0; i < bins; i++) {
  97         /* Make sure each wall is monotonically increasing. */
  98         wall = MAX(wall, exp(log_min + (i * (log_max - log_min)) / (bins-1)));
  99         hist->wall[start + i] = wall++;
 100     }
 101     if (hist->wall[NUM_BINS-2] < max) {
 102         hist->wall[NUM_BINS-2] = max;
 103     }
 104     hist->wall[NUM_BINS-1] = UINT32_MAX;
 105 }
 106
 107 uint64_t
 108 histogram_samples(const struct histogram *hist)
 109 {
 110     uint64_t samples = 0;
 111
 112     for (int i = 0; i < NUM_BINS; i++) {
 113         samples += hist->bin[i];
 114     }
 115     return samples;
 116 }
 117
 118 static void
 119 histogram_clear(struct histogram *hist)
 120 {
 121     int i;
 122
 123     for (i = 0; i < NUM_BINS; i++) {
 124         hist->bin[i] = 0;
 125     }
 126 }
 127
 128 static void
 129 history_init(struct history *h)
 130 {
 131     memset(h, 0, sizeof(*h));
 132 }
 133
 134 void
 135 pmd_perf_stats_init(struct pmd_perf_stats *s)
 136 {
 137     memset(s, 0, sizeof(*s));
 138     ovs_mutex_init(&s->stats_mutex);
 139     ovs_mutex_init(&s->clear_mutex);
 140     /* Logarithmic histogram for cycles/it ranging from 500 to 24M
 141      * (corresponding to 200 ns to 9.6 ms at 2.5 GHz TSC clock). */
 142     histogram_walls_set_log(&s->cycles, 500, 24000000);
 143     /* Logarithmic histogram for pkts/it ranging from 0 to 1000. */
 144     histogram_walls_set_log(&s->pkts, 0, 1000);
 145     /* Linear histogram for cycles/pkt ranging from 100 to 30K. */
 146     histogram_walls_set_lin(&s->cycles_per_pkt, 100, 30000);
 147     /* Linear histogram for pkts/rx batch ranging from 0 to 32,
 148      * the maximum rx batch size in OVS. */
 149     histogram_walls_set_lin(&s->pkts_per_batch, 0, 32);
 150     /* Linear histogram for upcalls/it ranging from 0 to 30. */
 151     histogram_walls_set_lin(&s->upcalls, 0, 30);
 152     /* Logarithmic histogram for cycles/upcall ranging from 1000 to 1M
 153      * (corresponding to 400 ns to 400 us at 2.5 GHz TSC clock). */
 154     histogram_walls_set_log(&s->cycles_per_upcall, 1000, 1000000);
 155     /* Log. histogram for max vhostuser queue fill level from 0 to 512.
 156      * 512 is the maximum fill level for a virtio queue with 1024
 157      * descriptors (maximum configurable length in Qemu), with the
 158      * DPDK 17.11 virtio PMD in the guest. */
 159     histogram_walls_set_log(&s->max_vhost_qfill, 0, 512);
 160     s->iteration_cnt = 0;
 161     s->start_ms = time_msec();
 162     s->log_susp_it = UINT32_MAX;
 163     s->log_begin_it = UINT32_MAX;
 164     s->log_end_it = UINT32_MAX;
 165     s->log_reason = NULL;
 166 }
 167
 168 void
 169 pmd_perf_format_overall_stats(struct ds *str, struct pmd_perf_stats *s,
 170                               double duration)
 171 {
 172     uint64_t stats[PMD_N_STATS];
 173     double us_per_cycle = 1000000.0 / get_tsc_hz();
 174
 175     if (duration == 0) {
 176         return;
 177     }
 178
 179     pmd_perf_read_counters(s, stats);
 180     uint64_t tot_cycles = stats[PMD_CYCLES_ITER_IDLE] +
 181                           stats[PMD_CYCLES_ITER_BUSY];
 182     uint64_t rx_packets = stats[PMD_STAT_RECV];
 183     uint64_t tx_packets = stats[PMD_STAT_SENT_PKTS];
 184     uint64_t tx_batches = stats[PMD_STAT_SENT_BATCHES];
 185     uint64_t passes = stats[PMD_STAT_RECV] +
 186                       stats[PMD_STAT_RECIRC];
 187     uint64_t upcalls = stats[PMD_STAT_MISS];
 188     uint64_t upcall_cycles = stats[PMD_CYCLES_UPCALL];
 189     uint64_t tot_iter = histogram_samples(&s->pkts);
 190     uint64_t idle_iter = s->pkts.bin[0];
 191     uint64_t busy_iter = tot_iter >= idle_iter ? tot_iter - idle_iter : 0;
 192
 193     ds_put_format(str,
 194             "  Cycles:          %12"PRIu64"  (%.2f GHz)\n"
 195             "  Iterations:      %12"PRIu64"  (%.2f us/it)\n"
 196             "  - idle:          %12"PRIu64"  (%4.1f %% cycles)\n"
 197             "  - busy:          %12"PRIu64"  (%4.1f %% cycles)\n",
 198             tot_cycles, (tot_cycles / duration) / 1E9,
 199             tot_iter, tot_cycles * us_per_cycle / tot_iter,
 200             idle_iter,
 201             100.0 * stats[PMD_CYCLES_ITER_IDLE] / tot_cycles,
 202             busy_iter,
 203             100.0 * stats[PMD_CYCLES_ITER_BUSY] / tot_cycles);
 204     if (rx_packets > 0) {
 205         ds_put_format(str,
 206             "  Rx packets:      %12"PRIu64"  (%.0f Kpps, %.0f cycles/pkt)\n"
 207             "  Datapath passes: %12"PRIu64"  (%.2f passes/pkt)\n"
 208             "  - EMC hits:      %12"PRIu64"  (%4.1f %%)\n"
 209             "  - Megaflow hits: %12"PRIu64"  (%4.1f %%, %.2f subtbl lookups/"
 210                                                                      "hit)\n"
 211             "  - Upcalls:       %12"PRIu64"  (%4.1f %%, %.1f us/upcall)\n"
 212             "  - Lost upcalls:  %12"PRIu64"  (%4.1f %%)\n",
 213             rx_packets, (rx_packets / duration) / 1000,
 214             1.0 * stats[PMD_CYCLES_ITER_BUSY] / rx_packets,
 215             passes, rx_packets ? 1.0 * passes / rx_packets : 0,
 216             stats[PMD_STAT_EXACT_HIT],
 217             100.0 * stats[PMD_STAT_EXACT_HIT] / passes,
 218             stats[PMD_STAT_MASKED_HIT],
 219             100.0 * stats[PMD_STAT_MASKED_HIT] / passes,
 220             stats[PMD_STAT_MASKED_HIT]
 221             ? 1.0 * stats[PMD_STAT_MASKED_LOOKUP] / stats[PMD_STAT_MASKED_HIT]
 222             : 0,
 223             upcalls, 100.0 * upcalls / passes,
 224             upcalls ? (upcall_cycles * us_per_cycle) / upcalls : 0,
 225             stats[PMD_STAT_LOST],
 226             100.0 * stats[PMD_STAT_LOST] / passes);
 227     } else {
 228         ds_put_format(str, "  Rx packets:      %12d\n", 0);
 229     }
 230     if (tx_packets > 0) {
 231         ds_put_format(str,
 232             "  Tx packets:      %12"PRIu64"  (%.0f Kpps)\n"
 233             "  Tx batches:      %12"PRIu64"  (%.2f pkts/batch)"
 234             "\n",
 235             tx_packets, (tx_packets / duration) / 1000,
 236             tx_batches, 1.0 * tx_packets / tx_batches);
 237     } else {
 238         ds_put_format(str, "  Tx packets:      %12d\n\n", 0);
 239     }
 240 }
 241
 242 void
 243 pmd_perf_format_histograms(struct ds *str, struct pmd_perf_stats *s)
 244 {
 245     int i;
 246
 247     ds_put_cstr(str, "Histograms\n");
 248     ds_put_format(str,
 249                   "   %-21s  %-21s  %-21s  %-21s  %-21s  %-21s  %-21s\n",
 250                   "cycles/it", "packets/it", "cycles/pkt", "pkts/batch",
 251                   "max vhost qlen", "upcalls/it", "cycles/upcall");
 252     for (i = 0; i < NUM_BINS-1; i++) {
 253         ds_put_format(str,
 254             "   %-9d %-11"PRIu64"  %-9d %-11"PRIu64"  %-9d %-11"PRIu64
 255             "  %-9d %-11"PRIu64"  %-9d %-11"PRIu64"  %-9d %-11"PRIu64
 256             "  %-9d %-11"PRIu64"\n",
 257             s->cycles.wall[i], s->cycles.bin[i],
 258             s->pkts.wall[i],s->pkts.bin[i],
 259             s->cycles_per_pkt.wall[i], s->cycles_per_pkt.bin[i],
 260             s->pkts_per_batch.wall[i], s->pkts_per_batch.bin[i],
 261             s->max_vhost_qfill.wall[i], s->max_vhost_qfill.bin[i],
 262             s->upcalls.wall[i], s->upcalls.bin[i],
 263             s->cycles_per_upcall.wall[i], s->cycles_per_upcall.bin[i]);
 264     }
 265     ds_put_format(str,
 266                   "   %-9s %-11"PRIu64"  %-9s %-11"PRIu64"  %-9s %-11"PRIu64
 267                   "  %-9s %-11"PRIu64"  %-9s %-11"PRIu64"  %-9s %-11"PRIu64
 268                   "  %-9s %-11"PRIu64"\n",
 269                   ">", s->cycles.bin[i],
 270                   ">", s->pkts.bin[i],
 271                   ">", s->cycles_per_pkt.bin[i],
 272                   ">", s->pkts_per_batch.bin[i],
 273                   ">", s->max_vhost_qfill.bin[i],
 274                   ">", s->upcalls.bin[i],
 275                   ">", s->cycles_per_upcall.bin[i]);
 276     if (s->totals.iterations > 0) {
 277         ds_put_cstr(str,
 278                     "-----------------------------------------------------"
 279                     "-----------------------------------------------------"
 280                     "------------------------------------------------\n");
 281         ds_put_format(str,
 282                       "   %-21s  %-21s  %-21s  %-21s  %-21s  %-21s  %-21s\n",
 283                       "cycles/it", "packets/it", "cycles/pkt", "pkts/batch",
 284                       "vhost qlen", "upcalls/it", "cycles/upcall");
 285         ds_put_format(str,
 286                       "   %-21"PRIu64"  %-21.5f  %-21"PRIu64
 287                       "  %-21.5f  %-21.5f  %-21.5f  %-21"PRIu32"\n",
 288                       s->totals.cycles / s->totals.iterations,
 289                       1.0 * s->totals.pkts / s->totals.iterations,
 290                       s->totals.pkts
 291                           ? s->totals.busy_cycles / s->totals.pkts : 0,
 292                       s->totals.batches
 293                           ? 1.0 * s->totals.pkts / s->totals.batches : 0,
 294                       1.0 * s->totals.max_vhost_qfill / s->totals.iterations,
 295                       1.0 * s->totals.upcalls / s->totals.iterations,
 296                       s->totals.upcalls
 297                           ? s->totals.upcall_cycles / s->totals.upcalls : 0);
 298     }
 299 }
 300
 301 void
 302 pmd_perf_format_iteration_history(struct ds *str, struct pmd_perf_stats *s,
 303                                   int n_iter)
 304 {
 305     struct iter_stats *is;
 306     size_t index;
 307     int i;
 308
 309     if (n_iter == 0) {
 310         return;
 311     }
 312     ds_put_format(str, "   %-17s   %-10s   %-10s   %-10s   %-10s   "
 313                   "%-10s   %-10s   %-10s\n",
 314                   "iter", "cycles", "packets", "cycles/pkt", "pkts/batch",
 315                   "vhost qlen", "upcalls", "cycles/upcall");
 316     for (i = 1; i <= n_iter; i++) {
 317         index = history_sub(s->iterations.idx, i);
 318         is = &s->iterations.sample[index];
 319         ds_put_format(str,
 320                       "   %-17"PRIu64"   %-11"PRIu64"  %-11"PRIu32
 321                       "  %-11"PRIu64"  %-11"PRIu32"  %-11"PRIu32
 322                       "  %-11"PRIu32"  %-11"PRIu32"\n",
 323                       is->timestamp,
 324                       is->cycles,
 325                       is->pkts,
 326                       is->pkts ? is->cycles / is->pkts : 0,
 327                       is->batches ? is->pkts / is->batches : 0,
 328                       is->max_vhost_qfill,
 329                       is->upcalls,
 330                       is->upcalls ? is->upcall_cycles / is->upcalls : 0);
 331     }
 332 }
 333
 334 void
 335 pmd_perf_format_ms_history(struct ds *str, struct pmd_perf_stats *s, int n_ms)
 336 {
 337     struct iter_stats *is;
 338     size_t index;
 339     int i;
 340
 341     if (n_ms == 0) {
 342         return;
 343     }
 344     ds_put_format(str,
 345                   "   %-12s   %-10s   %-10s   %-10s   %-10s"
 346                   "   %-10s   %-10s   %-10s   %-10s\n",
 347                   "ms", "iterations", "cycles/it", "Kpps", "cycles/pkt",
 348                   "pkts/batch", "vhost qlen", "upcalls", "cycles/upcall");
 349     for (i = 1; i <= n_ms; i++) {
 350         index = history_sub(s->milliseconds.idx, i);
 351         is = &s->milliseconds.sample[index];
 352         ds_put_format(str,
 353                       "   %-12"PRIu64"   %-11"PRIu32"  %-11"PRIu64
 354                       "  %-11"PRIu32"  %-11"PRIu64"  %-11"PRIu32
 355                       "  %-11"PRIu32"  %-11"PRIu32"  %-11"PRIu32"\n",
 356                       is->timestamp,
 357                       is->iterations,
 358                       is->iterations ? is->cycles / is->iterations : 0,
 359                       is->pkts,
 360                       is->pkts ? is->busy_cycles / is->pkts : 0,
 361                       is->batches ? is->pkts / is->batches : 0,
 362                       is->iterations
 363                           ? is->max_vhost_qfill / is->iterations : 0,
 364                       is->upcalls,
 365                       is->upcalls ? is->upcall_cycles / is->upcalls : 0);
 366     }
 367 }
 368
 369 void
 370 pmd_perf_read_counters(struct pmd_perf_stats *s,
 371                        uint64_t stats[PMD_N_STATS])
 372 {
 373     uint64_t val;
 374
 375     /* These loops subtracts reference values (.zero[*]) from the counters.
 376      * Since loads and stores are relaxed, it might be possible for a .zero[*]
 377      * value to be more recent than the current value we're reading from the
 378      * counter.  This is not a big problem, since these numbers are not
 379      * supposed to be 100% accurate, but we should at least make sure that
 380      * the result is not negative. */
 381     for (int i = 0; i < PMD_N_STATS; i++) {
 382         atomic_read_relaxed(&s->counters.n[i], &val);
 383         if (val > s->counters.zero[i]) {
 384             stats[i] = val - s->counters.zero[i];
 385         } else {
 386             stats[i] = 0;
 387         }
 388     }
 389 }
 390
 391 /* This function clears the PMD performance counters from within the PMD
 392  * thread or from another thread when the PMD thread is not executing its
 393  * poll loop. */
 394 void
 395 pmd_perf_stats_clear_lock(struct pmd_perf_stats *s)
 396     OVS_REQUIRES(s->stats_mutex)
 397 {
 398     ovs_mutex_lock(&s->clear_mutex);
 399     for (int i = 0; i < PMD_N_STATS; i++) {
 400         atomic_read_relaxed(&s->counters.n[i], &s->counters.zero[i]);
 401     }
 402     /* The following stats are only applicable in PMD thread and */
 403     memset(&s->current, 0 , sizeof(struct iter_stats));
 404     memset(&s->totals, 0 , sizeof(struct iter_stats));
 405     histogram_clear(&s->cycles);
 406     histogram_clear(&s->pkts);
 407     histogram_clear(&s->cycles_per_pkt);
 408     histogram_clear(&s->upcalls);
 409     histogram_clear(&s->cycles_per_upcall);
 410     histogram_clear(&s->pkts_per_batch);
 411     histogram_clear(&s->max_vhost_qfill);
 412     history_init(&s->iterations);
 413     history_init(&s->milliseconds);
 414     s->start_ms = time_msec();
 415     s->milliseconds.sample[0].timestamp = s->start_ms;
 416     s->log_susp_it = UINT32_MAX;
 417     s->log_begin_it = UINT32_MAX;
 418     s->log_end_it = UINT32_MAX;
 419     s->log_reason = NULL;
 420     /* Clearing finished. */
 421     s->clear = false;
 422     ovs_mutex_unlock(&s->clear_mutex);
 423 }
 424
 425 /* This function can be called from the anywhere to clear the stats
 426  * of PMD and non-PMD threads. */
 427 void
 428 pmd_perf_stats_clear(struct pmd_perf_stats *s)
 429 {
 430     if (ovs_mutex_trylock(&s->stats_mutex) == 0) {
 431         /* Locking successful. PMD not polling. */
 432         pmd_perf_stats_clear_lock(s);
 433         ovs_mutex_unlock(&s->stats_mutex);
 434     } else {
 435         /* Request the polling PMD to clear the stats. There is no need to
 436          * block here as stats retrieval is prevented during clearing. */
 437         s->clear = true;
 438     }
 439 }
 440
 441 /* Functions recording PMD metrics per iteration. */
 442
 443 inline void
 444 pmd_perf_start_iteration(struct pmd_perf_stats *s)
 445 OVS_REQUIRES(s->stats_mutex)
 446 {
 447     if (s->clear) {
 448         /* Clear the PMD stats before starting next iteration. */
 449         pmd_perf_stats_clear_lock(s);
 450     }
 451     s->iteration_cnt++;
 452     /* Initialize the current interval stats. */
 453     memset(&s->current, 0, sizeof(struct iter_stats));
 454     if (OVS_LIKELY(s->last_tsc)) {
 455         /* We assume here that last_tsc was updated immediately prior at
 456          * the end of the previous iteration, or just before the first
 457          * iteration. */
 458         s->start_tsc = s->last_tsc;
 459     } else {
 460         /* In case last_tsc has never been set before. */
 461         s->start_tsc = cycles_counter_update(s);
 462     }
 463 }
 464
 465 inline void
 466 pmd_perf_end_iteration(struct pmd_perf_stats *s, int rx_packets,
 467                        int tx_packets, bool full_metrics)
 468 {
 469     uint64_t now_tsc = cycles_counter_update(s);
 470     struct iter_stats *cum_ms;
 471     uint64_t cycles, cycles_per_pkt = 0;
 472     char *reason = NULL;
 473
 474     cycles = now_tsc - s->start_tsc;
 475     s->current.timestamp = s->iteration_cnt;
 476     s->current.cycles = cycles;
 477     s->current.pkts = rx_packets;
 478
 479     if (rx_packets + tx_packets > 0) {
 480         pmd_perf_update_counter(s, PMD_CYCLES_ITER_BUSY, cycles);
 481     } else {
 482         pmd_perf_update_counter(s, PMD_CYCLES_ITER_IDLE, cycles);
 483     }
 484     /* Add iteration samples to histograms. */
 485     histogram_add_sample(&s->cycles, cycles);
 486     histogram_add_sample(&s->pkts, rx_packets);
 487
 488     if (!full_metrics) {
 489         return;
 490     }
 491
 492     s->counters.n[PMD_CYCLES_UPCALL] += s->current.upcall_cycles;
 493
 494     if (rx_packets > 0) {
 495         cycles_per_pkt = cycles / rx_packets;
 496         histogram_add_sample(&s->cycles_per_pkt, cycles_per_pkt);
 497     }
 498     if (s->current.batches > 0) {
 499         histogram_add_sample(&s->pkts_per_batch,
 500                              rx_packets / s->current.batches);
 501     }
 502     histogram_add_sample(&s->upcalls, s->current.upcalls);
 503     if (s->current.upcalls > 0) {
 504         histogram_add_sample(&s->cycles_per_upcall,
 505                              s->current.upcall_cycles / s->current.upcalls);
 506     }
 507     histogram_add_sample(&s->max_vhost_qfill, s->current.max_vhost_qfill);
 508
 509     /* Add iteration samples to millisecond stats. */
 510     cum_ms = history_current(&s->milliseconds);
 511     cum_ms->iterations++;
 512     cum_ms->cycles += cycles;
 513     if (rx_packets > 0) {
 514         cum_ms->busy_cycles += cycles;
 515     }
 516     cum_ms->pkts += s->current.pkts;
 517     cum_ms->upcalls += s->current.upcalls;
 518     cum_ms->upcall_cycles += s->current.upcall_cycles;
 519     cum_ms->batches += s->current.batches;
 520     cum_ms->max_vhost_qfill += s->current.max_vhost_qfill;
 521
 522     if (log_enabled) {
 523         /* Log suspicious iterations. */
 524         if (cycles > iter_cycle_threshold) {
 525             reason = "Excessive total cycles";
 526         } else if (s->current.max_vhost_qfill >= log_q_thr) {
 527             reason = "Vhost RX queue full";
 528         }
 529         if (OVS_UNLIKELY(reason)) {
 530             pmd_perf_set_log_susp_iteration(s, reason);
 531             cycles_counter_update(s);
 532         }
 533
 534         /* Log iteration interval around suspicious iteration when reaching
 535          * the end of the range to be logged. */
 536         if (OVS_UNLIKELY(s->log_end_it == s->iterations.idx)) {
 537             pmd_perf_log_susp_iteration_neighborhood(s);
 538             cycles_counter_update(s);
 539         }
 540     }
 541
 542     /* Store in iteration history. This advances the iteration idx and
 543      * clears the next slot in the iteration history. */
 544     history_store(&s->iterations, &s->current);
 545
 546     if (now_tsc > s->next_check_tsc) {
 547         /* Check if ms is completed and store in milliseconds history. */
 548         uint64_t now = time_msec();
 549         if (now != cum_ms->timestamp) {
 550             /* Add ms stats to totals. */
 551             s->totals.iterations += cum_ms->iterations;
 552             s->totals.cycles += cum_ms->cycles;
 553             s->totals.busy_cycles += cum_ms->busy_cycles;
 554             s->totals.pkts += cum_ms->pkts;
 555             s->totals.upcalls += cum_ms->upcalls;
 556             s->totals.upcall_cycles += cum_ms->upcall_cycles;
 557             s->totals.batches += cum_ms->batches;
 558             s->totals.max_vhost_qfill += cum_ms->max_vhost_qfill;
 559             cum_ms = history_next(&s->milliseconds);
 560             cum_ms->timestamp = now;
 561         }
 562         /* Do the next check after 10K cycles (4 us at 2.5 GHz TSC clock). */
 563         s->next_check_tsc = cycles_counter_update(s) + 10000;
 564     }
 565 }
 566
 567 /* Delay logging of the suspicious iteration and the range of iterations
 568  * around it until after the last iteration in the range to be logged.
 569  * This avoids any distortion of the measurements through the cost of
 570  * logging itself. */
 571
 572 void
 573 pmd_perf_set_log_susp_iteration(struct pmd_perf_stats *s,
 574                                 char *reason)
 575 {
 576     if (s->log_susp_it == UINT32_MAX) {
 577         /* No logging scheduled yet. */
 578         s->log_susp_it = s->iterations.idx;
 579         s->log_reason = reason;
 580         s->log_begin_it = history_sub(s->iterations.idx, log_it_before);
 581         s->log_end_it = history_add(s->iterations.idx, log_it_after + 1);
 582     } else if (log_extend) {
 583         /* Logging was initiated earlier, we log the previous suspicious
 584          * iteration now and extend the logging interval, if possible. */
 585         struct iter_stats *susp = &s->iterations.sample[s->log_susp_it];
 586         uint32_t new_end_it, old_range, new_range;
 587
 588         VLOG_WARN_RL(&latency_rl,
 589                 "Suspicious iteration (%s): iter=%"PRIu64
 590                 " duration=%"PRIu64" us\n",
 591                 s->log_reason,
 592                 susp->timestamp,
 593                 (1000000L * susp->cycles) / get_tsc_hz());
 594
 595         new_end_it = history_add(s->iterations.idx, log_it_after + 1);
 596         new_range = history_sub(new_end_it, s->log_begin_it);
 597         old_range = history_sub(s->log_end_it, s->log_begin_it);
 598         if (new_range < old_range) {
 599             /* Extended range exceeds history length. */
 600             new_end_it = s->log_begin_it;
 601         }
 602         s->log_susp_it = s->iterations.idx;
 603         s->log_reason = reason;
 604         s->log_end_it = new_end_it;
 605     }
 606 }
 607
 608 void
 609 pmd_perf_log_susp_iteration_neighborhood(struct pmd_perf_stats *s)
 610 {
 611     ovs_assert(s->log_reason != NULL);
 612     ovs_assert(s->log_susp_it != UINT32_MAX);
 613
 614     struct ds log = DS_EMPTY_INITIALIZER;
 615     struct iter_stats *susp = &s->iterations.sample[s->log_susp_it];
 616     uint32_t range = history_sub(s->log_end_it, s->log_begin_it);
 617
 618     VLOG_WARN_RL(&latency_rl,
 619                  "Suspicious iteration (%s): iter=%"PRIu64
 620                  " duration=%"PRIu64" us\n",
 621                  s->log_reason,
 622                  susp->timestamp,
 623                  (1000000L * susp->cycles) / get_tsc_hz());
 624
 625     pmd_perf_format_iteration_history(&log, s, range);
 626     VLOG_WARN_RL(&latency_rl,
 627                  "Neighborhood of suspicious iteration:\n"
 628                  "%s", ds_cstr(&log));
 629     ds_destroy(&log);
 630     s->log_susp_it = s->log_end_it = s->log_begin_it = UINT32_MAX;
 631     s->log_reason = NULL;
 632
 633     if (range > 100) {
 634         /* Reset to safe default values to avoid disturbance. */
 635         log_it_before = LOG_IT_BEFORE;
 636         log_it_after = LOG_IT_AFTER;
 637         log_extend = false;
 638     }
 639 }
 640
 641 void
 642 pmd_perf_log_set_cmd(struct unixctl_conn *conn,
 643                  int argc, const char *argv[],
 644                  void *aux OVS_UNUSED)
 645 {
 646     unsigned int it_before, it_after, us_thr, q_thr;
 647     bool on, extend;
 648     bool usage = false;
 649
 650     on = log_enabled;
 651     extend = log_extend;
 652     it_before = log_it_before;
 653     it_after = log_it_after;
 654     q_thr = log_q_thr;
 655     us_thr = log_us_thr;
 656
 657     while (argc > 1) {
 658         if (!strcmp(argv[1], "on")) {
 659             on = true;
 660             argc--;
 661             argv++;
 662         } else if (!strcmp(argv[1], "off")) {
 663             on = false;
 664             argc--;
 665             argv++;
 666         } else if (!strcmp(argv[1], "-e")) {
 667             extend = true;
 668             argc--;
 669             argv++;
 670         } else if (!strcmp(argv[1], "-ne")) {
 671             extend = false;
 672             argc--;
 673             argv++;
 674         } else if (!strcmp(argv[1], "-a") && argc > 2) {
 675             if (str_to_uint(argv[2], 10, &it_after)) {
 676                 if (it_after > HISTORY_LEN - 2) {
 677                     it_after = HISTORY_LEN - 2;
 678                 }
 679             } else {
 680                 usage = true;
 681                 break;
 682             }
 683             argc -= 2;
 684             argv += 2;
 685         } else if (!strcmp(argv[1], "-b") && argc > 2) {
 686             if (str_to_uint(argv[2], 10, &it_before)) {
 687                 if (it_before > HISTORY_LEN - 2) {
 688                     it_before = HISTORY_LEN - 2;
 689                 }
 690             } else {
 691                 usage = true;
 692                 break;
 693             }
 694             argc -= 2;
 695             argv += 2;
 696         } else if (!strcmp(argv[1], "-q") && argc > 2) {
 697             if (!str_to_uint(argv[2], 10, &q_thr)) {
 698                 usage = true;
 699                 break;
 700             }
 701             argc -= 2;
 702             argv += 2;
 703         } else if (!strcmp(argv[1], "-us") && argc > 2) {
 704             if (!str_to_uint(argv[2], 10, &us_thr)) {
 705                 usage = true;
 706                 break;
 707             }
 708             argc -= 2;
 709             argv += 2;
 710         } else {
 711             usage = true;
 712             break;
 713         }
 714     }
 715     if (it_before + it_after > HISTORY_LEN - 2) {
 716         it_after = HISTORY_LEN - 2 - it_before;
 717     }
 718
 719     if (usage) {
 720         unixctl_command_reply_error(conn,
 721                 "Usage: ovs-appctl dpif-netdev/pmd-perf-log-set "
 722                 "[on|off] [-b before] [-a after] [-e|-ne] "
 723                 "[-us usec] [-q qlen]");
 724         return;
 725     }
 726
 727     VLOG_INFO("pmd-perf-log-set: %s, before=%d, after=%d, extend=%s, "
 728               "us_thr=%d, q_thr=%d\n",
 729               on ? "on" : "off", it_before, it_after,
 730               extend ? "true" : "false", us_thr, q_thr);
 731     log_enabled = on;
 732     log_extend = extend;
 733     log_it_before = it_before;
 734     log_it_after = it_after;
 735     log_q_thr = q_thr;
 736     log_us_thr = us_thr;
 737     iter_cycle_threshold = (log_us_thr * get_tsc_hz()) / 1000000L;
 738
 739     unixctl_command_reply(conn, "");
 740 }