unix-kelog.c

Go to the documentation of this file.

/*
  Copyright (c) 2010 Cisco and/or its affiliates.

  * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at:
 *
 *     http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
*/

#include <vppinfra/error.h>
#include <vppinfra/unix.h>
#include <vppinfra/elog.h>
#include <vppinfra/format.h>
#include <vppinfra/os.h>

#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <time.h>

typedef enum
  {
    RUNNING = 0,
    WAKEUP,
  } sched_event_type_t;

typedef struct 
{
  u32 cpu;
  u8 *task;
  u32 pid;
  f64 timestamp;
  sched_event_type_t type;
} sched_event_t;

void kelog_init (elog_main_t * em, char * kernel_tracer, u32 n_events)
{
  int enable_fd, current_tracer_fd, data_fd;
  int len;
  struct timespec ts, ts2;
  char *trace_enable = "/debug/tracing/tracing_enabled";
  char *current_tracer = "/debug/tracing/current_tracer";
  char *trace_data = "/debug/tracing/trace";
  f64 realtime, monotonic;
  f64 freq, secs_per_clock;

  ASSERT (kernel_tracer);

  /*$$$$ fixme */
  n_events = 1<<18;

  /* init first so we won't hurt ourselves if we bail */
  elog_init (em, n_events);

  enable_fd = open (trace_enable, O_RDWR);
  if (enable_fd < 0)
    {
      clib_warning ("Couldn't open %s", trace_enable);
      return;
    }
  /* disable kernel tracing */
  if (write (enable_fd, "0\n", 2) != 2) 
    {
      clib_unix_warning ("disable tracing");
      close(enable_fd);
      return;
    }
    
  /* 
   * open + clear the data buffer.
   * see .../linux/kernel/trace/trace.c:tracing_open()
   */
  data_fd = open (trace_data, O_RDWR | O_TRUNC);
  if (data_fd < 0) 
    {
      clib_warning ("Couldn't open+clear %s", trace_data);
      return;
    }
  close(data_fd);

  /* configure tracing */
  current_tracer_fd = open (current_tracer, O_RDWR);

  if (current_tracer_fd < 0)
    {
      clib_warning ("Couldn't open %s", current_tracer);
      close(enable_fd);
      return;
    }

  len = strlen(kernel_tracer);

  if (write (current_tracer_fd, kernel_tracer, len) != len) 
    {
      clib_unix_warning ("configure trace");
      close(current_tracer_fd);
      close(enable_fd);
      return;
    }
  
  close(current_tracer_fd);

  /* 
   * The kernel event log uses CLOCK_MONOTONIC timestamps,
   * not CLOCK_REALTIME timestamps. These differ by a constant
   * but the constant is not available in user mode.
   * This estimate will be off by one syscall round-trip.
   */
  clib_time_init (&em->cpu_timer);
  em->init_time.cpu = em->cpu_timer.init_cpu_time;
  syscall (SYS_clock_gettime, CLOCK_MONOTONIC, &ts);
  
  /* enable kernel tracing */
  if (write (enable_fd, "1\n", 2) != 2) 
    {
      clib_unix_warning ("enable tracing");
      close(enable_fd);
      return;
    }

  close(enable_fd);
}


u8 *format_sched_event (u8 * s, va_list * va)
{
  sched_event_t *e = va_arg (*va, sched_event_t *);

  s = format (s, "cpu %d task %10s type %s timestamp %12.6f\n",
              e->cpu, e->task, e->type ? "WAKEUP " : "RUNNING", e->timestamp);

  return s;
}

sched_event_t *parse_sched_switch_trace (u8 *tdata, u32 *index)
{
  u8 *cp = tdata + *index;
  u8 *limit = tdata + vec_len(tdata);
  int colons;
  static sched_event_t event;
  sched_event_t *e = &event;
  static u8 *task_name;
  u32 secs, usecs;
  int i;

 again:
  /* eat leading w/s */
  while (cp < limit && (*cp == ' ' && *cp == '\t'))
    cp++;
  if (cp == limit)
    return 0;
      
  /* header line */
  if (*cp == '#')
    {
      while (cp < limit && (*cp != '\n'))
        cp++;
      if (*cp == '\n')
        {
          cp++;
          goto again;
        }
      clib_warning ("bugger 0");
      return 0;
    }

  while (cp < limit && *cp != ']')
    cp++;

  if (*cp == 0)
    return 0;

  if (*cp != ']')
    {
      clib_warning ("bugger 0.1");
      return 0;
    }
        
  cp++;
  while (cp < limit && (*cp == ' ' && *cp == '\t'))
    cp++;
  if (cp == limit)
    {
      clib_warning ("bugger 0.2");
      return 0;
    }
      
  secs = atoi(cp);

  while (cp < limit && (*cp != '.'))
    cp++;

  if (cp == limit)
    {
      clib_warning ("bugger 0.3");
      return 0;
    }
      
  cp++;

  usecs = atoi (cp);

  e->timestamp = ((f64)secs) + ((f64)usecs)*1e-6;
      
  /* eat up to third colon */
  for (i = 0; i < 3; i++)
    {
      while (cp < limit && *cp != ':')
        cp++;
      cp++;
    }
  --cp;
  if (*cp != ':')
    {
      clib_warning ("bugger 1");
      return 0;
    }
  /* aim at '>' (switch-to) / '+' (wakeup) */
  cp += 5;
  if (cp >= limit)
    {
      clib_warning ("bugger 2");
      return 0;
    }
  if (*cp == '>')
    e->type = RUNNING;
  else if (*cp == '+')
    e->type = WAKEUP;
  else
    {
      clib_warning ("bugger 3");
      return 0;
    }

  cp += 3;
  if (cp >= limit) 
    {
      clib_warning ("bugger 4");
      return 0;
    }
            
  e->cpu = atoi (cp);
  cp += 4;
          
  if (cp >= limit) 
    {
      clib_warning ("bugger 4");
      return 0;
    }
  while (cp < limit && (*cp == ' ' || *cp == '\t'))
    cp++;

  e->pid = atoi (cp);
          
  for (i = 0; i < 2; i++)
    {
      while (cp < limit && *cp != ':')
        cp++;
      cp++;
    }
  --cp;
  if (*cp != ':')
    {
      clib_warning ("bugger 5");
      return 0;
    }

  cp += 3;
  if (cp >= limit) 
    {
      clib_warning ("bugger 6");
      return 0;
    }
  while (cp < limit && (*cp != ' ' && *cp != '\n'))
    {
      vec_add1(task_name, *cp);
      cp++;
    }
  vec_add1(task_name, 0);
  /* _vec_len() = 0 in caller */
  e->task = task_name;

  if (cp < limit)
      cp++;

  *index = cp - tdata;
  return e;
}

static u32 elog_id_for_pid (elog_main_t *em, u8 *name, u32 pid)
{
  uword * p, r;
  mhash_t * h = &em->string_table_hash;

  if (! em->string_table_hash.hash)
    mhash_init (h, sizeof (uword), sizeof (pid));
  
  p = mhash_get (h, &pid);
  if (p)
    return p[0];
  r = elog_string (em, "%s(%d)", name, pid);
  mhash_set (h, &pid, r, /* old_value */ 0);
  return r;
}

void kelog_collect_sched_switch_trace (elog_main_t *em)
{
  int enable_fd, data_fd;
  char *trace_enable = "/debug/tracing/tracing_enabled";
  char *trace_data = "/debug/tracing/trace";
  u8 *data = 0;
  u8 *dp;
  int bytes, total_bytes;
  u32 pos;
  sched_event_t *evt;
  u64 nsec_to_add;
  u32 index;
  f64 clocks_per_sec;
  
  enable_fd = open (trace_enable, O_RDWR);
  if (enable_fd < 0)
    {
      clib_warning ("Couldn't open %s", trace_enable);
      return;
    }
  /* disable kernel tracing */
  if (write (enable_fd, "0\n", 2) != 2) 
    {
      clib_unix_warning ("disable tracing");
      close(enable_fd);
      return;
    }
  close(enable_fd);

  /* Read the trace data */
  data_fd = open (trace_data, O_RDWR);
  if (data_fd < 0)
    {
      clib_warning ("Couldn't open %s", trace_data);
      return;
    }

  /* 
   * Extract trace into a vector. Note that seq_printf() [kernel]
   * is not guaranteed to produce 4096 bytes at a time.
   */
  vec_validate (data, 4095);
  total_bytes = 0;
  pos = 0;
  while (1)
    {
      bytes = read(data_fd, data+pos, 4096);
      if (bytes <= 0) 
          break;

      total_bytes += bytes;
      _vec_len(data) = total_bytes;

      pos = vec_len(data);
      vec_validate(data, vec_len(data)+4095);
    }
  vec_add1(data, 0);

  /* Synthesize events */
  em->is_enabled = 1;

  index = 0;
  while ((evt = parse_sched_switch_trace (data, &index)))
    {
      u64 fake_cpu_clock;

      fake_cpu_clock = evt->timestamp * em->cpu_timer.clocks_per_second;
      {
        ELOG_TYPE_DECLARE (e) = 
          {
            .format = "%d: %s %s",
            .format_args = "i4T4t4",
            .n_enum_strings = 2,
            .enum_strings = { "running", "wakeup", },
          };
        struct { u32 cpu, string_table_offset, which; } * ed;
        
        ed = elog_event_data_not_inline (em, &__ELOG_TYPE_VAR(e),
                                         &em->default_track, 
                                         fake_cpu_clock);
        ed->cpu = evt->cpu;
        ed->string_table_offset = elog_id_for_pid (em, evt->task, evt->pid);
        ed->which = evt->type;
      }
      _vec_len(evt->task) = 0;
    }
  em->is_enabled = 0;
}