mirror of
https://github.com/verilator/verilator.git
synced 2025-01-01 04:07:34 +00:00
Fix verilator_profcfunc profile accounting (#3115).
This commit is contained in:
Wilson Snyder
parent
7ae54ef973
commit
56dc66d842
2
Changes
2
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
|
||||
==========================
|
||||
|
||||
@ -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);
|
||||
}
|
||||
}
|
||||
|
||||
44
test_regress/t/t_profcfunc.gprof
Normal file
44
test_regress/t/t_profcfunc.gprof
Normal file
@ -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<Vt_prof> >(std::_Tuple_impl<0ul, Vt_prof*, std::default_delete<Vt_prof> > const&)
|
||||
1.78 0.00 0.78 3 0.00 0.00 Vt_prof*& std::__get_helper<0ul, Vt_prof*, std::default_delete<Vt_prof> >(std::_Tuple_impl<0ul, Vt_prof*, std::default_delete<Vt_prof> >&)
|
||||
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<char, std::char_traits<char>, std::allocator<char> >&, char const*, __va_list_tag*)
|
||||
1.26 0.00 0.26 1399 0.00 0.00 std::unique_ptr<VerilatedContext, std::default_delete<VerilatedContext> >::get() const
|
||||
1.25 0.00 0.25 3 0.00 0.00 unsigned long const& std::max<unsigned long>(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)
|
||||
|
||||
69
test_regress/t/t_profcfunc.out
Normal file
69
test_regress/t/t_profcfunc.out
Normal file
@ -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<Vt_prof> >(std::_Tuple_impl<0ul, Vt_prof*, std::default_delete<Vt_prof> > const&)
|
||||
1.78 8.31 0.78 3 Vt_prof VCommon Vt_prof*& std::__get_helper<0ul, Vt_prof*, std::default_delete<Vt_prof> >(std::_Tuple_impl<0ul, Vt_prof*, std::default_delete<Vt_prof> >&)
|
||||
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<char, std::char_traits<char>, std::allocator<char> >&, char const*, __va_list_tag*)
|
||||
1.26 22.51 0.26 1399 - C++ std::unique_ptr<VerilatedContext, std::default_delete<VerilatedContext> >::get() const
|
||||
1.25 22.76 0.25 3 - C++ unsigned long const& std::max<unsigned long>(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)
|
||||
20
test_regress/t/t_profcfunc.pl
Executable file
20
test_regress/t/t_profcfunc.pl
Executable file
@ -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;
|
||||
Loading…
Reference in New Issue
Block a user