vlib/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 /* Helper function for nodes which only trace buffer data. */
  44 void
  45 vlib_trace_frame_buffers_only (vlib_main_t * vm,
  46                                vlib_node_runtime_t * node,
  47                                u32 * buffers,
  48                                uword n_buffers,
  49                                uword next_buffer_stride,
  50                                uword n_buffer_data_bytes_in_trace)
  51 {
  52   u32 n_left, * from;
  53
  54   n_left = n_buffers;
  55   from = buffers;
  56
  57   while (n_left >= 4)
  58     {
  59       u32 bi0, bi1;
  60       vlib_buffer_t * b0, * b1;
  61       u8 * t0, * t1;
  62
  63       /* Prefetch next iteration. */
  64       vlib_prefetch_buffer_with_index (vm, from[2], LOAD);
  65       vlib_prefetch_buffer_with_index (vm, from[3], LOAD);
  66
  67       bi0 = from[0];
  68       bi1 = from[1];
  69
  70       b0 = vlib_get_buffer (vm, bi0);
  71       b1 = vlib_get_buffer (vm, bi1);
  72
  73       if (b0->flags & VLIB_BUFFER_IS_TRACED)
  74         {
  75           t0 = vlib_add_trace (vm, node, b0, n_buffer_data_bytes_in_trace);
  76           clib_memcpy (t0, b0->data + b0->current_data,
  77                   n_buffer_data_bytes_in_trace);
  78         }
  79       if (b1->flags & VLIB_BUFFER_IS_TRACED)
  80         {
  81           t1 = vlib_add_trace (vm, node, b1, n_buffer_data_bytes_in_trace);
  82           clib_memcpy (t1, b1->data + b1->current_data,
  83                   n_buffer_data_bytes_in_trace);
  84         }
  85       from += 2;
  86       n_left -= 2;
  87     }
  88
  89   while (n_left >= 1)
  90     {
  91       u32 bi0;
  92       vlib_buffer_t * b0;
  93       u8 * t0;
  94
  95       bi0 = from[0];
  96
  97       b0 = vlib_get_buffer (vm, bi0);
  98
  99       if (b0->flags & VLIB_BUFFER_IS_TRACED)
 100         {
 101           t0 = vlib_add_trace (vm, node, b0, n_buffer_data_bytes_in_trace);
 102           clib_memcpy (t0, b0->data + b0->current_data,
 103                   n_buffer_data_bytes_in_trace);
 104         }
 105       from += 1;
 106       n_left -= 1;
 107     }
 108 }
 109
 110 /* Free up all trace buffer memory. */
 111 always_inline void
 112 clear_trace_buffer (void)
 113 {
 114   int i;
 115   vlib_trace_main_t * tm;
 116
 117   foreach_vlib_main (
 118   ({
 119     void *mainheap;
 120
 121     tm = &this_vlib_main->trace_main;
 122     mainheap = clib_mem_set_heap (this_vlib_main->heap_base);
 123
 124     tm->trace_active_hint = 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     clib_mem_set_heap (mainheap);
 131   }));
 132 }
 133
 134 static u8 * format_vlib_trace (u8 * s, va_list * va)
 135 {
 136   vlib_main_t * vm = va_arg (*va, vlib_main_t *);
 137   vlib_trace_header_t * h = va_arg (*va, vlib_trace_header_t *);
 138   vlib_trace_header_t * e = vec_end (h);
 139   vlib_node_t * node, * prev_node;
 140   clib_time_t * ct = &vm->clib_time;
 141   f64 t;
 142
 143   prev_node = 0;
 144   while (h < e)
 145     {
 146       node = vlib_get_node (vm, h->node_index);
 147
 148       if (node != prev_node)
 149         {
 150           t = (h->time - vm->cpu_time_main_loop_start) * ct->seconds_per_clock;
 151           s = format (s, "\n%U: %v",
 152                       format_time_interval, "h:m:s:u", t,
 153                       node->name);
 154         }
 155       prev_node = node;
 156
 157       if (node->format_trace)
 158         s = format (s, "\n  %U",
 159                     node->format_trace, vm, node, h->data);
 160       else
 161         s = format (s, "\n  %U",
 162                     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 VLIB_CLI_COMMAND (trace_cli_command,static) = {
 172   .path = "trace",
 173   .short_help = "Packet tracer commands",
 174 };
 175
 176 static int
 177 trace_cmp (void * a1, void * a2)
 178 {
 179   vlib_trace_header_t ** t1 = a1;
 180   vlib_trace_header_t ** t2 = a2;
 181   i64 dt = t1[0]->time - t2[0]->time;
 182   return dt < 0 ? -1 : (dt > 0 ? +1 : 0);
 183 }
 184
 185 /*
 186  * Return 1 if this packet passes the trace filter, or 0 otherwise
 187  */
 188 u32 filter_accept (vlib_trace_main_t * tm, vlib_trace_header_t * h)
 189 {
 190   vlib_trace_header_t * e = vec_end (h);
 191
 192   if (tm->filter_flag == 0) return 1;
 193
 194   if (tm->filter_flag == FILTER_FLAG_INCLUDE)
 195     {
 196       while (h < e)
 197         {
 198           if (h->node_index == tm->filter_node_index)
 199             return 1;
 200           h = vlib_trace_header_next (h);
 201         }
 202       return 0;
 203    }
 204   else /* FILTER_FLAG_EXCLUDE */
 205     {
 206       while (h < e)
 207         {
 208           if (h->node_index == tm->filter_node_index)
 209             return 0;
 210           h = vlib_trace_header_next (h);
 211         }
 212       return 1;
 213    }
 214
 215   return 0;
 216 }
 217
 218 /*
 219  * Remove traces from the trace buffer pool that don't pass the filter
 220  */
 221 void trace_apply_filter (vlib_main_t * vm)
 222 {
 223   vlib_trace_main_t * tm = &vm->trace_main;
 224   vlib_trace_header_t ** h;
 225   vlib_trace_header_t *** traces_to_remove = 0;
 226   u32 index;
 227   u32 trace_index;
 228   u32 n_accepted;
 229
 230   u32 accept;
 231
 232   if (tm->filter_flag == FILTER_FLAG_NONE)
 233     return;
 234
 235   /*
 236    * Ideally we would retain the first N traces that pass the filter instead
 237    * of any N traces.
 238    */
 239   n_accepted = 0;
 240   pool_foreach (h, tm->trace_buffer_pool,
 241    ({
 242       accept = filter_accept(tm, h[0]);
 243
 244       if ((n_accepted == tm->filter_count) || !accept)
 245           vec_add1 (traces_to_remove, h);
 246       else
 247           n_accepted++;
 248   }));
 249
 250   /* remove all traces that we don't want to keep */
 251   for (index=0; index<vec_len(traces_to_remove); index++)
 252     {
 253       trace_index = traces_to_remove[index] - tm->trace_buffer_pool;
 254       _vec_len (tm->trace_buffer_pool[trace_index]) = 0;
 255       pool_put_index (tm->trace_buffer_pool, trace_index);
 256     }
 257
 258   vec_free (traces_to_remove);
 259 }
 260
 261 static clib_error_t *
 262 cli_show_trace_buffer (vlib_main_t * vm,
 263                        unformat_input_t * input,
 264                        vlib_cli_command_t * cmd)
 265 {
 266   vlib_trace_main_t * tm;
 267   vlib_trace_header_t ** h, ** traces;
 268   u32 i, index = 0;
 269   char * fmt;
 270   u8 * s = 0;
 271   u32 max;
 272
 273   /*
 274    * By default display only this many traces. To display more, explicitly
 275    * specify a max. This prevents unexpectedly huge outputs.
 276    */
 277   max = 50;
 278   while (unformat_check_input(input) != (uword)UNFORMAT_END_OF_INPUT)
 279     {
 280       if (unformat (input, "max %d", &max))
 281         ;
 282       else
 283         return clib_error_create ("expected 'max COUNT', got `%U'",
 284                                   format_unformat_error, input);
 285     }
 286
 287
 288   /* Get active traces from pool. */
 289
 290   foreach_vlib_main (
 291   ({
 292     void *mainheap;
 293
 294     fmt = "------------------- Start of thread %d %s -------------------\n";
 295     s = format (s, fmt, index, vlib_worker_threads[index].name);
 296
 297     tm = &this_vlib_main->trace_main;
 298
 299     mainheap = clib_mem_set_heap (this_vlib_main->heap_base);
 300
 301     trace_apply_filter(this_vlib_main);
 302
 303     traces = 0;
 304     pool_foreach (h, tm->trace_buffer_pool,
 305     ({
 306       vec_add1 (traces, h[0]);
 307     }));
 308
 309     if (vec_len (traces) == 0)
 310       {
 311         clib_mem_set_heap (mainheap);
 312         s = format (s, "No packets in trace buffer\n");
 313         goto done;
 314       }
 315
 316     /* Sort them by increasing time. */
 317     vec_sort_with_function (traces, trace_cmp);
 318
 319     for (i = 0; i < vec_len (traces); i++)
 320       {
 321         if (i == max)
 322           {
 323             vlib_cli_output (vm, "Limiting display to %d packets."
 324                                  " To display more specify max.", max);
 325             goto done;
 326           }
 327
 328         clib_mem_set_heap (mainheap);
 329
 330         s = format (s, "Packet %d\n%U\n\n", i + 1,
 331                          format_vlib_trace, vm, traces[i]);
 332
 333         mainheap = clib_mem_set_heap (this_vlib_main->heap_base);
 334       }
 335
 336   done:
 337     vec_free (traces);
 338     clib_mem_set_heap (mainheap);
 339
 340     index++;
 341   }));
 342
 343   vlib_cli_output (vm, (char *) s);
 344   vec_free (s);
 345   return 0;
 346 }
 347
 348 VLIB_CLI_COMMAND (show_trace_cli,static) = {
 349   .path = "show trace",
 350   .short_help = "Show trace buffer [max COUNT]",
 351   .function = cli_show_trace_buffer,
 352 };
 353
 354 static clib_error_t *
 355 cli_add_trace_buffer (vlib_main_t * vm,
 356                       unformat_input_t * input,
 357                       vlib_cli_command_t * cmd)
 358 {
 359   vlib_trace_main_t * tm;
 360   vlib_trace_node_t * tn;
 361   u32 node_index, add;
 362   u8 verbose = 0;
 363
 364   while (unformat_check_input(input) != (uword)UNFORMAT_END_OF_INPUT)
 365     {
 366       if (unformat (input, "%U %d", unformat_vlib_node, vm, &node_index, &add))
 367         ;
 368       else if (unformat (input, "verbose"))
 369         verbose = 1;
 370       else
 371         return clib_error_create ("expected NODE COUNT, got `%U'",
 372                                   format_unformat_error, input);
 373     }
 374
 375   foreach_vlib_main (
 376   ({
 377     void *oldheap;
 378     tm = &this_vlib_main->trace_main;
 379
 380     tm->trace_active_hint = 1;
 381     tm->verbose = verbose;
 382
 383     oldheap = clib_mem_set_heap (this_vlib_main->heap_base);
 384
 385     vec_validate (tm->nodes, node_index);
 386     tn = tm->nodes + node_index;
 387     tn->limit += add;
 388     clib_mem_set_heap (oldheap);
 389   }));
 390
 391   return 0;
 392 }
 393
 394 VLIB_CLI_COMMAND (add_trace_cli,static) = {
 395   .path = "trace add",
 396   .short_help = "Trace given number of packets",
 397   .function = cli_add_trace_buffer,
 398 };
 399
 400
 401 /*
 402  * Configure a filter for packet traces.
 403  *
 404  * This supplements the packet trace feature so that only packets matching
 405  * the filter are included in the trace. Currently the only filter is to
 406  * keep packets that include a certain node in the trace or exclude a certain
 407  * node in the trace.
 408  *
 409  * The count of traced packets in the "trace add" command is still used to
 410  * create a certain number of traces. The "trace filter" command specifies
 411  * how many of those packets should be retained in the trace.
 412  *
 413  * For example, 1Mpps of traffic is arriving and one of those packets is being
 414  * dropped. To capture the trace for only that dropped packet, you can do:
 415  *     trace filter include error-drop 1
 416  *     trace add dpdk-input 1000000
 417  *     <wait one second>
 418  *     show trace
 419  *
 420  * Note that the filter could be implemented by capturing all traces and just
 421  * reducing traces displayed by the "show trace" function. But that would
 422  * require a lot of memory for storing the traces, making that infeasible.
 423  *
 424  * To remove traces from the trace pool that do not include a certain node
 425  * requires that the trace be "complete" before applying the filter. To
 426  * accomplish this, the trace pool is filtered upon each iteraction of the
 427  * main vlib loop. Doing so keeps the number of allocated traces down to a
 428  * reasonably low number. This requires that tracing for a buffer is not
 429  * performed after the vlib main loop interation completes. i.e. you can't
 430  * save away a buffer temporarily then inject it back into the graph and
 431  * expect that the trace_index is still valid (such as a traffic manager might
 432  * do). A new trace buffer should be allocated for those types of packets.
 433  *
 434  * The filter can be extended to support multiple nodes and other match
 435  * criteria (e.g. input sw_if_index, mac address) but for now just checks if
 436  * a specified node is in the trace or not in the trace.
 437  */
 438 static clib_error_t *
 439 cli_filter_trace (vlib_main_t * vm,
 440                   unformat_input_t * input,
 441                   vlib_cli_command_t * cmd)
 442 {
 443   vlib_trace_main_t * tm = &vm->trace_main;
 444   u32 filter_node_index;
 445   u32 filter_flag;
 446   u32 filter_count;
 447   void *mainheap;
 448
 449   if (unformat (input, "include %U %d",
 450       unformat_vlib_node, vm, &filter_node_index, &filter_count))
 451     {
 452       filter_flag = FILTER_FLAG_INCLUDE;
 453     }
 454   else if (unformat (input, "exclude %U %d",
 455       unformat_vlib_node, vm, &filter_node_index, &filter_count))
 456     {
 457       filter_flag = FILTER_FLAG_EXCLUDE;
 458     }
 459   else if (unformat (input, "none"))
 460     {
 461       filter_flag = FILTER_FLAG_NONE;
 462       filter_node_index = 0;
 463       filter_count = 0;
 464     }
 465   else
 466     return clib_error_create ("expected 'include NODE COUNT' or 'exclude NODE COUNT' or 'none', got `%U'",
 467                               format_unformat_error, input);
 468
 469   foreach_vlib_main (
 470   ({
 471     tm = &this_vlib_main->trace_main;
 472     tm->filter_node_index = filter_node_index;
 473     tm->filter_flag = filter_flag;
 474     tm->filter_count = filter_count;
 475
 476     /*
 477      * Clear the trace limits to stop any in-progress tracing
 478      * Prevents runaway trace allocations when the filter changes (or is removed)
 479      */
 480     mainheap = clib_mem_set_heap (this_vlib_main->heap_base);
 481     vec_free (tm->nodes);
 482     clib_mem_set_heap (mainheap);
 483   }));
 484
 485   return 0;
 486 }
 487
 488 VLIB_CLI_COMMAND (filter_trace_cli,static) = {
 489   .path = "trace filter",
 490   .short_help = "filter trace output - include NODE COUNT | exclude NODE COUNT | none",
 491   .function = cli_filter_trace,
 492 };
 493
 494 static clib_error_t *
 495 cli_clear_trace_buffer (vlib_main_t * vm,
 496                         unformat_input_t * input,
 497                         vlib_cli_command_t * cmd)
 498 {
 499   clear_trace_buffer ();
 500   return 0;
 501 }
 502
 503 VLIB_CLI_COMMAND (clear_trace_cli,static) = {
 504   .path = "clear trace",
 505   .short_help = "Clear trace buffer and free memory",
 506   .function = cli_clear_trace_buffer,
 507 };
 508
 509 /* Dummy function to get us linked in. */
 510 void vlib_trace_cli_reference (void) {}