http://qs321.pair.com?node_id=11114118


in reply to Re^2: NYTProf line report failure
in thread NYTProf line report failure

One thing is sure, $self->profile returns undef. Just a wild guess: strip_prefix_from_paths() removes the ABC::XYZ from ABC::XYZ::myscript from the filename string. Or something to that effect, the ABC::XYZ is taken from your @INC I guess. I also guess that it's likely the eval refers to eval'ing some require'd modules. You could change the code like: [defined($self->profile) ? $self->profile->inc : () ], that is, give it an empty @INC if profile is undefined.

However, something must be seriously wrong in your usage and right now you are the only one who can fix that, the rest of us we are just guessing wildly. So, reduce this problem to a minimum. Also, show the versions of all modules involved.

Replies are listed 'Best First'.
Re^4: NYTProf line report failure
by swl (Priest) on Mar 13, 2020 at 01:40 UTC

    This is just a wild guess, but perhaps substitute some arbitrary path name when inc is undefined? This might give it something to work with instead of an empty array. Or patch the code later to handle an empty array from that call.

    [defined($self->profile) ? $self->profile->inc : ('.') ]

    That might send you down the rabbit hole, though, in which case bliako's advice in 11114191 should be followed.

    When doing that, it is probably worth looking for what code is triggering the issue. Maybe it is the nested evals that were being warned about in the output in a previous post, but a quick check with the code below works without problem so if it is nested evals then it is under more complex conditions.

    use strict; use warnings; my $code1 = 'print "nested eval run here\n"'; my $code2 = 'eval $code1'; my $code3 = 'eval $code2'; eval $code3;
      I added "warn $self->filename" to "sub filename_without_inc" in Devel::NYTProf::FileInfo:
      sub filename_without_inc {
          my $self = shift;
          my $f    = [$self->filename];
      warn $self->filename;
      
      These warnings lead me to believe the problem is not in my code:
      Reading nytprof.out
      Processing nytprof.out data
      
      collapse_sibling_evals: nested evals in (eval 656)[/ExtUtils/MM_Unix.pm:2920] 
      not handled at /Devel/NYTProf/FileInfo.pm line 291.
      
      collapse_sibling_evals: nested evals in (eval 2695)[/Module/Metadata.pm:13] 
      not handled at /Devel/NYTProf/FileInfo.pm line 291.
      
      Here are the results with my added warn:
      98% ... (eval 657)[(eval 656)[/ExtUtils/MM_Unix.pm:2920]:1] at /Devel/ +NYTProf/FileInfo.pm line 431. (eval 657)[(eval 656)[/ExtUtils/MM_Unix.pm:2920]:1] at /Devel/NYTProf/ +FileInfo.pm line 431. Warning: something's wrong at /Devel/NYTProf/FileInfo.pm line 431. 99% ... (eval 2699)[(eval 2698)[/Module/Metadata.pm:13]:6] at /Devel/N +YTProf/FileInfo.pm line 431. (eval 2699)[(eval 2698)[/Module/Metadata.pm:13]:6] at /Devel/NYTProf/F +ileInfo.pm line 431. Warning: something's wrong at /Devel/NYTProf/FileInfo.pm line 431.
      Here's line 13 of Module::Metadata:
      sub __clean_eval { eval $_[0] }
      
      Here's line 2921 of ExtUtils::MM_Unix (right after strict is disabled on line 2917, and warnings are disabled on line 2919):
      eval($line); ## no critic
      

        Which of the output lines you provided are the result of the warn $self->filename call? Also, what does a "normal" filename look like when printed? Seeing the difference will help.

        Another question is why your code is using what appears to be a module installation process? Perhaps it tries to install on-the-fly? In which case perhaps it is best to get everything installed before running the code?

Re^4: NYTProf line report failure
by Anonymous Monk on Mar 12, 2020 at 18:16 UTC
    Thank you for the suggested patch. The change to line 430 of Devel::NYTProf::FileInfo has restored functionality to nytprofhtml with some warnings about uninitialized values. I treasure your wild guesses.

    What is $self->profile and what could cause it to be undef? Is it the result of profiling a statement, or a subroutine? What do you think my usage of is seriously wrong, Perl or NYTProf? I have no problem with the module that's being profiled, or scripts that use it, or with commandline usage. I'm not doing anything unusual with NYTProf either.

    Here are those warnings:

    Writing line reports to nytprof directory 97% ... Use of uninitialized value in numeric gt (>) at /Devel/NYTPr +of/Reader.pm line 184. Use of uninitialized value in numeric gt (>) at /Devel/NYTProf/Reader. +pm line 185. Use of uninitialized value $fname in substitution (s///) at /Devel/NYT +Prof/Util.pm line 235. Use of uninitialized value $fname in substitution (s///) at /Devel/NYT +Prof/Util.pm line 237. Use of uninitialized value $fname in substitution (s///) at /Devel/NYT +Prof/Util.pm line 238. Use of uninitialized value in concatenation (.) or string at /Devel/NY +TProf/Reader.pm line 188. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 540. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 541. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 542. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 543. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 544. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 545. Use of uninitialized value in sprintf at /bin/nytprofhtml line 202. 98% ... Use of uninitialized value in numeric gt (>) at /Devel/NYTPr +of/Reader.pm line 184. Use of uninitialized value in numeric gt (>) at /Devel/NYTProf/Reader. +pm line 185. Use of uninitialized value $fname in substitution (s///) at /Devel/NYT +Prof/Util.pm line 235. Use of uninitialized value $fname in substitution (s///) at /Devel/NYT +Prof/Util.pm line 237. Use of uninitialized value $fname in substitution (s///) at /Devel/NYT +Prof/Util.pm line 238. Use of uninitialized value in concatenation (.) or string at /Devel/NY +TProf/Reader.pm line 188. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 540. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 541. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 542. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 543. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 544. Use of uninitialized value $_ in substitution (s///) at /bin/nytprofht +ml line 545. Use of uninitialized value in sprintf at /bin/nytprofhtml line 202. 100% ... Extracting subroutine call data (There were 9159849 of them, so this m +ay take some time, or cancel and use --no-flame to skip this step.) . +.. Extracting subroutine links Generating subroutine stack flame graph ...

      I said that you must be using NYTProf completely wrong because I don't think a module like this can break so spectacularly. Again, a wild guess :)

      What is the commandline you used, or are you using NYTProf via Apache (i.e. How to use Devel::NYTProf on Apache)? Does NYTProf work without these problems on a different file?

      For the particular log you provided, line 175 of /Devel/NYTProf/Reader.pm sets my $fname = $fi->filename_without_inc; and most of the complaints you see are saying that $fname is undefined. Why is that? Well it has something to do with that ->inc I guess again, because $fi->filename_without_inc must be somehow related? So there is no filename, there is no profile!

      I propose that you restore NYTProf to its previous state (remove what I provided) and then if you want to debug, you must slowly work your way inside nytprofhtml and the modules it's using, inserting a print statement here or there. But first let's double check that the commandline is correct and that no ENV var is messing things up. Also make sure that NYTProf is properly installed by profiling a simple script and checking you get valid output.

        I use NYTProf often enough to have aliases set to maximize laziness:
        alias profile='perl -d:NYTProf'
        alias profileh='nytprofhtml --open'
        
        That's been working for a very long time. I don't know how to use NYTProf wrong. It works well for me except for this one big module that does things which would cause modern PerlMonks to hide their children, but under strict conditions with no warnings, so I don't see why it upsets NYTProf.

        I'm happy with the hack that gets me a report because I like to browse code as a website. Seeing it outside the comfort of my editor provides a different perspective. Maybe this thread will be useful to whoever adopts NYTProf and tries to improve filename handling of the profiler. Thanks for guessing :)