strange behavior mod_perl 2, DBD::Pg, Archive::ZIP
Alex Hunsaker
some boilerplate:
NYTProf-4.03
mod_perl 2.04
Archive::Zip 1.30
DBD::Pg 2.17.1
perl v5.12.1
linux x86_64
First off it seems to work if I run it from the command line: "perl
-d:NYTProf -T index.cgi".
When I Add "PerlModule Devel::NYTProf::Apache" to my conf I get the
below segfault:
Program received signal SIGSEGV, Segmentation fault.
0x00007ffff3059c1c in resolve_sub_to_cv (sv=0x93800384b454552,
subname_gv_ptr=0x7fffffffe088) at NYTProf.xs:2046
2046 switch (SvTYPE(sv)) {
(gdb)
(gdb) bt
#0 0x00007ffff3059c1c in resolve_sub_to_cv (sv=0x93800384b454552,
subname_gv_ptr=0x7fffffffe088) at NYTProf.xs:2046
#1 0x00007ffff305a37f in subr_entry_setup (prev_cop=0x7ffff4083740,
clone_subr_entry=0x0, op_type=173, subr_sv=0x93800384b454552) at
NYTProf.xs:2188
#2 0x00007ffff305b243 in pp_subcall_profiler (is_slowop=0) at NYTProf.xs:2447
#3 0x00007ffff305b056 in pp_entersub_profiler () at NYTProf.xs:2373
#4 0x00007ffff3d9a602 in Perl_call_sv () from
/usr/lib/perl5/core_perl/CORE/libperl.so
#5 0x00007ffff409e24a in modperl_perl_call_list () from
/usr/lib/httpd/modules/mod_perl.so
#6 0x00007ffff40a7a13 in modperl_perl_destruct () from
/usr/lib/httpd/modules/mod_perl.so
#7 0x00007ffff40a7a82 in modperl_shutdown.2753 () from
/usr/lib/httpd/modules/mod_perl.so
#8 0x00007ffff770fb1d in run_cleanups () from /usr/lib/libapr-1.so.0
#9 0x00007ffff7710687 in apr_pool_destroy () from /usr/lib/libapr-1.so.0
#10 0x00007ffff77108ad in apr_pool_clear () from /usr/lib/libapr-1.so.0
#11 0x00007ffff7fc3f0d in main ()
Ok lets try disabling some things:
# NYTPROF="subs=0:blocks=0:stmts=0:savesrc=0" httpd
Segmentation fault
OK so I thought what happens if I try start=no:
# NYTPROF="start=no" httpd
Undefined subroutine &main::1 called.
END failed--call queue aborted.
If I take out my preloading of modules in my startup file it seems to
work. So I tried figuring out if there was a single module that was
bad... after much sweating (It preloads ~900 modules). I found this
simple test case to demonstrate the problem:
PerlPassEnv NYTPROF
PerlModule Devel::NYTProf::Apache
PerlRequire empty.pm
<FilesMatch ".cgi">
SetHandler perl-script
PerlResponseHandler empty
PerlSendHeader On
</FilesMatch>
empty.pm:
package empty;
use Archive::Zip();
use DBD::Pg();
sub handler
{
print "Content-type: text/plain\n\nhi\n";
return 0;
}
1;
Basically I can use Archive::Zip or DBD::Pg, but not both at the same
time :-) Any Ideas?
bad...@gmail.com
On Jun 24, 1:14 pm, Alex Hunsaker <bada...@gmail.com> wrote:
I found this
> simple test case to demonstrate the problem:
PerlModule Devel::NYTProf::Apache
PerlModule Archive::Zip
PerlModule DBD::Pg
It also crashes for me on an i686 with perl 5.10.1.
Both have gcc 4.5.0; Ive hit some other oddities with that version gcc
(err well an earlier snapshot anyway). Maybe its related?
gcc version 4.5.0 20100610
Tim Bunce
> When I Add "PerlModule Devel::NYTProf::Apache" to my conf I get the
> below segfault:
>
> Program received signal SIGSEGV, Segmentation fault.
> 0x00007ffff3059c1c in resolve_sub_to_cv (sv=0x93800384b454552,
> subname_gv_ptr=0x7fffffffe088) at NYTProf.xs:2046
> 2046 switch (SvTYPE(sv)) {
Please do a "print *sv*" in gdb. Anything else you can find out about
the sv would be very helpful.
> #0 0x00007ffff3059c1c in resolve_sub_to_cv (sv=0x93800384b454552, subname_gv_ptr=0x7fffffffe088) at NYTProf.xs:2046
> #1 0x00007ffff305a37f in subr_entry_setup (prev_cop=0x7ffff4083740, clone_subr_entry=0x0, op_type=173, subr_sv=0x93800384b454552) at NYTProf.xs:2188
> #2 0x00007ffff305b243 in pp_subcall_profiler (is_slowop=0) at NYTProf.xs:2447
> #3 0x00007ffff305b056 in pp_entersub_profiler () at NYTProf.xs:2373
> #4 0x00007ffff3d9a602 in Perl_call_sv () from /usr/lib/perl5/core_perl/CORE/libperl.so
> #5 0x00007ffff409e24a in modperl_perl_call_list () from /usr/lib/httpd/modules/mod_perl.so
> #6 0x00007ffff40a7a13 in modperl_perl_destruct () from /usr/lib/httpd/modules/mod_perl.so
> #7 0x00007ffff40a7a82 in modperl_shutdown.2753 () from /usr/lib/httpd/modules/mod_perl.so
So apache is shutting down and destroying perl. Looking at the code I
see that modperl_perl_call_list is running END blocks (PL_endav).
Please also try NYTPROF=stmts=0:trace=99:log=/tmp/nytprof.log
to get a detailed log (without statement profiler noise).
Specifically that trace level 99 enables a dump of the sv that's
getting passed to subr_entry_setup and resolve_sub_to_cv.
The log will be big, but last few lines of should shed more light on
the problem.
> Ok lets try disabling some things:
> # NYTPROF="subs=0:blocks=0:stmts=0:savesrc=0" httpd
> Segmentation fault
Um. With subs=0 the resolve_sub_to_cv() shouldn't be called so I suspect
this is a different problem. Please start a new thread with a stack
dump from that case (including a perl *sv if the core dump suggests a
particular sv is the problem). The end of the log from trace level 99
may also be useful.
> OK so I thought what happens if I try start=no:
> # NYTPROF="start=no" httpd
> Undefined subroutine &main::1 called.
> END failed--call queue aborted.
Odd.
> If I take out my preloading of modules in my startup file it seems to
> work. So I tried figuring out if there was a single module that was
> bad... after much sweating (It preloads ~900 modules). I found this
> simple test case to demonstrate the problem:
> Basically I can use Archive::Zip or DBD::Pg, but not both at the same
> time :-) Any Ideas?
Given that mod_perl is in shutdown/destroy mode the underlying cause
could be only distantly related to the particular modules used.
I'd rather approach this problem from the core dump first.
On Thu, Jun 24, 2010 at 06:03:37PM -0700, bad...@gmail.com wrote:
> I found this simple test case to demonstrate the problem:
>
> Err duh... This is even simpler:
>
> PerlModule Devel::NYTProf::Apache
> PerlModule Archive::Zip
> PerlModule DBD::Pg
>
> It also crashes for me on an i686 with perl 5.10.1.
>
> Both have gcc 4.5.0; Ive hit some other oddities with that version gcc
> (err well an earlier snapshot anyway). Maybe its related?
> gcc version 4.5.0 20100610
That's fairly bleading edge. Sending us your Perl -V output would be
appreciated.
Thanks.
Tim.
Alex Hunsaker
> Hi Alex.
*waves* Hi Tim!
>> When I Add "PerlModule Devel::NYTProf::Apache" to my conf I get the
>> below segfault:
>>
> Please do a "print *sv*" in gdb. Anything else you can find out about
> the sv would be very helpful.
[ back on my i686, 5.10.1 ]
Hrm seems to be null on this setup:
Program received signal SIGSEGV, Segmentation fault.
0xb761f136 in resolve_sub_to_cv (my_perl=0x81ad2c0, sv=0x0,
subname_gv_ptr=0xbfffeed8) at NYTProf.xs:2046
2046 switch (SvTYPE(sv)) {
(gdb) p sv
$1 = (SV *) 0x0
(gdb) p *sv
Cannot access memory at address 0x0
(gdb) bt
#0 0xb761f136 in resolve_sub_to_cv (my_perl=0x81ad2c0, sv=0x0,
subname_gv_ptr=0xbfffeed8) at NYTProf.xs:2046
#1 0xb761f819 in subr_entry_setup (my_perl=0x81ad2c0,
prev_cop=0x81ad6e4, clone_subr_entry=0x0, op_type=169, subr_sv=0x0) at
NYTProf.xs:2188
#2 0xb762047a in pp_subcall_profiler (my_perl=0x81ad2c0, is_slowop=0)
at NYTProf.xs:2447
#3 0xb7620256 in pp_entersub_profiler (my_perl=0x0) at NYTProf.xs:2373
#4 0xb78941a6 in Perl_call_sv () from /usr/lib/perl5/core_perl/CORE/libperl.so
#5 0xb79bb2ee in modperl_perl_call_list () from /etc/httpd/modules/mod_perl.so
#6 0xb79c4168 in modperl_perl_call_endav () from /etc/httpd/modules/mod_perl.so
#7 0xb79c41c3 in modperl_perl_destruct () from /etc/httpd/modules/mod_perl.so
...
> So apache is shutting down and destroying perl. Looking at the code I
> see that modperl_perl_call_list is running END blocks (PL_endav).
>
> Please also try NYTPROF=stmts=0:trace=99:log=/tmp/nytprof.log
> to get a detailed log (without statement profiler noise).
Here are the last lines: [ find the whole thing attached ]
1 <- DBI::SQL_REAL 0.000016s excl = 0.000016s incl - 0.000000s
(0.352317-0.352317), oh 0.000000-0.000000=0.000000t, d1 @43:1376 #2655
0x8ee45dc
1 << DBI::SQL_REAL done (seix 0<-940, ac1)
profiling a call [op 169, entersub, seix 0]
fid 43: /usr/lib/perl5/vendor_perl/DBD/Pg.pm
finding current_cv(2,0x8cf9098) - cx_type 3 CXt_LOOP, si_type 9
finding current_cv(1,0x8cf9098) - cx_type 2 CXt_EVAL, si_type 9
finding current_cv(0,0x8cf9098) - cx_type 2 CXt_EVAL, si_type 9
finding current_cv(-1,0x8cdd8e8) si_type 1 - context stack empty
1 >> entersub at 43:1376 from main::NULL (calculated) (seix 0->1052, ac0)
1 ->xsub DBI::SQL_DOUBLE from main::NULL @43:1376 (d1, oh 0.000000t,
sub 0.352333s) #2656
Marking 'DBI::SQL_DOUBLE' as xsub
1 <- DBI::SQL_DOUBLE 0.000016s excl = 0.000016s incl - 0.000000s
(0.352333-0.352333), oh 0.000000-0.000000=0.000000t, d1 @43:1376 #2656
0x8ee464c
1 << DBI::SQL_DOUBLE done (seix 0<-1052, ac1)
profiling a call [op 169, entersub, seix 0]
fid 43: /usr/lib/perl5/vendor_perl/DBD/Pg.pm
finding current_cv(2,0x8cf9098) - cx_type 3 CXt_LOOP, si_type 9
finding current_cv(1,0x8cf9098) - cx_type 2 CXt_EVAL, si_type 9
finding current_cv(0,0x8cf9098)
For fun I also tried with stmts=1, the last lines look different...
fid 37: /usr/share/perl5/core_perl/File/Temp.pm
@37:896 looking for block and sub lines
visit_contexts:
visit_context: CXt_BLOCK cxix 3 (si_prev (nil))
CXt_BLOCK
start_cop_of_context CXt_BLOCK is nextstate line 877 of
/usr/share/perl5/core_perl/File/Temp.pm
at 896: block 877 for CXt_BLOCK
visit_context: CXt_SUB cxix 2 (si_prev (nil))
start_cop_of_context CXt_SUB is nextstate line 877 of
/usr/share/perl5/core_perl/File/Temp.pm
at 896: block 877 sub 877 for CXt_SUB cleanup
@37:896 28 ticks (877, 877)
@37:896 looki
<Segfault happened here>
>> Ok lets try disabling some things:
>> # NYTPROF="subs=0:blocks=0:stmts=0:savesrc=0" httpd
>> Segmentation fault
>
> Um. With subs=0 the resolve_sub_to_cv() shouldn't be called so I suspect
> this is a different problem. Please start a new thread with a stack
> dump from that case
Yeah, it looks to be different I cant trigger it here (I dont have all
the same perl modules). Same with the below.
>> OK so I thought what happens if I try start=no:
>> # NYTPROF="start=no" httpd
>> Undefined subroutine &main::1 called.
>> END failed--call queue aborted.
[ snip ]
>> Both have gcc 4.5.0; Ive hit some other oddities with that version gcc
>> (err well an earlier snapshot anyway). Maybe its related?
>> gcc version 4.5.0 20100610
>
> That's fairly bleading edge. Sending us your Perl -V output would be
> appreciated.
[ I do apologize for originally reporting it on an x86_64 with 5.12.1
and then replying with different setup ]
$ perl -V
Summary of my perl5 (revision 5 version 10 subversion 1) configuration:
Platform:
osname=linux, osvers=2.6.31-arch, archname=i686-linux-thread-multi
uname='linux samarqand 2.6.31-arch #1 smp preempt sat sep 26
02:39:09 cest 2009 i686 amd athlon(tm) 64 processor 3200+ authenticamd
gnulinux '
config_args='-des -Dusethreads -Duseshrplib -Doptimize=-march=i686
-mtune=generic -O2 -pipe -Dprefix=/usr -Dinstallprefix=/usr
-Dvendorprefix=/usr -Dprivlib=/usr/share/perl5/core_perl
-Darchlib=/usr/lib/perl5/core_perl
-Dsitelib=/usr/share/perl5/site_perl/5.10.1
-Dsitearch=/usr/lib/perl5/site_perl/5.10.1
-Dvendorlib=/usr/share/perl5/vendor_perl
-Dvendorarch=/usr/lib/perl5/vendor_perl
-Dotherlibdirs=/usr/lib/perl5/current:/usr/lib/perl5/site_perl/current
-Dscriptdir=/usr/bin/perlbin/core -Dsitescript=/usr/bin/perlbin/site
-Dvendorscript=/usr/bin/perlbin/vendor -Dman1ext=1perl
-Dman3ext=3perl'
hint=recommended, useposix=true, d_sigaction=define
useithreads=define, usemultiplicity=define
useperlio=define, d_sfio=undef, uselargefiles=define, usesocks=undef
use64bitint=undef, use64bitall=undef, uselongdouble=undef
usemymalloc=n, bincompat5005=undef
Compiler:
cc='cc', ccflags ='-D_REENTRANT -D_GNU_SOURCE -fno-strict-aliasing
-pipe -fstack-protector -I/usr/local/include -D_LARGEFILE_SOURCE
-D_FILE_OFFSET_BITS=64',
optimize='-march=i686 -mtune=generic -O2 -pipe',
cppflags='-D_REENTRANT -D_GNU_SOURCE -fno-strict-aliasing -pipe
-fstack-protector -I/usr/local/include'
ccversion='', gccversion='4.4.1', gccosandvers=''
intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=1234
d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=12
ivtype='long', ivsize=4, nvtype='double', nvsize=8, Off_t='off_t',
lseeksize=8
alignbytes=4, prototype=define
Linker and Libraries:
ld='cc', ldflags =' -fstack-protector -L/usr/local/lib'
libpth=/usr/local/lib /lib /usr/lib
libs=-lnsl -lgdbm -ldb -ldl -lm -lcrypt -lutil -lpthread -lc -lgdbm_compat
perllibs=-lnsl -ldl -lm -lcrypt -lutil -lpthread -lc
libc=/lib/libc-2.10.1.so, so=so, useshrplib=true, libperl=libperl.so
gnulibc_version='2.10.1'
Dynamic Linking:
dlsrc=dl_dlopen.xs, dlext=so, d_dlsymun=undef, ccdlflags='-Wl,-E
-Wl,-rpath,/usr/lib/perl5/core_perl/CORE'
cccdlflags='-fPIC', lddlflags='-shared -march=i686 -mtune=generic
-O2 -pipe -L/usr/local/lib -fstack-protector'
Characteristics of this binary (from libperl):
Compile-time options: MULTIPLICITY PERL_DONT_CREATE_GVSV
PERL_IMPLICIT_CONTEXT PERL_MALLOC_WRAP USE_ITHREADS
USE_LARGE_FILES USE_PERLIO USE_REENTRANT_API
Built under linux
Compiled at Oct 7 2009 09:47:11
@INC:
/usr/lib/perl5/site_perl/5.10.1
/usr/share/perl5/site_perl/5.10.1
/usr/lib/perl5/vendor_perl
/usr/share/perl5/vendor_perl
/usr/share/perl5/vendor_perl
/usr/lib/perl5/core_perl
/usr/share/perl5/core_perl
/usr/lib/perl5/current
/usr/lib/perl5/site_perl/current
Alex Hunsaker
> On Fri, Jun 25, 2010 at 04:47, Tim Bunce <Tim....@pobox.com> wrote:
>> Hi Alex.
>
> *waves* Hi Tim!
>
>>> When I Add "PerlModule Devel::NYTProf::Apache" to my conf I get the
>>> below segfault:
>>>
>> Please do a "print *sv*" in gdb. Anything else you can find out about
>> the sv would be very helpful.
>
> [ back on my i686, 5.10.1 ]
[ And back on my x86_64 5.12.1 machine ]
Program received signal SIGSEGV, Segmentation fault.
0x00007ffff3059c1c in resolve_sub_to_cv (sv=0x93800384b454552,
subname_gv_ptr=0x7fffffffe088) at NYTProf.xs:2046
2046 NYTProf.xs: No such file or directory.
in NYTProf.xs
(gdb) p sv
$1 = (SV *) 0x93800384b454552
(gdb) p *sv
Cannot access memory at address 0x93800384b454552
*Spoiler alert if you have not read the other thread yet*
This problem also goes away if I take out the { END { } } block in File::Temp.
Alex Hunsaker
> This problem also goes away if I take out the { END { } } block in File::Temp.
Ok I have an even simpler case:
PerlModule Devel::NYTProf::Apache
PerlModule bad
package bad;
END { }
END { }
1;
Apparently the reason I had to use Archive::ZIP and DBD::Pg is I dont
have use other packages that have end blocks. Still have not been
able to get it to trigger without mod_perl :-(.
Tim Bunce
> On Fri, Jun 25, 2010 at 04:47, Tim Bunce <Tim....@pobox.com> wrote:
>
> Hrm seems to be null on this setup:
>
> Program received signal SIGSEGV, Segmentation fault.
> 0xb761f136 in resolve_sub_to_cv (my_perl=0x81ad2c0, sv=0x0,
> subname_gv_ptr=0xbfffeed8) at NYTProf.xs:2046
> 2046 switch (SvTYPE(sv)) {
> (gdb) p sv
> $1 = (SV *) 0x0
NYTProf's pp_entersub_profiler() gets called instead of
perl's pp_entersub(). The first thing pp_entersub() does is call
SvTYPE(sv) on the value on the top of the stack.
pp_entersub_profiler() is just taking that value and passing it to
subr_entry_setup() which passes it to resolve_sub_to_cv() which calls
SvTYPE(sv).
So I can't see an obvious reason for this.
> > Please also try NYTPROF=stmts=0:trace=99:log=/tmp/nytprof.log
> > to get a detailed log (without statement profiler noise).
>
> Here are the last lines: [ find the whole thing attached ]
Sadly that's not much help - other than reminding me that NYTProf
doesn't flush it's logs! I've fixed that now in r1318.
Please rerun with that and send the log to me (only, no point in
troubling the list with it - anyone interested can just ask).
Thanks.
Tim
Alex Hunsaker
> On Fri, Jun 25, 2010 at 10:02:29AM -0600, Alex Hunsaker wrote:
>> On Fri, Jun 25, 2010 at 04:47, Tim Bunce <Tim....@pobox.com> wrote:
>>
>> Hrm seems to be null on this setup:
> NYTProf's pp_entersub_profiler() gets called instead of
> perl's pp_entersub(). The first thing pp_entersub() does is call
> SvTYPE(sv) on the value on the top of the stack.
Yeah, If I throw in some quick fprintf to mod_perls
modperl_perl_call_list we see it calls call_sv with bad values.
modperl_util.c:482
for (i=0; i<=AvFILLp(subs); i++) {
CV *cv = (CV*)ary[i];
SV *atsv = ERRSV;
fprintf(stderr, "call_list: %d %p\n\n", i, cv);
...
gives us:
call_list: 0 0x82b16dc
call_list: 1 0x82aece4
call_list: 2 0x820db2c
call_list: 3 0xc1
Interestingly if I change the options I give NYTProf I can change cv:
default: 0xf09
stmts=0: 0xc1
subs=0: 0x41
So it smells like some kind of corruption to me. If I run it under valgrind:
==27940== Invalid read of size 4
==27940== at 0x4A52F84: modperl_perl_call_list (modperl_util.c:479)
==27940== by 0x4A61697: modperl_perl_call_endav (modperl_perl.c:199)
==27940== by 0x4A616F2: modperl_perl_destruct (modperl_perl.c:142)
==27940== by 0x4A454DC: modperl_interp_destroy (modperl_interp.c:146)
==27940== by 0x4A455FB: modperl_interp_pool_destroy (modperl_interp.c:202)
==27940== by 0x40B14CC: run_cleanups (in /usr/lib/libapr-1.so.0.4.2)
==27940== by 0x40B2136: apr_pool_destroy (in /usr/lib/libapr-1.so.0.4.2)
==27940== by 0x40B23C7: apr_pool_clear (in /usr/lib/libapr-1.so.0.4.2)
==27940== by 0x8064D94: main (in /usr/sbin/httpd)
==27940== Address 0x5717d04 is 0 bytes after a block of size 28 free'd
==27940== at 0x4023B1C: free (in
/usr/lib/valgrind/vgpreload_memcheck-x86-linux.so)
==27940== by 0x4B39F4B: Perl_safesysfree (util.c:262)
==27940== by 0x4B59E4A: Perl_av_extend (av.c:166)
==27940== by 0x4B5A3D5: Perl_av_store (av.c:352)
==27940== by 0x4B5B43D: Perl_av_push (av.c:562)
==27940== by 0x5739B31: XS_DB__END (NYTProf.xs:4973)
==27940== by 0x4B6CCD2: Perl_pp_entersub (pp_hot.c:2888)
==27940== by 0x572F5EB: pp_subcall_profiler (NYTProf.xs:2421)
==27940== by 0x572F467: pp_entersub_profiler (NYTProf.xs:2378)
==27940== by 0x4AC7F91: Perl_call_sv (perl.c:2717)
==27940== by 0x4A5304A: modperl_perl_call_list (modperl_util.c:484)
==27940== by 0x4A61697: modperl_perl_call_endav (modperl_perl.c:199)
I dont have any idea _why_. Ring any bells ?
>> > Please also try NYTPROF=stmts=0:trace=99:log=/tmp/nytprof.log
>> > to get a detailed log (without statement profiler noise).
>>
>> Here are the last lines: [ find the whole thing attached ]
>
> Sadly that's not much help - other than reminding me that NYTProf
> doesn't flush it's logs! I've fixed that now in r1318.
> Please rerun with that and send the log to me (only, no point in
> troubling the list with it - anyone interested can just ask).
Sent and oops! where was my netiquette on that one? I think my dog ate it :-).
Nicholas Clark
No, but by inspection:
http://perl.apache.org/dist/mod_perl-2.0-current/src/modules/perl/modperl_util.c
void modperl_perl_call_list(pTHX_ AV *subs, const char *name)
{
I32 i, oldscope = PL_scopestack_ix;
SV **ary = AvARRAY(subs);
MP_TRACE_g(MP_FUNC, "pid %lu" MP_TRACEf_TID MP_TRACEf_PERLID
" running %d %s subs",
(unsigned long)getpid(), MP_TRACEv_TID_ MP_TRACEv_PERLID_
AvFILLp(subs)+1, name);
for (i=0; i<=AvFILLp(subs); i++) {
CV *cv = (CV*)ary[i];
SV *atsv = ERRSV;
PUSHMARK(PL_stack_sp);
call_sv((SV*)cv, G_EVAL|G_DISCARD);
if (SvCUR(atsv)) {
Perl_sv_catpvf(aTHX_ atsv, "%s failed--call queue aborted",
name);
while (PL_scopestack_ix > oldscope) {
LEAVE;
}
Perl_croak(aTHX_ "%s", SvPVX(atsv));
}
}
}
you could argue whose fault it is, but their code is not robust against the
array changing whilst they are iterating over it. They've used AvARRAY() to
get a pointer to the array's storage, and a side effect of a recent code
change I made is that we now might cause that array to get extended.
Of course, I looked at the core perl source to see how END blocks were run,
and the behaviour was safe with perl. perl unshifts each CV from the list
before it calls it. I should have remembered that inevitably mod_perl is
"special".
On reflection, I think that this *is* a bug in mod_perl, as they're going
to get tripped up in similar fashion if any code run as part of an END block
contains a string eval containing an END block.
This list, obviously, isn't the right place to report bugs in mod_perl.
Nicholas Clark
Alex Hunsaker
> On Sat, Jun 26, 2010 at 04:37:17PM -0600, Alex Hunsaker wrote:
>> So it smells like some kind of corruption to me. If I run it under valgrind:
>> ==27940== Invalid read of size 4
>> ==27940== at 0x4A52F84: modperl_perl_call_list (modperl_util.c:479)
>> I dont have any idea _why_. Ring any bells ?
>
> No, but by inspection:
> On reflection, I think that this *is* a bug in mod_perl, as they're going
> to get tripped up in similar fashion if any code run as part of an END block
> contains a string eval containing an END block.
Yep! If I switch that over to use Perl_call_list() (note, i have not
looked *to* closely to make sure it does the right thing for mod_perl)
instead of it using its own builtin thing everything seems to work!
> This list, obviously, isn't the right place to report bugs in mod_perl.
Yeah, ill go post a report on that list (tomorrow) and point back to
this thread. Course feel free to beat me to the punch :-).
Thanks!
Tim Bunce
Given Nicholas's analysis (thanks Nick!) I'd guess that you could create
a test case that doesn't involve NYTProf by doing something like:
END { eval "END { }" for 1..10 }
Tim.
p.s. A cross-check of this analysis would be to change the "if (1)" in
_END to "if (0)" so PL_endav doesn't get altered at END time.
p.p.s. I'll tweak NYTProf to pre-extend PL_endav enough to reduce the
risk of this happening.
Alex Hunsaker
> On Mon, Jun 28, 2010 at 12:24:44AM -0600, Alex Hunsaker wrote:
>> On Sun, Jun 27, 2010 at 15:18, Nicholas Clark <ni...@ccl4.org> wrote:
>>
>> > This list, obviously, isn't the right place to report bugs in mod_perl.
>>
>> Yeah, ill go post a report on that list (tomorrow) and point back to
>> this thread. Course feel free to beat me to the punch :-).
>
> Given Nicholas's analysis (thanks Nick!) I'd guess that you could create
> a test case that doesn't involve NYTProf by doing something like:
>
> END { eval "END { }" for 1..10 }
Yep, kind of interestingly it fails with the below instead of a segfault:
Not a CODE reference.
END failed--call queue aborted.
Mainly as it is passing in NULL to call_sv().
BTW, thanks you guys are awesome!
> p.s. A cross-check of this analysis would be to change the "if (1)" in
> _END to "if (0)" so PL_endav doesn't get altered at END time.
Yeah, if I do this i no longer get a segfault.
> p.p.s. I'll tweak NYTProf to pre-extend PL_endav enough to reduce the
> risk of this happening.
I thought we might need to check that sv is not NULL in
resolve_sub_to_cv(). As it still might get called with NULL. But I
checked out r1319 and everything seems to be working...
Thanks!
Alex Hunsaker
*sigh* I think I spoke to soon with: "END { eval "END { }" for 1..10
}"; I end up getting:
Undefined subroutine &main:: called.
END failed--call queue aborted.
[ note it works fine with a patched mod_perl ]
I dont see anything we can do about that :-(. Basically it causes a
sort of recursion, If I use the debugging i stuck in
mod_perl_call_list() I see:
call_list: 0x7fb3c0df9e10 # Should be END { eval "END {}" for 1..10 }
call_list: 0x7fb3bac17b08
call_list: 0x7fb3c398cdc8
call_list: 0x7fb3c398cc60
call_list: 0x7fb3c398caf8
call_list: 0x7fb3c398c990
call_list: 0x7fb3c397a820
call_list: 0x7fb3c396c638
call_list: 0x7fb3ba7bebc0
call_list: 0x7fb3bcbf11a0
call_list: 0x7fb3ba933720
call_list: 0x7fb3ba4ceb90
call_list: 0x7fb3c0df9e10 # Hey.. this looks familiar :-(
call_list: 0x7fb3bac17b08
call_list: 0x7fb3ba545280
call_list: 0x7fb3ba0d2818
call_list: 0x7fb3b56d8b40
Undefined subroutine &main:: called.
END failed--call queue aborted.
Would a trace=99 help?
Tim Bunce
>
> > p.p.s. I'll tweak NYTProf to pre-extend PL_endav enough to reduce the
> > risk of this happening.
>
> I thought we might need to check that sv is not NULL in resolve_sub_to_cv().
It gets called with garbage, so checking it's not NULL wouldn't help much.
Tim.
Tim Bunce
> On Mon, Jun 28, 2010 at 10:28, Alex Hunsaker <bad...@gmail.com> wrote:
> > On Mon, Jun 28, 2010 at 02:02, Tim Bunce <Tim....@pobox.com> wrote:
> >> p.p.s. I'll tweak NYTProf to pre-extend PL_endav enough to reduce the
> >> risk of this happening.
> >
> > I thought we might need to check that sv is not NULL in
> > resolve_sub_to_cv(). As it still might get called with NULL. But I
> > checked out r1319 and everything seems to be working...
>
> *sigh* I think I spoke to soon with: "END { eval "END { }" for 1..10
> }"; I end up getting:
> Undefined subroutine &main:: called.
> END failed--call queue aborted.
I offered that example as something you could use to file a bug report
against mod_perl without involving NYTProf. Any behaviour other than
"it works" counts as a useful bug report test case :)
The change I made to NYTProf will only protect mod_perl+NYTProf against
'reasonable' numbers of END blocks being defined at runtime.
You could bump up the constants in
http://code.google.com/p/perl-devel-nytprof/source/detail?r=1319
Tim.
Alex Hunsaker
My thinking was:
1: Some of the times I have triggered it, it gets passed NULL
2: if we extend the array, there might be a larger chance of getting
called with NULL instead of a bogus value
Yeah, I might just be flat out wrong about #2. Not to mention I've no
idea what to do when you get a NULL; that and it *is* a bug with
mod_perl. So uh, sorry for badgering you :-)
> I offered that example as something you could use to file a bug report
> against mod_perl without involving NYTProf. Any behaviour other than
> "it works" counts as a useful bug report test case :)
Point taken. Sorry for the noise. I do _try_ to not be a pain. :)
Thank you for the time you spent looking and adding a workaround for
this. [ That goes for you as well, Nicholas. Err well I guess mainly
the looking, not so much the workaround part :-) ]