Devel::NYTProf::Apache with trace > 0 [rt.cpan.org #65200]

[timbunce]

trafficstars

Migrated from rt.cpan.org#65200 (status was 'open')

Requestors:

• [email protected]

Attachments:

• trace4.txt

From [email protected] on 2011-01-27 22:57:46:

I wanted to profile an application suite running Apache 2 with mod_perl2
so I enabled Devel::NYTProf::Apache in my httpd.conf.

    PerlSetEnv NYTPROF trace=2:file=/tmp/mm-nytprof.out
    PerlModule Devel::NYTProf::Apache

I was seeing issues where "NYTProf is confused about CV" multiple times
for each thing that I did in my app. If I try to convert the out files
to html, it is very clear that something bad happened. (The top 15
subroutines doesn't get populated, the subroutine exclusive time treemap
is empty, etc.)

I bumped it up to trace=4 and captured one instance of it occurring
(attached as trace4.txt). I'm not sure what other information you need
from me
to assist you.

I have verified that when trace=0, the problem does not happen and the
resulting html output is as pretty as usual.

From [email protected] on 2011-01-28 09:38:09:

On Thu, Jan 27, 2011 at 05:57:46PM -0500, Matthew Musgrove via RT wrote:
> NYTProf is confused about CV 0x2ab2388a0568 called as /opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm at /opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm line 225 (please report as a bug)

Thanks for the report. Please try this change just to give me more infomation:

--- NYTProf.xs  (revision 1407)
+++ NYTProf.xs  (working copy)
@@ -2639,8 +2639,10 @@
                 logwarn("NYTProf is confused about CV %p called as %s at %s line %d (please report as a bug)\n",
                     (void*)called_cv, SvPV_nolen(sub_sv), OutCopFILE(prev_cop), (int)CopLINE(prev_cop));
                 /* looks like Class::MOP doesn't give the CV GV stash a name */
-                if (trace_level >= 2)
+                if (trace_level >= 2) {
                     sv_dump((SV*)called_cv); /* coredumps in Perl_do_gvgv_dump, looks line GvXPVGV is false, presumably on a Class::MOP wierdo sub */
+                    sv_dump((SV*)gv);
+                }
             }
         }

Tim.

From [email protected] on 2011-01-28 16:08:30:

Thanks Tim. Here's the latest dump from running at trace=2.

NYTProf is confused about CV 0x2b41eac6afb8 called as
/opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm
at
/opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm
line 225 (please report as a bug)
SV = PVCV(0x2b41eac6fa40) at 0x2b41eac6afb8
  REFCNT = 2
  FLAGS = (POK,pPOK,CONST)
  PROTOTYPE = ""
  COMP_STASH = 0x2b41eabb46f8   "ModPerl::RegistryCooker"
  XSUB = 0x2b41dc1665b0
  XSUBANY = 0x2b41eac41308 (CONST SV)
    SV = IV(0x2b41eac41300) at 0x2b41eac41308
      REFCNT = 2
      FLAGS = (PADMY,IOK,READONLY,pIOK)
      IV = 0
  GVGV::GV = 0x2b41eac41518     ""
  FILE =
"/opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm"
  DEPTH = 0
  FLAGS = 0xc00
  OUTSIDE_SEQ = 0
  PADLIST = 0x0
  OUTSIDE = 0x0 (null)
SV = IV(0x2b41eac41510) at 0x2b41eac41518
  REFCNT = 1
  FLAGS = (ROK)
  RV = 0x2b41eac41308
    SV = IV(0x2b41eac41300) at 0x2b41eac41308
      REFCNT = 2
      FLAGS = (PADMY,IOK,READONLY,pIOK)
      IV = 0

From [email protected] on 2011-02-01 15:55:35:

On Fri, Jan 28, 2011 at 11:08:31AM -0500, Matthew Musgrove via RT wrote:
>        Queue: devel-nytprof
>  Ticket <URL: https://rt.cpan.org/Ticket/Display.html?id=65200 >
> 
> Thanks Tim. Here's the latest dump from running at trace=2.
> 
> SV = IV(0x2b41eac41510) at 0x2b41eac41518
>   REFCNT = 1
>   FLAGS = (ROK)
>   RV = 0x2b41eac41308
>     SV = IV(0x2b41eac41300) at 0x2b41eac41308
>       REFCNT = 2
>       FLAGS = (PADMY,IOK,READONLY,pIOK)
>       IV = 0

Great. Now after the

    sv_dump((SV*)gv);   

add

    sv_dump((SV*)SvRV(gv));   

and re-run.

Thanks.

Tim.

From [email protected] on 2011-02-01 16:14:33:

NYTProf is confused about CV 0x2b397579fdd0 called as
/opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm
at
/opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm
line 225 (please report as a bug)
SV = PVCV(0x2b39757a4690) at 0x2b397579fdd0
  REFCNT = 2
  FLAGS = (POK,pPOK,CONST)
  PROTOTYPE = ""
  COMP_STASH = 0x2b39756e95a0   "ModPerl::RegistryCooker"
  XSUB = 0x2b39674715b0
  XSUBANY = 0x2b3975776280 (CONST SV)
    SV = IV(0x2b3975776278) at 0x2b3975776280
      REFCNT = 2
      FLAGS = (PADMY,IOK,READONLY,pIOK)
      IV = 0
  GVGV::GV = 0x2b3975776490     ""
  FILE =
"/opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm"
  DEPTH = 0
  FLAGS = 0xc00
  OUTSIDE_SEQ = 0
  PADLIST = 0x0
  OUTSIDE = 0x0 (null)
SV = IV(0x2b3975776488) at 0x2b3975776490
  REFCNT = 1
  FLAGS = (ROK)
  RV = 0x2b3975776280
    SV = IV(0x2b3975776278) at 0x2b3975776280
      REFCNT = 2
      FLAGS = (PADMY,IOK,READONLY,pIOK)
      IV = 0
SV = IV(0x2b3975776278) at 0x2b3975776280
  REFCNT = 2
  FLAGS = (PADMY,IOK,READONLY,pIOK)
  IV = 0

From [email protected] on 2011-02-01 21:46:21:

Hi Matthew.

> NYTProf is confused about CV 0x2ab2388a0568 called as /opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm at /opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm line 225 (please report as a bug)

Please hack RegistryCooker.pm to log the class of the object that
should_reset_inc_hash() is called on. Thanks.

Tim.

From [email protected] on 2011-02-01 22:28:54:

Howdy Tim,

I've never peered inside ModPerl::RegistryCooker before. I used
$self->log_error("should_reset_inc_hash $package"). I hope that was what
you were asking for. 

[Tue Feb 01 22:23:44 2011] [error] should_reset_inc_hash
ModPerl::ROOT::ModPerl::Registry::view_mm_2dnms_vobs_NMS_nms_www_cgi_2dbin_security_login_2ecgi
Marking 'Apache2::RequestRec::log_error' as xsub
Marking 'Apache2::RequestRec::notes' as xsub
Marking 'APR::Table::set' as xsub
NYTProf is confused about CV 0x2b7915c79368 called as
/opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm
at
/opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm
line 226 (please report as a bug)
SV = PVCV(0x2b7915c7ddf0) at 0x2b7915c79368
  REFCNT = 2
  FLAGS = (POK,pPOK,CONST)
  PROTOTYPE = ""
  COMP_STASH = 0x2b7915bc2850   "ModPerl::RegistryCooker"
  XSUB = 0x2b791bfc25b0
  XSUBANY = 0x2b7915c4f810 (CONST SV)
    SV = IV(0x2b7915c4f808) at 0x2b7915c4f810
      REFCNT = 2
      FLAGS = (PADMY,IOK,READONLY,pIOK)
      IV = 0
  GVGV::GV = 0x2b7915c4fa20     ""
  FILE =
"/opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm"
  DEPTH = 0
  FLAGS = 0xc00
  OUTSIDE_SEQ = 0
  PADLIST = 0x0
  OUTSIDE = 0x0 (null)
SV = IV(0x2b7915c4fa18) at 0x2b7915c4fa20
  REFCNT = 1
  FLAGS = (ROK)
  RV = 0x2b7915c4f810
    SV = IV(0x2b7915c4f808) at 0x2b7915c4f810
      REFCNT = 2
      FLAGS = (PADMY,IOK,READONLY,pIOK)
      IV = 0


It looks like my login script is the package in question. I hope that I
haven't missed anything in my conversion from CGI to mod_perl to waste
your time.