Open jkeenan opened 3 years ago
In commit 8f4088c02b, I added debugging statements to NYTProf.xs and to t/rt70211.t. When I run the test file via prove
, I get:
$ prove -vb t/rt70211.t
t/rt70211.t ..
XXXXXX: t/rt70211.t
not ok 1 - RT-70211: No warning logged # TODO logwarn is still being triggered
# Failed (TODO) test 'RT-70211: No warning logged'
# at t/rt70211.t line 20.
# ABC: entering 'write_src_of_files'
# DEF: 1; if 1, enter 'if' block
# GHI: 1; if 1, set hint
# JKL: 1; if 1, conditions met for logwarn
# fid 1 has no src saved for /tmp/JAEnFK1iLq (NYTP_FIDf_HAS_SRC not set but src available!)
1..1
ok
All tests successful.
Files=1, Tests=1, 0 wallclock secs ( 0.02 usr 0.00 sys + 0.07 cusr 0.00 csys = 0.09 CPU)
Result: PASS
... which at first appears to demonstrate the conditions under which the spurious warnings will be generated. *However, when I run make test
, (a) none of the added logwarns in NYTProf.xs
are generated by t/rt70211.t
; and (b) nowhere in the entire test suite are the conditions met for generating the spurious warning (see https://github.com/timbunce/devel-nytprof/blob/8f4088c02b26a86b2337c1974c7f0f3df423006c/NYTProf.xs#L3741 and https://github.com/timbunce/devel-nytprof/blob/8f4088c02b26a86b2337c1974c7f0f3df423006c/NYTProf.xs#L3751).
Data point: you get this spurious log warning whenever you simply include Devel::NYTProf via the command line.
$ perl -MDevel::NYTProf -E 'say q|hello world|;'
hello world
fid 1 has no src saved for -e (NYTP_FIDf_HAS_SRC not set but src available!)
In commit 8f4088c, I added debugging statements to NYTProf.xs and to t/rt70211.t. When I run the test file via
prove
, I get:$ prove -vb t/rt70211.t t/rt70211.t .. XXXXXX: t/rt70211.t not ok 1 - RT-70211: No warning logged # TODO logwarn is still being triggered # Failed (TODO) test 'RT-70211: No warning logged' # at t/rt70211.t line 20. # ABC: entering 'write_src_of_files' # DEF: 1; if 1, enter 'if' block # GHI: 1; if 1, set hint # JKL: 1; if 1, conditions met for logwarn # fid 1 has no src saved for /tmp/JAEnFK1iLq (NYTP_FIDf_HAS_SRC not set but src available!) 1..1 ok All tests successful. Files=1, Tests=1, 0 wallclock secs ( 0.02 usr 0.00 sys + 0.07 cusr 0.00 csys = 0.09 CPU) Result: PASS
... which at first appears to demonstrate the conditions under which the spurious warnings will be generated. *However, when I run
make test
, (a) none of the added logwarns inNYTProf.xs
are generated byt/rt70211.t
; and (b) nowhere in the entire test suite are the conditions met for generating the spurious warning (see
To clarify (at least for my future self): In the test suite as it currently stands we never encounter a situation where the "GHI" case -- (src_av && av_len(src_av) > -1)
-- evaluates to a true value (1
). Hence the condition for setting hint
is never met in the test suite.
And since, in the absence of setting trace_level >= 3
before running the test suite, *hint
evaluates to false, the "JKL" logwarn is never exercised in the test suite.
But that logwarn is clearly exercised in real code, so we have a coverage shortfall in the test suite.
If I do set export NYTPROF=trace=3
, compile, then run the test suite, there is one file in which the logwarn is generated.
$ prove -vb t/80-version.t
t/80-version.t ..
1..4
# trace=3
ok 1 - use Devel::NYTProf::Core;
ok 2 - lib/Devel/NYTProf/Core.pm $VERSION should be set
[snip]
ok 4 - lib/Devel/NYTProf.pm $VERSION should match
~ finish_profile (overhead 686t, is_profiling 1)
~ disable_profile (previously enabled, pid 122841, trace 3)
ABC: entering 'write_src_of_files'
~ writing file source code
DEF: 1; if 1, enter 'if' block
GHI: 0; if 1, set hint
JKL: 1; if 1, conditions met for logwarn
fid 1 has no src saved for t/80-version.t
DEF: 1; if 1, enter 'if' block
GHI: 0; if 1, set hint
JKL: 1; if 1, conditions met for logwarn
fid 2 has no src saved for /home/jkeenan/perl5/perlbrew/perls/perl-5.34.0/lib/site_perl/5.34.0/Test/More.pm
DEF: 1; if 1, enter 'if' block
GHI: 0; if 1, set hint
JKL: 1; if 1, conditions met for logwarn
fid 3 has no src saved for /home/jkeenan/perl5/perlbrew/perls/perl-5.34.0/lib/site_perl/5.34.0/Test/Builder.pm
DEF: 0; if 1, enter 'if' block
fid 4 has 7 src lines for (eval 10)[/home/jkeenan/perl5/perlbrew/perls/perl-5.34.0/lib/site_perl/5.34.0/Test/Builder.pm:973]
DEF: 0; if 1, enter 'if' block
[snip]
fid hash: 5 of 512 buckets used, 5 items, max chain 1
~ END done
~ finish_profile (overhead 0t, is_profiling 0)
~ disable_profile (previously disabled, pid 122841, trace 3)
fid hash: 5 of 512 buckets used, 5 items, max chain 1
ok
All tests successful.
Files=1, Tests=4, 0 wallclock secs ( 0.01 usr 0.01 sys + 0.05 cusr 0.00 csys = 0.07 CPU)
Result: PASS
Note that the "GHI" condition is still not met, so hint
never gets assigned to during the test suite. Because of the elevated trace_level, however, condition "JKL" is satisfied and the logwarn is emitted. However, whether it is a meaningful log warning is debatable.
Thank you very much. Jim Keenan
This ticket was originally filed in 2011 as RT 70211. The ticket failed to be correctly converted to a GitHub issue in 2015 and so has remained unresolved. The original ticket began like this:
Subsequently, in 2013, Zefram reported being able to reduce the problem to the following:
The puzzling warning emanates from https://github.com/timbunce/devel-nytprof/blob/master/NYTProf.xs#L3742:
Since the warning is being generated when
trace_level
is unset, it follows that the warning is being generated from*hint
. This can be confirmed by changing the assignment tohint
at line 3740 above and recompiling. In addition, ifhint
is assigned an empty string at line 3740 above and you re-compile, the warning goes away.In the rt70211-20210424 branch, I have added one test file which demonstrates the problem. The sole test in that file is currently
TODO
-ed. Once we solve the problem, that test can be un-TODO
-ed, but we may have to fix some tests in other files that are expecting the current sub-optimal behavior.This should enable us to close https://github.com/timbunce/devel-nytprof/issues/53.
Thank you very much. Jim Keenan