From 56dc66d84280a56bc7838918bb03936a333270b0 Mon Sep 17 00:00:00 2001 From: Wilson Snyder Date: Fri, 3 Sep 2021 19:59:10 -0400 Subject: [PATCH] Fix verilator_profcfunc profile accounting (#3115). --- Changes | 2 + bin/verilator_profcfunc | 58 ++++++++++++++++++--------- test_regress/t/t_profcfunc.gprof | 44 ++++++++++++++++++++ test_regress/t/t_profcfunc.out | 69 ++++++++++++++++++++++++++++++++ test_regress/t/t_profcfunc.pl | 20 +++++++++ 5 files changed, 173 insertions(+), 20 deletions(-) create mode 100644 test_regress/t/t_profcfunc.gprof create mode 100644 test_regress/t/t_profcfunc.out create mode 100755 test_regress/t/t_profcfunc.pl diff --git a/Changes b/Changes index 611e8d679..f308f4c4d 100644 --- a/Changes +++ b/Changes @@ -11,6 +11,8 @@ contributors that suggested a given feature are shown in []. Thanks! Verilator 4.213 devel ========================== +* Fix verilator_profcfunc profile accounting (#3115). + Verilator 4.212 2021-09-01 ========================== diff --git a/bin/verilator_profcfunc b/bin/verilator_profcfunc index 7ee22f54c..8fee5f2cc 100755 --- a/bin/verilator_profcfunc +++ b/bin/verilator_profcfunc @@ -59,11 +59,11 @@ sub parameter { sub profcfunc { my $filename = shift; # Remove hex numbers before diffing - my $fh = IO::File->new ($filename) or die "%Error: $! $filename,"; + my $fh = IO::File->new($filename) or die "%Error: $! $filename,"; my %funcs; - while (defined (my $line=$fh->getline())) { + while (defined(my $line = $fh->getline)) { # %time cumesec selfsec calls {stuff} name if ($line =~ /^\s*([0-9.]+)\s+[0-9.]+\s+([0-9.]+)\s+([0-9.]+)\s+[^a-zA-Z_]*([a-zA-Z_].*)$/) { my $pct=$1; my $sec=$2; my $calls=$3; my $func=$4; @@ -83,44 +83,44 @@ sub profcfunc { $fh->close; # Find modules - my %pointer_mods; my %verilated_mods; foreach my $func (keys %funcs) { - if ($func =~ /(.*)::_eval\(([a-zA-Z_0-9]+__Syms).*\)$/) { + if ($func =~ /(.*)::eval\(/) { + print "-got _eval $func prefix=$1\n" if $Debug; $verilated_mods{$1} = qr/^$1/; - $pointer_mods{$2} = $1; } } - #print Dumper(\%pointer_mods, \%verilated_mods); + #print Dumper(\%verilated_mods); - # Resort by Verilog name + # Sort by Verilog name my %vfuncs; my %groups; foreach my $func (keys %funcs) { my $pct = $funcs{$func}{pct}; my $vfunc = $func; + + (my $funcarg = $func) =~ s/^.*\(//; + my $design; - - if ($func =~ /\(([a-zA-Z_0-9]+__Syms)/) { - $design = $pointer_mods{$1}; - } - foreach my $vde (keys %verilated_mods) { - last if $design; - if ($func =~ /$verilated_mods{$vde}/) { - $design=$vde; + if ($func =~ /$verilated_mods{$vde}/ + || $funcarg =~ /$verilated_mods{$vde}/) { + $design = $vde; last; } } - if ($vfunc =~ /__PROF__([a-zA-Z_0-9]+)__l?([0-9]+)\(/) { + my $vdesign = "-"; + if ($design && $vfunc =~ /__PROF__([a-zA-Z_0-9]+)__l?([0-9]+)\(/) { $vfunc = sprintf("VBlock %s:%d", $1, $2); + $vdesign = $design; $groups{type}{"Verilog Blocks under $design"} += $pct; $groups{design}{$design} += $pct; $groups{module}{$1} += $pct; } else { if ($design) { $vfunc = sprintf("VCommon %s", $func); + $vdesign = $design; $groups{type}{"Common code under $design"} += $pct; $groups{design}{$design} += $pct; $groups{module}{$design." common code"} += $pct; @@ -143,7 +143,14 @@ sub profcfunc { $groups{module}{'C++'} += $pct; } } - $vfuncs{$vfunc} = $funcs{$func}; + if (!$vfuncs{$vfunc}) { + $vfuncs{$vfunc} = $funcs{$func}; + $vfuncs{$vfunc}{design} = $vdesign; + } else { + $vfuncs{$vfunc}{pct} += $funcs{$func}{pct}; + $vfuncs{$vfunc}{calls} += $funcs{$func}{calls}; + $vfuncs{$vfunc}{sec} += $funcs{$func}{sec}; + } } @@ -165,6 +172,13 @@ sub profcfunc { print("\n"); } + my $design_width = 1; + foreach my $func (keys %vfuncs) { + if ($design_width < length($vfuncs{$func}{design})) { + $design_width = length($vfuncs{$func}{design}); + } + } + print("Verilog code profile:\n"); print(" These are split into three categories:\n"); print(" C++: Time in non-Verilated C++ code\n"); @@ -175,17 +189,21 @@ sub profcfunc { print("\n"); print(" % cumulative self \n"); - print(" time seconds seconds calls type filename and line number\n"); + print(" time seconds seconds calls "); + printf("%-${design_width}s", "design"); + print(" type filename and line number\n"); my $cume = 0; foreach my $func (sort {$vfuncs{$b}{sec} <=> $vfuncs{$a}{sec} || $a cmp $b} (keys %vfuncs)) { $cume += $vfuncs{$func}{sec}; - printf +("%6.2f %9.2f %8.2f %8d %s\n", + printf +("%6.2f %9.2f %8.2f %8d %-${design_width}s %s\n", $vfuncs{$func}{pct}, - $cume, $vfuncs{$func}{sec}, + $cume, + $vfuncs{$func}{sec}, $vfuncs{$func}{calls}, + $vfuncs{$func}{design}, $func); } } diff --git a/test_regress/t/t_profcfunc.gprof b/test_regress/t/t_profcfunc.gprof new file mode 100644 index 000000000..91be91407 --- /dev/null +++ b/test_regress/t/t_profcfunc.gprof @@ -0,0 +1,44 @@ +Flat profile: + + Note all numbers below were faked for this test, so might not be consistent. + + % cumulative self self total + time seconds seconds calls Ts/call Ts/call name + 1.99 1.99 0.99 200578 0.00 0.00 VL_EXTENDS_QQ(int, int, unsigned long) + 1.98 0.00 0.98 100000 0.00 0.00 VL_POWSS_QQQ(int, int, int, unsigned long, unsigned long, bool, bool) + 1.89 0.00 0.89 1407 0.00 0.00 Verilated::debug() + 1.88 0.00 0.88 202 0.00 0.00 VerilatedContext::gotFinish() const + 1.87 0.00 0.87 6 0.00 0.00 VerilatedContext::randReset() + 1.86 0.00 0.86 9 0.00 0.00 VlWide<2ul>::operator unsigned int*() + 1.79 0.00 0.79 600 0.00 0.00 Vt_prof* const& std::__get_helper<0ul, Vt_prof*, std::default_delete >(std::_Tuple_impl<0ul, Vt_prof*, std::default_delete > const&) + 1.78 0.00 0.78 3 0.00 0.00 Vt_prof*& std::__get_helper<0ul, Vt_prof*, std::default_delete >(std::_Tuple_impl<0ul, Vt_prof*, std::default_delete >&) + 1.77 0.00 0.77 1 0.00 0.00 Vt_prof::Vt_prof(VerilatedContext*, char const*) + 1.76 0.00 0.76 1 0.00 0.00 Vt_prof::Vt_prof(char const*) + 1.75 0.00 0.75 200 0.00 0.00 Vt_prof::eval() + 1.74 0.00 0.74 200 0.00 0.00 Vt_prof::eval_step() + 1.73 0.00 0.73 1 0.00 0.00 Vt_prof::final() + 1.72 0.00 0.72 1 0.00 0.00 Vt_prof::~Vt_prof() + 1.71 0.00 0.71 1 0.00 0.00 Vt_prof__Syms::Vt_prof__Syms(VerilatedContext*, char const*, Vt_prof*) + 1.70 0.00 0.70 1 0.00 0.00 Vt_prof__Syms::~Vt_prof__Syms() + 1.69 0.00 0.69 1 0.00 0.00 Vt_prof___024root::__Vconfigure(Vt_prof__Syms*, bool) + 1.68 0.00 0.68 1 0.00 0.00 Vt_prof___024root::Vt_prof___024root(char const*) + 1.67 0.00 0.67 1 0.00 0.00 Vt_prof___024root::~Vt_prof___024root() + 1.66 0.00 0.66 201 0.00 0.00 Vt_prof___024root___eval(Vt_prof___024root*) + 1.65 0.00 0.65 200 0.00 0.00 Vt_prof___024root___eval_debug_assertions(Vt_prof___024root*) + 1.64 0.00 0.64 100 0.00 0.00 Vt_prof___024root___sequent__TOP__5__PROF__t_prof__l31(Vt_prof___024root*) + 1.63 0.00 0.63 100 0.00 0.00 Vt_prof___024root___sequent__TOP__50__PROF__t_prof__l31(Vt_prof___024root*) + 1.62 0.00 0.62 100 0.00 0.00 Vt_prof___024root___sequent__TOP__6__PROF__t_prof__l30(Vt_prof___024root*) + 1.61 0.00 0.61 1 0.00 0.00 Vt_prof___024root___final(Vt_prof___024root*) + 1.60 0.00 0.60 1 0.00 0.00 Vt_prof___024root___eval_settle(Vt_prof___024root*) + 1.59 0.00 0.59 1 0.00 0.00 Vt_prof___024root___eval_initial(Vt_prof___024root*) + 1.58 0.00 0.58 1 0.00 0.00 Vt_prof___024root___ctor_var_reset(Vt_prof___024root*) + 1.57 0.00 0.57 1 0.00 0.00 Vt_prof___024root___initial__TOP__13__PROF__t_prof__l13(Vt_prof___024root*) + 1.30 0.00 0.30 1 0.00 0.00 _eval_initial_loop(Vt_prof__Syms*) + 1.29 0.00 0.29 1 0.00 0.00 _vl_cmp_w(int, unsigned int const*, unsigned int const*) + 1.28 0.00 0.28 2 0.00 0.00 _vl_moddiv_w(int, unsigned int*, unsigned int const*, unsigned int const*, bool) + 1.27 0.00 0.27 2 0.00 0.00 _vl_vsformat(std::__cxx11::basic_string, std::allocator >&, char const*, __va_list_tag*) + 1.26 0.00 0.26 1399 0.00 0.00 std::unique_ptr >::get() const + 1.25 0.00 0.25 3 0.00 0.00 unsigned long const& std::max(unsigned long const&, unsigned long const&) + 1.19 0.00 0.19 1 0.00 0.00 vl_finish(char const*, int, char const*) + 1.18 0.00 0.18 2 0.00 0.00 vl_time_pow10(int) + diff --git a/test_regress/t/t_profcfunc.out b/test_regress/t/t_profcfunc.out new file mode 100644 index 000000000..fb22d5c8e --- /dev/null +++ b/test_regress/t/t_profcfunc.out @@ -0,0 +1,69 @@ +Overall summary by type: + % time type + 4.37 C++ + 33.48 Common code under Vt_prof + 15.82 VLib + 6.46 Verilog Blocks under Vt_prof + 39.87 Unaccounted for/rounding error + +Overall summary by design: + % time design + 4.37 C++ + 15.82 VLib + 39.94 Vt_prof + 39.87 Unaccounted for/rounding error + +Overall summary by module: + % time module + 4.37 C++ + 15.82 VLib + 33.48 Vt_prof common code + 6.46 t_prof + 39.87 Unaccounted for/rounding error + +Verilog code profile: + These are split into three categories: + C++: Time in non-Verilated C++ code + Prof: Time in profile overhead + VBlock: Time attributable to a block in a Verilog file and line + VCommon: Time in a Verilated module, due to all parts of the design + VLib: Time in Verilated common libraries, called by the Verilated code + + % cumulative self + time seconds seconds calls design type filename and line number + 3.27 1.27 1.27 200 Vt_prof VBlock t_prof:31 + 1.99 2.26 0.99 200578 - VLib VL_EXTENDS_QQ(int, int, unsigned long) + 1.98 3.24 0.98 100000 - VLib VL_POWSS_QQQ(int, int, int, unsigned long, unsigned long, bool, bool) + 1.89 4.13 0.89 1407 - VLib Verilated::debug() + 1.88 5.01 0.88 202 - VLib VerilatedContext::gotFinish() const + 1.87 5.88 0.87 6 - VLib VerilatedContext::randReset() + 1.86 6.74 0.86 9 - C++ VlWide<2ul>::operator unsigned int*() + 1.79 7.53 0.79 600 Vt_prof VCommon Vt_prof* const& std::__get_helper<0ul, Vt_prof*, std::default_delete >(std::_Tuple_impl<0ul, Vt_prof*, std::default_delete > const&) + 1.78 8.31 0.78 3 Vt_prof VCommon Vt_prof*& std::__get_helper<0ul, Vt_prof*, std::default_delete >(std::_Tuple_impl<0ul, Vt_prof*, std::default_delete >&) + 1.77 9.08 0.77 1 Vt_prof VCommon Vt_prof::Vt_prof(VerilatedContext*, char const*) + 1.76 9.84 0.76 1 Vt_prof VCommon Vt_prof::Vt_prof(char const*) + 1.75 10.59 0.75 200 Vt_prof VCommon Vt_prof::eval() + 1.74 11.33 0.74 200 Vt_prof VCommon Vt_prof::eval_step() + 1.73 12.06 0.73 1 Vt_prof VCommon Vt_prof::final() + 1.72 12.78 0.72 1 Vt_prof VCommon Vt_prof::~Vt_prof() + 1.71 13.49 0.71 1 Vt_prof VCommon Vt_prof__Syms::Vt_prof__Syms(VerilatedContext*, char const*, Vt_prof*) + 1.70 14.19 0.70 1 Vt_prof VCommon Vt_prof__Syms::~Vt_prof__Syms() + 1.69 14.88 0.69 1 Vt_prof VCommon Vt_prof___024root::__Vconfigure(Vt_prof__Syms*, bool) + 1.68 15.56 0.68 1 Vt_prof VCommon Vt_prof___024root::Vt_prof___024root(char const*) + 1.67 16.23 0.67 1 Vt_prof VCommon Vt_prof___024root::~Vt_prof___024root() + 1.66 16.89 0.66 201 Vt_prof VCommon Vt_prof___024root___eval(Vt_prof___024root*) + 1.65 17.54 0.65 200 Vt_prof VCommon Vt_prof___024root___eval_debug_assertions(Vt_prof___024root*) + 1.62 18.16 0.62 100 Vt_prof VBlock t_prof:30 + 1.61 18.77 0.61 1 Vt_prof VCommon Vt_prof___024root___final(Vt_prof___024root*) + 1.60 19.37 0.60 1 Vt_prof VCommon Vt_prof___024root___eval_settle(Vt_prof___024root*) + 1.59 19.96 0.59 1 Vt_prof VCommon Vt_prof___024root___eval_initial(Vt_prof___024root*) + 1.58 20.54 0.58 1 Vt_prof VCommon Vt_prof___024root___ctor_var_reset(Vt_prof___024root*) + 1.57 21.11 0.57 1 Vt_prof VBlock t_prof:13 + 1.30 21.41 0.30 1 Vt_prof VCommon _eval_initial_loop(Vt_prof__Syms*) + 1.29 21.70 0.29 1 - VLib _vl_cmp_w(int, unsigned int const*, unsigned int const*) + 1.28 21.98 0.28 2 - VLib _vl_moddiv_w(int, unsigned int*, unsigned int const*, unsigned int const*, bool) + 1.27 22.25 0.27 2 - VLib _vl_vsformat(std::__cxx11::basic_string, std::allocator >&, char const*, __va_list_tag*) + 1.26 22.51 0.26 1399 - C++ std::unique_ptr >::get() const + 1.25 22.76 0.25 3 - C++ unsigned long const& std::max(unsigned long const&, unsigned long const&) + 1.19 22.95 0.19 1 - VLib vl_finish(char const*, int, char const*) + 1.18 23.13 0.18 2 - VLib vl_time_pow10(int) diff --git a/test_regress/t/t_profcfunc.pl b/test_regress/t/t_profcfunc.pl new file mode 100755 index 000000000..f6d5ee8ae --- /dev/null +++ b/test_regress/t/t_profcfunc.pl @@ -0,0 +1,20 @@ +#!/usr/bin/env perl +if (!$::Driver) { use FindBin; exec("$FindBin::Bin/bootstrap.pl", @ARGV, $0); die; } +# DESCRIPTION: Verilator: Verilog Test driver/expect definition +# +# Copyright 2003 by Wilson Snyder. This program is free software; you +# can redistribute it and/or modify it under the terms of either the GNU +# Lesser General Public License Version 3 or the Perl Artistic License +# Version 2.0. +# SPDX-License-Identifier: LGPL-3.0-only OR Artistic-2.0 + +scenarios(vlt_all => 1); + +run(cmd => ["cd $Self->{obj_dir} && $ENV{VERILATOR_ROOT}/bin/verilator_profcfunc $Self->{t_dir}/t_profcfunc.gprof > cfuncs.out"], + check_finished => 0); + +files_identical("$Self->{obj_dir}/cfuncs.out", $Self->{golden_filename}); + +ok(1); + +1;