devel-nytprof icon indicating copy to clipboard operation
devel-nytprof copied to clipboard

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

Open jkeenan opened this issue 4 years ago • 0 comments

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.

jkeenan avatar Apr 07 '21 16:04 jkeenan