lkml.org 
[lkml]   [2009]   [Jan]   [16]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    SubjectRe: [PATCH 0/2] ftrace: updates to tip
    From
    Date
    On Thu, 2009-01-15 at 19:40 -0500, Steven Rostedt wrote:
    > Ingo,
    >
    > The first patch is critical, and needs to stay with trace_output.c
    > Not that critical since trace_output.c is not in mainline yet.
    >
    > The second patch gives the ability to stack trace functions.
    > I've been leery about adding this and still keep it a separate
    > option from the "stacktrace" that already exists. This is because
    > when enabled with no filtering, the lag between typing and seeing
    > what is typed can be up to 10 seconds or more.
    >

    I mostly asked for this because I often try to find the most common
    reason a given function is called, and oprofile isn't always a great way
    to catch it. systemtap can do it too if you can get systemtap to work
    against your current devel kernel, but there are limits on how much
    memory it'll use.

    I've attached some simple python code that parses the output of the
    function stack tracer, it makes some dumb assumptions about the format
    but isn't a bad proof of concept. The first such assumption is that
    you're only filtering on a single function.

    Here is some example output, trying to find the most common causes of
    native_smp_send_reschedule() during a btrfs dbench run.

    It relates to the Oracle OLTP thread because oracle heavily uses IPC
    semaphores to trigger wakeups of processes as various events finish.
    I'd bet that try_to_wakeup is the most common cause of the reschedule
    calls there as well.

    For btrfs, the btree lock mutexes come back into the profile yet again.
    It would be interesting to change the spinning mutex code to look for
    spinners and skip the wakeup on unlock, but that's a different thread
    entirely.

    The short version is: thanks Steve, this is really cool!

    12058 hits:
    <= check_preempt_wakeup
    <= try_to_wake_up
    <= wake_up_process
    <= __mutex_unlock_slowpath
    <= mutex_unlock
    <= btrfs_tree_unlock
    <= unlock_up
    ===========

    11678 hits:
    <= check_preempt_curr_idle
    <= try_to_wake_up
    <= wake_up_process
    <= __mutex_unlock_slowpath
    <= mutex_unlock
    <= btrfs_tree_unlock
    <= unlock_up
    ===========

    1569 hits:
    <= check_preempt_wakeup
    <= try_to_wake_up
    <= default_wake_function
    <= autoremove_wake_function
    <= wake_bit_function
    <= __wake_up_common
    <= __wake_up
    ===========

    1505 hits:
    <= check_preempt_curr_idle
    <= try_to_wake_up
    <= default_wake_function
    <= autoremove_wake_function
    <= wake_bit_function
    <= __wake_up_common
    <= __wake_up
    ===========

    1377 hits: # the output isn't perfectly parsable, or I'm dumb
    <= 0
    <= 0
    <= 0
    <= 0
    <= 0
    <= 0
    <= 0
    ===========

    1194 hits:
    <= check_preempt_curr_idle
    <= try_to_wake_up
    <= wake_up_process
    <= btrfs_queue_worker
    <= schedule_bio
    <= btrfs_map_bio
    <= __btrfs_submit_bio_done
    ===========

    1108 hits:
    <= check_preempt_curr_idle
    <= try_to_wake_up
    <= default_wake_function
    <= autoremove_wake_function
    <= __wake_up_common
    <= __wake_up
    <= cache_drop_leaf_ref
    ===========

    935 hits:
    <= check_preempt_wakeup
    <= try_to_wake_up
    <= wake_up_process
    <= btrfs_queue_worker
    <= schedule_bio
    <= btrfs_map_bio
    <= __btrfs_submit_bio_done
    ===========

    856 hits:
    <= check_preempt_curr_idle
    <= try_to_wake_up
    <= wake_up_process
    <= btrfs_queue_worker
    <= btrfs_wq_submit_bio
    <= btrfs_submit_bio_hook
    <= submit_one_bio
    ===========

    502 hits:
    <= check_preempt_wakeup
    <= try_to_wake_up
    <= wake_up_process
    <= btrfs_queue_worker
    <= btrfs_wq_submit_bio
    <= btrfs_submit_bio_hook
    <= submit_one_bio
    ===========

    442 hits:
    <= check_preempt_curr_idle
    <= try_to_wake_up
    <= wake_up_process
    <= __mutex_unlock_slowpath
    <= mutex_unlock
    <= btrfs_tree_unlock
    <= btrfs_release_path
    ===========

    327 hits:
    <= check_preempt_wakeup
    <= try_to_wake_up
    <= default_wake_function
    <= autoremove_wake_function
    <= __wake_up_common
    <= __wake_up
    <= cache_drop_leaf_ref
    ===========


    ... output continues for a bit


    #!/usr/bin/env python
    #
    # this is a fairly trivial parser of the ftrace function stack trace output
    # the idea is to find the most common stack traces that lead to calling
    # given function, even those that don't use much CPU time and won't
    # show up in other profilers.
    #
    # It assumes ftrace output looks like this:
    # some text including the function name
    # <= func
    # <= func2
    # <= func3
    # some text including the function name
    # <= func4
    # <= func5
    # <= func6
    #
    # The traces above would generate two histogram entries, one for
    # func,func2,func3 and one for func4,func5,fun6
    #

    import sys, os, signal

    stacks = {}

    last = []
    printed = False

    def summary(arg1, arg2):
    global printed;

    printed = True
    count = {}

    for lines, c in stacks.items():
    count.setdefault(c, []).append(lines + ' ===========\n')

    limit = 50
    keys = count.keys()
    keys.sort()
    for x in keys.__reversed__():
    print "%d hits: \n%s" % (x, "".join(count[x]))
    limit -= 1
    if limit <= 0:
    break
    sys.exit(0)

    signal.signal(signal.SIGTERM, summary)
    signal.signal(signal.SIGINT, summary)

    while True:
    try:
    l = sys.stdin.readline()
    except:
    break

    if not l:
    break

    if l[0] == '#':
    continue
    if not l.startswith(' <='):
    if last:
    lines = ''.join(last)
    val = stacks.get(lines, 0) + 1
    stacks[lines] = val
    # we don't put the header line into the trace because that might
    # have timestamp info in it.
    last = []
    else:
    last.append(l)

    if not printed:
    summary(1, 2)
    \
     
     \ /
      Last update: 2009-01-16 22:51    [W:4.142 / U:0.008 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site