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_dummy;
  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
 126     for (i = 0; i < vec_len (tm->trace_buffer_pool); i++)
 127       if (! pool_is_free_index (tm->trace_buffer_pool, i))
 128         vec_free (tm->trace_buffer_pool[i]);
 129     pool_free (tm->trace_buffer_pool);
 130   }));
 131   /* *INDENT-ON* */
 132 }
 133
 134 u8 *
 135 format_vlib_trace (u8 * s, va_list * va)
 136 {
 137   vlib_main_t *vm = va_arg (*va, vlib_main_t *);
 138   vlib_trace_header_t *h = va_arg (*va, vlib_trace_header_t *);
 139   vlib_trace_header_t *e = vec_end (h);
 140   vlib_node_t *node, *prev_node;
 141   clib_time_t *ct = &vm->clib_time;
 142   f64 t;
 143
 144   prev_node = 0;
 145   while (h < e)
 146     {
 147       node = vlib_get_node (vm, h->node_index);
 148
 149       if (node != prev_node)
 150         {
 151           t =
 152             (h->time - vm->cpu_time_main_loop_start) * ct->seconds_per_clock;
 153           s =
 154             format (s, "\n%U: %v", format_time_interval, "h:m:s:u", t,
 155                     node->name);
 156         }
 157       prev_node = node;
 158
 159       if (node->format_trace)
 160         s = format (s, "\n  %U", node->format_trace, vm, node, h->data);
 161       else
 162         s = format (s, "\n  %U", node->format_buffer, h->data);
 163
 164       h = vlib_trace_header_next (h);
 165     }
 166
 167   return s;
 168 }
 169
 170 /* Root of all trace cli commands. */
 171 /* *INDENT-OFF* */
 172 VLIB_CLI_COMMAND (trace_cli_command,static) = {
 173   .path = "trace",
 174   .short_help = "Packet tracer commands",
 175 };
 176 /* *INDENT-ON* */
 177
 178 static int
 179 trace_cmp (void *a1, void *a2)
 180 {
 181   vlib_trace_header_t **t1 = a1;
 182   vlib_trace_header_t **t2 = a2;
 183   i64 dt = t1[0]->time - t2[0]->time;
 184   return dt < 0 ? -1 : (dt > 0 ? +1 : 0);
 185 }
 186
 187 /*
 188  * Return 1 if this packet passes the trace filter, or 0 otherwise
 189  */
 190 u32
 191 filter_accept (vlib_trace_main_t * tm, vlib_trace_header_t * h)
 192 {
 193   vlib_trace_header_t *e = vec_end (h);
 194
 195   if (tm->filter_flag == 0)
 196     return 1;
 197
 198   if (tm->filter_flag == FILTER_FLAG_INCLUDE)
 199     {
 200       while (h < e)
 201         {
 202           if (h->node_index == tm->filter_node_index)
 203             return 1;
 204           h = vlib_trace_header_next (h);
 205         }
 206       return 0;
 207     }
 208   else                          /* FILTER_FLAG_EXCLUDE */
 209     {
 210       while (h < e)
 211         {
 212           if (h->node_index == tm->filter_node_index)
 213             return 0;
 214           h = vlib_trace_header_next (h);
 215         }
 216       return 1;
 217     }
 218
 219   return 0;
 220 }
 221
 222 /*
 223  * Remove traces from the trace buffer pool that don't pass the filter
 224  */
 225 void
 226 trace_apply_filter (vlib_main_t * vm)
 227 {
 228   vlib_trace_main_t *tm = &vm->trace_main;
 229   vlib_trace_header_t **h;
 230   vlib_trace_header_t ***traces_to_remove = 0;
 231   u32 index;
 232   u32 trace_index;
 233   u32 n_accepted;
 234
 235   u32 accept;
 236
 237   if (tm->filter_flag == FILTER_FLAG_NONE)
 238     return;
 239
 240   /*
 241    * Ideally we would retain the first N traces that pass the filter instead
 242    * of any N traces.
 243    */
 244   n_accepted = 0;
 245   /* *INDENT-OFF* */
 246   pool_foreach (h, tm->trace_buffer_pool,
 247    ({
 248       accept = filter_accept(tm, h[0]);
 249
 250       if ((n_accepted == tm->filter_count) || !accept)
 251           vec_add1 (traces_to_remove, h);
 252       else
 253           n_accepted++;
 254   }));
 255   /* *INDENT-ON* */
 256
 257   /* remove all traces that we don't want to keep */
 258   for (index = 0; index < vec_len (traces_to_remove); index++)
 259     {
 260       trace_index = traces_to_remove[index] - tm->trace_buffer_pool;
 261       _vec_len (tm->trace_buffer_pool[trace_index]) = 0;
 262       pool_put_index (tm->trace_buffer_pool, trace_index);
 263     }
 264
 265   vec_free (traces_to_remove);
 266 }
 267
 268 static clib_error_t *
 269 cli_show_trace_buffer (vlib_main_t * vm,
 270                        unformat_input_t * input, vlib_cli_command_t * cmd)
 271 {
 272   vlib_trace_main_t *tm;
 273   vlib_trace_header_t **h, **traces;
 274   u32 i, index = 0;
 275   char *fmt;
 276   u8 *s = 0;
 277   u32 max;
 278
 279   /*
 280    * By default display only this many traces. To display more, explicitly
 281    * specify a max. This prevents unexpectedly huge outputs.
 282    */
 283   max = 50;
 284   while (unformat_check_input (input) != (uword) UNFORMAT_END_OF_INPUT)
 285     {
 286       if (unformat (input, "max %d", &max))
 287         ;
 288       else
 289         return clib_error_create ("expected 'max COUNT', got `%U'",
 290                                   format_unformat_error, input);
 291     }
 292
 293
 294   /* Get active traces from pool. */
 295
 296   /* *INDENT-OFF* */
 297   foreach_vlib_main (
 298   ({
 299     fmt = "------------------- Start of thread %d %s -------------------\n";
 300     s = format (s, fmt, index, vlib_worker_threads[index].name);
 301
 302     tm = &this_vlib_main->trace_main;
 303
 304     trace_apply_filter(this_vlib_main);
 305
 306     traces = 0;
 307     pool_foreach (h, tm->trace_buffer_pool,
 308     ({
 309       vec_add1 (traces, h[0]);
 310     }));
 311
 312     if (vec_len (traces) == 0)
 313       {
 314         s = format (s, "No packets in trace buffer\n");
 315         goto done;
 316       }
 317
 318     /* Sort them by increasing time. */
 319     vec_sort_with_function (traces, trace_cmp);
 320
 321     for (i = 0; i < vec_len (traces); i++)
 322       {
 323         if (i == max)
 324           {
 325             vlib_cli_output (vm, "Limiting display to %d packets."
 326                                  " To display more specify max.", max);
 327             goto done;
 328           }
 329
 330         s = format (s, "Packet %d\n%U\n\n", i + 1,
 331                          format_vlib_trace, vm, traces[i]);
 332       }
 333
 334   done:
 335     vec_free (traces);
 336
 337     index++;
 338   }));
 339   /* *INDENT-ON* */
 340
 341   vlib_cli_output (vm, "%v", s);
 342   vec_free (s);
 343   return 0;
 344 }
 345
 346 /* *INDENT-OFF* */
 347 VLIB_CLI_COMMAND (show_trace_cli,static) = {
 348   .path = "show trace",
 349   .short_help = "Show trace buffer [max COUNT]",
 350   .function = cli_show_trace_buffer,
 351 };
 352 /* *INDENT-ON* */
 353
 354 static clib_error_t *
 355 cli_add_trace_buffer (vlib_main_t * vm,
 356                       unformat_input_t * input, vlib_cli_command_t * cmd)
 357 {
 358   unformat_input_t _line_input, *line_input = &_line_input;
 359   vlib_trace_main_t *tm;
 360   vlib_trace_node_t *tn;
 361   u32 node_index, add;
 362   u8 verbose = 0;
 363   clib_error_t *error = 0;
 364
 365   if (!unformat_user (input, unformat_line_input, line_input))
 366     return 0;
 367
 368   if (vnet_trace_dummy == 0)
 369     vec_validate_aligned (vnet_trace_dummy, 2048, CLIB_CACHE_LINE_BYTES);
 370
 371   while (unformat_check_input (line_input) != (uword) UNFORMAT_END_OF_INPUT)
 372     {
 373       if (unformat (line_input, "%U %d",
 374                     unformat_vlib_node, vm, &node_index, &add))
 375         ;
 376       else if (unformat (line_input, "verbose"))
 377         verbose = 1;
 378       else
 379         {
 380           error = clib_error_create ("expected NODE COUNT, got `%U'",
 381                                      format_unformat_error, line_input);
 382           goto done;
 383         }
 384     }
 385
 386   /* *INDENT-OFF* */
 387   foreach_vlib_main ((
 388     {
 389       tm = &this_vlib_main->trace_main;
 390       tm->verbose = verbose;
 391       vec_validate (tm->nodes, node_index);
 392       tn = tm->nodes + node_index;
 393       tn->limit += add;
 394       tm->trace_enable = 1;
 395     }));
 396   /* *INDENT-ON* */
 397
 398 done:
 399   unformat_free (line_input);
 400
 401   return error;
 402 }
 403
 404 /* *INDENT-OFF* */
 405 VLIB_CLI_COMMAND (add_trace_cli,static) = {
 406   .path = "trace add",
 407   .short_help = "Trace given number of packets",
 408   .function = cli_add_trace_buffer,
 409 };
 410 /* *INDENT-ON* */
 411
 412
 413 /*
 414  * Configure a filter for packet traces.
 415  *
 416  * This supplements the packet trace feature so that only packets matching
 417  * the filter are included in the trace. Currently the only filter is to
 418  * keep packets that include a certain node in the trace or exclude a certain
 419  * node in the trace.
 420  *
 421  * The count of traced packets in the "trace add" command is still used to
 422  * create a certain number of traces. The "trace filter" command specifies
 423  * how many of those packets should be retained in the trace.
 424  *
 425  * For example, 1Mpps of traffic is arriving and one of those packets is being
 426  * dropped. To capture the trace for only that dropped packet, you can do:
 427  *     trace filter include error-drop 1
 428  *     trace add dpdk-input 1000000
 429  *     <wait one second>
 430  *     show trace
 431  *
 432  * Note that the filter could be implemented by capturing all traces and just
 433  * reducing traces displayed by the "show trace" function. But that would
 434  * require a lot of memory for storing the traces, making that infeasible.
 435  *
 436  * To remove traces from the trace pool that do not include a certain node
 437  * requires that the trace be "complete" before applying the filter. To
 438  * accomplish this, the trace pool is filtered upon each iteraction of the
 439  * main vlib loop. Doing so keeps the number of allocated traces down to a
 440  * reasonably low number. This requires that tracing for a buffer is not
 441  * performed after the vlib main loop interation completes. i.e. you can't
 442  * save away a buffer temporarily then inject it back into the graph and
 443  * expect that the trace_index is still valid (such as a traffic manager might
 444  * do). A new trace buffer should be allocated for those types of packets.
 445  *
 446  * The filter can be extended to support multiple nodes and other match
 447  * criteria (e.g. input sw_if_index, mac address) but for now just checks if
 448  * a specified node is in the trace or not in the trace.
 449  */
 450 static clib_error_t *
 451 cli_filter_trace (vlib_main_t * vm,
 452                   unformat_input_t * input, vlib_cli_command_t * cmd)
 453 {
 454   vlib_trace_main_t *tm = &vm->trace_main;
 455   u32 filter_node_index;
 456   u32 filter_flag;
 457   u32 filter_count;
 458
 459   if (unformat (input, "include %U %d",
 460                 unformat_vlib_node, vm, &filter_node_index, &filter_count))
 461     {
 462       filter_flag = FILTER_FLAG_INCLUDE;
 463     }
 464   else if (unformat (input, "exclude %U %d",
 465                      unformat_vlib_node, vm, &filter_node_index,
 466                      &filter_count))
 467     {
 468       filter_flag = FILTER_FLAG_EXCLUDE;
 469     }
 470   else if (unformat (input, "none"))
 471     {
 472       filter_flag = FILTER_FLAG_NONE;
 473       filter_node_index = 0;
 474       filter_count = 0;
 475     }
 476   else
 477     return
 478       clib_error_create
 479       ("expected 'include NODE COUNT' or 'exclude NODE COUNT' or 'none', got `%U'",
 480        format_unformat_error, input);
 481
 482   /* *INDENT-OFF* */
 483   foreach_vlib_main (
 484     ({
 485     tm = &this_vlib_main->trace_main;
 486     tm->filter_node_index = filter_node_index;
 487     tm->filter_flag = filter_flag;
 488     tm->filter_count = filter_count;
 489
 490     /*
 491      * Clear the trace limits to stop any in-progress tracing
 492      * Prevents runaway trace allocations when the filter changes
 493      * (or is removed)
 494      */
 495     vec_free (tm->nodes);
 496   }));
 497   /* *INDENT-ON* */
 498
 499   return 0;
 500 }
 501
 502 /* *INDENT-OFF* */
 503 VLIB_CLI_COMMAND (filter_trace_cli,static) = {
 504   .path = "trace filter",
 505   .short_help = "filter trace output - include NODE COUNT | exclude NODE COUNT | none",
 506   .function = cli_filter_trace,
 507 };
 508 /* *INDENT-ON* */
 509
 510 static clib_error_t *
 511 cli_clear_trace_buffer (vlib_main_t * vm,
 512                         unformat_input_t * input, vlib_cli_command_t * cmd)
 513 {
 514   clear_trace_buffer ();
 515   return 0;
 516 }
 517
 518 /* *INDENT-OFF* */
 519 VLIB_CLI_COMMAND (clear_trace_cli,static) = {
 520   .path = "clear trace",
 521   .short_help = "Clear trace buffer and free memory",
 522   .function = cli_clear_trace_buffer,
 523 };
 524 /* *INDENT-ON* */
 525
 526 /* Dummy function to get us linked in. */
 527 void
 528 vlib_trace_cli_reference (void)
 529 {
 530 }
 531
 532 /*
 533  * fd.io coding-style-patch-verification: ON
 534  *
 535  * Local Variables:
 536  * eval: (c-set-style "gnu")
 537  * End:
 538  */