search

timbunce / devel-nytprof

Devel::NYTProf is a powerful feature-rich source code profiler for Perl. (Mostly in maintenance mode, so PRs are much more likely to be acted upon than Issues.)
http://blog.timbunce.org/tag/nytprof/
67 stars 51 forks source link

t/test14.t and others failing on older versions of perl #154

Open jkeenan opened 3 years ago

jkeenan commented 3 years ago

On older versions of Perl (5.8.9 thru 5.12.5), on FreeBSD and Linux, t/test14.t is failing like this:

#   Failed test 'test14.rdt match generated profile data for blocks=1 calls=0 compress=0 leave=1 savesrc=0 slowops=2 start=init use_db_sub=0'
#   at t/lib/NYTProfTest.pm line 464.
#     Structures begin differing at:
#          $got->[60] = 'sub_subinfo    test14::bar [ 2:16-18 calls 0 times 0 0 0 0 ]'
#     $expected->[60] = 'sub_subinfo    test14::bar [ 2:16-18 calls 1 times 0 0 0 0 ]'
--- test14.rdt  2021-03-23 19:37:26.000000000 +0000
+++ test14.rdt_new  2021-04-06 13:43:42.079228508 +0000
@@ -58,9 +58,7 @@
 sub_subinfo    main::BEGIN [ 1:16-16 calls 0 times 0 0 0 0 ]
 sub_subinfo    main::RUNTIME   [ 1:1-1 calls 0 times 0 0 0 0 ]
 sub_subinfo    test14::BEGIN   [ 2:2-2 calls 0 times 0 0 0 0 ]
-sub_subinfo    test14::bar [ 2:16-18 calls 1 times 0 0 0 0 ]
-sub_subinfo    test14::bar called_by   3:1 [ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo    test14::foo [ 2:12-14 calls 1 times 0 0 0 0 ]
-sub_subinfo    test14::foo called_by   3:1 [ 1 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo    test14::bar [ 2:16-18 calls 0 times 0 0 0 0 ]
+sub_subinfo    test14::foo [ 2:12-14 calls 0 times 0 0 0 0 ]
 sub_subinfo    test14::pre [ 2:8-8 calls 1 times 0 0 0 0 ]
 sub_subinfo    test14::pre called_by   1:17    [ 1 0 0 0 0 0 0 main::RUNTIME ]

#   Failed test 'test14.rdt match generated profile data for blocks=1 calls=1 compress=0 leave=0 savesrc=1 slowops=2 start=init use_db_sub=0'
#   at t/lib/NYTProfTest.pm line 464.
#     Structures begin differing at:
#          $got->[23] = 'fid_block_time 3   1   [ 0 1 ]'
#     $expected->[23] = 'fid_block_time 4   1   [ 0 1 ]'
--- test14.rdt  2021-03-23 19:37:26.000000000 +0000
+++ test14.rdt_new  2021-04-06 13:43:42.171233325 +0000
@@ -21,7 +21,7 @@
 fid_block_time 2   13  [ 0 1 ]
 fid_block_time 2   17  [ 0 2 ]
 fid_block_time 2   20  [ 0 1 ]
-fid_block_time 4   1   [ 0 1 ]
+fid_block_time 3   1   [ 0 1 ]
 fid_fileinfo   1   [ test14.p   1 2 0 0 ]
 fid_fileinfo   1   sub main::BEGIN 16-16
 fid_fileinfo   1   sub main::RUNTIME   1-1
@@ -34,8 +34,8 @@
 fid_fileinfo   2   sub test14::foo 12-14
 fid_fileinfo   2   sub test14::pre 8-8
 fid_fileinfo   2   eval    17  [ count 1 nested 0 merged 0 ]
-fid_fileinfo   3   [ AutoLoader.pm   3 2 0 0 ]
-fid_fileinfo   4   [ (eval 0)[test14.pm (autosplit into auto/test14/bar.al):17] 2 17 4 2 0 0 ]
+fid_fileinfo   3   [ (eval 0)[test14.pm (autosplit into auto/test14/bar.al):17] 2 17 3 2 0 0 ]
+fid_fileinfo   4   [ AutoLoader.pm   4 4 0 0 ]
 fid_line_time  1   17  [ 0 1 ]
 fid_line_time  1   18  [ 0 1 ]
 fid_line_time  1   19  [ 0 1 ]
@@ -43,7 +43,7 @@
 fid_line_time  2   13  [ 0 1 ]
 fid_line_time  2   17  [ 0 2 ]
 fid_line_time  2   20  [ 0 1 ]
-fid_line_time  4   1   [ 0 1 ]
+fid_line_time  3   1   [ 0 1 ]
 fid_sub_time   1   17  [ 0 1 ]
 fid_sub_time   1   18  [ 0 1 ]
 fid_sub_time   1   19  [ 0 1 ]
@@ -51,16 +51,14 @@
 fid_sub_time   2   13  [ 0 1 ]
 fid_sub_time   2   17  [ 0 2 ]
 fid_sub_time   2   20  [ 0 1 ]
-fid_sub_time   4   1   [ 0 1 ]
+fid_sub_time   3   1   [ 0 1 ]
 profile_modes  fid_block_time  block
 profile_modes  fid_line_time   line
 profile_modes  fid_sub_time    sub
 sub_subinfo    main::BEGIN [ 1:16-16 calls 0 times 0 0 0 0 ]
 sub_subinfo    main::RUNTIME   [ 1:1-1 calls 0 times 0 0 0 0 ]
 sub_subinfo    test14::BEGIN   [ 2:2-2 calls 0 times 0 0 0 0 ]
-sub_subinfo    test14::bar [ 2:16-18 calls 1 times 0 0 0 0 ]
-sub_subinfo    test14::bar called_by   3:1 [ 1 0 0 0 0 0 0 main::RUNTIME ]
-sub_subinfo    test14::foo [ 2:12-14 calls 1 times 0 0 0 0 ]
-sub_subinfo    test14::foo called_by   3:1 [ 1 0 0 0 0 0 0 main::RUNTIME ]
+sub_subinfo    test14::bar [ 2:16-18 calls 0 times 0 0 0 0 ]
+sub_subinfo    test14::foo [ 2:12-14 calls 0 times 0 0 0 0 ]
 sub_subinfo    test14::pre [ 2:8-8 calls 1 times 0 0 0 0 ]
 sub_subinfo    test14::pre called_by   1:17    [ 1 0 0 0 0 0 0 main::RUNTIME ]
 ...

Test Summary Report
-------------------
t/test14.t             (Wstat: 4096 Tests: 97 Failed: 16)
  Failed tests:  3, 9, 15, 21, 27, 33, 39, 45, 51, 57, 63
                69, 75, 81, 87, 93
  Non-zero exit status: 16
Files=56, Tests=4776, 101 wallclock secs ( 0.57 usr  0.46 sys + 24.53 cusr 16.34 csys = 41.90 CPU)
Result: FAIL
Failed 1/56 test programs. 16/4776 subtests failed.
Makefile:1255: recipe for target 'test_dynamic' failed
make: *** [test_dynamic] Error 255

This is from the first of these CPANtesters reports:

In addition, in the reports from perl-5.8.9 above, there are similar failures in t/test22-strevala.t and what is now t/test62-subcaller1-a.t.

These failures are not new. Similar failures can be observed beginning with NYTProf 6.03.