Re: [tip:perfcounters/core] perf tools: callchain: Fix sum of percentages to be 100% by displaying amount of ignored chains in fractal mode

Frederic Weisbecker
2009-08-09T02:42:45Z

On Sat, Aug 08, 2009 at 02:29:23PM +0200, Ingo Molnar wrote:
>
> * tip-bot for Frederic Weisbecker <fweisbec@gmail.com> wrote:
>
> > Commit-ID: 84fce09c6b21ef675de079a724c13a205c89520b
> > Gitweb: http://git.kernel.org/tip/84fce09c6b21ef675de079a724c13a205c89520b
> > Author: Frederic Weisbecker <fweisbec@gmail.com>
> > AuthorDate: Sat, 8 Aug 2009 02:16:25 +0200
> > Committer: Ingo Molnar <mingo@elte.hu>
> > CommitDate: Sat, 8 Aug 2009 13:49:21 +0200
> >
> > perf tools: callchain: Fix sum of percentages to be 100% by displaying amount of ignored chains in fractal mode
> >
> > When we filter the callchains below a given percentage, we
> > ignore them and the end result only shows entries that have an
> > upper percentage than the filter threshold.
> >
> > It seems to users then that we have an imbalance in the
> > percentage, as if the sum inside a profiled branch doesn't
> > reach 100%.
> >
> > Since in the past there have been real perf report bugs that
> > showed the same sypmtom, it would be nice to assure the user
> > that the data is perfect and trustable and it all sums up to
> > 100.00%.
> >
> > So fix this by displaying the remaining hits that have been
> > filtered but without more detail than their amount in each
> > branches. Example while filtering below 50%:
> >
> > 7.73% [k] delay_tsc
> > |
> > |--98.22%-- __const_udelay
> > | |
> > | |--86.37%-- ath5k_hw_register_timeout
> > | | ath5k_hw_noise_floor_calibration
> > | | ath5k_hw_reset
> > | | ath5k_reset
> > | | ath5k_config
> > | | ieee80211_hw_config
> > | | |
> > | | |--88.53%-- ieee80211_scan_work
> > | | | worker_thread
> > | | | kthread
> > | | | child_rip
> > | | --11.47%-- [...]
> > | --13.63%-- [...]
> > --1.78%-- [...]
>
> i dont seem to be able to get the bracketed numbers. I only get:
>
> titan:~> perf record -f -g -a ./hackbench 10
> titan:~> perf report -g fractal,10.0
>
> # Samples: 26832
> #
> # Overhead Command Shared Object Symbol
> # ........ .............. ........................ ......
> #
> 8.69% hackbench [kernel] [k] copy_user_generic_string
>
> 6.84% hackbench [kernel] [k] unix_stream_recvmsg
>
> 6.07% hackbench [kernel] [k] sock_alloc_send_pskb
>
> 4.33% hackbench [kernel] [k] _spin_lock
>
> 3.77% hackbench [kernel] [k] __kmalloc_node_track_caller
>
> 3.74% hackbench [kernel] [k] __alloc_skb
> |
> |--80.00%-- sock_alloc_send_pskb
> | sock_alloc_send_skb
> | unix_stream_sendmsg
> | __sock_sendmsg
> | sock_aio_write
> | do_sync_write
> | vfs_write
> | sys_write
> | sysenter_dispatch
> | 0xf7ffa430
> | 0xffadeb0000000014
> |
> --20.00%-- sock_alloc_send_skb
> unix_stream_sendmsg
> __sock_sendmsg
> sock_aio_write
> do_sync_write
> vfs_write
> sys_write
> sysenter_dispatch
> 0xf7ffa430
> 0xffadeb0000000014
>
> 3.53% hackbench [kernel] [k] ia32_sysenter_target
>
> 2.92% hackbench [vdso] [.] 0x000000f7ffa430
> |
> |--66.67%-- 0xf7ffa430
> | 0xffadeb0000000014
> |
> --33.33%-- 0xf7ffa431
> 0xffadeb0000000014
>
> 2.56% hackbench [kernel] [k] virt_to_head_page
>
> 2.37% hackbench [kernel] [k] kmem_cache_alloc_node
>
> 2.33% hackbench [kernel] [k] _spin_lock_irqsave
> |
> |--78.57%-- remove_wait_queue
> | poll_freewait
> | do_sys_poll
> | sys_poll
> | sysenter_dispatch
> | 0xf7ffa430
> | 0x1ffadea3c
> |
> |--7.14%-- __up_read
> | up_read
> | do_page_fault
> | page_fault
> | 0xf7ffa430
> | 0xa0df710000000a
> |
> |--7.14%-- unix_stream_sendmsg
> | __sock_sendmsg
> | sock_aio_write
> | do_sync_write
> | vfs_write
> | sys_write
> | sysenter_dispatch
> | 0xf7ffa430
> | 0xffadeb0000000014
> |
> --7.14%-- skb_queue_tail
> unix_stream_sendmsg
> __sock_sendmsg
> sock_aio_write
> do_sync_write
> vfs_write
> sys_write
> sysenter_dispatch
> 0xf7ffa430
> 0xffadeb0000000014
>
>
> I dont see the brackets anymore, nor does the 10% limit seem to have
> been listened to for the 7.14% result above, right?
>
> Ingo

Oh damn. I've been investigating for several hours in the wrong direction
just because this bug triggered only when I wasn't using -s s

Actually, it's just that the other kind of sorting make this bug occur
much more quickly: in the first results. It was then more obvious in these
cases, but the issue was present in every kind of sorting.

Please find the fix below, thanks!

Frederic.

---
>From 52c89279744db58a68fa2339b3c8038e67113fca Mon Sep 17 00:00:00 2001
From: Frederic Weisbecker <fweisbec@gmail.com>
Date: Sun, 9 Aug 2009 04:19:15 +0200
Subject: [PATCH] perf tools: callchain: Fix bad rounding of minimum rate

Sometimes we get callchain branches that have a rate under the limit
given by the user.

Say you launched:

perf record -f -g -a ./hackbench 10
perf report -g fractal,10.0

And you get:

2.33% hackbench [kernel] [k] _spin_lock_irqsave
|
|--78.57%-- remove_wait_queue
| poll_freewait
| do_sys_poll
| sys_poll
| sysenter_dispatch
| 0xf7ffa430
| 0x1ffadea3c
|
|--7.14%-- __up_read
| up_read
| do_page_fault
| page_fault
| 0xf7ffa430
| 0xa0df710000000a
...

It is abnormal to get a 7.14% branch whereas we passed a 10% filter.

The problem is that we round down the minimum threshold.
This happens mostly when we have very low number of events.
If the total amount of your branch is 4 and you have a subranch of 3
events, filtering to 90% will be computed like follows:

limit = 4 * 0.9;

The result is about 3.6, but the cast to integer will round down to 3.
It means that our filter is actually of 75%

We must then explicitly round up the minimum threshold.

Reported-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Frederic Weisbecker <fweisbec@gmail.com>
---
tools/perf/util/callchain.c | 5 +++--
1 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/tools/perf/util/callchain.c b/tools/perf/util/callchain.c
index a8e67aa..0114734 100644
--- a/tools/perf/util/callchain.c
+++ b/tools/perf/util/callchain.c
@@ -13,6 +13,7 @@
#include <stdio.h>
#include <stdbool.h>
#include <errno.h>
+#include <math.h>

#include "callchain.h"

@@ -112,7 +113,7 @@ static void __sort_chain_graph_rel(struct callchain_node *node,
u64 min_hit;

node->rb_root = RB_ROOT;
- min_hit = node->children_hit * min_percent / 100.0;
+ min_hit = ceil(node->children_hit * min_percent);

chain_for_each_child(child, node) {
__sort_chain_graph_rel(child, min_percent);
@@ -126,7 +127,7 @@ static void
sort_chain_graph_rel(struct rb_root *rb_root, struct callchain_node *chain_root,
u64 min_hit __used, struct callchain_param *param)
{
- __sort_chain_graph_rel(chain_root, param->min_percent);
+ __sort_chain_graph_rel(chain_root, param->min_percent / 100.0);
rb_root->rb_node = chain_root->rb_root.rb_node;
}

--
1.6.2.3