offwaketime.py

#!/usr/bin/python
#
# offwaketime   Summarize blocked time by kernel off-CPU stack + waker stack
#               For Linux, uses BCC, eBPF.
#
# USAGE: offwaketime [-h] [-p PID | -u | -k] [-U | -K] [-f] [duration]
#
# Copyright 2016 Netflix, Inc.
# Licensed under the Apache License, Version 2.0 (the "License")
#
# 20-Jan-2016   Brendan Gregg   Created this.

from __future__ import print_function
from bcc import BPF
from time import sleep
import signal
import errno
from sys import stderr
from cStringIO import StringIO

# arguments
examples = """examples:
    ./offwaketime             # trace off-CPU + waker stack time until Ctrl-C
    ./offwaketime 5           # trace for 5 seconds only
    ./offwaketime -f 5        # 5 seconds, and output in folded format
    ./offwaketime -m 1000     # trace only events that last more than 1000 usec
    ./offwaketime -M 9000     # trace only events that last less than 9000 usec
    ./offwaketime -p 185      # only trace threads for PID 185
    ./offwaketime -t 188      # only trace thread 188
    ./offwaketime -u          # only trace user threads (no kernel)
    ./offwaketime -k          # only trace kernel threads (no user)
    ./offwaketime -U          # only show user space stacks (no kernel)
    ./offwaketime -K          # only show kernel space stacks (no user)
"""

def init_bpf():
  # define BPF program
  bpf_text = """
#include <uapi/linux/ptrace.h>
#include <linux/sched.h>

#define MINBLOCK_US    MINBLOCK_US_VALUEULL
#define MAXBLOCK_US    MAXBLOCK_US_VALUEULL

struct key_t {
    char waker[TASK_COMM_LEN];
    char target[TASK_COMM_LEN];
    int w_k_stack_id;
    int w_u_stack_id;
    int t_k_stack_id;
    int t_u_stack_id;
    u32 t_pid;
    u32 w_pid;
    u32 tgid;
};
BPF_HASH(counts, struct key_t);
BPF_HASH(start, u32);
struct wokeby_t {
    char name[TASK_COMM_LEN];
    int k_stack_id;
    int u_stack_id;
    int w_pid;
};
BPF_HASH(wokeby, u32, struct wokeby_t);

BPF_STACK_TRACE(stack_traces, STACK_STORAGE_SIZE)

int waker(struct pt_regs *ctx, struct task_struct *p) {
    u32 pid = p->pid;
    u32 tgid = p->tgid;

    if (!(THREAD_FILTER)) {
        return 0;
    }

    struct wokeby_t woke = {};
    bpf_get_current_comm(&woke.name, sizeof(woke.name));

    woke.k_stack_id = KERNEL_STACK_GET;
    woke.u_stack_id = USER_STACK_GET;
    woke.w_pid = pid;
    wokeby.update(&pid, &woke);
    return 0;
}

int oncpu(struct pt_regs *ctx, struct task_struct *p) {
    u32 pid = p->pid, t_pid=pid;
    u32 tgid = p->tgid;
    u64 ts, *tsp;

    // record previous thread sleep time
    if (THREAD_FILTER) {
        ts = bpf_ktime_get_ns();
        start.update(&pid, &ts);
    }

    // calculate current thread's delta time
    pid = bpf_get_current_pid_tgid();
    tgid = bpf_get_current_pid_tgid() >> 32;
    tsp = start.lookup(&pid);
    if (tsp == 0) {
        return 0;        // missed start or filtered
    }
    u64 delta = bpf_ktime_get_ns() - *tsp;
    start.delete(&pid);
    delta = delta / 1000;
    if ((delta < MINBLOCK_US) || (delta > MAXBLOCK_US)) {
        return 0;
    }

    // create map key
    u64 zero = 0, *val;
    struct key_t key = {};
    struct wokeby_t *woke;
    bpf_get_current_comm(&key.target, sizeof(key.target));

    key.t_k_stack_id = KERNEL_STACK_GET;
    key.t_u_stack_id = USER_STACK_GET;
    key.t_pid = t_pid;

    woke = wokeby.lookup(&pid);
    if (woke) {
        key.w_k_stack_id = woke->k_stack_id;
        key.w_u_stack_id = woke->u_stack_id;
        key.w_pid = woke->w_pid;
        key.tgid = tgid;
        __builtin_memcpy(&key.waker, woke->name, TASK_COMM_LEN);
        wokeby.delete(&pid);
    }

    val = counts.lookup_or_init(&key, &zero);
    (*val) += delta;
    return 0;
}
  """
  return bpf_text

def offwaketimeUtil(duration):

  tgid = None
  pid = None
  user_threads_only = False
  kernel_threads_only = False
  user_stacks_only = False
  kernel_stacks_only = False
  delimited = False
  folded = True

  stack_storage_size = 1024
  min_block_time = 1
  max_block_time = (1 << 64) - 1

  output = StringIO()

  bpf_text = init_bpf()
  # set thread filter
  thread_context = ""
  if tgid is not None:
    thread_context = "PID %d" % tgid
    thread_filter = 'tgid == %d' % tgid
  elif pid is not None:
    thread_context = "TID %d" % pid
    thread_filter = 'pid == %d' % pid
  elif user_threads_only:
    thread_context = "user threads"
    thread_filter = '!(p->flags & PF_KTHREAD)'
  elif kernel_threads_only:
    thread_context = "kernel threads"
    thread_filter = 'p->flags & PF_KTHREAD'
  else:
    thread_context = "all threads"
    thread_filter = '1'
  bpf_text = bpf_text.replace('THREAD_FILTER', thread_filter)

  # set stack storage size
  bpf_text = bpf_text.replace('STACK_STORAGE_SIZE', str(stack_storage_size))
  bpf_text = bpf_text.replace('MINBLOCK_US_VALUE', str(min_block_time))
  bpf_text = bpf_text.replace('MAXBLOCK_US_VALUE', str(max_block_time))

  # handle stack args
  kernel_stack_get = "stack_traces.get_stackid(ctx, BPF_F_REUSE_STACKID)"
  user_stack_get = \
    "stack_traces.get_stackid(ctx, BPF_F_REUSE_STACKID | BPF_F_USER_STACK)"
  stack_context = ""
  if user_stacks_only:
    stack_context = "user"
    kernel_stack_get = "-1"
  elif kernel_stacks_only:
    stack_context = "kernel"
    user_stack_get = "-1"
  else:
    stack_context = "user + kernel"
  bpf_text = bpf_text.replace('USER_STACK_GET', user_stack_get)
  bpf_text = bpf_text.replace('KERNEL_STACK_GET', kernel_stack_get)

  # initialize BPF
  b = BPF(text=bpf_text)
  b.attach_kprobe(event="finish_task_switch", fn_name="oncpu")
  b.attach_kprobe(event="try_to_wake_up", fn_name="waker")
  matched = b.num_open_kprobes()
  if matched == 0:
    print("0 functions traced. Exiting.", file=output)
    return output.getvalue()

  # header
  if not folded:
    print("Tracing blocked time (us) by %s off-CPU and waker stack" %
        stack_context, end="", file=output)
    if duration < 99999999:
        print(" for %d secs." % duration, file=output)
    else:
        print("... Hit Ctrl-C to end.", file=output)

  sleep(duration)

  if not folded:
    print(file=output)

  missing_stacks = 0
  has_enomem = False
  counts = b.get_table("counts")
  stack_traces = b.get_table("stack_traces")
  for k, v in sorted(counts.items(), key=lambda counts: counts[1].value):
    # handle get_stackid errors
    # check for an ENOMEM error
    if k.w_k_stack_id == -errno.ENOMEM or \
       k.t_k_stack_id == -errno.ENOMEM or \
       k.w_u_stack_id == -errno.ENOMEM or \
       k.t_u_stack_id == -errno.ENOMEM:
        missing_stacks += 1
        continue

    waker_user_stack = [] if k.w_u_stack_id < 1 else \
        reversed(list(stack_traces.walk(k.w_u_stack_id))[1:])
    waker_kernel_stack = [] if k.w_k_stack_id < 1 else \
        reversed(list(stack_traces.walk(k.w_k_stack_id))[1:])
    target_user_stack = [] if k.t_u_stack_id < 1 else \
        stack_traces.walk(k.t_u_stack_id)
    target_kernel_stack = [] if k.t_k_stack_id < 1 else \
        stack_traces.walk(k.t_k_stack_id)

    if folded:
        # print folded stack output
        line = \
            [k.target] + \
            [b.sym(addr, k.tgid)
                for addr in reversed(list(target_user_stack)[1:])] + \
            (["-"] if delimited else [""]) + \
            [b.ksym(addr)
                for addr in reversed(list(target_kernel_stack)[1:])] + \
            ["--"] + \
            [b.ksym(addr)
                for addr in reversed(list(waker_kernel_stack))] + \
            (["-"] if delimited else [""]) + \
            [b.sym(addr, k.tgid)
                for addr in reversed(list(waker_user_stack))] + \
            [k.waker]
        print("%s %d" % (";".join(line), v.value), file=output)

    else:
        # print wakeup name then stack in reverse order
        print("    %-16s %s %s" % ("waker:", k.waker.decode(), k.t_pid), file=output)
        for addr in waker_user_stack:
            print("    %s" % b.sym(addr, k.tgid), file=output)
        if delimited:
            print("    -", file=output)
        for addr in waker_kernel_stack:
            print("    %s" % b.ksym(addr), file=output)

        # print waker/wakee delimiter
        print("    %-16s %s" % ("--", "--"), file=output)

        # print default multi-line stack output
        for addr in target_kernel_stack:
            print("    %s" % b.ksym(addr), file=output)
        if delimited:
            print("    -", file=output)
        for addr in target_user_stack:
            print("    %s" % b.sym(addr, k.tgid), file=output)
        print("    %-16s %s %s" % ("target:", k.target.decode(), k.w_pid), file=output)
        print("        %d\n" % v.value, file=output)

  if missing_stacks > 0:
    enomem_str = " Consider increasing --stack-storage-size."
    print("WARNING: %d stack traces could not be displayed.%s" %
        (missing_stacks, enomem_str),
        file=stderr)

  b.detach_kprobe(event="finish_task_switch")
  b.detach_kprobe(event="try_to_wake_up")
  return output.getvalue()