linux-kernel - Re: [PATCH 0/2] ftrace: updates to tip

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:	Fri, 16 Jan 2009 16:47:47 -0500
From:	Chris Mason <chris.mason@...cle.com>
To:	Steven Rostedt <rostedt@...dmis.org>
Cc:	linux-kernel@...r.kernel.org, Ingo Molnar <mingo@...e.hu>,
	Andrew Morton <akpm@...ux-foundation.org>,
	Frederic Weisbecker <fweisbec@...il.com>
Subject: Re: [PATCH 0/2] ftrace: updates to tip

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



View attachment "trace-histogram" of type "text/x-python" (1639 bytes)