Feel free to ignore this report.
I think the problem is a result of the profiler output (to STDOUT) confusing the TAP stream. I'm working around the problem and I've not seen anyone else report it.
The only thing I can imagine that might be the source of this is that I'm testing this against 5.24.1-RC2.
$>make; perl -Mblib t/40profile.t 2>/dev/null
1..60
Test enabling the profile
ok 1 - connect
ok 2 - Profile and DBI_PROFILE not set
ok 3
ok 4
ok 5
bless( {
'Data' => {
'do' => {
'40profile.t line 80' => [
1,
'6.60419464111328e-05',
'6.60419464111328e-05',
'6.60419464111328e-05',
'6.60419464111328e-05',
'1470854886.26406',
'1470854886.26406'
]
}
},
'Path' => [
'!MethodName',
'!Caller2'
]
}, 'DBI::Profile' )
ok 6
ok 7
ok 8 - on at connect, 1 key
ok 9 - on at connect, 1 key
ok 10 - STORE is ref
dbi_profile
bless( {
'Data' => {
'' => {
'connected' => [
1,
'9.5367431640625e-07',
'9.5367431640625e-07',
'9.5367431640625e-07',
'9.5367431640625e-07',
'1470854886.26502',
'1470854886.26502'
],
'STORE' => [
5,
'1.40666961669922e-05',
'4.05311584472656e-06',
'1.9073486328125e-06',
'4.05311584472656e-06',
'1470854886.26499',
'1470854886.26502'
]
},
'Hi mom' => {
'my_method_name' => [
1,
'1',
'1',
'1',
'1',
'1470854886.26572',
'1470854886.26572'
]
}
},
'Path' => [
'!Statement',
'!MethodName'
]
}, 'DBI::Profile' )
ok 11 - avoid rounding, 1 key
ok 12 - avoid rounding, 1 dummy statement
ok 13 - dummy method name is array
ok 14 - should return ref to leaf node
ok 15 - should return ref to leaf node
ok 16 - should return ref to correct leaf node
1 1 1 1 1 1470854886.26572 1470854886.26572
ok 17
2 3 1 1 2 1470854886.26572 1470854886.26682
ok 18
Test collected profile data
bless( {
'Path' => [
'!Statement'
],
'Data' => {
'' => [
6,
'1.43051147460938e-05',
'3.09944152832031e-06',
'1.19209289550781e-06',
'3.09944152832031e-06',
'1470854886.26711',
'1470854886.26714'
],
'select mode,size,name from ?' => [
2351,
'0.0430629253387451',
'5.50746917724609e-05',
'1.09672546386719e-05',
'7.20024108886719e-05',
'1470854886.2673',
'1470854886.31572'
],
'set foo=1' => [
1,
'8.51154327392578e-05',
'8.51154327392578e-05',
'8.51154327392578e-05',
'8.51154327392578e-05',
'1470854886.31573',
'1470854886.31573'
]
}
}, 'DBI::Profile' )
ok 19 - profile data
ok 20 - ARRAY ref
ok 21 - 7 elements
ok 22 - all 7 defined
ok 23 - all 7 numeric
ok 24 - count is 3
ok 25 - total > first
ok 26 - total > longest
ok 27 - longest > 0
ok 28 - longest > shortest
ok 29 - time1 later than start time
ok 30 - time2 later than start time
ok 31 - time1 <= time2
ok 32 - next > time1
ok 33 - next > time2
ok 34 - profile
Test profile format
Profile Output
DBI::Profile: 0.043162s 88.77% (2358 calls) 40profile.t @ 2016-08-10 13:48:06
'' =>
0.000014s / 6 = 0.000002s avg (first 0.000003s, min 0.000001s, max 0.000003s)
'select mode,size,name from ?' =>
0.043063s / 2351 = 0.000018s avg (first 0.000055s, min 0.000011s, max 0.000072s)
'set foo=1' =>
0.000085s
ok 35 - non zero length
ok 36 - DBI::Profile
ok 37 - some calls
ok 38 - calls >= count
ok 39 - username stored
ok 40
ok 41 - should have 8 nodes
ok 42
testing '!File', '!Caller' and their variants in Path
ok 43
testing '!Time' and variants in Path
ok 44 - !Time and !Time~1000000 should work
testing &norm_std_n3 in Path
ok 45
ok 46 - &norm_std_n3 should normalize statement
testing code ref in Path
ok 47
ok 48
ok 49 - should be vetoed
ok 50 - $_ should contain statement
ok 51 - should have @_ as keys
ok 52 - should be able to filter by method
ok 53 - output should go to log file
testing as_text
ok 54 - as_text
ok 55 - as_text sortsub
DBI::Profile: 2.000000s 200.00% (203 calls) 40profile.t @ 2016-08-10 13:48:07
'A' =>
'Z' =>
1.000000s / 101 = 0.009901s avg (first 2.000000s, min 3.000000s, max 4.000000s)
'B' =>
'Y' =>
1.000000s / 102 = 0.009804s avg (first 2.000000s, min 3.000000s, max 4.000000s)
ok 56 - as_text general
dbi_profile_merge_nodes
ok 57 - merged nodes
ok 58 - merged time
ok 59 - merged time foo/bar
ok 60 - merged nodes foo/bar time
DBI::Profile: 0.000000s 0.00% (11 calls) 40profile.t @ 2016-08-10 13:48:07
'foo' =>
'DESTROY' =>
'baz' =>
0.000000s
'STORE' =>
'baz' =>
0.000000s / 5 = 0.000000s avg (first 0.000000s, min 0.000000s, max 0.000000s)
'connected' =>
'baz' =>
0.000000s
'execute' =>
'baz' =>
0.000000s
'fetchrow_hashref' =>
'baz' =>
0.000000s
'finish' =>
'baz' =>
0.000000s
'prepare' =>
'baz' =>
0.000000s
RT for rt.cpan.org