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;
}
 
/*
 * fd.io coding-style-patch-verification: ON
 *
 * Local Variables:
 * eval: (c-set-style "gnu")
 * End:
 */