Skip Menu |
Report information
Id: 131124
Status: resolved
Priority: 0/
Queue: perl5

Owner: Nobody
Requestors: public [at] khwilliamson.com
Cc:
AdminCc:

Operating System: (no value)
PatchStatus: (no value)
Severity: low
Type: unknown
Perl Version: (no value)
Fixed In: (no value)



To: perlbug [...] perl.org
Subject: commit 2e6f1ae9c: breaks blead
From: Karl Williamson <public [...] khwilliamson.com>
Date: Fri, 7 Apr 2017 22:42:21 -0600
Download (untitled) / with headers
text/plain 6.7k
This is a bug report for perl from khw@cpan.org, generated with the help of perlbug 1.40 running under perl 5.26.0. ----------------------------------------------------------------- commit 2e6f1ae9c4f7857e86f85fde07fe1af1254c4600 Author: David Mitchell <davem@iabyn.com> Date: Fri Apr 7 12:39:53 2017 +0100 fix and test execution of non-empty .bs files This commit consistently causes this: panic: free from wrong pool, eea800!=d40c20 during global destruction. ../dist/threads-shared/t/object2.t ................................. but only under certain circumstances. One that threw us off scent, is this failure does not seem to happen if the directory the workspace is in is named 'blead'. I've tried maybe 20 times, and it always succeeds. Yet it fails 100% of the time on every other directory name I've tried. The @INC shown in this perlbug looks weird. I don't know how it's getting /backup or 5.26 there. The former is a backup to another disk of snapshots of my main disk, set off by a cron job several times a day. I don't know how 5.26 got in there. I am using ccache. I have tried clearing it before running, with no change in symptoms. You can see the Configure options below. I run on an 8-core system with TEST_JOBS=12 make -j12 all test_harness ----------------------------------------------------------------- --- Flags: category=core severity=high --- Site configuration information for perl 5.26.0: Configured by khw at Fri Apr 7 16:55:52 MDT 2017. Summary of my perl5 (revision 5 version 26 subversion 0) configuration: Commit id: 2e59c0a4ed3c79478858423c133613d43383eaaa Platform: osname=linux osvers=4.4.0-71-generic archname=x86_64-linux-thread-multi-ld uname='linux khw 4.4.0-71-generic #92-ubuntu smp fri mar 24 12:59:01 utc 2017 x86_64 x86_64 x86_64 gnulinux ' config_args='-des -Uversiononly -Dprefix=/home/khw/blead -Dusedevel -D'optimize=-ggdb3' -A'optimize=-ggdb3' -A'optimize=-O0' -Accflags='-DPERL_BOOL_AS_CHAR' -Accflags='-DPERL_EXTERNAL_GLOB' -Dman1dir=none -Dman3dir=none -Dcc=g++ -DDEBUGGING -Dusemorebits -Dusecbacktrace -Dusethreads' hint=recommended useposix=true d_sigaction=define useithreads=define usemultiplicity=define use64bitint=define use64bitall=define uselongdouble=define usemymalloc=n default_inc_excludes_dot=define bincompat5005=undef Compiler: cc='g++' ccflags ='-D_REENTRANT -D_GNU_SOURCE -DPERL_BOOL_AS_CHAR -DPERL_EXTERNAL_GLOB -fwrapv -DDEBUGGING -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include -DUSE_C_BACKTRACE -g -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64 -D_FORTIFY_SOURCE=2' optimize='-ggdb3 -ggdb3 -O0' cppflags='-D_REENTRANT -D_GNU_SOURCE -DPERL_BOOL_AS_CHAR -DPERL_EXTERNAL_GLOB -fwrapv -DDEBUGGING -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include' ccversion='' gccversion='5.4.0 20160609' gccosandvers='' intsize=4 longsize=8 ptrsize=8 doublesize=8 byteorder=12345678 doublekind=3 d_longlong=define longlongsize=8 d_longdbl=define longdblsize=16 longdblkind=3 ivtype='long' ivsize=8 nvtype='long double' nvsize=16 Off_t='off_t' lseeksize=8 alignbytes=16 prototype=define Linker and Libraries: ld='g++' ldflags =' -fstack-protector-strong -L/usr/local/lib' libpth=/usr/include/c++/5 /usr/include/x86_64-linux-gnu/c++/5 /usr/include/c++/5/backward /usr/local/lib /usr/lib/gcc/x86_64-linux-gnu/5/include-fixed /usr/include/x86_64-linux-gnu /usr/lib /lib/x86_64-linux-gnu /lib/../lib /usr/lib/x86_64-linux-gnu /usr/lib/../lib /lib libs=-lpthread -lnsl -ldl -lm -lcrypt -lutil -lc perllibs=-lpthread -lnsl -ldl -lm -lcrypt -lutil -lc libc=libc-2.23.so so=so useshrplib=false libperl=libperl.a gnulibc_version='2.23' Dynamic Linking: dlsrc=dl_dlopen.xs dlext=so d_dlsymun=undef ccdlflags='-Wl,-E' cccdlflags='-fPIC' lddlflags='-shared -ggdb3 -ggdb3 -O0 -L/usr/local/lib -fstack-protector-strong' --- @INC for perl 5.26.0: /backup/home/khw/perl/blead/lib /backup/home/khw/perl/blead/t /home/khw/blead/lib/perl5/site_perl/5.26.0/x86_64-linux-thread-multi-ld /home/khw/blead/lib/perl5/site_perl/5.26.0 /home/khw/blead/lib/perl5/5.26.0/x86_64-linux-thread-multi-ld /home/khw/blead/lib/perl5/5.26.0 /home/khw/blead/lib/perl5/site_perl/5.25.11 /home/khw/blead/lib/perl5/site_perl/5.25.10 /home/khw/blead/lib/perl5/site_perl/5.25.9 /home/khw/blead/lib/perl5/site_perl/5.25.8 /home/khw/blead/lib/perl5/site_perl/5.25.7 /home/khw/blead/lib/perl5/site_perl/5.25.6 /home/khw/blead/lib/perl5/site_perl/5.25.5 /home/khw/blead/lib/perl5/site_perl/5.25.4 /home/khw/blead/lib/perl5/site_perl/5.25.3 /home/khw/blead/lib/perl5/site_perl/5.25.2 /home/khw/blead/lib/perl5/site_perl/5.25.1 /home/khw/blead/lib/perl5/site_perl/5.24.0 /home/khw/blead/lib/perl5/site_perl/5.23.10 /home/khw/blead/lib/perl5/site_perl/5.23.9 /home/khw/blead/lib/perl5/site_perl/5.23.8 /home/khw/blead/lib/perl5/site_perl/5.23.7 /home/khw/blead/lib/perl5/site_perl/5.23.6 /home/khw/blead/lib/perl5/site_perl/5.23.5 /home/khw/blead/lib/perl5/site_perl/5.23.4 /home/khw/blead/lib/perl5/site_perl/5.23.3 /home/khw/blead/lib/perl5/site_perl/5.23.2 /home/khw/blead/lib/perl5/site_perl/5.23.1 /home/khw/blead/lib/perl5/site_perl/5.23.0 /home/khw/blead/lib/perl5/site_perl/5.22.0 /home/khw/blead/lib/perl5/site_perl/5.21.12 /home/khw/blead/lib/perl5/site_perl/5.21.11 /home/khw/blead/lib/perl5/site_perl/5.21.10 /home/khw/blead/lib/perl5/site_perl/5.21.9 /home/khw/blead/lib/perl5/site_perl/5.21.8 /home/khw/blead/lib/perl5/site_perl/5.21.7 /home/khw/blead/lib/perl5/site_perl/5.21.6 /home/khw/blead/lib/perl5/site_perl/5.21.5 /home/khw/blead/lib/perl5/site_perl/5.21.4 /home/khw/blead/lib/perl5/site_perl/5.21.3 /home/khw/blead/lib/perl5/site_perl/5.21.2 /home/khw/blead/lib/perl5/site_perl/5.21.1 /home/khw/blead/lib/perl5/site_perl/5.20.0 /home/khw/blead/lib/perl5/site_perl/5.19.12 /home/khw/blead/lib/perl5/site_perl/5.19.11 /home/khw/blead/lib/perl5/site_perl/5.19.10 /home/khw/blead/lib/perl5/site_perl --- Environment for perl 5.26.0: HOME=/home/khw LANG=en_US.UTF-8 LANGUAGE=en_US LD_LIBRARY_PATH (unset) LOGDIR (unset) PATH=/usr/lib/ccache:/home/khw/bin:/home/khw/perl5/perlbrew/bin:/home/khw/print/bin:/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/usr/games:/usr/local/games:/home/khw/iands/www:/home/khw/cxoffice/bin PERL5OPT=-w PERL_BADLANG (unset) PERL_DIFF_TOOL=wgdiff PERL_POD_PEDANTIC=1 SHELL=/bin/ksh
RT-Send-CC: perl5-porters [...] perl.org
On Sat, 08 Apr 2017 04:43:13 GMT, public@khwilliamson.com wrote: Show quoted text
> This is a bug report for perl from khw@cpan.org, > generated with the help of perlbug 1.40 running under perl 5.26.0. > > > ----------------------------------------------------------------- > commit 2e6f1ae9c4f7857e86f85fde07fe1af1254c4600 > Author: David Mitchell <davem@iabyn.com> > Date: Fri Apr 7 12:39:53 2017 +0100 > > fix and test execution of non-empty .bs files > > > This commit consistently causes this: > > panic: free from wrong pool, eea800!=d40c20 during global destruction. > ../dist/threads-shared/t/object2.t ................................. > > but only under certain circumstances. One that threw us off scent, is > this failure does not seem to happen if the directory the workspace is > in is named 'blead'. I've tried maybe 20 times, and it always > succeeds. > Yet it fails 100% of the time on every other directory name I've > tried. > The @INC shown in this perlbug looks weird. I don't know how it's > getting /backup or 5.26 there. The former is a backup to another > disk > of snapshots of my main disk, set off by a cron job several times a > day. > I don't know how 5.26 got in there. > > I am using ccache. I have tried clearing it before running, with no > change in symptoms. > > You can see the Configure options below. I run on an 8-core system > with > TEST_JOBS=12 make -j12 all test_harness > >
I have not been able to reproduce this problem. I configured like this: ##### sh ./Configure -des -Uversiononly -Dusedevel -D'optimize=-ggdb3' -A'optimize=-ggdb3' -A'optimize=-O0' -Accflags='-DPERL_BOOL_AS_CHAR' -Accflags='-DPERL_EXTERNAL_GLOB' -Dman1dir=none -Dman3dir=none -Dcc=g++ -DDEBUGGING -Dusemorebits -Dusecbacktrace -Dusethreads -Dprefix=/home/jkeenan/blead ##### ... then called 'make test_harness' in a terminal where $TEST_JOBS = 8 and I have 4 cores. All tests PASSed. I then changed the name of the directory from 'blead' to 'rando', then reconfigured changing only the last switch. Again, all tests PASSed. I did not use ccache in either case. In situations like this I try to start from as few switches as possible and add switches until the problem occurs. Conversely, you could also start subtracting switches from what you currently have. I know from backscrolling #p5p that you've done some of that. (I should note that normally I configure with just '-des -Dusedevel' with possibly '-Duseithreads'. 'make' runs without warnings for me. But with all your switches, I get warnings like this: ##### In file included from perlio.c:50:0: XSUB.h:122:43: warning: unused parameter ‘cv’ [-Wunused-parameter] #define XSPROTO(name) void name(pTHX_ CV* cv) ^ XSUB.h:141:44: note: in expansion of macro ‘XSPROTO’ # define XS_EXTERNAL(name) extern "C" XSPROTO(name) ^ XSUB.h:152:18: note: in expansion of macro ‘XS_EXTERNAL’ #define XS(name) XS_EXTERNAL(name) ^ perlio.c:846:1: note: in expansion of macro ‘XS’ XS(XS_PerlIO__Layer__NoWarnings) ^ XSUB.h:122:43: warning: unused parameter ‘cv’ [-Wunused-parameter] #define XSPROTO(name) void name(pTHX_ CV* cv) ^ XSUB.h:141:44: note: in expansion of macro ‘XSPROTO’ # define XS_EXTERNAL(name) extern "C" XSPROTO(name) ^ XSUB.h:152:18: note: in expansion of macro ‘XS_EXTERNAL’ #define XS(name) XS_EXTERNAL(name) ^ perlio.c:860:1: note: in expansion of macro ‘XS’ XS(XS_PerlIO__Layer__find) ^ g++ -c -DPERL_CORE -D_REENTRANT -D_GNU_SOURCE -DPERL_BOOL_AS_CHAR -DPERL_EXTERNAL_GLOB -fwrapv -DDEBUGGING -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include -DUSE_C_BACKTRACE -g -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64 -D_FORTIFY_SOURCE=2 -ansi -ggdb3 -ggdb3 -O0 -Wall -Werror=declaration-after-statement -Wextra -Wwrite-strings perlapi.c ##### End parenthesis.) And, as you note, your @INC looks very strange. Thank you very much. -- James E Keenan (jkeenan@cpan.org)
Date: Mon, 10 Apr 2017 11:55:59 +0100
To: perl5-porters [...] perl.org
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Dave Mitchell <davem [...] iabyn.com>
Download (untitled) / with headers
text/plain 1.2k
On Fri, Apr 07, 2017 at 09:43:13PM -0700, karl williamson wrote: Show quoted text
> commit 2e6f1ae9c4f7857e86f85fde07fe1af1254c4600 > Author: David Mitchell <davem@iabyn.com> > Date: Fri Apr 7 12:39:53 2017 +0100 > > fix and test execution of non-empty .bs files > > > This commit consistently causes this: > > panic: free from wrong pool, eea800!=d40c20 during global destruction. > ../dist/threads-shared/t/object2.t .................................
Is it definitely object2.t which is generating the panic? How far can you reduce the execution to? E.g. does this fail: cd dist/threads-shared/ ../../t/perl -I../.. -MTestInit=U2T t/object2.t And if so can the test sccipt be reduced, e.g. perhaps just loading an XS module triggers it? And what if run under valgrind? And what if just the "local @INC = ('.');" bit is reverted from XSLoader.pm? Alternatively, if you reduce your Configure options, does the problem go away? Especially if you you specify a completely clean install dir that hasn't got any old version dirs in it? -- The warp engines start playing up a bit, but seem to sort themselves out after a while without any intervention from boy genius Wesley Crusher. -- Things That Never Happen in "Star Trek" #17
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Karl Williamson <public [...] khwilliamson.com>
To: Dave Mitchell <davem [...] iabyn.com>, perl5-porters [...] perl.org
Date: Mon, 10 Apr 2017 09:03:53 -0600
Download (untitled) / with headers
text/plain 500b
On 04/10/2017 04:55 AM, Dave Mitchell wrote: Show quoted text
>> This commit consistently causes this: >> >> panic: free from wrong pool, eea800!=d40c20 during global destruction. >> ../dist/threads-shared/t/object2.t .................................
> Is it definitely object2.t which is generating the panic?
Test Summary Report ------------------- ../dist/threads-shared/t/object2.t (Wstat: 139 Tests: 131 Failed: 0) Non-zero wait status: 139 I'm now trying your other ideas.
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Karl Williamson <public [...] khwilliamson.com>
To: Dave Mitchell <davem [...] iabyn.com>, perl5-porters [...] perl.org
Date: Mon, 10 Apr 2017 12:38:21 -0600
Download (untitled) / with headers
text/plain 2.1k
On 04/10/2017 04:55 AM, Dave Mitchell wrote: Show quoted text
> On Fri, Apr 07, 2017 at 09:43:13PM -0700, karl williamson wrote:
>> commit 2e6f1ae9c4f7857e86f85fde07fe1af1254c4600 >> Author: David Mitchell <davem@iabyn.com> >> Date: Fri Apr 7 12:39:53 2017 +0100 >> >> fix and test execution of non-empty .bs files >> >> >> This commit consistently causes this: >> >> panic: free from wrong pool, eea800!=d40c20 during global destruction. >> ../dist/threads-shared/t/object2.t .................................
> > Is it definitely object2.t which is generating the panic? > How far can you reduce the execution to? E.g. does this fail: > > cd dist/threads-shared/ > ../../t/perl -I../.. -MTestInit=U2T t/object2.t > > And if so can the test sccipt be reduced, e.g. perhaps just loading an > XS module triggers it? And what if run under valgrind? > And what if just the "local @INC = ('.');" bit is reverted from > XSLoader.pm? > > Alternatively, if you reduce your Configure options, does the problem go > away? Especially if you you specify a completely clean install dir that > hasn't got any old version dirs in it? >
The problem doesn't arise when running the test in isolation. I already knew that, but hadn't tried TestInit=U2T. The line of code that changed to cause the problem, is indeed local @INC = ('.') in XSLoader. The problem persists when I whittle down the Configure script to /bin/sh ./Configure -des '-Dprefix=/home/khw/tempdevel' -Dusedevel -DDEBUGGING -Dusethreads That means it fails for both gcc and g++, and both -O0 and -O2. -DDEBUGGING is required. In part, that is because the function that outputs the error doesn't normally get compiled except under DEBUGGING. That's because PERL_TRACK_MEMPOOL doesn't get #defined except under DEBUGGING. However, when I Configure so that PERL_TRACK_MEMPOOL does get #defined anyway, it still works. So DEBUGGING is really required, though there may be other components besides PERL_TRACK_MEMPOOL that DEBUGGING sets that are also prerequisites. tempdevel/ is empty. I removed the earlier /home/khw/devel. And, now this fails even if the directory is named 'blead'. I tried this on my laptop, which has a later gcc, and only 4 cores, and it did not fail.
To: Karl Williamson <public [...] khwilliamson.com>
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Dave Mitchell <davem [...] iabyn.com>
CC: perl5-porters [...] perl.org
Date: Tue, 11 Apr 2017 00:08:25 +0100
Download (untitled) / with headers
text/plain 967b
On Mon, Apr 10, 2017 at 12:38:21PM -0600, Karl Williamson wrote: Show quoted text
> The problem doesn't arise when running the test in isolation. I already > knew that, but hadn't tried TestInit=U2T.
Does it require running multiple jobs in parallel to fail? So does ./perl harness ../dist/threads-shared/t/object2.t on its own fail? If not, how about running just a minimal number of tests in parallel? HARNESS_OPTIONS=j8 ./perl harness ../dist/threads-shared/t/object2.t \ ... plus a few ... \ ... other test scripts.... If harness fails with just the one test script, then maybe invoking directly with -MTestInit=U2T can be made to fail if in addition any env vars that harness would have set are set manually. These seem to be: PERL5LIB=../../lib:../../t PERL_CORE=/home/....whatever is the top-level dir of the perl src... Other than that I'm totally bemused. -- A problem shared is a problem doubled.
Date: Mon, 10 Apr 2017 21:09:01 -0600
CC: perl5-porters [...] perl.org
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Karl Williamson <public [...] khwilliamson.com>
To: Dave Mitchell <davem [...] iabyn.com>
On 04/10/2017 05:08 PM, Dave Mitchell wrote: Show quoted text
> On Mon, Apr 10, 2017 at 12:38:21PM -0600, Karl Williamson wrote:
>> The problem doesn't arise when running the test in isolation. I already >> knew that, but hadn't tried TestInit=U2T.
> > Does it require running multiple jobs in parallel to fail? So does > > ./perl harness ../dist/threads-shared/t/object2.t > > on its own fail?
No If not, how about running just a minimal number of tests Show quoted text
> in parallel? > > HARNESS_OPTIONS=j8 ./perl harness ../dist/threads-shared/t/object2.t \ > ... plus a few ... \ > ... other test scripts....
I haven't tried this, but I did try a make test.valgrind with 12 parallel jobs, and it didn't fail. Show quoted text
> > If harness fails with just the one test script, then maybe invoking > directly with -MTestInit=U2T can be made to fail if in addition any env > vars that harness would have set are set manually. These seem to be: > > PERL5LIB=../../lib:../../t > PERL_CORE=/home/....whatever is the top-level dir of the perl src... > > Other than that I'm totally bemused. >
To: Dave Mitchell <davem [...] iabyn.com>
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Karl Williamson <public [...] khwilliamson.com>
CC: perl5-porters [...] perl.org
Date: Tue, 11 Apr 2017 17:01:25 -0600
Download (untitled) / with headers
text/plain 1.7k
On 04/10/2017 09:09 PM, Karl Williamson wrote: Show quoted text
> On 04/10/2017 05:08 PM, Dave Mitchell wrote:
>> On Mon, Apr 10, 2017 at 12:38:21PM -0600, Karl Williamson wrote:
>>> The problem doesn't arise when running the test in isolation. I already >>> knew that, but hadn't tried TestInit=U2T.
>> >> Does it require running multiple jobs in parallel to fail? So does >> >> ./perl harness ../dist/threads-shared/t/object2.t >> >> on its own fail?
> > No > > If not, how about running just a minimal number of tests
>> in parallel? >> >> HARNESS_OPTIONS=j8 ./perl harness >> ../dist/threads-shared/t/object2.t \ >> ... plus a few ... \ >> ... other test scripts....
> > I haven't tried this, but I did try a make test.valgrind with 12 > parallel jobs, and it didn't fail.
>> >> If harness fails with just the one test script, then maybe invoking >> directly with -MTestInit=U2T can be made to fail if in addition any env >> vars that harness would have set are set manually. These seem to be: >> >> PERL5LIB=../../lib:../../t >> PERL_CORE=/home/....whatever is the top-level dir of the perl src... >> >> Other than that I'm totally bemused. >>\
I managed to get this to fail on an individual run, by grepping for all environment settings in t/TEST and t/harness: EMXSHELL=sh PERL_DL_NONLAZY=1 ../../perl -I../.. -MTestInit=U2T t/object2.t 2>&1 | more Removing either of the environment settings causes it to not fail. The fact that I'm running on Linux, and EMXSHELL is supposedly only OS2 is ... not bemusing to me. If I add PERL5LIB=../../lib:../../t it also succeeds, which makes me think it is somehow a library path problem. I don't see, unlike what you said, how harness is automatically adding this. Also, it appears to be adding PERL_CORE=1; maybe
From: Dave Mitchell <davem [...] iabyn.com>
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
To: Karl Williamson <public [...] khwilliamson.com>
CC: perl5-porters [...] perl.org
Date: Wed, 12 Apr 2017 08:15:38 +0100
Download (untitled) / with headers
text/plain 2.5k
On Tue, Apr 11, 2017 at 05:01:25PM -0600, Karl Williamson wrote: Show quoted text
> On 04/10/2017 09:09 PM, Karl Williamson wrote:
> > On 04/10/2017 05:08 PM, Dave Mitchell wrote:
> > > On Mon, Apr 10, 2017 at 12:38:21PM -0600, Karl Williamson wrote:
> > > > The problem doesn't arise when running the test in isolation. I already > > > > knew that, but hadn't tried TestInit=U2T.
> > > > > > Does it require running multiple jobs in parallel to fail? So does > > > > > > ./perl harness ../dist/threads-shared/t/object2.t > > > > > > on its own fail?
> > > > No > > > > If not, how about running just a minimal number of tests
> > > in parallel? > > > > > > HARNESS_OPTIONS=j8 ./perl harness > > > ../dist/threads-shared/t/object2.t \ > > > ... plus a few ... \ > > > ... other test scripts....
> > > > I haven't tried this, but I did try a make test.valgrind with 12 > > parallel jobs, and it didn't fail.
> > > > > > If harness fails with just the one test script, then maybe invoking > > > directly with -MTestInit=U2T can be made to fail if in addition any env > > > vars that harness would have set are set manually. These seem to be: > > > > > > PERL5LIB=../../lib:../../t > > > PERL_CORE=/home/....whatever is the top-level dir of the perl src... > > > > > > Other than that I'm totally bemused. > > > \
> > I managed to get this to fail on an individual run, by grepping for all > environment settings in t/TEST and t/harness: > > EMXSHELL=sh PERL_DL_NONLAZY=1 ../../perl -I../.. -MTestInit=U2T t/object2.t
> 2>&1 | more
> > Removing either of the environment settings causes it to not fail. The fact > that I'm running on Linux, and EMXSHELL is supposedly only OS2 is ... not > bemusing to me. > > If I add PERL5LIB=../../lib:../../t it also succeeds, which makes me think > it is somehow a library path problem. I don't see, unlike what you said, > how harness is automatically adding this. Also, it appears to be adding > PERL_CORE=1; maybe
The PERL5LIB and PERL_CORE is being set by TestInit itself - I was dumping the env from within t/object2.t itself, and so was seeing what had already been set by TestInit. Having said that, I still can't reproduce it. Can you run it under valgrind? Also, can you run it under strace to see what files (and paths) it's statting and loading - especially any .bs files? -- "Strange women lying in ponds distributing swords is no basis for a system of government. Supreme executive power derives from a mandate from the masses, not from some farcical aquatic ceremony." -- Dennis, "Monty Python and the Holy Grail"
Date: Wed, 12 Apr 2017 09:23:07 -0600
CC: perl5-porters [...] perl.org
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Karl Williamson <public [...] khwilliamson.com>
To: Dave Mitchell <davem [...] iabyn.com>
Download (untitled) / with headers
text/plain 2.3k
On 04/12/2017 01:15 AM, Dave Mitchell wrote: Show quoted text
> On Tue, Apr 11, 2017 at 05:01:25PM -0600, Karl Williamson wrote:
>> On 04/10/2017 09:09 PM, Karl Williamson wrote:
>>> On 04/10/2017 05:08 PM, Dave Mitchell wrote:
>>>> On Mon, Apr 10, 2017 at 12:38:21PM -0600, Karl Williamson wrote:
>>>>> The problem doesn't arise when running the test in isolation. I already >>>>> knew that, but hadn't tried TestInit=U2T.
>>>> >>>> Does it require running multiple jobs in parallel to fail? So does >>>> >>>> ./perl harness ../dist/threads-shared/t/object2.t >>>> >>>> on its own fail?
>>> >>> No >>> >>> If not, how about running just a minimal number of tests
>>>> in parallel? >>>> >>>> HARNESS_OPTIONS=j8 ./perl harness >>>> ../dist/threads-shared/t/object2.t \ >>>> ... plus a few ... \ >>>> ... other test scripts....
>>> >>> I haven't tried this, but I did try a make test.valgrind with 12 >>> parallel jobs, and it didn't fail.
>>>> >>>> If harness fails with just the one test script, then maybe invoking >>>> directly with -MTestInit=U2T can be made to fail if in addition any env >>>> vars that harness would have set are set manually. These seem to be: >>>> >>>> PERL5LIB=../../lib:../../t >>>> PERL_CORE=/home/....whatever is the top-level dir of the perl src... >>>> >>>> Other than that I'm totally bemused. >>>> \
>> >> I managed to get this to fail on an individual run, by grepping for all >> environment settings in t/TEST and t/harness: >> >> EMXSHELL=sh PERL_DL_NONLAZY=1 ../../perl -I../.. -MTestInit=U2T t/object2.t
>> 2>&1 | more
>> >> Removing either of the environment settings causes it to not fail. The fact >> that I'm running on Linux, and EMXSHELL is supposedly only OS2 is ... not >> bemusing to me. >> >> If I add PERL5LIB=../../lib:../../t it also succeeds, which makes me think >> it is somehow a library path problem. I don't see, unlike what you said, >> how harness is automatically adding this. Also, it appears to be adding >> PERL_CORE=1; maybe
> > The PERL5LIB and PERL_CORE is being set by TestInit itself - I was dumping > the env from within t/object2.t itself, and so was seeing what had already > been set by TestInit. > > Having said that, I still can't reproduce it. > > Can you run it under valgrind? > > Also, can you run it under strace to see what files (and paths) it's > statting and loading - especially any .bs files? >
Both attached.
Download valgrind.log
text/x-log 8.3k

Message body is not shown because sender requested not to inline it.

Download strace.log
text/x-log 50k

Message body is not shown because sender requested not to inline it.

CC: perl5-porters [...] perl.org
Date: Wed, 12 Apr 2017 16:48:57 +0100
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Dave Mitchell <davem [...] iabyn.com>
To: Karl Williamson <public [...] khwilliamson.com>
Download (untitled) / with headers
text/plain 1.7k
On Wed, Apr 12, 2017 at 09:23:07AM -0600, Karl Williamson wrote: Show quoted text
> > Can you run it under valgrind? > > > > Also, can you run it under strace to see what files (and paths) it's > > statting and loading - especially any .bs files?
The strace shows that the only interaction it's having with .bs files is failing to find any: stat("../../lib/auto/Cwd/Cwd.bs", 0x1221eb0) = -1 ENOENT (No such file or directory) stat("../../lib/auto/threads/threads.bs", 0x1221eb0) = -1 ENOENT (No such file or directory) stat("../../lib/auto/List/Util/Util.bs", 0x1221eb0) = -1 ENOENT (No such file or directory) stat("../../lib/auto/threads/shared/shared.bs", 0x1221eb0) = -1 ENOENT (No such file or directory) stat("../../lib/auto/attributes/attributes.bs", 0x1221eb0) = -1 ENOENT (No such file or directory) which strongly indicates that the modified branch in XSLoader.pm is never taken: if (-s $bs) { # only read file if it's not empty # print STDERR "BS: $bs ($^O, $dlsrc)\n" if $dl_debug; eval { local @INC = ('.'); do $bs; }; Could you temporarily replace the 'eval' line with a die to confim that that code path is never taken when running object2.t? If so, it would indicate that my commit only changed some code which is compiled but never executed; which would tend to imply that some other bug in threads is being tickled; e.g. something in the optree which isn't threadsafe in some way. The valgrind stack trace shows that Perl_croak_nocontext("panic: free from wrong pool") is being called when free()ing the main threads's SV malloc()ed arenas - i.e. very late in the process cleanup - and the valgrind error is only because the context stack appears to have already been freed at that point. -- Dave's first rule of Opera: If something needs saying, say it: don't warble it.
To: Dave Mitchell <davem [...] iabyn.com>
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Karl Williamson <public [...] khwilliamson.com>
Date: Wed, 12 Apr 2017 10:37:05 -0600
CC: perl5-porters [...] perl.org
Download (untitled) / with headers
text/plain 1.8k
On 04/12/2017 09:48 AM, Dave Mitchell wrote: Show quoted text
> On Wed, Apr 12, 2017 at 09:23:07AM -0600, Karl Williamson wrote:
>>> Can you run it under valgrind? >>> >>> Also, can you run it under strace to see what files (and paths) it's >>> statting and loading - especially any .bs files?
> > The strace shows that the only interaction it's having with .bs files is > failing to find any: > > stat("../../lib/auto/Cwd/Cwd.bs", 0x1221eb0) = -1 ENOENT (No such file or directory) > stat("../../lib/auto/threads/threads.bs", 0x1221eb0) = -1 ENOENT (No such file or directory) > stat("../../lib/auto/List/Util/Util.bs", 0x1221eb0) = -1 ENOENT (No such file or directory) > stat("../../lib/auto/threads/shared/shared.bs", 0x1221eb0) = -1 ENOENT (No such file or directory) > stat("../../lib/auto/attributes/attributes.bs", 0x1221eb0) = -1 ENOENT (No such file or directory) > > which strongly indicates that the modified branch in XSLoader.pm is never > taken: > > if (-s $bs) { # only read file if it's not empty > # print STDERR "BS: $bs ($^O, $dlsrc)\n" if $dl_debug; > eval { local @INC = ('.'); do $bs; }; > > Could you temporarily replace the 'eval' line with a die to confim that > that code path is never taken when running object2.t? > > If so, it would indicate that my commit only changed some code which is > compiled but never executed; which would tend to imply that some other bug > in threads is being tickled; e.g. something in the optree which isn't > threadsafe in some way. > > The valgrind stack trace shows that > > Perl_croak_nocontext("panic: free from wrong pool") > > is being called when free()ing the main threads's SV malloc()ed arenas - > i.e. very late in the process cleanup - and the valgrind error is only > because the context stack appears to have already been freed at that > point. > >
The die doesn't get called, but the pool bug is gone too.
To: Dave Mitchell <davem [...] iabyn.com>
From: Karl Williamson <public [...] khwilliamson.com>
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
Date: Wed, 12 Apr 2017 16:58:43 -0600
CC: perl5-porters [...] perl.org
Download (untitled) / with headers
text/plain 2.4k
On 04/12/2017 10:37 AM, Karl Williamson wrote: Show quoted text
> On 04/12/2017 09:48 AM, Dave Mitchell wrote:
>> On Wed, Apr 12, 2017 at 09:23:07AM -0600, Karl Williamson wrote:
>>>> Can you run it under valgrind? >>>> >>>> Also, can you run it under strace to see what files (and paths) it's >>>> statting and loading - especially any .bs files?
>> >> The strace shows that the only interaction it's having with .bs files is >> failing to find any: >> >> stat("../../lib/auto/Cwd/Cwd.bs", 0x1221eb0) = -1 ENOENT (No such file >> or directory) >> stat("../../lib/auto/threads/threads.bs", 0x1221eb0) = -1 ENOENT (No >> such file or directory) >> stat("../../lib/auto/List/Util/Util.bs", 0x1221eb0) = -1 ENOENT (No >> such file or directory) >> stat("../../lib/auto/threads/shared/shared.bs", 0x1221eb0) = -1 ENOENT >> (No such file or directory) >> stat("../../lib/auto/attributes/attributes.bs", 0x1221eb0) = -1 ENOENT >> (No such file or directory) >> >> which strongly indicates that the modified branch in XSLoader.pm is never >> taken: >> >> if (-s $bs) { # only read file if it's not empty >> # print STDERR "BS: $bs ($^O, $dlsrc)\n" if $dl_debug; >> eval { local @INC = ('.'); do $bs; }; >> >> Could you temporarily replace the 'eval' line with a die to confim that >> that code path is never taken when running object2.t? >> >> If so, it would indicate that my commit only changed some code which is >> compiled but never executed; which would tend to imply that some other >> bug >> in threads is being tickled; e.g. something in the optree which isn't >> threadsafe in some way. >> >> The valgrind stack trace shows that >> >> Perl_croak_nocontext("panic: free from wrong pool") >> >> is being called when free()ing the main threads's SV malloc()ed arenas - >> i.e. very late in the process cleanup - and the valgrind error is only >> because the context stack appears to have already been freed at that >> point. >> >>
> > The die doesn't get called, but the pool bug is gone too. >
Just to be sure, I replaced the die by opening a file and writing to it, then closing it. It did not get created, and the panic did not happen. I then commented out the file lines, and the panic comes back. If I uncomment the line print STDERR "BS: $bs ($^O, \n" if $dl_debug; the panic goes away, but, and this may be important, this message gets output before any of the tests: Use of uninitialized value in subroutine entry at ../../lib/XSLoader.pm line 14 . I fail to see how this could be connected except through some weirdness.
From: Dave Mitchell <davem [...] iabyn.com>
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
To: Karl Williamson <public [...] khwilliamson.com>
CC: perl5-porters [...] perl.org
Date: Thu, 13 Apr 2017 09:04:02 +0100
Download (untitled) / with headers
text/plain 745b
On Wed, Apr 12, 2017 at 04:58:43PM -0600, Karl Williamson wrote: Show quoted text
> If I uncomment the line > > print STDERR "BS: $bs ($^O, \n" if $dl_debug; > > the panic goes away, but, and this may be important, this message gets > output before any of the tests: > > Use of uninitialized value in subroutine entry at ../../lib/XSLoader.pm > line 14 . > > I fail to see how this could be connected except through some weirdness.
That's just bizarre. Maybe run it under gdb and see where and what in the Dynaloader XS is triggering the "uninitialized value" warning? -- The crew of the Enterprise encounter an alien life form which is surprisingly neither humanoid nor made from pure energy. -- Things That Never Happen in "Star Trek" #22
CC: perl5-porters [...] perl.org, "perlbug-followup [...] perl.org" <perlbug-followup [...] perl.org>
Date: Thu, 13 Apr 2017 10:05:31 -0600
To: Dave Mitchell <davem [...] iabyn.com>
From: Karl Williamson <public [...] khwilliamson.com>
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
Download (untitled) / with headers
text/plain 3.6k
On 04/13/2017 02:04 AM, Dave Mitchell wrote: Show quoted text
> On Wed, Apr 12, 2017 at 04:58:43PM -0600, Karl Williamson wrote:
>> If I uncomment the line >> >> print STDERR "BS: $bs ($^O, \n" if $dl_debug; >> >> the panic goes away, but, and this may be important, this message gets >> output before any of the tests: >> >> Use of uninitialized value in subroutine entry at ../../lib/XSLoader.pm >> line 14 . >> >> I fail to see how this could be connected except through some weirdness.
> > That's just bizarre. > > Maybe run it under gdb and see where and what in the Dynaloader XS is > triggering the "uninitialized value" warning? >
Running under valgrind did not show any errors: Here's the gdb stack trace #0 S_find_uninit_var (my_perl=0xad0c20, obase=0xb92ac8, uninit_sv=0xc08720, match=0 '\000', desc_p=0x7fffffffa448) at sv.c:15953 #1 0x00000000006657ac in Perl_report_uninit (my_perl=0xad0c20, uninit_sv=0xc08720) at sv.c:16626 #2 0x00000000006061dd in S_sv_2iuv_common (my_perl=0xad0c20, sv=0xc08720) at sv.c:2407 #3 0x0000000000606eb8 in Perl_sv_2iv_flags (my_perl=0xad0c20, sv=0xc08720, flags=2) at sv.c:2504 #4 0x00000000007b3047 in dl_generic_private_init (my_perl=0xad0c20) at dlutils.c:115 #5 0x00000000007b362c in dl_private_init (my_perl=0xad0c20) at DynaLoader.xs:153 #6 0x00000000007b4f8d in boot_DynaLoader (my_perl=0xad0c20, cv=0xaf6308) at DynaLoader.xs:159 #7 0x00000000005f8525 in Perl_pp_entersub (my_perl=0xad0c20) at pp_hot.c:4231 #8 0x0000000000585ded in Perl_runops_debug (my_perl=0xad0c20) at dump.c:2451 #9 0x00000000004699d3 in Perl_call_sv (my_perl=0xad0c20, sv=0xb315f0, flags=13) at perl.c:2848 #10 0x00000000004747c5 in Perl_call_list (my_perl=0xad0c20, oldscope=6, paramList=0xb30840) at perl.c:5016 #11 0x0000000000446282 in S_process_special_blocks (my_perl=0xad0c20, floor=157, fullname=0xad9210 "BEGIN", gv=0xb31638, cv=0xb315f0) at op.c:9055 #12 0x0000000000445949 in Perl_newATTRSUB_x (my_perl=0xad0c20, floor=157, o=0xb3d580, proto=0x0, attrs=0x0, block=0xb3d540, o_is_gv=0 '\000') at op.c:8984 #13 0x0000000000434fae in Perl_utilize (my_perl=0xad0c20, aver=1, floor=157, version=0x0, idop=0xb3a648, arg=0x0) at op.c:6343 #14 0x00000000004f173e in Perl_yyparse (my_perl=0xad0c20, gramtype=258) at perly.y:354 #15 0x00000000006c2bd4 in S_doeval_compile (my_perl=0xad0c20, gimme=2 '\002', outside=0x0, seq=314, hh=0x0) at pp_ctl.c:3436 #16 0x00000000006c91ac in S_require_file (my_perl=0xad0c20, sv=0xb04260) at pp_ctl.c:4177 #17 0x00000000006c9324 in Perl_pp_require (my_perl=0xad0c20) at pp_ctl.c:4198 #18 0x0000000000585ded in Perl_runops_debug (my_perl=0xad0c20) at dump.c:2451 #19 0x00000000004699d3 in Perl_call_sv (my_perl=0xad0c20, sv=0xb04350, flags=13) at perl.c:2848 #20 0x00000000004747c5 in Perl_call_list (my_perl=0xad0c20, oldscope=2, paramList=0xb043e0) at perl.c:5016 #21 0x0000000000446282 in S_process_special_blocks (my_perl=0xad0c20, floor=45, fullname=0xad9210 "BEGIN", gv=0xb043f8, cv=0xb04350) at op.c:9055 #22 0x0000000000445949 in Perl_newATTRSUB_x (my_perl=0xad0c20, floor=45, o=0xb119c0, proto=0x0, attrs=0x0, block=0xb11980, o_is_gv=0 '\000') at op.c:8984 #23 0x0000000000434fae in Perl_utilize (my_perl=0xad0c20, aver=1, floor=45, version=0x0, idop=0xb0fd38, arg=0x0) at op.c:6343 #24 0x00000000004f173e in Perl_yyparse (my_perl=0xad0c20, gramtype=258) at perly.y:354 #25 0x0000000000467031 in S_parse_body (my_perl=0xad0c20, env=0x0, xsinit=0x41c0c1 <xs_init(PerlInterpreter*)>) at perl.c:2377 #26 0x0000000000464ea7 in perl_parse (my_perl=0xad0c20, xsinit=0x41c0c1 <xs_init(PerlInterpreter*)>, argc=4, argv=0x7fffffffd418, env=0x0) at perl.c:1692 #27 0x000000000041bffc in main (argc=4, argv=0x7fffffffd418, env=0x7fffffffd440) at perlmain.c:121
CC: perl5-porters [...] perl.org, "perlbug-followup [...] perl.org" <perlbug-followup [...] perl.org>
Date: Thu, 13 Apr 2017 11:12:18 -0600
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Karl Williamson <public [...] khwilliamson.com>
To: Dave Mitchell <davem [...] iabyn.com>
Download (untitled) / with headers
text/plain 4.7k
On 04/13/2017 10:05 AM, Karl Williamson wrote: Show quoted text
> On 04/13/2017 02:04 AM, Dave Mitchell wrote:
>> On Wed, Apr 12, 2017 at 04:58:43PM -0600, Karl Williamson wrote:
>>> If I uncomment the line >>> >>> print STDERR "BS: $bs ($^O, \n" if $dl_debug; >>> >>> the panic goes away, but, and this may be important, this message gets >>> output before any of the tests: >>> >>> Use of uninitialized value in subroutine entry at >>> ../../lib/XSLoader.pm >>> line 14 . >>> >>> I fail to see how this could be connected except through some weirdness.
>> >> That's just bizarre. >> >> Maybe run it under gdb and see where and what in the Dynaloader XS is >> triggering the "uninitialized value" warning?
Some more data points. I tried it compiling under clang, with -fsanitize=address. The panic did not happen. I then tried uncommenting that print statement that should not be getting executed. The uninitialized warning comes out. I noticed these interesting comments at the top of XSLoader_pm.PL # dlutils.c before 5.006 has this: # # #ifdef DEBUGGING # dl_debug = SvIV( perl_get_sv("DynaLoader::dl_debug", 0x04) ); # #endif # # where 0x04 is GV_ADDWARN, which causes a warning to be issued by the call # into XS below, if DynaLoader.pm hasn't been loaded. # It was changed to 0 in the commit(s) that added XSLoader to the core # (9cf41c4d23a47c8b and its parent 9426adcd48655815) # Hence to backport XSLoader to work silently with earlier DynaLoaders we need # to ensure that the variable exists: It still makes no sense to me that this should happen, given that the print isn't in a branch that appears to be getting executed. Show quoted text
>>
> > Running under valgrind did not show any errors: Here's the gdb stack trace > > #0 S_find_uninit_var (my_perl=0xad0c20, obase=0xb92ac8, > uninit_sv=0xc08720, match=0 '\000', desc_p=0x7fffffffa448) at sv.c:15953 > #1 0x00000000006657ac in Perl_report_uninit (my_perl=0xad0c20, > uninit_sv=0xc08720) at sv.c:16626 > #2 0x00000000006061dd in S_sv_2iuv_common (my_perl=0xad0c20, > sv=0xc08720) at sv.c:2407 > #3 0x0000000000606eb8 in Perl_sv_2iv_flags (my_perl=0xad0c20, > sv=0xc08720, flags=2) at sv.c:2504 > #4 0x00000000007b3047 in dl_generic_private_init (my_perl=0xad0c20) at > dlutils.c:115 > #5 0x00000000007b362c in dl_private_init (my_perl=0xad0c20) at > DynaLoader.xs:153 > #6 0x00000000007b4f8d in boot_DynaLoader (my_perl=0xad0c20, > cv=0xaf6308) at DynaLoader.xs:159 > #7 0x00000000005f8525 in Perl_pp_entersub (my_perl=0xad0c20) at > pp_hot.c:4231 > #8 0x0000000000585ded in Perl_runops_debug (my_perl=0xad0c20) at > dump.c:2451 > #9 0x00000000004699d3 in Perl_call_sv (my_perl=0xad0c20, sv=0xb315f0, > flags=13) at perl.c:2848 > #10 0x00000000004747c5 in Perl_call_list (my_perl=0xad0c20, oldscope=6, > paramList=0xb30840) at perl.c:5016 > #11 0x0000000000446282 in S_process_special_blocks (my_perl=0xad0c20, > floor=157, fullname=0xad9210 "BEGIN", gv=0xb31638, cv=0xb315f0) at > op.c:9055 > #12 0x0000000000445949 in Perl_newATTRSUB_x (my_perl=0xad0c20, > floor=157, o=0xb3d580, proto=0x0, attrs=0x0, block=0xb3d540, o_is_gv=0 > '\000') at op.c:8984 > #13 0x0000000000434fae in Perl_utilize (my_perl=0xad0c20, aver=1, > floor=157, version=0x0, idop=0xb3a648, arg=0x0) at op.c:6343 > #14 0x00000000004f173e in Perl_yyparse (my_perl=0xad0c20, gramtype=258) > at perly.y:354 > #15 0x00000000006c2bd4 in S_doeval_compile (my_perl=0xad0c20, gimme=2 > '\002', outside=0x0, seq=314, hh=0x0) at pp_ctl.c:3436 > #16 0x00000000006c91ac in S_require_file (my_perl=0xad0c20, sv=0xb04260) > at pp_ctl.c:4177 > #17 0x00000000006c9324 in Perl_pp_require (my_perl=0xad0c20) at > pp_ctl.c:4198 > #18 0x0000000000585ded in Perl_runops_debug (my_perl=0xad0c20) at > dump.c:2451 > #19 0x00000000004699d3 in Perl_call_sv (my_perl=0xad0c20, sv=0xb04350, > flags=13) at perl.c:2848 > #20 0x00000000004747c5 in Perl_call_list (my_perl=0xad0c20, oldscope=2, > paramList=0xb043e0) at perl.c:5016 > #21 0x0000000000446282 in S_process_special_blocks (my_perl=0xad0c20, > floor=45, fullname=0xad9210 "BEGIN", gv=0xb043f8, cv=0xb04350) at op.c:9055 > #22 0x0000000000445949 in Perl_newATTRSUB_x (my_perl=0xad0c20, floor=45, > o=0xb119c0, proto=0x0, attrs=0x0, block=0xb11980, o_is_gv=0 '\000') at > op.c:8984 > #23 0x0000000000434fae in Perl_utilize (my_perl=0xad0c20, aver=1, > floor=45, version=0x0, idop=0xb0fd38, arg=0x0) at op.c:6343 > #24 0x00000000004f173e in Perl_yyparse (my_perl=0xad0c20, gramtype=258) > at perly.y:354 > #25 0x0000000000467031 in S_parse_body (my_perl=0xad0c20, env=0x0, > xsinit=0x41c0c1 <xs_init(PerlInterpreter*)>) at perl.c:2377 > #26 0x0000000000464ea7 in perl_parse (my_perl=0xad0c20, xsinit=0x41c0c1 > <xs_init(PerlInterpreter*)>, argc=4, argv=0x7fffffffd418, env=0x0) at > perl.c:1692 > #27 0x000000000041bffc in main (argc=4, argv=0x7fffffffd418, > env=0x7fffffffd440) at perlmain.c:121 >
Date: Thu, 13 Apr 2017 19:39:55 +0100
CC: perl5-porters [...] perl.org, "perlbug-followup [...] perl.org" <perlbug-followup [...] perl.org>
From: Dave Mitchell <davem [...] iabyn.com>
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
To: Karl Williamson <public [...] khwilliamson.com>
Download (untitled) / with headers
text/plain 3.1k
On Thu, Apr 13, 2017 at 11:12:18AM -0600, Karl Williamson wrote: Show quoted text
> On 04/13/2017 10:05 AM, Karl Williamson wrote:
> > On 04/13/2017 02:04 AM, Dave Mitchell wrote:
> > > On Wed, Apr 12, 2017 at 04:58:43PM -0600, Karl Williamson wrote:
> > > > If I uncomment the line > > > > > > > > print STDERR "BS: $bs ($^O, \n" if $dl_debug; > > > > > > > > the panic goes away, but, and this may be important, this message gets > > > > output before any of the tests: > > > > > > > > Use of uninitialized value in subroutine entry at > > > > ../../lib/XSLoader.pm > > > > line 14 . > > > > > > > > I fail to see how this could be connected except through some weirdness.
> > > > > > That's just bizarre. > > > > > > Maybe run it under gdb and see where and what in the Dynaloader XS is > > > triggering the "uninitialized value" warning?
> > Some more data points. I tried it compiling under clang, with > -fsanitize=address. The panic did not happen. > > I then tried uncommenting that print statement that should not be getting > executed. The uninitialized warning comes out. I noticed these interesting > comments at the top of XSLoader_pm.PL > > # dlutils.c before 5.006 has this: > # > # #ifdef DEBUGGING > # dl_debug = SvIV( perl_get_sv("DynaLoader::dl_debug", 0x04) ); > # #endif > # > # where 0x04 is GV_ADDWARN, which causes a warning to be issued by the call > # into XS below, if DynaLoader.pm hasn't been loaded. > # It was changed to 0 in the commit(s) that added XSLoader to the core > # (9cf41c4d23a47c8b and its parent 9426adcd48655815) > # Hence to backport XSLoader to work silently with earlier DynaLoaders we > need > # to ensure that the variable exists: > > It still makes no sense to me that this should happen, given that the print > isn't in a branch that appears to be getting executed.
It's this code in dl_generic_private_init(): #ifdef DEBUGGING { SV *sv = get_sv("DynaLoader::dl_debug", 0); dl_debug = sv ? SvIV(sv) : 0; } #endif Normally *DynaLoader::dl_debug doesn't exist, so sv is null. By uncommenting the '... if $dl_debug;' line in XSLoader.pm, the glob gets created at compile time, so $DynaLoader::dl_debug exists but is undef. Hence the warning. So I think this is a red herring. Perhaps another approach concerning this panic: panic: free from wrong pool, eea800!=d40c20 during global destruction. ../dist/threads-shared/t/object2.t ................................. would be to analyse it under gdb. When PERL_TRACK_MEMPOOL is defined, every malloc/free has a header which stores the current my_perl value. If when later freeing it, header->interpreter != my_perl, then the panic ensues (i.e. mallocs and free of the same address must occur within the same interpreter/thread). So run the failing process once in gdb, breakpointing on the panic line at util.c:240, Then do a (gdb) watch -l header->interpreter and re-run, to see when header is allocated, and when header->interpreter is set and/or modified. Full backtracks at those points might illuminate things a bit. -- Wesley Crusher gets beaten up by his classmates for being a smarmy git, and consequently has a go at making some friends of his own age for a change. -- Things That Never Happen in "Star Trek" #18
Date: Thu, 13 Apr 2017 21:48:09 -0600
CC: perl5-porters [...] perl.org, "perlbug-followup [...] perl.org" <perlbug-followup [...] perl.org>
To: Dave Mitchell <davem [...] iabyn.com>
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
From: Karl Williamson <public [...] khwilliamson.com>
Download (untitled) / with headers
text/plain 6.8k
On 04/13/2017 12:39 PM, Dave Mitchell wrote: Show quoted text
> On Thu, Apr 13, 2017 at 11:12:18AM -0600, Karl Williamson wrote:
>> On 04/13/2017 10:05 AM, Karl Williamson wrote:
>>> On 04/13/2017 02:04 AM, Dave Mitchell wrote:
>>>> On Wed, Apr 12, 2017 at 04:58:43PM -0600, Karl Williamson wrote:
>>>>> If I uncomment the line >>>>> >>>>> print STDERR "BS: $bs ($^O, \n" if $dl_debug; >>>>> >>>>> the panic goes away, but, and this may be important, this message gets >>>>> output before any of the tests: >>>>> >>>>> Use of uninitialized value in subroutine entry at >>>>> ../../lib/XSLoader.pm >>>>> line 14 . >>>>> >>>>> I fail to see how this could be connected except through some weirdness.
>>>> >>>> That's just bizarre. >>>> >>>> Maybe run it under gdb and see where and what in the Dynaloader XS is >>>> triggering the "uninitialized value" warning?
>> >> Some more data points. I tried it compiling under clang, with >> -fsanitize=address. The panic did not happen. >> >> I then tried uncommenting that print statement that should not be getting >> executed. The uninitialized warning comes out. I noticed these interesting >> comments at the top of XSLoader_pm.PL >> >> # dlutils.c before 5.006 has this: >> # >> # #ifdef DEBUGGING >> # dl_debug = SvIV( perl_get_sv("DynaLoader::dl_debug", 0x04) ); >> # #endif >> # >> # where 0x04 is GV_ADDWARN, which causes a warning to be issued by the call >> # into XS below, if DynaLoader.pm hasn't been loaded. >> # It was changed to 0 in the commit(s) that added XSLoader to the core >> # (9cf41c4d23a47c8b and its parent 9426adcd48655815) >> # Hence to backport XSLoader to work silently with earlier DynaLoaders we >> need >> # to ensure that the variable exists: >> >> It still makes no sense to me that this should happen, given that the print >> isn't in a branch that appears to be getting executed.
> > It's this code in dl_generic_private_init(): > > #ifdef DEBUGGING > { > SV *sv = get_sv("DynaLoader::dl_debug", 0); > dl_debug = sv ? SvIV(sv) : 0; > } > #endif > > Normally *DynaLoader::dl_debug doesn't exist, so sv is null. By > uncommenting the '... if $dl_debug;' line in XSLoader.pm, the glob gets > created at compile time, so $DynaLoader::dl_debug exists but is undef. > Hence the warning. > > So I think this is a red herring. > > > Perhaps another approach concerning this panic: > > panic: free from wrong pool, eea800!=d40c20 during global destruction. > ../dist/threads-shared/t/object2.t ................................. > > would be to analyse it under gdb. When PERL_TRACK_MEMPOOL is defined, > every malloc/free has a header which stores the current my_perl value. > If when later freeing it, header->interpreter != my_perl, then the panic > ensues (i.e. mallocs and free of the same address must occur within the > same interpreter/thread). > > So run the failing process once in gdb, breakpointing on the panic line at > util.c:240, > > Then do a > (gdb) watch -l header->interpreter > and re-run, to see when header is allocated, and when header->interpreter > is set and/or modified. > > Full backtracks at those points might illuminate things a bit. > > >
... ok 120 - Created scalar object in shared hash ok 121 - Scalar object removed from undef shared hash Hardware watchpoint 2: -location header->interpreter Old value = <unreadable> New value = (PerlInterpreter *) 0xd40ae0 Perl_reentrant_init (my_perl=0xd337d0) at reentr.c:210 210 Newx(PL_reentrant_buffer->_spent_buffer, PL_reentrant_buffer->_spent_size, char); (gdb) bt #0 Perl_reentrant_init (my_perl=0xd337d0) at reentr.c:210 #1 0x000000000065bf2f in perl_clone (proto_perl=0xad0c20, flags=2) at sv.c:15118 #2 0x00007ffff2c39c57 in S_ithread_create (parent_perl=0xad0c20, my_pool=0xc776f0, init_function=0xd2f188, stack_size=0, gimme=2, exit_opt=0, params_start=3, num_params=0) at threads.xs:829 #3 0x00007ffff2c3e22a in XS_threads_create (my_perl=0xad0c20, cv=0xc5f370) at threads.xs:1156 #4 0x00000000006bf455 in Perl_pp_goto (my_perl=0xad0c20) at pp_ctl.c:2872 #5 0x0000000000585ded in Perl_runops_debug (my_perl=0xad0c20) at dump.c:2451 #6 0x00000000004681e4 in S_run_body (my_perl=0xad0c20, oldscope=1) at perl.c:2524 #7 0x0000000000467526 in perl_run (my_perl=0xad0c20) at perl.c:2447 #8 0x000000000041c014 in main (argc=4, argv=0x7fffffffd418, env=0x7fffffffd440) at perlmain.c:123 (gdb) c Continuing. [New Thread 0x7ffff25f3700 (LWP 21226)] [Thread 0x7ffff25f3700 (LWP 21226) exited] ok 122 - Scalar object removed from shared scalar ok 123 - remove array object 1 by $#a=N ok 124 - remove array object 2 by $#a=N ok 125 - remove array object 3 by $#a=N ok 126 - remove array object 4 by $#a=N ok 127 - remove array object 1 by pop ok 128 - remove array object 2 by pop ok 129 - remove array object 3 by pop ok 130 - remove array object 4 by pop Thread 1 "perl" hit Hardware watchpoint 2: -location header->interpreter Old value = (PerlInterpreter *) 0xd40ae0 New value = (PerlInterpreter *) 0xd3b578 S_sv_add_arena (my_perl=0xad0c20, ptr=0xd3b3e0 "\240E\261", size=4080, flags=0) at sv.c:443 443 SvREFCNT(sv) = 0; (gdb) bt #0 S_sv_add_arena (my_perl=0xad0c20, ptr=0xd3b3e0 "\240E\261", size=4080, flags=0) at sv.c:443 #1 0x00000000005fde71 in S_more_sv (my_perl=0xad0c20) at sv.c:308 #2 0x000000000063f614 in Perl_sv_newmortal (my_perl=0xad0c20) at sv.c:9248 #3 0x00007ffff2808d15 in XS_threads__shared__tie_STORESIZE (my_perl=0xc7a6b0, cv=0xbc93f8) at shared.xs:1387 #4 0x00000000005f8525 in Perl_pp_entersub (my_perl=0xad0c20) at pp_hot.c:4231 #5 0x0000000000585ded in Perl_runops_debug (my_perl=0xad0c20) at dump.c:2451 #6 0x0000000000469657 in Perl_call_sv (my_perl=0xad0c20, sv=0xd2eae0, flags=4102) at perl.c:2831 #7 0x00000000005a57be in Perl_magic_methcall (my_perl=0xad0c20, sv=0xd2e810, mg=0xd45040, meth=0xd2eae0, flags=4, argc=0) at mg.c:1836 #8 0x00000000005d82af in Perl_av_fill (my_perl=0xad0c20, av=0xd2e810, fill=-1) at av.c:853 #9 0x00000000005d7444 in Perl_av_undef (my_perl=0xad0c20, av=0xd2e810) at av.c:552 #10 0x000000000066f12b in Perl_pp_undef (my_perl=0xad0c20) at pp.c:978 #11 0x0000000000585ded in Perl_runops_debug (my_perl=0xad0c20) at dump.c:2451 #12 0x00000000004681e4 in S_run_body (my_perl=0xad0c20, oldscope=1) at perl.c:2524 #13 0x0000000000467526 in perl_run (my_perl=0xad0c20) at perl.c:2447 #14 0x000000000041c014 in main (argc=4, argv=0x7fffffffd418, env=0x7fffffffd440) at perlmain.c:123 (gdb) c Continuing. ok 131 - remove array object by undef Thread 1 "perl" hit Breakpoint 1, Perl_safesysfree (where=0xd3b3e0) at util.c:349 349 Perl_croak_nocontext("panic: free from wrong pool, %p!=%p", (gdb) bt #0 Perl_safesysfree (where=0xd3b3e0) at util.c:349 #1 0x00000000005ffbca in Perl_sv_free_arenas (my_perl=0xad0c20) at sv.c:743 #2 0x0000000000463d21 in perl_destruct (my_perl=0xad0c20) at perl.c:1380 #3 0x000000000041c095 in main (argc=4, argv=0x7fffffffd418, env=0x7fffffffd440) at perlmain.c:134 (gdb)
Date: Fri, 14 Apr 2017 11:25:31 +0100
CC: perl5-porters [...] perl.org, "perlbug-followup [...] perl.org" <perlbug-followup [...] perl.org>
From: Dave Mitchell <davem [...] iabyn.com>
Subject: Re: [perl #131124] commit 2e6f1ae9c: breaks blead
To: Karl Williamson <public [...] khwilliamson.com>
Download (untitled) / with headers
text/plain 5.2k
On Thu, Apr 13, 2017 at 09:48:09PM -0600, Karl Williamson wrote: Show quoted text
> On 04/13/2017 12:39 PM, Dave Mitchell wrote:
> > Full backtracks at those points might illuminate things a bit.
Show quoted text
> Old value = (PerlInterpreter *) 0xd40ae0 > New value = (PerlInterpreter *) 0xd3b578 > S_sv_add_arena (my_perl=0xad0c20, ptr=0xd3b3e0 "\240E\261", size=4080, > flags=0) at sv.c:443 > 443 SvREFCNT(sv) = 0; > (gdb) bt > #0 S_sv_add_arena (my_perl=0xad0c20, ptr=0xd3b3e0 "\240E\261", size=4080, > flags=0) at sv.c:443 > #1 0x00000000005fde71 in S_more_sv (my_perl=0xad0c20) at sv.c:308 > #2 0x000000000063f614 in Perl_sv_newmortal (my_perl=0xad0c20) at sv.c:9248 > #3 0x00007ffff2808d15 in XS_threads__shared__tie_STORESIZE > (my_perl=0xc7a6b0, cv=0xbc93f8) at shared.xs:1387
Aha, that was the vital info I needed. Turns out the @INC changes were a red-herring. There's a couple of bugs in threads::shared which I've now fixed with the commit below which I've just pushed to blead. The @INC changes in the src code just happened to alter the number of SVs allocated slightly in such a way that it now triggered a new arena alloc at the exact right point in the buggy shared.xs code. commit defb77b559d3c08f94e6db14937a91a4cac8e204 Author: David Mitchell <davem@iabyn.com> AuthorDate: Fri Apr 14 10:51:56 2017 +0100 Commit: David Mitchell <davem@iabyn.com> CommitDate: Fri Apr 14 11:14:44 2017 +0100 threads::shared: alloc arenas with correct context RT #131124 In a couple of places in shared.xs, it calls sv_newmortal() with a perl context different from that currently set by PERL_SET_CONTEXT(). If sv_newmortal() happens to trigger the malloc of a new SV HEAD arena, then under PERL_TRACK_MEMPOOL, this will cause panics when the arena is freed or realloced. Affected files ... M dist/threads-shared/lib/threads/shared.pm M dist/threads-shared/shared.xs M dist/threads-shared/t/object2.t Differences ... diff --git a/dist/threads-shared/lib/threads/shared.pm b/dist/threads-shared/lib/threads/shared.pm index 5a203b0..73c4dd9 100644 --- a/dist/threads-shared/lib/threads/shared.pm +++ b/dist/threads-shared/lib/threads/shared.pm @@ -7,7 +7,7 @@ use warnings; use Scalar::Util qw(reftype refaddr blessed); -our $VERSION = '1.55'; # Please update the pod, too. +our $VERSION = '1.56'; # Please update the pod, too. my $XS_VERSION = $VERSION; $VERSION = eval $VERSION; @@ -195,7 +195,7 @@ threads::shared - Perl extension for sharing data structures between threads =head1 VERSION -This document describes threads::shared version 1.55 +This document describes threads::shared version 1.56 =head1 SYNOPSIS diff --git a/dist/threads-shared/shared.xs b/dist/threads-shared/shared.xs index dab5e36..3c1b5e6 100644 --- a/dist/threads-shared/shared.xs +++ b/dist/threads-shared/shared.xs @@ -1104,8 +1104,9 @@ sharedsv_array_mg_CLEAR(pTHX_ SV *sv, MAGIC *mg) if (!sv) continue; if ( (SvOBJECT(sv) || (SvROK(sv) && (sv = SvRV(sv)))) && SvREFCNT(sv) == 1 ) { - SV *tmp = Perl_sv_newmortal(caller_perl); + SV *tmp; PERL_SET_CONTEXT((aTHX = caller_perl)); + tmp = sv_newmortal(); sv_upgrade(tmp, SVt_RV); get_RV(tmp, sv); PERL_SET_CONTEXT((aTHX = PL_sharedsv_space)); @@ -1384,8 +1385,9 @@ STORESIZE(SV *obj,IV count) if ( (SvOBJECT(sv) || (SvROK(sv) && (sv = SvRV(sv)))) && SvREFCNT(sv) == 1 ) { - SV *tmp = Perl_sv_newmortal(caller_perl); + SV *tmp; PERL_SET_CONTEXT((aTHX = caller_perl)); + tmp = sv_newmortal(); sv_upgrade(tmp, SVt_RV); get_RV(tmp, sv); PERL_SET_CONTEXT((aTHX = PL_sharedsv_space)); diff --git a/dist/threads-shared/t/object2.t b/dist/threads-shared/t/object2.t index 3d795b9..31c3797 100644 --- a/dist/threads-shared/t/object2.t +++ b/dist/threads-shared/t/object2.t @@ -17,7 +17,7 @@ use ExtUtils::testlib; BEGIN { $| = 1; - print("1..131\n"); ### Number of tests that will be run ### + print("1..133\n"); ### Number of tests that will be run ### }; use threads; @@ -445,6 +445,28 @@ ok($destroyed[$ID], 'Scalar object removed from shared scalar'); ::ok($count == $n, "remove array object by undef"); } +# RT #131124 +# Emptying a shared array creates new temp SVs. If there are no spare +# SVs, a new arena is allocated. shared.xs was mallocing a new arena +# with the wrong perl context set, meaning that when the arena was later +# freed, it would "panic: realloc from wrong pool" +# + +{ + threads->new(sub { + my @a :shared; + push @a, bless &threads::shared::share({}) for 1..1000; + undef @a; # this creates lots of temp SVs + })->join; + ok(1, "#131124 undef array doesnt panic"); + + threads->new(sub { + my @a :shared; + push @a, bless &threads::shared::share({}) for 1..1000; + @a = (); # this creates lots of temp SVs + })->join; + ok(1, "#131124 clear array doesnt panic"); +} -- The optimist believes that he lives in the best of all possible worlds. As does the pessimist.
RT-Send-CC: perl5-porters [...] perl.org
Fixed by defb77b559d3c08f94e6db14937a91a4cac8e204 -- Karl Williamson


This service is sponsored and maintained by Best Practical Solutions and runs on Perl.org infrastructure.

For issues related to this RT instance (aka "perlbug"), please contact perlbug-admin at perl.org