Re: problems with sched tapset on ubuntu precise 3.2.0

[David Smith <dsmith@redhat.com>]

[-- Attachment #1: Type: text/plain, Size: 2188 bytes --]

On 05/08/2013 08:25 AM, Thiago Manel wrote:
> Hi David, sorry for the late response
> 
> - for the first check, I see an error:
> 
> stap -vv -l 'kernel.trace("sched_*")'
> Systemtap translator/driver (version 1.6/0.152 non-git sources)
> Copyright (C) 2005-2011 Red Hat, Inc. and others
> This is free software; see the source for copying conditions.
> enabled features: AVAHI LIBSQLITE3 NSS BOOST_SHARED_PTR TR1_UNORDERED_MAP NLS
> Created temporary directory "/tmp/stapNw4kVW"
> Session arch: x86_64 release: 3.2.0-23-generic
> Searched: " /usr/share/systemtap/tapset/x86_64/*.stp ", found: 4, processed: 4
> Searched: " /usr/share/systemtap/tapset/*.stp ", found: 73, processed: 73
> Pass 1: parsed user script and 77 library script(s) using
> 84096virt/22508res/2556shr kb, in 60usr/0sys/70real ms.
> semantic error: no match while resolving probe point kernel.trace("sched_*")
> Pass 2: analyzed script: 0 probe(s), 0 function(s), 0 embed(s), 0
> global(s) using 230984virt/23700res/2908shr kb, in
> 40usr/100sys/125real ms.
> Running rm -rf /tmp/stapNw4kVW
> Spawn waitpid result (0x0): 0
> 
> - whereas for the second one, it succeeds:
> 
>  stap -l 'kernel.function("context_switch")'
> kernel.function("context_switch@/build/buildd/linux-3.2.0/kernel/sched.c:3287")
> 
> Regarding the CONFIG_TRACEPOINTS (I'm not sure I'm looking to the
> right place) I have ...

On a fedora system, you'd look in /boot/config-`uname -r`. I don't know
where you'd find the kernel config file on ubuntu.

I see where the error is coming from now. The process/schedtimes.stp
script is written to only use tracepoints, it doesn't have the
kernel.function fallback like the scheduler.cpu_off tapset probe alias.
So, if your kernel doesn't have the sched kernel tracepoints the
schedtimes.stp script won't work as written. We could try adding in the
kernel.function fallback, but on many kernels that kernel function gets
inlined which makes it difficult to find the arguments.

Here's an (untested) version of schedtimes.stp with the kernel.function
fallbacks added. See if it works for you.

-- 
David Smith
dsmith@redhat.com
Red Hat
http://www.redhat.com
256.217.0141 (direct)
256.837.0057 (fax)

[-- Attachment #2: schedtimes.stp --]
[-- Type: text/plain, Size: 5493 bytes --]

#! /usr/bin/env stap

############################################################
# Schedtimes.stp
#
# Copyright (C) 2009 Red Hat, Inc.
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License version 2 as
# published by the Free Software Foundation.

# Author: Jason Baron <jbaron@redhat.com>
# profiles threads and displays their run times, queued times,
# wait times, including i/o wait times.
# Has two modes. When no arguments are given it profiles all
# threads. Alternatively, you can pass -c "program name"
############################################################

//constants
global RUNNING=0, QUEUED=1, SLEEPING=2

global traced_pid
global run_time, queued_time,  sleep_time, io_wait_time
global pid_state, pid_names
global previous_timestamp
global io_wait_count
global io_wait_incremented

function get_iowait:long(queue:long)
{
  return @cast(queue,"rq","kernel")->nr_iowait->counter;
}

probe kernel.trace("sched_switch")!, kernel.function("context_switch") {
  previous_pid = $prev->pid;
  next_pid = $next->pid;
  if (traced_pid) {
    if (previous_pid != traced_pid) {
      previous_pid = 0;
    }
    if (next_pid != traced_pid) {
      next_pid = 0;
    }
  }
  if (previous_pid) {
    if (!([previous_pid] in pid_state)) {
      //use this state as entry into state machine
      previous_timestamp[previous_pid] = gettimeofday_us();
      pid_names[previous_pid] = kernel_string($prev->comm);
      if ($prev->state > 0) {
        pid_state[previous_pid] = SLEEPING;
      } else if ($prev->state == 0) {
        pid_state[previous_pid] = QUEUED;
      } else {
        printf("unknown transition:\n");
        printf("pid state: %d our state: %d\n",
          $prev->state, pid_state[previous_pid]);
      }
    } else if (pid_state[previous_pid] == RUNNING) {
      pid_names[previous_pid] = kernel_string($prev->comm);
      t = gettimeofday_us();  
      run_time[previous_pid] += (t - previous_timestamp[previous_pid]);
      previous_timestamp[previous_pid] = t;
      if ($prev->state > 0) {
        if (@defined($rq) && (get_iowait($rq) - io_wait_count[previous_pid]) > 0)
          io_wait_incremented[previous_pid] = 1;  
        pid_state[previous_pid] = SLEEPING;
      } else if ($prev->state == 0) {
        pid_state[previous_pid] = QUEUED;
      } else {
        printf("unknown transition:\n");
        printf("pid state: %d our state: %d\n",
          $prev->state, pid_state[previous_pid]);
      }
    } else {
      printf("unknown transition:\n");
      printf("%s pid state: %d our state: %d\n",
           pid_names[previous_pid],
           $prev->state, pid_state[previous_pid]);
    }
  }
  if (next_pid) {
    if (@defined($rq))
      io_wait_count[next_pid] = get_iowait($rq);
    if (!([next_pid] in pid_state)) {
      //use this state as entry into state machine
      previous_timestamp[next_pid] =  gettimeofday_us();
      pid_state[next_pid] = RUNNING;
      pid_names[next_pid] = kernel_string($next->comm);
    } else if (pid_state[next_pid] == QUEUED) {
      t = gettimeofday_us();
      queued_time[next_pid] += (t - previous_timestamp[next_pid]);
      previous_timestamp[next_pid] = t;
      pid_state[next_pid] = RUNNING;
      pid_names[next_pid] = kernel_string($next->comm);
    } else {
      printf("unknown transition:\n");
      printf("%s pid state: %d our state: %d\n",
        pid_names[next_pid],
        $next->state, pid_state[next_pid]);
    }
  }
}

probe kernel.trace("sched_wakeup"), kernel.function("try_to_wake_up") {
  wakeup_pid = $p->pid;
  if (traced_pid && (wakeup_pid != traced_pid)) next
  if ((!$success) && (pid_state[wakeup_pid] != SLEEPING)) next
  if (!wakeup_pid) next

  if (!([wakeup_pid] in pid_state)) {
    //use this state as entry into state machine
    previous_timestamp[wakeup_pid] =  gettimeofday_us();
    pid_state[wakeup_pid] = QUEUED;
    pid_names[wakeup_pid] = kernel_string($p->comm);
  } else if (pid_state[wakeup_pid] == SLEEPING) {
    t = gettimeofday_us();
    sleep_time[wakeup_pid] += (t - previous_timestamp[wakeup_pid]);
    if (io_wait_incremented[wakeup_pid] == 1) {
      io_wait_time[wakeup_pid] += (t - previous_timestamp[wakeup_pid]);
      io_wait_incremented[wakeup_pid] = 0;
    }
    previous_timestamp[wakeup_pid] = t;
    pid_state[wakeup_pid] = QUEUED;
    pid_names[wakeup_pid] = kernel_string($p->comm);
  } else {
    printf("unknown transition:\n");
    printf("pid state: %d our state: %d\n",
      $p->state, pid_state[wakeup_pid]);
  }
}

probe begin {
  traced_pid = target();
  if (traced_pid == 0) {
    printf("all mode\n");
  } else {
    printf("target mode\n");
    printf("traced pid: %d\n", traced_pid);
  }
}

probe end {
  t = gettimeofday_us();
  foreach (pid in pid_state) {
    if (pid_state[pid] == SLEEPING)
      sleep_time[pid] += (t - previous_timestamp[pid]);
    if (pid_state[pid] == QUEUED)
      queued_time[pid] += (t - previous_timestamp[pid]);
    if (pid_state[pid] == RUNNING)
      run_time[pid] += (t - previous_timestamp[pid]);
  }
  printf ("%16s: %6s %10s %10s %10s %10s %10s\n\n",
         "execname", "pid", "run(us)", "sleep(us)", "io_wait(us)",
         "queued(us)", "total(us)")
  foreach (pid+ in run_time) {
    printf("%16s: %6d %10d %10d %10d %10d %10d\n", 
      pid_names[pid], pid, run_time[pid], sleep_time[pid], 
      io_wait_time[pid], queued_time[pid],
      (run_time[pid] + sleep_time[pid] + queued_time[pid]));
  }
}