src/vppinfra/unix-kelog.c

/*
  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:
 */