NYTProf.xs: Spurious logwarning being generated

[jkeenan]

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:

I run Devel::NYTProf all the time and have no problems with it until
this morning. Now I get quite a lot of [warnings like those below]:

fid 23 has no src saved for /home/martin/perl5/perlbrew/perls/
perl-5.14.0/lib/5.14.0/Getopt/Std.pm (NYTP_FIDf_HAS_SRC not set but
src available!)
fid 193 has no src saved for /home/martin/perl5/perlbrew/perls/
perl-5.14.0/lib/5.14.0/Benchmark.pm (NYTP_FIDf_HAS_SRC not set but src
available!)

Subsequently, in 2013, Zefram reported being able to reduce the problem to the following:

$ cat t0
BEGIN { }
1;
$ perl -MDevel::NYTProf t0
fid 1 has no src saved for t0 (NYTP_FIDf_HAS_SRC not set but src available!)

The puzzling warning emanates from https://github.com/timbunce/devel-nytprof/blob/master/NYTProf.xs#L3742:

1880 static void
1881 close_output_file(pTHX) {
1882     int result;
1883     NV  timeofday;
1884 
1885     if (!out)
1886         return;
1887 
1888     timeofday = gettimeofday_nv(); /* before write_*() calls */
1889     NYTP_write_attribute_nv(out, STR_WITH_LEN("cumulative_overhead_ticks"), cumulative_overhead_ticks)     ;
1890 
1891     write_src_of_files(aTHX);
...
1905 }
1906 
...
3719 static void
3720 write_src_of_files(pTHX)
3721 {
...
3731     for (e = (fid_hash_entry*)fidhash.first_inserted; e; e = (fid_hash_entry*)e->he.next_inserted) {
3732         I32 lines;
3733         int line;
3734         AV *src_av = GvAV(gv_fetchfile_flags(e->he.key, e->he.key_len, 0));
3735 
3736         if ( !(e->fid_flags & NYTP_FIDf_HAS_SRC) ) {
3737             const char *hint = "";
3738             ++t_no_src;
3739             if (src_av && av_len(src_av) > -1) /* sanity check */
3740                 hint = " (NYTP_FIDf_HAS_SRC not set but src available!)";
3741             if (trace_level >= 3 || *hint)
3742                 logwarn("fid %d has no src saved for %.*s%s\n",
...
3781 }
3782 

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 to hint at line 3740 above and recompiling. In addition, if hint 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 #53.

Thank you very much.
Jim Keenan

[jkeenan]

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 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

devel-nytprof/NYTProf.xs

Line 3741 in 8f4088c

logwarn("GHI: %d; if 1, set hint\n", (src_av && av_len(src_av) > -1));

and

devel-nytprof/NYTProf.xs

Line 3751 in 8f4088c

logwarn("JKL: %d; if 1, conditions met for logwarn\n", (trace_level >= 3 || *hint));

).

[jkeenan]

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!)

[jkeenan]

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 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

devel-nytprof/NYTProf.xs

Line 3741 in 8f4088c

logwarn("GHI: %d; if 1, set hint\n", (src_av && av_len(src_av) > -1));

and

devel-nytprof/NYTProf.xs

Line 3751 in 8f4088c

logwarn("JKL: %d; if 1, conditions met for logwarn\n", (trace_level >= 3 || *hint));

).

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.

[jkeenan]

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