Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S934304AbdCVMBC (ORCPT ); Wed, 22 Mar 2017 08:01:02 -0400 Received: from mail-pg0-f65.google.com ([74.125.83.65]:32905 "EHLO mail-pg0-f65.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S934180AbdCVMAx (ORCPT ); Wed, 22 Mar 2017 08:00:53 -0400 Subject: Re: [PATCH 2/4] perf annotate: Avoid division by zero when calculating percent To: Arnaldo Carvalho de Melo References: <1489978617-31396-1-git-send-email-treeze.taeung@gmail.com> <1489978617-31396-3-git-send-email-treeze.taeung@gmail.com> <20170320181559.GD27647@kernel.org> <939347e4-593c-4ef6-37d9-daa2fee3aed8@gmail.com> <20170321141407.GB3641@kernel.org> <20170321142155.GC3641@kernel.org> Cc: linux-kernel@vger.kernel.org, Jiri Olsa , Namhyung Kim , Ingo Molnar , Peter Zijlstra , Wang Nan , Masami Hiramatsu , Jiri Olsa From: Taeung Song Message-ID: <61fdd1df-0ca9-0131-9521-2138b328a65b@gmail.com> Date: Wed, 22 Mar 2017 21:00:23 +0900 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Thunderbird/45.2.0 MIME-Version: 1.0 In-Reply-To: <20170321142155.GC3641@kernel.org> Content-Type: text/plain; charset=windows-1252; format=flowed Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 6565 Lines: 132 On 03/21/2017 11:21 PM, Arnaldo Carvalho de Melo wrote: > Em Tue, Mar 21, 2017 at 11:14:07AM -0300, Arnaldo Carvalho de Melo escreveu: >> Em Tue, Mar 21, 2017 at 07:20:20AM +0900, Taeung Song escreveu: >>> And, >>> I tested by perf-stat on the same situation as below. >>> >>> $ perf stat -e "{cycles,page-faults,branch-misses}" ./old >> 6623856 >> >> Please always try to spell out all the steps needed to get to some >> result, for instance, in this case the info above, that you are asking >> for three counters to be recorded at once probably has the key to >> reproduce this, as I think that you may run your workload and sometimes >> not get one page fault, leading tho that division by zero, but I have to >> try to reproduce it now that I have this clue. > > Bingo! > > [root@jouet ~]# perf record -e "{cycles,page-faults,branch-misses}" usleep 1 > [ perf record: Woken up 1 times to write data ] > [ perf record: Captured and wrote 0.020 MB perf.data (20 samples) ] > [root@jouet ~]# perf annotate -l --stdio 2>&1 | grep -w nan | head > 100.00 -nan 100.00 msr.h:104 > 0.00 -nan 0.00 : ffffffff81060bf0: mov %edi,%ecx > 0.00 -nan 0.00 : ffffffff81060bf2: mov %esi,%eax > 0.00 -nan 0.00 : ffffffff81060bf4: wrmsr > msr.h:104 100.00 -nan 100.00 : ffffffff81060bf6: nopl 0x0(%rax,%rax,1) > 0.00 -nan 0.00 : ffffffff81060bfb: retq > 0.00 -nan 0.00 : ffffffff81060bfc: push %rbp > 0.00 -nan 0.00 : ffffffff81060bfd: mov %esi,%eax > 0.00 -nan 0.00 : ffffffff81060bff: mov %rdx,%rsi > 0.00 -nan 0.00 : ffffffff81060c02: shl $0x20,%rsi > [root@jouet ~]# > > So, if we don't use -l/--print-line we get: > > [root@jouet ~]# perf annotate --stdio --no-source native_write_msr > Percent | Source code & Disassembly of vmlinux for cycles (3 samples) > ------------------------------------------------------------------------------------------- > : ffffffff81060bf0 : > : __wrmsr(): > 0.00 0.00 0.00 : ffffffff81060bf0: mov %edi,%ecx > 0.00 0.00 0.00 : ffffffff81060bf2: mov %esi,%eax > 0.00 0.00 0.00 : ffffffff81060bf4: wrmsr > : arch_static_branch(): > 100.00 0.00 100.00 : ffffffff81060bf6: nopl 0x0(%rax,%rax,1) > : native_write_msr(): > 0.00 0.00 0.00 : ffffffff81060bfb: retq > 0.00 0.00 0.00 : ffffffff81060bfc: push %rbp > 0.00 0.00 0.00 : ffffffff81060bfd: mov %esi,%eax > 0.00 0.00 0.00 : ffffffff81060bff: mov %rdx,%rsi > 0.00 0.00 0.00 : ffffffff81060c02: shl $0x20,%rsi > 0.00 0.00 0.00 : ffffffff81060c06: mov %eax,%edx > 0.00 0.00 0.00 : ffffffff81060c08: mov %rsp,%rbp > 0.00 0.00 0.00 : ffffffff81060c0b: or %rdx,%rsi > 0.00 0.00 0.00 : ffffffff81060c0e: xor %edx,%edx > 0.00 0.00 0.00 : ffffffff81060c10: callq ffffffff81457df0 > 0.00 0.00 0.00 : ffffffff81060c15: pop %rbp > 0.00 0.00 0.00 : ffffffff81060c16: retq > [root@jouet ~]# > > I.e. one column per event in that group, and no -nan, all is well. The reason is the below if statement at util/annotate.c:910. 881 double disasm__calc_percent(struct annotation *notes, int evidx, s64 offset, ... 904 struct sym_hist *h = annotation__histogram(notes, evidx); 905 unsigned int hits = 0; 906 907 while (offset < end) 908 hits += h->addr[offset++]; 909 910 if (h->sum) { 911 *nr_samples = hits; 912 percent = 100.0 * hits / h->sum; 913 } 914 } The if statement 'if (h->sum)' prevent division by zero, so all is well. So I sent this patch because of same reason adding the if statement 'if (h->sum)' in symbol__get_source_line(). But will resend v2 with more clearly commit log message! I think previous log message is a bit insufficient.. Thanks, Taeung > > But if we ask for --lines it gets b0rked: > > [root@jouet ~]# perf annotate --stdio --no-source native_write_msr --print-line > > Sorted summary for file /lib/modules/4.11.0-rc2+/build/vmlinux > ---------------------------------------------- > > 100.00 -nan 100.00 msr.h:104 > Percent | Source code & Disassembly of vmlinux for cycles (3 samples) > ------------------------------------------------------------------------------------------- > : ffffffff81060bf0 : > : __wrmsr(): > 0.00 -nan 0.00 : ffffffff81060bf0: mov %edi,%ecx > 0.00 -nan 0.00 : ffffffff81060bf2: mov %esi,%eax > 0.00 -nan 0.00 : ffffffff81060bf4: wrmsr > : arch_static_branch(): > msr.h:104 100.00 -nan 100.00 : ffffffff81060bf6: nopl 0x0(%rax,%rax,1) > : native_write_msr(): > 0.00 -nan 0.00 : ffffffff81060bfb: retq > 0.00 -nan 0.00 : ffffffff81060bfc: push %rbp > 0.00 -nan 0.00 : ffffffff81060bfd: mov %esi,%eax > 0.00 -nan 0.00 : ffffffff81060bff: mov %rdx,%rsi > 0.00 -nan 0.00 : ffffffff81060c02: shl $0x20,%rsi > 0.00 -nan 0.00 : ffffffff81060c06: mov %eax,%edx > 0.00 -nan 0.00 : ffffffff81060c08: mov %rsp,%rbp > 0.00 -nan 0.00 : ffffffff81060c0b: or %rdx,%rsi > 0.00 -nan 0.00 : ffffffff81060c0e: xor %edx,%edx > 0.00 -nan 0.00 : ffffffff81060c10: callq ffffffff81457df0 > 0.00 -nan 0.00 : ffffffff81060c15: pop %rbp > 0.00 -nan 0.00 : ffffffff81060c16: retq > [root@jouet ~]# > > I don't have that much time to continue pursuing this, try to continue > investigating, I'll try to help and to fix this later. > > - Arnaldo >