Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

commit 2e6f1ae9c: breaks blead #15945

Closed
p5pRT opened this issue Apr 8, 2017 · 24 comments
Closed

commit 2e6f1ae9c: breaks blead #15945

p5pRT opened this issue Apr 8, 2017 · 24 comments

Comments

@p5pRT
Copy link

p5pRT commented Apr 8, 2017

Migrated from rt.perl.org#131124 (status was 'resolved')

Searchable as RT131124$

@p5pRT
Copy link
Author

p5pRT commented Apr 8, 2017

From @khwilliamson

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 2e6f1ae
  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​: 2e59c0a
  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

@p5pRT
Copy link
Author

p5pRT commented Apr 8, 2017

From @jkeenan

On Sat, 08 Apr 2017 04​:43​:13 GMT, public@​khwilliamson.com wrote​:

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 2e6f1ae
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)

@p5pRT
Copy link
Author

p5pRT commented Apr 8, 2017

The RT System itself - Status changed from 'new' to 'open'

@p5pRT
Copy link
Author

p5pRT commented Apr 10, 2017

From @iabyn

On Fri, Apr 07, 2017 at 09​:43​:13PM -0700, karl williamson wrote​:

commit 2e6f1ae
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

@p5pRT
Copy link
Author

p5pRT commented Apr 10, 2017

From @khwilliamson

On 04/10/2017 04​:55 AM, Dave Mitchell wrote​:

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.

@p5pRT
Copy link
Author

p5pRT commented Apr 10, 2017

From @khwilliamson

On 04/10/2017 04​:55 AM, Dave Mitchell wrote​:

On Fri, Apr 07, 2017 at 09​:43​:13PM -0700, karl williamson wrote​:

commit 2e6f1ae
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.

@p5pRT
Copy link
Author

p5pRT commented Apr 10, 2017

From @iabyn

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? 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.

@p5pRT
Copy link
Author

p5pRT commented Apr 11, 2017

From @khwilliamson

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&#8203;:\.\./\.\./t
PERL\_CORE=/home/\.\.\.\.whatever is the top\-level dir of the perl src\.\.\.

Other than that I'm totally bemused.

@p5pRT
Copy link
Author

p5pRT commented Apr 11, 2017

From @khwilliamson

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&#8203;:\.\./\.\./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

@p5pRT
Copy link
Author

p5pRT commented Apr 12, 2017

From @iabyn

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&#8203;:\.\./\.\./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"

@p5pRT
Copy link
Author

p5pRT commented Apr 12, 2017

From @khwilliamson

On 04/12/2017 01​:15 AM, Dave Mitchell wrote​:

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&#8203;:\.\./\.\./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.

@p5pRT
Copy link
Author

p5pRT commented Apr 12, 2017

From @khwilliamson

valgrind.log

@p5pRT
Copy link
Author

p5pRT commented Apr 12, 2017

From @khwilliamson

strace.log

@p5pRT
Copy link
Author

p5pRT commented Apr 12, 2017

From @iabyn

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.

--
Dave's first rule of Opera​:
If something needs saying, say it​: don't warble it.

@p5pRT
Copy link
Author

p5pRT commented Apr 12, 2017

From @khwilliamson

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&#8203;: 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.

@p5pRT
Copy link
Author

p5pRT commented Apr 12, 2017

From @khwilliamson

On 04/12/2017 10​:37 AM, Karl Williamson wrote​:

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&#8203;: 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.

@p5pRT
Copy link
Author

p5pRT commented Apr 13, 2017

From @iabyn

On Wed, Apr 12, 2017 at 04​:58​:43PM -0600, Karl Williamson wrote​:

If I uncomment the line

   print STDERR "BS&#8203;: $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

@p5pRT
Copy link
Author

p5pRT commented Apr 13, 2017

From @khwilliamson

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&#8203;: $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

@p5pRT
Copy link
Author

p5pRT commented Apr 13, 2017

From @khwilliamson

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&#8203;: $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
# (9cf41c4 and its parent 9426adc)
# 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.

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

@p5pRT
Copy link
Author

p5pRT commented Apr 13, 2017

From @iabyn

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&#8203;: $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
# (9cf41c4 and its parent 9426adc)
# 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

@p5pRT
Copy link
Author

p5pRT commented Apr 14, 2017

From @khwilliamson

On 04/13/2017 12​:39 PM, Dave Mitchell wrote​:

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&#8203;: $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
# (9cf41c4 and its parent 9426adc)
# 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)

@p5pRT
Copy link
Author

p5pRT commented Apr 14, 2017

From @iabyn

On Thu, Apr 13, 2017 at 09​:48​:09PM -0600, Karl Williamson wrote​:

On 04/13/2017 12​:39 PM, Dave Mitchell wrote​:

Full backtracks at those points might illuminate things a bit.

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 defb77b
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 ...

Inline Patch
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.

@p5pRT
Copy link
Author

p5pRT commented Apr 14, 2017

From @khwilliamson

Fixed by defb77b
--
Karl Williamson

@p5pRT
Copy link
Author

p5pRT commented Apr 14, 2017

@khwilliamson - Status changed from 'open' to 'resolved'

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant