Skip Menu |

Preferred bug tracker

Please visit the preferred bug tracker to report your issue.

This queue is for tickets about the devel-nytprof CPAN distribution.

Report information
The Basics
Id: 65200
Status: resolved
Priority: 0/
Queue: devel-nytprof
People
Owner: Nobody in particular
Requestors: mmusgrove [...] cpan.org
Cc:
AdminCc:
Bug Information
Severity: Normal
Broken in: 4.06
Fixed in: (no value)

History Show all quoted text
  Thu Jan 27 17:57:46 2011 mmusgrove [...] cpan.org - Ticket created
Subject: Devel::NYTProf::Apache with trace > 0
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.
Subject: trace4.txt
4 >> entersub at 43:207 from ModPerl::RegistryCooker::run (inherited) (seix 1640->2440, ac0) 4 -> sub ModPerl::RegistryCooker::error_check from ModPerl::RegistryCooker::run @43:207 (d1, oh 1311430.000000t, sub 1.088200s) #29687 4 >> entersub at 43:213 from ModPerl::RegistryCooker::run (inherited) (seix 1640->2688, ac0) 4 ->xsub ModPerl::Global::special_list_call from ModPerl::RegistryCooker::run @43:213 (d1, oh 1311510.000000t, sub 1.088212s) #29688 4 >> entersub at 43:216 from ModPerl::RegistryCooker::run (inherited) (seix 1640->2888, ac0) 4 -> sub ModPerl::RegistryCooker::error_check from ModPerl::RegistryCooker::run @43:216 (d1, oh 1311530.000000t, sub 1.088226s) #29689 4 >> entersub at 43:225 from ModPerl::RegistryCooker::run (inherited) (seix 1640->2416, ac0) 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) SV = PVCV(0x2ab2388a3e00) at 0x2ab2388a0568 REFCNT = 2 FLAGS = (POK,pPOK,CONST) PROTOTYPE = "" COMP_STASH = 0x2ab2387e8b98 "ModPerl::RegistryCooker" XSUB = 0x2ab21f4455b0 XSUBANY = 0x2ab238875a38 (CONST SV) SV = IV(0x2ab238875a30) at 0x2ab238875a38 REFCNT = 2 FLAGS = (PADMY,IOK,READONLY,pIOK) IV = 0 GVGV::GV = 0x2ab238875c48 "^B" 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) unknown entersub xsub assumed to be anon called_cv '/opt/perl/lib/site_perl/5.12.3/x86_64-linux-thread-multi/ModPerl/RegistryCooker.pm' 4 ->xsub ModPerl::RegistryCooker::__UNKNOWN__[xsub,0x2ab2388a0568] from ModPerl::RegistryCooker::run @43:225 (d1, oh 1311600.000000t, sub 1.088239s) #29690 4 >> entersub at 43:237 from ModPerl::RegistryCooker::run (inherited) (seix 1640->2616, ac0) 4 ->xsub ModPerl::RegistryCooker::NOP from ModPerl::RegistryCooker::run @43:237 (d1, oh 1311610.000000t, sub 1.088318s) #29691 4 >> entersub at 43:239 from ModPerl::RegistryCooker::run (inherited) (seix 1640->2816, ac0) 4 ->xsub ModPerl::RegistryCooker::NOP from ModPerl::RegistryCooker::run @43:239 (d1, oh 1311620.000000t, sub 1.088326s) #29692 3 >> entersub at 43:171 from ModPerl::RegistryCooker::default_handler (inherited) (seix 728->1856, ac0) 3 ->xsub Apache2::RequestRec::status from ModPerl::RegistryCooker::default_handler @43:171 (d1, oh 1311660.000000t, sub 1.088405s) #29693
  Fri Jan 28 04:38:09 2011 Tim.Bunce [...] pobox.com - Correspondence added
Subject: Re: [rt.cpan.org #65200] Devel::NYTProf::Apache with trace > 0
Date: Fri, 28 Jan 2011 09:37:57 +0000
To: Matthew Musgrove via RT <bug-devel-nytprof [...] rt.cpan.org>
From: Tim Bunce <Tim.Bunce [...] pobox.com>
On Thu, Jan 27, 2011 at 05:57:46PM -0500, Matthew Musgrove via RT wrote: Show quoted text
> 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.
  Fri Jan 28 04:38:10 2011 The RT System itself - Status changed from 'new' to 'open'
  Fri Jan 28 11:08:30 2011 mmusgrove [...] cpan.org - Correspondence added
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
  Tue Feb 01 10:55:35 2011 Tim.Bunce [...] pobox.com - Correspondence added
Subject: Re: [rt.cpan.org #65200] Devel::NYTProf::Apache with trace > 0
Date: Tue, 1 Feb 2011 13:25:15 +0000
To: Matthew Musgrove via RT <bug-devel-nytprof [...] rt.cpan.org>
From: Tim Bunce <Tim.Bunce [...] pobox.com>
On Fri, Jan 28, 2011 at 11:08:31AM -0500, Matthew Musgrove via RT wrote: Show quoted text
> 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.
  Tue Feb 01 11:14:33 2011 mmusgrove [...] cpan.org - Correspondence added
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
  Tue Feb 01 16:46:21 2011 Tim.Bunce [...] pobox.com - Correspondence added
Subject: Re: [rt.cpan.org #65200] Devel::NYTProf::Apache with trace > 0
Date: Tue, 1 Feb 2011 21:46:09 +0000
To: Matthew Musgrove via RT <bug-devel-nytprof [...] rt.cpan.org>
From: Tim Bunce <Tim.Bunce [...] pobox.com>
Hi Matthew. Show quoted text
> 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.
  Tue Feb 01 17:28:54 2011 mmusgrove [...] cpan.org - Correspondence added
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.
  Sun Feb 22 08:35:05 2015 TIMB [...] cpan.org - Correspondence added
Ticket migrated to github as https://github.com/timbunce/devel-nytprof/issues/52
  Sun Feb 22 08:35:12 2015 TIMB [...] cpan.org - Status changed from 'open' to 'resolved'