Document gprof steps better. Add t_prof_timing test to show GCC bug (#4858).

docs/guide/simulating.rst

@@ -279,13 +279,17 @@ profiled C++ code functions.
 
 To use profiling:
 
-#. Use Verilator's :vlopt:`--prof-cfuncs`.
+#. Make sure the Verilog code will call `$finish` at the end of simulation
+   (otherwise the C library may not correctly create the `gmon.out` file in
+   the later steps below).
+#. Run Verilator, adding the :vlopt:`--prof-cfuncs` option.
 #. Build and run the simulation model.
-#. The model will create gmon.out.
-#. Run :command:`gprof` to see where in the C++ code the time is spent.
-#. Run the gprof output through the :command:`verilator_profcfunc` program,
-   and it will tell you what Verilog line numbers on which most of the time
-   is being spent.
+#. The model will create `gmon.out`.
+#. Run :command:`gprof gmon.out > gprof.log` to see where in the C++ code
+   the time is spent.
+#. Run :command:`verilator_profcfunc gprof.log > profcfunc.log` to take the
+   gprof output and translate into output showing the Verilog line numbers
+   on which most of the time is being spent.
 
 
 .. _Execution Profiling:

test_regress/t/t_prof.pl

@@ -21,7 +21,7 @@ ok(1);
 
 sub dotest {
     compile(
-        verilator_flags2 => ["--stats --prof-cfuncs"],
+        verilator_flags2 => ["--stats --prof-cfuncs +define+T_PROF"],
         );
 
     unlink $_ foreach (glob "$Self->{obj_dir}/gmon.out.*");
@@ -36,15 +36,15 @@ sub dotest {
     $gmon_path or error("Profiler did not create a gmon.out");
     (my $gmon_base = $gmon_path) =~ s!.*[/\\]!!;
 
-    run(cmd => ["cd $Self->{obj_dir} && gprof $Self->{vm_prefix} $gmon_base > gprof.out"],
+    run(cmd => ["cd $Self->{obj_dir} && gprof $Self->{vm_prefix} $gmon_base > gprof.log"],
         check_finished => 0);
 
-    run(cmd => ["cd $Self->{obj_dir} && $ENV{VERILATOR_ROOT}/bin/verilator_profcfunc gprof.out > cfuncs.out"],
+    run(cmd => ["cd $Self->{obj_dir} && $ENV{VERILATOR_ROOT}/bin/verilator_profcfunc gprof.log > profcfuncs.log"],
         check_finished => 0);
 
-    file_grep("$Self->{obj_dir}/cfuncs.out", qr/Overall summary by/);
-    file_grep("$Self->{obj_dir}/cfuncs.out", qr/VLib + VL_POWSS_QQQ/);
-    file_grep("$Self->{obj_dir}/cfuncs.out", qr/VBlock + t_prof:/);
+    file_grep("$Self->{obj_dir}/profcfuncs.log", qr/Overall summary by/);
+    file_grep("$Self->{obj_dir}/profcfuncs.log", qr/VLib + VL_POWSS_QQQ/);
+    file_grep("$Self->{obj_dir}/profcfuncs.log", qr/VBlock + t_prof:/);
 }
 
 1;

test_regress/t/t_prof.v

@@ -4,11 +4,17 @@
 // any use, without warranty, 2021 by Wilson Snyder.
 // SPDX-License-Identifier: CC0-1.0
 
-module t(/*AUTOARG*/
-   // Inputs
+module t(
+`ifdef T_PROF
    clk
+`endif
    );
+`ifdef T_PROF
    input clk;
+`else
+   bit clk;
+   initial forever begin #5; clk = !clk; end
+`endif
 
    integer cyc = 0;
    wire [63:0] result;

test_regress/t/t_prof_timing.pl

@@ -0,0 +1,55 @@
+#!/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);
+
+top_filename("t/t_prof.v");
+
+# TODO below might no longer be required as configure checks for -pg
+if ($ENV{VERILATOR_TEST_NO_GPROF}) {
+    skip("Skipping due to VERILATOR_TEST_NO_GPROF");
+} else {
+    dotest();
+}
+
+ok(1);
+
+sub dotest {
+    compile(
+        verilator_flags2 => ["--stats --prof-cfuncs --binary"],
+        );
+
+    unlink $_ foreach (glob "$Self->{obj_dir}/gmon.out.*");
+    setenv('GMON_OUT_PREFIX', "$Self->{obj_dir}/gmon.out");
+
+    execute(
+        check_finished => 1,
+        );
+
+    my $gmon_path;
+    $gmon_path = $_ foreach (glob "$Self->{obj_dir}/gmon.out.*");
+    $gmon_path or error("Profiler did not create a gmon.out");
+    (my $gmon_base = $gmon_path) =~ s!.*[/\\]!!;
+
+    run(cmd => ["cd $Self->{obj_dir} && gprof $Self->{vm_prefix} $gmon_base > gprof.log"],
+        check_finished => 0);
+
+    run(cmd => ["cd $Self->{obj_dir} && $ENV{VERILATOR_ROOT}/bin/verilator_profcfunc gprof.log > profcfuncs.log"],
+        check_finished => 0);
+
+    file_grep("$Self->{obj_dir}/profcfuncs.log", qr/Overall summary by/);
+#   Appears that GCC 11.4 has a bug whereby it doesn't trace function calls
+#   within coroutines; CLang seems to work correctly.
+#   file_grep("$Self->{obj_dir}/profcfuncs.log", qr/VLib + VL_POWSS_QQQ/);
+    file_grep("$Self->{obj_dir}/profcfuncs.log", qr/VLib + VL_WRITEF/);
+    file_grep("$Self->{obj_dir}/profcfuncs.log", qr/VBlock + t_prof:/);
+}
+
+1;

test_regress/t/t_profc.pl

@@ -31,7 +31,7 @@ sub dotest {
     $gmon_path or error("Profiler did not create a gmon.out");
     (my $gmon_base = $gmon_path) =~ s!.*[/\\]!!;
 
-    run(cmd => ["cd $Self->{obj_dir} && gprof $Self->{vm_prefix} $gmon_base > gprof.out"],
+    run(cmd => ["cd $Self->{obj_dir} && gprof $Self->{vm_prefix} $gmon_base > gprof.log"],
         check_finished => 0);
 }
 

test_regress/t/t_profcfunc.pl

@@ -10,10 +10,10 @@ if (!$::Driver) { use FindBin; exec("$FindBin::Bin/bootstrap.pl", @ARGV, $0); di
 
 scenarios(dist => 1);
 
-run(cmd => ["cd $Self->{obj_dir} && $ENV{VERILATOR_ROOT}/bin/verilator_profcfunc $Self->{t_dir}/t_profcfunc.gprof > cfuncs.out"],
+run(cmd => ["cd $Self->{obj_dir} && $ENV{VERILATOR_ROOT}/bin/verilator_profcfunc $Self->{t_dir}/t_profcfunc.gprof > profcfuncs.log"],
     check_finished => 0);
 
-files_identical("$Self->{obj_dir}/cfuncs.out", $Self->{golden_filename});
+files_identical("$Self->{obj_dir}/profcfuncs.log", $Self->{golden_filename});
 
 ok(1);