src/vppinfra/unix-kelog.c

   1 /*
   2   Copyright (c) 2010 Cisco and/or its affiliates.
   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 <vppinfra/error.h>
  18 #include <vppinfra/unix.h>
  19 #include <vppinfra/elog.h>
  20 #include <vppinfra/format.h>
  21 #include <vppinfra/os.h>
  22
  23 #include <sys/types.h>
  24 #include <sys/stat.h>
  25 #include <fcntl.h>
  26 #include <time.h>
  27
  28 typedef enum
  29 {
  30   RUNNING = 0,
  31   WAKEUP,
  32 } sched_event_type_t;
  33
  34 typedef struct
  35 {
  36   u32 cpu;
  37   u8 *task;
  38   u32 pid;
  39   f64 timestamp;
  40   sched_event_type_t type;
  41 } sched_event_t;
  42
  43 void
  44 kelog_init (elog_main_t * em, char *kernel_tracer, u32 n_events)
  45 {
  46   int enable_fd, current_tracer_fd, data_fd;
  47   int len;
  48   struct timespec ts, ts2;
  49   char *trace_enable = "/debug/tracing/tracing_enabled";
  50   char *current_tracer = "/debug/tracing/current_tracer";
  51   char *trace_data = "/debug/tracing/trace";
  52   f64 realtime, monotonic;
  53   f64 freq, secs_per_clock;
  54
  55   ASSERT (kernel_tracer);
  56
  57   /*$$$$ fixme */
  58   n_events = 1 << 18;
  59
  60   /* init first so we won't hurt ourselves if we bail */
  61   elog_init (em, n_events);
  62
  63   enable_fd = open (trace_enable, O_RDWR);
  64   if (enable_fd < 0)
  65     {
  66       clib_warning ("Couldn't open %s", trace_enable);
  67       return;
  68     }
  69   /* disable kernel tracing */
  70   if (write (enable_fd, "0\n", 2) != 2)
  71     {
  72       clib_unix_warning ("disable tracing");
  73       close (enable_fd);
  74       return;
  75     }
  76
  77   /*
  78    * open + clear the data buffer.
  79    * see .../linux/kernel/trace/trace.c:tracing_open()
  80    */
  81   data_fd = open (trace_data, O_RDWR | O_TRUNC);
  82   if (data_fd < 0)
  83     {
  84       clib_warning ("Couldn't open+clear %s", trace_data);
  85       return;
  86     }
  87   close (data_fd);
  88
  89   /* configure tracing */
  90   current_tracer_fd = open (current_tracer, O_RDWR);
  91
  92   if (current_tracer_fd < 0)
  93     {
  94       clib_warning ("Couldn't open %s", current_tracer);
  95       close (enable_fd);
  96       return;
  97     }
  98
  99   len = strlen (kernel_tracer);
 100
 101   if (write (current_tracer_fd, kernel_tracer, len) != len)
 102     {
 103       clib_unix_warning ("configure trace");
 104       close (current_tracer_fd);
 105       close (enable_fd);
 106       return;
 107     }
 108
 109   close (current_tracer_fd);
 110
 111   /*
 112    * The kernel event log uses CLOCK_MONOTONIC timestamps,
 113    * not CLOCK_REALTIME timestamps. These differ by a constant
 114    * but the constant is not available in user mode.
 115    * This estimate will be off by one syscall round-trip.
 116    */
 117   clib_time_init (&em->cpu_timer);
 118   em->init_time.cpu = em->cpu_timer.init_cpu_time;
 119   syscall (SYS_clock_gettime, CLOCK_MONOTONIC, &ts);
 120
 121   /* enable kernel tracing */
 122   if (write (enable_fd, "1\n", 2) != 2)
 123     {
 124       clib_unix_warning ("enable tracing");
 125       close (enable_fd);
 126       return;
 127     }
 128
 129   close (enable_fd);
 130 }
 131
 132
 133 u8 *
 134 format_sched_event (u8 * s, va_list * va)
 135 {
 136   sched_event_t *e = va_arg (*va, sched_event_t *);
 137
 138   s = format (s, "cpu %d task %10s type %s timestamp %12.6f\n",
 139               e->cpu, e->task, e->type ? "WAKEUP " : "RUNNING", e->timestamp);
 140
 141   return s;
 142 }
 143
 144 sched_event_t *
 145 parse_sched_switch_trace (u8 * tdata, u32 * index)
 146 {
 147   u8 *cp = tdata + *index;
 148   u8 *limit = tdata + vec_len (tdata);
 149   int colons;
 150   static sched_event_t event;
 151   sched_event_t *e = &event;
 152   static u8 *task_name;
 153   u32 secs, usecs;
 154   int i;
 155
 156 again:
 157   /* eat leading w/s */
 158   while (cp < limit && (*cp == ' ' && *cp == '\t'))
 159     cp++;
 160   if (cp == limit)
 161     return 0;
 162
 163   /* header line */
 164   if (*cp == '#')
 165     {
 166       while (cp < limit && (*cp != '\n'))
 167         cp++;
 168       if (*cp == '\n')
 169         {
 170           cp++;
 171           goto again;
 172         }
 173       clib_warning ("bugger 0");
 174       return 0;
 175     }
 176
 177   while (cp < limit && *cp != ']')
 178     cp++;
 179
 180   if (*cp == 0)
 181     return 0;
 182
 183   if (*cp != ']')
 184     {
 185       clib_warning ("bugger 0.1");
 186       return 0;
 187     }
 188
 189   cp++;
 190   while (cp < limit && (*cp == ' ' && *cp == '\t'))
 191     cp++;
 192   if (cp == limit)
 193     {
 194       clib_warning ("bugger 0.2");
 195       return 0;
 196     }
 197
 198   secs = atoi (cp);
 199
 200   while (cp < limit && (*cp != '.'))
 201     cp++;
 202
 203   if (cp == limit)
 204     {
 205       clib_warning ("bugger 0.3");
 206       return 0;
 207     }
 208
 209   cp++;
 210
 211   usecs = atoi (cp);
 212
 213   e->timestamp = ((f64) secs) + ((f64) usecs) * 1e-6;
 214
 215   /* eat up to third colon */
 216   for (i = 0; i < 3; i++)
 217     {
 218       while (cp < limit && *cp != ':')
 219         cp++;
 220       cp++;
 221     }
 222   --cp;
 223   if (*cp != ':')
 224     {
 225       clib_warning ("bugger 1");
 226       return 0;
 227     }
 228   /* aim at '>' (switch-to) / '+' (wakeup) */
 229   cp += 5;
 230   if (cp >= limit)
 231     {
 232       clib_warning ("bugger 2");
 233       return 0;
 234     }
 235   if (*cp == '>')
 236     e->type = RUNNING;
 237   else if (*cp == '+')
 238     e->type = WAKEUP;
 239   else
 240     {
 241       clib_warning ("bugger 3");
 242       return 0;
 243     }
 244
 245   cp += 3;
 246   if (cp >= limit)
 247     {
 248       clib_warning ("bugger 4");
 249       return 0;
 250     }
 251
 252   e->cpu = atoi (cp);
 253   cp += 4;
 254
 255   if (cp >= limit)
 256     {
 257       clib_warning ("bugger 4");
 258       return 0;
 259     }
 260   while (cp < limit && (*cp == ' ' || *cp == '\t'))
 261     cp++;
 262
 263   e->pid = atoi (cp);
 264
 265   for (i = 0; i < 2; i++)
 266     {
 267       while (cp < limit && *cp != ':')
 268         cp++;
 269       cp++;
 270     }
 271   --cp;
 272   if (*cp != ':')
 273     {
 274       clib_warning ("bugger 5");
 275       return 0;
 276     }
 277
 278   cp += 3;
 279   if (cp >= limit)
 280     {
 281       clib_warning ("bugger 6");
 282       return 0;
 283     }
 284   while (cp < limit && (*cp != ' ' && *cp != '\n'))
 285     {
 286       vec_add1 (task_name, *cp);
 287       cp++;
 288     }
 289   vec_add1 (task_name, 0);
 290   /* _vec_len() = 0 in caller */
 291   e->task = task_name;
 292
 293   if (cp < limit)
 294     cp++;
 295
 296   *index = cp - tdata;
 297   return e;
 298 }
 299
 300 static u32
 301 elog_id_for_pid (elog_main_t * em, u8 * name, u32 pid)
 302 {
 303   uword *p, r;
 304   mhash_t *h = &em->string_table_hash;
 305
 306   if (!em->string_table_hash.hash)
 307     mhash_init (h, sizeof (uword), sizeof (pid));
 308
 309   p = mhash_get (h, &pid);
 310   if (p)
 311     return p[0];
 312   r = elog_string (em, "%s(%d)", name, pid);
 313   mhash_set (h, &pid, r, /* old_value */ 0);
 314   return r;
 315 }
 316
 317 void
 318 kelog_collect_sched_switch_trace (elog_main_t * em)
 319 {
 320   int enable_fd, data_fd;
 321   char *trace_enable = "/debug/tracing/tracing_enabled";
 322   char *trace_data = "/debug/tracing/trace";
 323   u8 *data = 0;
 324   u8 *dp;
 325   int bytes, total_bytes;
 326   u32 pos;
 327   sched_event_t *evt;
 328   u64 nsec_to_add;
 329   u32 index;
 330   f64 clocks_per_sec;
 331
 332   enable_fd = open (trace_enable, O_RDWR);
 333   if (enable_fd < 0)
 334     {
 335       clib_warning ("Couldn't open %s", trace_enable);
 336       return;
 337     }
 338   /* disable kernel tracing */
 339   if (write (enable_fd, "0\n", 2) != 2)
 340     {
 341       clib_unix_warning ("disable tracing");
 342       close (enable_fd);
 343       return;
 344     }
 345   close (enable_fd);
 346
 347   /* Read the trace data */
 348   data_fd = open (trace_data, O_RDWR);
 349   if (data_fd < 0)
 350     {
 351       clib_warning ("Couldn't open %s", trace_data);
 352       return;
 353     }
 354
 355   /*
 356    * Extract trace into a vector. Note that seq_printf() [kernel]
 357    * is not guaranteed to produce 4096 bytes at a time.
 358    */
 359   vec_validate (data, 4095);
 360   total_bytes = 0;
 361   pos = 0;
 362   while (1)
 363     {
 364       bytes = read (data_fd, data + pos, 4096);
 365       if (bytes <= 0)
 366         break;
 367
 368       total_bytes += bytes;
 369       _vec_len (data) = total_bytes;
 370
 371       pos = vec_len (data);
 372       vec_validate (data, vec_len (data) + 4095);
 373     }
 374   vec_add1 (data, 0);
 375
 376   /* Synthesize events */
 377   em->is_enabled = 1;
 378
 379   index = 0;
 380   while ((evt = parse_sched_switch_trace (data, &index)))
 381     {
 382       u64 fake_cpu_clock;
 383
 384       fake_cpu_clock = evt->timestamp * em->cpu_timer.clocks_per_second;
 385       {
 386         ELOG_TYPE_DECLARE (e) =
 387         {
 388           .format = "%d: %s %s",.format_args = "i4T4t4",.n_enum_strings =
 389             2,.enum_strings =
 390           {
 391           "running", "wakeup",}
 392         ,};
 393         struct
 394         {
 395           u32 cpu, string_table_offset, which;
 396         } *ed;
 397
 398         ed = elog_event_data_not_inline (em, &__ELOG_TYPE_VAR (e),
 399                                          &em->default_track, fake_cpu_clock);
 400         ed->cpu = evt->cpu;
 401         ed->string_table_offset = elog_id_for_pid (em, evt->task, evt->pid);
 402         ed->which = evt->type;
 403       }
 404       _vec_len (evt->task) = 0;
 405     }
 406   em->is_enabled = 0;
 407 }
 408
 409 /*
 410  * fd.io coding-style-patch-verification: ON
 411  *
 412  * Local Variables:
 413  * eval: (c-set-style "gnu")
 414  * End:
 415  */