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