src/vlib/trace.c

   1 /*
   2  * Copyright (c) 2015 Cisco and/or its affiliates.
   3  * Licensed under the Apache License, Version 2.0 (the "License");
   4  * you may not use this file except in compliance with the License.
   5  * You may obtain a copy of the License at:
   6  *
   7  *     http://www.apache.org/licenses/LICENSE-2.0
   8  *
   9  * Unless required by applicable law or agreed to in writing, software
  10  * distributed under the License is distributed on an "AS IS" BASIS,
  11  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  12  * See the License for the specific language governing permissions and
  13  * limitations under the License.
  14  */
  15 /*
  16  * trace.c: VLIB trace buffer.
  17  *
  18  * Copyright (c) 2008 Eliot Dresselhaus
  19  *
  20  * Permission is hereby granted, free of charge, to any person obtaining
  21  * a copy of this software and associated documentation files (the
  22  * "Software"), to deal in the Software without restriction, including
  23  * without limitation the rights to use, copy, modify, merge, publish,
  24  * distribute, sublicense, and/or sell copies of the Software, and to
  25  * permit persons to whom the Software is furnished to do so, subject to
  26  * the following conditions:
  27  *
  28  * The above copyright notice and this permission notice shall be
  29  * included in all copies or substantial portions of the Software.
  30  *
  31  *  THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
  32  *  EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF
  33  *  MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
  34  *  NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE
  35  *  LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
  36  *  OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION
  37  *  WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
  38  */
  39
  40 #include <vlib/vlib.h>
  41 #include <vlib/threads.h>
  42
  43 u8 *vnet_trace_placeholder;
  44
  45 /* Helper function for nodes which only trace buffer data. */
  46 void
  47 vlib_trace_frame_buffers_only (vlib_main_t * vm,
  48                                vlib_node_runtime_t * node,
  49                                u32 * buffers,
  50                                uword n_buffers,
  51                                uword next_buffer_stride,
  52                                uword n_buffer_data_bytes_in_trace)
  53 {
  54   u32 n_left, *from;
  55
  56   n_left = n_buffers;
  57   from = buffers;
  58
  59   while (n_left >= 4)
  60     {
  61       u32 bi0, bi1;
  62       vlib_buffer_t *b0, *b1;
  63       u8 *t0, *t1;
  64
  65       /* Prefetch next iteration. */
  66       vlib_prefetch_buffer_with_index (vm, from[2], LOAD);
  67       vlib_prefetch_buffer_with_index (vm, from[3], LOAD);
  68
  69       bi0 = from[0];
  70       bi1 = from[1];
  71
  72       b0 = vlib_get_buffer (vm, bi0);
  73       b1 = vlib_get_buffer (vm, bi1);
  74
  75       if (b0->flags & VLIB_BUFFER_IS_TRACED)
  76         {
  77           t0 = vlib_add_trace (vm, node, b0, n_buffer_data_bytes_in_trace);
  78           clib_memcpy_fast (t0, b0->data + b0->current_data,
  79                             n_buffer_data_bytes_in_trace);
  80         }
  81       if (b1->flags & VLIB_BUFFER_IS_TRACED)
  82         {
  83           t1 = vlib_add_trace (vm, node, b1, n_buffer_data_bytes_in_trace);
  84           clib_memcpy_fast (t1, b1->data + b1->current_data,
  85                             n_buffer_data_bytes_in_trace);
  86         }
  87       from += 2;
  88       n_left -= 2;
  89     }
  90
  91   while (n_left >= 1)
  92     {
  93       u32 bi0;
  94       vlib_buffer_t *b0;
  95       u8 *t0;
  96
  97       bi0 = from[0];
  98
  99       b0 = vlib_get_buffer (vm, bi0);
 100
 101       if (b0->flags & VLIB_BUFFER_IS_TRACED)
 102         {
 103           t0 = vlib_add_trace (vm, node, b0, n_buffer_data_bytes_in_trace);
 104           clib_memcpy_fast (t0, b0->data + b0->current_data,
 105                             n_buffer_data_bytes_in_trace);
 106         }
 107       from += 1;
 108       n_left -= 1;
 109     }
 110 }
 111
 112 /* Free up all trace buffer memory. */
 113 always_inline void
 114 clear_trace_buffer (void)
 115 {
 116   int i;
 117   vlib_trace_main_t *tm;
 118
 119   /* *INDENT-OFF* */
 120   foreach_vlib_main (
 121   ({
 122     tm = &this_vlib_main->trace_main;
 123
 124     tm->trace_enable = 0;
 125     vec_free (tm->nodes);
 126   }));
 127
 128   foreach_vlib_main (
 129   ({
 130     tm = &this_vlib_main->trace_main;
 131
 132     for (i = 0; i < vec_len (tm->trace_buffer_pool); i++)
 133       if (! pool_is_free_index (tm->trace_buffer_pool, i))
 134         vec_free (tm->trace_buffer_pool[i]);
 135     pool_free (tm->trace_buffer_pool);
 136   }));
 137   /* *INDENT-ON* */
 138 }
 139
 140 u8 *
 141 format_vlib_trace (u8 * s, va_list * va)
 142 {
 143   vlib_main_t *vm = va_arg (*va, vlib_main_t *);
 144   vlib_trace_header_t *h = va_arg (*va, vlib_trace_header_t *);
 145   vlib_trace_header_t *e = vec_end (h);
 146   vlib_node_t *node, *prev_node;
 147   clib_time_t *ct = &vm->clib_time;
 148   f64 t;
 149
 150   prev_node = 0;
 151   while (h < e)
 152     {
 153       node = vlib_get_node (vm, h->node_index);
 154
 155       if (node != prev_node)
 156         {
 157           t =
 158             (h->time - vm->cpu_time_main_loop_start) * ct->seconds_per_clock;
 159           s =
 160             format (s, "\n%U: %v", format_time_interval, "h:m:s:u", t,
 161                     node->name);
 162         }
 163       prev_node = node;
 164
 165       if (node->format_trace)
 166         s = format (s, "\n  %U", node->format_trace, vm, node, h->data);
 167       else
 168         s = format (s, "\n  %U", node->format_buffer, h->data);
 169
 170       h = vlib_trace_header_next (h);
 171     }
 172
 173   return s;
 174 }
 175
 176 /* Root of all trace cli commands. */
 177 /* *INDENT-OFF* */
 178 VLIB_CLI_COMMAND (trace_cli_command,static) = {
 179   .path = "trace",
 180   .short_help = "Packet tracer commands",
 181 };
 182 /* *INDENT-ON* */
 183
 184 int
 185 trace_time_cmp (void *a1, void *a2)
 186 {
 187   vlib_trace_header_t **t1 = a1;
 188   vlib_trace_header_t **t2 = a2;
 189   i64 dt = t1[0]->time - t2[0]->time;
 190   return dt < 0 ? -1 : (dt > 0 ? +1 : 0);
 191 }
 192
 193 /*
 194  * Return 1 if this packet passes the trace filter, or 0 otherwise
 195  */
 196 u32
 197 filter_accept (vlib_trace_main_t * tm, vlib_trace_header_t * h)
 198 {
 199   vlib_trace_header_t *e = vec_end (h);
 200
 201   if (tm->filter_flag == 0)
 202     return 1;
 203
 204   /*
 205    * When capturing a post-mortem dispatch trace,
 206    * toss all existing traces once per dispatch cycle.
 207    * So we can trace 4 billion pkts without running out of
 208    * memory...
 209    */
 210   if (tm->filter_flag == FILTER_FLAG_POST_MORTEM)
 211     return 0;
 212
 213   if (tm->filter_flag == FILTER_FLAG_INCLUDE)
 214     {
 215       while (h < e)
 216         {
 217           if (h->node_index == tm->filter_node_index)
 218             return 1;
 219           h = vlib_trace_header_next (h);
 220         }
 221       return 0;
 222     }
 223   else                          /* FILTER_FLAG_EXCLUDE */
 224     {
 225       while (h < e)
 226         {
 227           if (h->node_index == tm->filter_node_index)
 228             return 0;
 229           h = vlib_trace_header_next (h);
 230         }
 231       return 1;
 232     }
 233
 234   return 0;
 235 }
 236
 237 /*
 238  * Remove traces from the trace buffer pool that don't pass the filter
 239  */
 240 void
 241 trace_apply_filter (vlib_main_t * vm)
 242 {
 243   vlib_trace_main_t *tm = &vm->trace_main;
 244   vlib_trace_header_t **h;
 245   vlib_trace_header_t ***traces_to_remove = 0;
 246   u32 index;
 247   u32 trace_index;
 248   u32 n_accepted;
 249
 250   u32 accept;
 251
 252   if (tm->filter_flag == FILTER_FLAG_NONE)
 253     return;
 254
 255   /*
 256    * Ideally we would retain the first N traces that pass the filter instead
 257    * of any N traces.
 258    */
 259   n_accepted = 0;
 260   /* *INDENT-OFF* */
 261   pool_foreach (h, tm->trace_buffer_pool)
 262     {
 263       accept = filter_accept(tm, h[0]);
 264
 265       if ((n_accepted == tm->filter_count) || !accept)
 266           vec_add1 (traces_to_remove, h);
 267       else
 268           n_accepted++;
 269   }
 270   /* *INDENT-ON* */
 271
 272   /* remove all traces that we don't want to keep */
 273   for (index = 0; index < vec_len (traces_to_remove); index++)
 274     {
 275       trace_index = traces_to_remove[index] - tm->trace_buffer_pool;
 276       _vec_len (tm->trace_buffer_pool[trace_index]) = 0;
 277       pool_put_index (tm->trace_buffer_pool, trace_index);
 278     }
 279
 280   vec_free (traces_to_remove);
 281 }
 282
 283 static clib_error_t *
 284 cli_show_trace_buffer (vlib_main_t * vm,
 285                        unformat_input_t * input, vlib_cli_command_t * cmd)
 286 {
 287   vlib_trace_main_t *tm;
 288   vlib_trace_header_t **h, **traces;
 289   u32 i, index = 0;
 290   char *fmt;
 291   u8 *s = 0;
 292   u32 max;
 293
 294   /*
 295    * By default display only this many traces. To display more, explicitly
 296    * specify a max. This prevents unexpectedly huge outputs.
 297    */
 298   max = 50;
 299   while (unformat_check_input (input) != (uword) UNFORMAT_END_OF_INPUT)
 300     {
 301       if (unformat (input, "max %d", &max))
 302         ;
 303       else
 304         return clib_error_create ("expected 'max COUNT', got `%U'",
 305                                   format_unformat_error, input);
 306     }
 307
 308
 309   /* Get active traces from pool. */
 310
 311   /* *INDENT-OFF* */
 312   foreach_vlib_main (
 313   ({
 314     fmt = "------------------- Start of thread %d %s -------------------\n";
 315     s = format (s, fmt, index, vlib_worker_threads[index].name);
 316
 317     tm = &this_vlib_main->trace_main;
 318
 319     trace_apply_filter(this_vlib_main);
 320
 321     traces = 0;
 322     pool_foreach (h, tm->trace_buffer_pool)
 323      {
 324       vec_add1 (traces, h[0]);
 325     }
 326
 327     if (vec_len (traces) == 0)
 328       {
 329         s = format (s, "No packets in trace buffer\n");
 330         goto done;
 331       }
 332
 333     /* Sort them by increasing time. */
 334     vec_sort_with_function (traces, trace_time_cmp);
 335
 336     for (i = 0; i < vec_len (traces); i++)
 337       {
 338         if (i == max)
 339           {
 340             vlib_cli_output (vm, "Limiting display to %d packets."
 341                                  " To display more specify max.", max);
 342             goto done;
 343           }
 344
 345         s = format (s, "Packet %d\n%U\n\n", i + 1,
 346                          format_vlib_trace, vm, traces[i]);
 347       }
 348
 349   done:
 350     vec_free (traces);
 351
 352     index++;
 353   }));
 354   /* *INDENT-ON* */
 355
 356   vlib_cli_output (vm, "%v", s);
 357   vec_free (s);
 358   return 0;
 359 }
 360
 361 /* *INDENT-OFF* */
 362 VLIB_CLI_COMMAND (show_trace_cli,static) = {
 363   .path = "show trace",
 364   .short_help = "Show trace buffer [max COUNT]",
 365   .function = cli_show_trace_buffer,
 366 };
 367 /* *INDENT-ON* */
 368
 369 int vlib_enable_disable_pkt_trace_filter (int enable) __attribute__ ((weak));
 370
 371 int
 372 vlib_enable_disable_pkt_trace_filter (int enable)
 373 {
 374   return 0;
 375 }
 376
 377 void
 378 vlib_trace_stop_and_clear (void)
 379 {
 380   vlib_enable_disable_pkt_trace_filter (0);     /* disble tracing */
 381   clear_trace_buffer ();
 382 }
 383
 384
 385 void
 386 trace_update_capture_options (u32 add, u32 node_index, u32 filter, u8 verbose)
 387 {
 388   vlib_trace_main_t *tm;
 389   vlib_trace_node_t *tn;
 390
 391   if (add == ~0)
 392     add = 50;
 393
 394   /* *INDENT-OFF* */
 395   foreach_vlib_main ((
 396     {
 397       tm = &this_vlib_main->trace_main;
 398       tm->verbose = verbose;
 399       vec_validate (tm->nodes, node_index);
 400       tn = tm->nodes + node_index;
 401
 402       /*
 403        * Adding 0 makes no real sense, and there wa no other way
 404        * to explicilty zero-out the limits and count, so make
 405        * an "add 0" request really be "set to 0".
 406        */
 407       if (add == 0)
 408           tn->limit = tn->count = 0;
 409       else
 410           tn->limit += add;
 411     }));
 412
 413   foreach_vlib_main ((
 414     {
 415       tm = &this_vlib_main->trace_main;
 416       tm->trace_enable = 1;
 417     }));
 418   /* *INDENT-ON* */
 419 }
 420
 421 static clib_error_t *
 422 cli_add_trace_buffer (vlib_main_t * vm,
 423                       unformat_input_t * input, vlib_cli_command_t * cmd)
 424 {
 425   unformat_input_t _line_input, *line_input = &_line_input;
 426   vlib_node_t *node;
 427   u32 node_index, add;
 428   u8 verbose = 0;
 429   int filter = 0;
 430   clib_error_t *error = 0;
 431
 432   if (!unformat_user (input, unformat_line_input, line_input))
 433     return 0;
 434
 435   if (vnet_trace_placeholder == 0)
 436     vec_validate_aligned (vnet_trace_placeholder, 2048,
 437                           CLIB_CACHE_LINE_BYTES);
 438
 439   while (unformat_check_input (line_input) != (uword) UNFORMAT_END_OF_INPUT)
 440     {
 441       if (unformat (line_input, "%U %d",
 442                     unformat_vlib_node, vm, &node_index, &add))
 443         ;
 444       else if (unformat (line_input, "verbose"))
 445         verbose = 1;
 446       else if (unformat (line_input, "filter"))
 447         filter = 1;
 448       else
 449         {
 450           error = clib_error_create ("expected NODE COUNT, got `%U'",
 451                                      format_unformat_error, line_input);
 452           goto done;
 453         }
 454     }
 455
 456   node = vlib_get_node (vm, node_index);
 457
 458   if ((node->flags & VLIB_NODE_FLAG_TRACE_SUPPORTED) == 0)
 459     {
 460       error = clib_error_create ("node '%U' doesn't support per-node "
 461                                  "tracing. There may be another way to "
 462                                  "initiate trace on this node.",
 463                                  format_vlib_node_name, vm, node_index);
 464       goto done;
 465     }
 466
 467   if (filter)
 468     {
 469       if (vlib_enable_disable_pkt_trace_filter (1 /* enable */ ))
 470         {
 471           error = clib_error_create ("No packet trace filter configured...");
 472           goto done;
 473         }
 474     }
 475
 476   trace_update_capture_options (add, node_index, filter, verbose);
 477
 478 done:
 479   unformat_free (line_input);
 480
 481   return error;
 482 }
 483
 484 /* *INDENT-OFF* */
 485 VLIB_CLI_COMMAND (add_trace_cli,static) = {
 486   .path = "trace add",
 487   .short_help = "trace add <input-graph-node> <add'l-pkts-for-node-> [filter] [verbose]",
 488   .function = cli_add_trace_buffer,
 489 };
 490 /* *INDENT-ON* */
 491
 492 /*
 493  * Configure a filter for packet traces.
 494  *
 495  * This supplements the packet trace feature so that only packets matching
 496  * the filter are included in the trace. Currently the only filter is to
 497  * keep packets that include a certain node in the trace or exclude a certain
 498  * node in the trace.
 499  *
 500  * The count of traced packets in the "trace add" command is still used to
 501  * create a certain number of traces. The "trace filter" command specifies
 502  * how many of those packets should be retained in the trace.
 503  *
 504  * For example, 1Mpps of traffic is arriving and one of those packets is being
 505  * dropped. To capture the trace for only that dropped packet, you can do:
 506  *     trace filter include error-drop 1
 507  *     trace add dpdk-input 1000000
 508  *     <wait one second>
 509  *     show trace
 510  *
 511  * Note that the filter could be implemented by capturing all traces and just
 512  * reducing traces displayed by the "show trace" function. But that would
 513  * require a lot of memory for storing the traces, making that infeasible.
 514  *
 515  * To remove traces from the trace pool that do not include a certain node
 516  * requires that the trace be "complete" before applying the filter. To
 517  * accomplish this, the trace pool is filtered upon each iteraction of the
 518  * main vlib loop. Doing so keeps the number of allocated traces down to a
 519  * reasonably low number. This requires that tracing for a buffer is not
 520  * performed after the vlib main loop interation completes. i.e. you can't
 521  * save away a buffer temporarily then inject it back into the graph and
 522  * expect that the trace_index is still valid (such as a traffic manager might
 523  * do). A new trace buffer should be allocated for those types of packets.
 524  *
 525  * The filter can be extended to support multiple nodes and other match
 526  * criteria (e.g. input sw_if_index, mac address) but for now just checks if
 527  * a specified node is in the trace or not in the trace.
 528  */
 529
 530 void
 531 trace_filter_set (u32 node_index, u32 flag, u32 count)
 532 {
 533   /* *INDENT-OFF* */
 534   foreach_vlib_main (
 535   ({
 536     vlib_trace_main_t *tm;
 537
 538     tm = &this_vlib_main->trace_main;
 539     tm->filter_node_index = node_index;
 540     tm->filter_flag = flag;
 541     tm->filter_count = count;
 542
 543     /*
 544      * Clear the trace limits to stop any in-progress tracing
 545      * Prevents runaway trace allocations when the filter changes
 546      * (or is removed)
 547      */
 548     vec_free (tm->nodes);
 549   }));
 550   /* *INDENT-ON* */
 551 }
 552
 553
 554 static clib_error_t *
 555 cli_filter_trace (vlib_main_t * vm,
 556                   unformat_input_t * input, vlib_cli_command_t * cmd)
 557 {
 558   u32 filter_node_index;
 559   u32 filter_flag;
 560   u32 filter_count;
 561
 562   if (unformat (input, "include %U %d",
 563                 unformat_vlib_node, vm, &filter_node_index, &filter_count))
 564     {
 565       filter_flag = FILTER_FLAG_INCLUDE;
 566     }
 567   else if (unformat (input, "exclude %U %d",
 568                      unformat_vlib_node, vm, &filter_node_index,
 569                      &filter_count))
 570     {
 571       filter_flag = FILTER_FLAG_EXCLUDE;
 572     }
 573   else if (unformat (input, "none"))
 574     {
 575       filter_flag = FILTER_FLAG_NONE;
 576       filter_node_index = 0;
 577       filter_count = 0;
 578     }
 579   else
 580     return
 581       clib_error_create
 582       ("expected 'include NODE COUNT' or 'exclude NODE COUNT' or 'none', got `%U'",
 583        format_unformat_error, input);
 584
 585   trace_filter_set (filter_node_index, filter_flag, filter_count);
 586
 587   return 0;
 588 }
 589
 590 /* *INDENT-OFF* */
 591 VLIB_CLI_COMMAND (filter_trace_cli,static) = {
 592   .path = "trace filter",
 593   .short_help = "trace filter none | [include|exclude] NODE COUNT",
 594   .function = cli_filter_trace,
 595 };
 596 /* *INDENT-ON* */
 597
 598 static clib_error_t *
 599 cli_clear_trace_buffer (vlib_main_t * vm,
 600                         unformat_input_t * input, vlib_cli_command_t * cmd)
 601 {
 602   vlib_trace_stop_and_clear ();
 603   return 0;
 604 }
 605
 606 /* *INDENT-OFF* */
 607 VLIB_CLI_COMMAND (clear_trace_cli,static) = {
 608   .path = "clear trace",
 609   .short_help = "Clear trace buffer and free memory",
 610   .function = cli_clear_trace_buffer,
 611 };
 612 /* *INDENT-ON* */
 613
 614 /* Placeholder function to get us linked in. */
 615 void
 616 vlib_trace_cli_reference (void)
 617 {
 618 }
 619
 620 int
 621 vnet_is_packet_traced (vlib_buffer_t * b,
 622                        u32 classify_table_index, int func)
 623 __attribute__ ((weak));
 624
 625 int
 626 vnet_is_packet_traced (vlib_buffer_t * b, u32 classify_table_index, int func)
 627 {
 628   clib_warning ("BUG: STUB called");
 629   return 1;
 630 }
 631
 632 void *
 633 vlib_add_trace (vlib_main_t * vm,
 634                 vlib_node_runtime_t * r, vlib_buffer_t * b, u32 n_data_bytes)
 635 {
 636   return vlib_add_trace_inline (vm, r, b, n_data_bytes);
 637 }
 638
 639
 640
 641 /*
 642  * fd.io coding-style-patch-verification: ON
 643  *
 644  * Local Variables:
 645  * eval: (c-set-style "gnu")
 646  * End:
 647  */