Thread: Re: [Pgbuildfarm-members] CREATE FUNCTION hang on test machine polecat on HEAD

On 06/06/2011 07:30 PM, Robert Creager wrote:
> [4de65a8f.607a:1] LOG:  connection received: host=[local]
> [4de65a8f.607a:2] LOG:  connection authorized: user=Robert database=pl_regression
> [4de65a8f.607a:3] LOG:  statement: CREATE OR REPLACE FUNCTION bar() RETURNS integer AS $$
>         #die 'BANG!'; # causes server process to exit(2)
>         # alternative - causes server process to exit(255)
>         spi_exec_query("invalid sql statement");
>     $$ language plperl;
>
> I'll leave it running tonight (going home), so I can poke tomorrow if anyone wants me to.
>
>

That's weird. Why it should hang there I have no idea. Did it hang at 
the same spot both times? Can you get a backtrace?

cheers

andrew

Andrew Dunstan <andrew@dunslane.net> writes:
> On 06/06/2011 07:30 PM, Robert Creager wrote:
>> [4de65a8f.607a:3] LOG:  statement: CREATE OR REPLACE FUNCTION bar() RETURNS integer AS $$
>> #die 'BANG!'; # causes server process to exit(2)
>> # alternative - causes server process to exit(255)
>> spi_exec_query("invalid sql statement");
>> $$ language plperl;
>> 
>> I'll leave it running tonight (going home), so I can poke tomorrow if anyone wants me to.

> That's weird. Why it should hang there I have no idea. Did it hang at 
> the same spot both times? Can you get a backtrace?

You sure it's hung on that statement, and not the following one?
The following one would be trying to load plperlu into a backend
already using plperl, which is an area that it wouldn't exactly
be surprising to find platform-dependent issues in.
        regards, tom lane

On 06/06/2011 07:30 PM, Robert Creager wrote:

[4de65a8f.607a:1] LOG:  connection received: host=[local]

[4de65a8f.607a:2] LOG:  connection authorized: user=Robert database=pl_regression

[4de65a8f.607a:3] LOG:  statement: CREATE OR REPLACE FUNCTION bar() RETURNS integer AS $$

       #die 'BANG!'; # causes server process to exit(2)

       # alternative - causes server process to exit(255)

       spi_exec_query("invalid sql statement");

   $$ language plperl;

I'll leave it running tonight (going home), so I can poke tomorrow if anyone wants me to.

That's weird. Why it should hang there I have no idea. Did it hang at the same spot both times? Can you get a backtrace?

On 06/07/2011 12:35 AM, Tom Lane wrote:
> Andrew Dunstan<andrew@dunslane.net>  writes:
>> On 06/06/2011 07:30 PM, Robert Creager wrote:
>>> [4de65a8f.607a:3] LOG:  statement: CREATE OR REPLACE FUNCTION bar() RETURNS integer AS $$
>>> #die 'BANG!'; # causes server process to exit(2)
>>> # alternative - causes server process to exit(255)
>>> spi_exec_query("invalid sql statement");
>>> $$ language plperl;
>>>
>>> I'll leave it running tonight (going home), so I can poke tomorrow if anyone wants me to.
>> That's weird. Why it should hang there I have no idea. Did it hang at
>> the same spot both times? Can you get a backtrace?
> You sure it's hung on that statement, and not the following one?
> The following one would be trying to load plperlu into a backend
> already using plperl, which is an area that it wouldn't exactly
> be surprising to find platform-dependent issues in.
>
>             

That's true, but he has log_statement = all, so the statement should be 
logged before it's executed. And the stack trace he's sent shows that's 
the statement being executed.

It seems to be hung in Perl_get_hash_seed().

cheers

andrew

Andrew Dunstan <andrew@dunslane.net> writes:
> On 06/07/2011 12:35 AM, Tom Lane wrote:
>> You sure it's hung on that statement, and not the following one?
>> The following one would be trying to load plperlu into a backend
>> already using plperl, which is an area that it wouldn't exactly
>> be surprising to find platform-dependent issues in.

> That's true, but he has log_statement = all, so the statement should be 
> logged before it's executed. And the stack trace he's sent shows that's 
> the statement being executed.

Yeah, the stack trace destroyed that theory.

> It seems to be hung in Perl_get_hash_seed().

Which is not our code, of course.  Who wants to dig into perl guts?
        regards, tom lane

On Mon, Jun 6, 2011 at 21:16, Robert Creager <Robert.Creager@oracle.com> wrote:

> That's weird. Why it should hang there I have no idea. Did it hang at the
> same spot both times? Can you get a backtrace?
>
> I think so, but I didn't pay much attention :-(
> GNU gdb 6.3.50-20050815 (Apple version gdb-1518) (Sat Feb 12 02:52:12 UTC
> 2011)
> Copyright 2004 Free Software Foundation, Inc.
> GDB is free software, covered by the GNU General Public License, and you are
> welcome to change it and/or distribute copies of it under certain
> conditions.
> Type "show copying" to see the conditions.
> There is absolutely no warranty for GDB.  Type "show warranty" for details.
> This GDB was configured as "x86_64-apple-darwin"...Reading symbols for
> shared libraries ...... done
>
> Attaching to program: `/Volumes/High
> Usage/usr/local/src/build-farm-4.4/builds/HEAD/inst/bin/postgres', process
> 24698.
> Reading symbols for shared libraries .+++++......... done
> 0x0000000100a505e4 in Perl_get_hash_seed ()
> (gdb) bt
> #0  0x0000000100a505e4 in Perl_get_hash_seed ()
> #1  0x0000000100a69b94 in perl_parse ()

Perl_get_hash_seed is basically:

Perl_get_hash_seed {   char *s = getenv("PERL_HASH_SEED");   unsigned long myseed = 0;   if(s) {     ....     myseed =
atoul(s);  }   srand(Perl_seed());   myseed = rand() *  UV_MAX;   return myseed; 
}

U32 Perl_seed()
{   U32 u;   struct timeval when;   ...   open(fd, "/dev/urandom"...)   read(fd, &u, sizeof(u));   gettimeofday(&when,
NULL);  u = when[0] + SEED_C2 * when[1];   u += getpid();   u += PTR2UV(PL_stack_sp);   return u; 
}

I don't suppose /dev/urandom blocks on OS X?  Granted, I may have
missed something in translation with the macro fest that is perl...

On 06/07/2011 01:18 PM, Alex Hunsaker wrote:
>
> I don't suppose /dev/urandom blocks on OS X?  Granted, I may have
> missed something in translation with the macro fest that is perl...


I wondered if we were possibly exhausting some entropy pool. It seems 
like this would be just such a bad bug that it would be amazing if we 
were the first to trip up on it. But I guess you never know.

cheers

andrew

On Tuesday, June 07, 2011 19:40:21 Andrew Dunstan wrote:
> On 06/07/2011 01:18 PM, Alex Hunsaker wrote:
> > I don't suppose /dev/urandom blocks on OS X?  Granted, I may have
> > missed something in translation with the macro fest that is perl...
> 
> I wondered if we were possibly exhausting some entropy pool. It seems
> like this would be just such a bad bug that it would be amazing if we
> were the first to trip up on it. But I guess you never know.
Shouldn't the backtrace show a syscall in that case?

I guess one would need a debug perl build + single stepping for a more 
convincing answer...

Andres

Alex Hunsaker <badalex@gmail.com> writes:
> On Mon, Jun 6, 2011 at 21:16, Robert Creager <Robert.Creager@oracle.com> wrote:
>> (gdb) bt
>> #0  0x0000000100a505e4 in Perl_get_hash_seed ()
>> #1  0x0000000100a69b94 in perl_parse ()

> I don't suppose /dev/urandom blocks on OS X?

The man page for it avers not, and besides it's hard to believe that
there wouldn't be a libc routine or two on the stack if we were blocked
in a kernel call, and also Robert showed that the process was consuming
CPU time, so it's not blocked.  Tis puzzling if there's no loop in the
function.
        regards, tom lane

On Tue, Jun 7, 2011 at 5:40 PM, Andrew Dunstan <andrew@dunslane.net> wrote:
>
>
> On 06/07/2011 01:18 PM, Alex Hunsaker wrote:
>>
>> I don't suppose /dev/urandom blocks on OS X?  Granted, I may have
>> missed something in translation with the macro fest that is perl...
>
>
> I wondered if we were possibly exhausting some entropy pool. It seems like
> this would be just such a bad bug that it would be amazing if we were the
> first to trip up on it. But I guess you never know.

/dev/urandom is the one that's supposed to be "unblocking" (that's
what the "u" is for).

Supposedly, /dev/random and /dev/urandom behave identically on OS-X,
using Yarrow for RNG.  It shouldn't be blocking.

http://developer.apple.com/library/mac/#documentation/Darwin/Reference/ManPages/man4/urandom.4.html
--
When confronted by a difficult problem, solve it by reducing it to the
question, "How would the Lone Ranger handle this?"

On Tue, Jun 7, 2011 at 11:48, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Alex Hunsaker <badalex@gmail.com> writes:
>> On Mon, Jun 6, 2011 at 21:16, Robert Creager <Robert.Creager@oracle.com> wrote:
>>> (gdb) bt
>>> #0  0x0000000100a505e4 in Perl_get_hash_seed ()
>>> #1  0x0000000100a69b94 in perl_parse ()
>
>> I don't suppose /dev/urandom blocks on OS X?
>
> The man page for it avers not, and besides it's hard to believe that
> there wouldn't be a libc routine or two on the stack if we were blocked
> in a kernel call,

Yeah.

> and also Robert showed that the process was consuming
> CPU time, so it's not blocked.  Tis puzzling if there's no loop in the
> function.

Well there is one, I snipped it out for brevity (I don't see how it
could be at fault):

const char *s = PerlEnv_getenv("PERL_HASH_SEED");
if (s)  while (isSPACE(*s))    s++;
if (s && isDIGIT(*s))   myseed = (UV)Atoul(s);
else
{ srand(Perl_seed()); myseed = rand() *UV_MAX;  ....
}

Im looking at the "raw" perl 5.10.0 source... I wonder if apple is
shipping a modified version?

Alex Hunsaker <badalex@gmail.com> writes:
> Im looking at the "raw" perl 5.10.0 source... I wonder if apple is
> shipping a modified version?

You could find out by digging around at
http://www.opensource.apple.com/
polecat appears to be running OSX 10.6.7, so this is what you want:
http://www.opensource.apple.com/tarballs/perl/perl-63.tar.gz

Another question worth asking here is whether PG is picking up perl
5.10.0 or 5.8.9, both of which are shipped in this OSX release.
        regards, tom lane

On Tue, Jun 7, 2011 at 12:22, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Alex Hunsaker <badalex@gmail.com> writes:
>> Im looking at the "raw" perl 5.10.0 source... I wonder if apple is
>> shipping a modified version?
>
> You could find out by digging around at
> http://www.opensource.apple.com/
> polecat appears to be running OSX 10.6.7, so this is what you want:
> http://www.opensource.apple.com/tarballs/perl/perl-63.tar.gz

Thanks!

> Another question worth asking here is whether PG is picking up perl
> 5.10.0 or 5.8.9, both of which are shipped in this OSX release.

I was looking at
http://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=polecat&dt=2011-06-07%2015%3A23%3A34&stg=config
which seems to point at 5.10.0.

Robert: perl -V might be useful

On 06/07/2011 02:22 PM, Tom Lane wrote:
> Alex Hunsaker<badalex@gmail.com>  writes:
>> Im looking at the "raw" perl 5.10.0 source... I wonder if apple is
>> shipping a modified version?
> You could find out by digging around at
> http://www.opensource.apple.com/
> polecat appears to be running OSX 10.6.7, so this is what you want:
> http://www.opensource.apple.com/tarballs/perl/perl-63.tar.gz
>
> Another question worth asking here is whether PG is picking up perl
> 5.10.0 or 5.8.9, both of which are shipped in this OSX release.

configure: using perl 5.10.0

cheers

andrew

Robert Creager <Robert.Creager@Oracle.com> writes:
>>> Another question worth asking here is whether PG is picking up perl
>>> 5.10.0 or 5.8.9, both of which are shipped in this OSX release.

> Hmm...  This might be a problem:

> which perl
> /opt/local/bin/perl

> type -a perl
> /opt/local/bin/perl
> /usr/bin/perl

> /opt/local/bin/perl -V
> This is perl, v5.8.9 built for darwin-2level

The configure log mentioned upthread says it's finding /usr/bin/perl,
so apparently the buildfarm is running with a different PATH than you're
using here.  But that log also shows

configure:7158: checking for flags to link embedded Perl
configure:7174: result:  -L/usr/local/lib  -L/System/Library/Perl/5.10.0/darwin-thread-multi-2level/CORE -lperl -ldl
-lm-lutil -lc
 

If there's anything perl-related in /usr/local/lib (not /opt/local/lib),
that could be confusing matters.
        regards, tom lane

Excerpts from Tom Lane's message of mar jun 07 14:22:13 -0400 2011:
> Alex Hunsaker <badalex@gmail.com> writes:
> > Im looking at the "raw" perl 5.10.0 source... I wonder if apple is
> > shipping a modified version?
> 
> You could find out by digging around at
> http://www.opensource.apple.com/
> polecat appears to be running OSX 10.6.7, so this is what you want:
> http://www.opensource.apple.com/tarballs/perl/perl-63.tar.gz
> 
> Another question worth asking here is whether PG is picking up perl
> 5.10.0 or 5.8.9, both of which are shipped in this OSX release.

Another question is whether this environment variable is set at all.

-- 
Álvaro Herrera <alvherre@commandprompt.com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

Robert Creager <Robert.Creager@Oracle.com> writes:
> On Jun 7, 2011, at 3:01 PM, Tom Lane wrote:
>> Robert Creager <Robert.Creager@Oracle.com> writes:
>> configure:7158: checking for flags to link embedded Perl
>> configure:7174: result:  -L/usr/local/lib  -L/System/Library/Perl/5.10.0/darwin-thread-multi-2level/CORE -lperl -ldl
-lm-lutil -lc
 
>> 
>> If there's anything perl-related in /usr/local/lib (not /opt/local/lib),
>> that could be confusing matters.

> That's what I get for doing this in a meeting, doing both poorly.
> run_build.pl:
> #!/usr/bin/perl

> No perl in /usr/local/lib.

Hrmph.  FWIW, I see the same configure results on my own Macbook Pro:

configure:7158: checking for flags to link embedded Perl
configure:7174: result:  -L/usr/local/lib  -L/System/Library/Perl/5.10.0/darwin-thread-multi-2level/CORE -lperl -ldl
-lm-lutil -lc
 

But I tried "make installcheck" in plperl quite a few times with no
problems.  (And yes, I tried some assorted settings of PERL_HASH_SEED,
as well as none at all.)

At this point I'm thinking that the perl you've got in /opt/local must
be bollixing the works somehow, though it's not clear how.  It's also
really strange that it evidently only fails some of the time ...
        regards, tom lane

On Jun 7, 2011, at 3:01 PM, Tom Lane wrote:

> Robert Creager <Robert.Creager@Oracle.com> writes:
>
> The configure log mentioned upthread says it's finding /usr/bin/perl,
> so apparently the buildfarm is running with a different PATH than you're
> using here.  But that log also shows
>
> configure:7158: checking for flags to link embedded Perl
> configure:7174: result:  -L/usr/local/lib  -L/System/Library/Perl/5.10.0/darwin-thread-multi-2level/CORE -lperl -ldl
-lm-lutil -lc 
>
> If there's anything perl-related in /usr/local/lib (not /opt/local/lib),
> that could be confusing matters.

That's what I get for doing this in a meeting, doing both poorly.
run_build.pl:
#!/usr/bin/perl

No perl in /usr/local/lib.

Rob
--


Robert Creager, Principal Software Engineer
Oracle Server Technologies
500 Eldorado Blvd, Bldg 5
Broomfield, CO, 80021
Phone: 303-272-6830
Email: Robert.Creager@Oracle.com

Oracle is committed to developing practices and products that help protect the environment

On Tue, Jun 7, 2011 at 12:42, Alex Hunsaker <badalex@gmail.com> wrote:
> On Tue, Jun 7, 2011 at 12:22, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Alex Hunsaker <badalex@gmail.com> writes:
>>> Im looking at the "raw" perl 5.10.0 source... I wonder if apple is
>>> shipping a modified version?
>>
>> You could find out by digging around at
>> http://www.opensource.apple.com/
>> polecat appears to be running OSX 10.6.7, so this is what you want:
>> http://www.opensource.apple.com/tarballs/perl/perl-63.tar.gz
>
> Thanks!

Hrm they don't seem to touch util.c where PL_get_hash_seed lives at
all :-(. I also looked at 5.8.9 and Perl_get_hash_seed looks the same
as in 5.10.0.

But I tried "make installcheck" in plperl quite a few times with no
problems.  (And yes, I tried some assorted settings of PERL_HASH_SEED,
as well as none at all.)

At this point I'm thinking that the perl you've got in /opt/local must
be bollixing the works somehow, though it's not clear how.  It's also
really strange that it evidently only fails some of the time ...

Got another one (no env since the last changes).  I'll try and run the "kept" install from when I killed 22853 (had to
use-9) to see if it reproduces the problem with the same binaries.  Is there interest in me removing the perl in
/opt/local/bin/perl? I can install ccache elsewhere and rename that directory. 

  502   310     1   0   0:00.09 ??         0:00.14 /Library/PostgreSQL/8.3/bin/postgres -D /Library/PostgreSQL/8.3/data
  502   313   310   0   0:00.36 ??         0:00.51 postgres: logger process

                                                                                                                        
  502   315   310   0   0:01.10 ??         0:02.43 postgres: writer process



  502   316   310   0   0:01.03 ??         0:01.62 postgres: wal writer process

                                                                                                                        
  502   317   310   0   0:00.28 ??         0:00.40 postgres: autovacuum launcher process

                                                                                                                        
  502   318   310   0   0:00.29 ??         0:00.33 postgres: stats collector process



  501 22813     1   0   0:00.29 ??         0:00.38 /Volumes/High
Usage/usr/local/src/build-farm-4.4/builds/HEAD/inst/bin/postgres-D data-C 
  501 22815 22813   0   0:00.57 ??         0:01.31 postgres: writer process
  501 22816 22813   0   0:00.53 ??         0:00.85 postgres: wal writer process
  501 22817 22813   0   0:00.28 ??         0:00.65 postgres: autovacuum launcher process
  501 22818 22813   0   0:01.19 ??         0:01.47 postgres: stats collector process
  501 22853 22813   0  78:13.79 ??        89:26.32 postgres: Robert pl_regression [local] CREATE FUNCTION

Robert:/usr/local/src/build-farm-4.4/builds/HEAD
% gdb inst/bin/postgres 22853
GNU gdb 6.3.50-20050815 (Apple version gdb-1518) (Sat Feb 12 02:52:12 UTC 2011)
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB.  Type "show warranty" for details.
This GDB was configured as "x86_64-apple-darwin"...Reading symbols for shared libraries ...... done
/Volumes/High Usage/usr/local/src/build-farm-4.4/builds/HEAD/22853: No such file or directory

Attaching to program: `/Volumes/High Usage/usr/local/src/build-farm-4.4/builds/HEAD/inst/bin/postgres', process 22853.
Reading symbols for shared libraries .+++++......... done
0x0000000100a505e4 in Perl_get_hash_seed ()
(gdb) bt
#0  0x0000000100a505e4 in Perl_get_hash_seed ()
#1  0x0000000100a69b94 in perl_parse ()
#2  0x00000001007c0680 in plperl_init_interp () at plperl.c:781
#3  0x00000001007c117a in _PG_init () at plperl.c:443
#4  0x0000000100304396 in internal_load_library (libname=0x10100d540 "/Volumes/High
Usage/usr/local/src/build-farm-4.4/builds/HEAD/inst/lib/postgresql/plperl.so")at dfmgr.c:284 
#5  0x0000000100304ce5 in load_external_function (filename=<value temporarily unavailable, due to optimizations>,
funcname=0x10100d508"plperl_validator", signalNotFound=1 '\001', filehandle=0x7fff5fbfd3b8) at dfmgr.c:113 
#6  0x0000000100307200 in fmgr_info_C_lang [inlined] () at /Volumes/High
Usage/usr/local/src/build-farm-4.4/builds/HEAD/pgsql.4091/src/backend/utils/fmgr/fmgr.c:349
#7  0x0000000100307200 in fmgr_info_cxt_security (functionId=41362, finfo=0x7fff5fbfd410, mcxt=<value temporarily
unavailable,due to optimizations>, ignore_security=<value temporarily unavailable, due to optimizations>) at fmgr.c:280 
#8  0x00000001003083f0 in OidFunctionCall1Coll (functionId=<value temporarily unavailable, due to optimizations>,
collation=0,arg1=41430) at fmgr.c:1585 
#9  0x000000010009f58d in ProcedureCreate (procedureName=0x1010064d0 "perl_elog", procNamespace=2200, replace=1 '\001',
returnsSet=0'\0', returnType=2278, languageObjectId=41363, languageValidator=41362, prosrc=0x101006958 "\n\n  my $msg =
shift;\n elog(NOTICE,$msg);\n\n", probin=0x0, isAgg=0 '\0', isWindowFunc=0 '\0', security_definer=0 '\0', isStrict=0
'\0',volatility=118 'v', parameterTypes=0x10100d7d8, allParameterTypes=0, parameterModes=0, parameterNames=0,
parameterDefaults=0x0,proconfig=0, procost=100, prorows=0) at pg_proc.c:653 
#10 0x0000000100105aae in CreateFunction (stmt=0x101006ab8, queryString=0x101005a38 "create or replace function
perl_elog(text)returns void language plperl as $$\n\n  my $msg = shift;\n  elog(NOTICE,$msg);\n\n$$;") at
functioncmds.c:942
#11 0x000000010023839b in MemoryContextSwitchTo [inlined] () at /Volumes/High
Usage/usr/local/src/build-farm-4.4/builds/HEAD/pgsql.4091/src/include/utils/palloc.h:1184
#12 0x000000010023839b in PortalRunUtility (portal=0x101027238, utilityStmt=0x101006ab8, isTopLevel=<value temporarily
unavailable,due to optimizations>, dest=0x101006e60, completionTag=0x7fff5fbfdea0 "") at pquery.c:1192 
#13 0x0000000100239b55 in PortalRunMulti (portal=0x101027238, isTopLevel=<value temporarily unavailable, due to
optimizations>,dest=0x101006e60, altdest=0x101006e60, completionTag=0x7fff5fbfdea0 "") at pquery.c:1315 
#14 0x000000010023a508 in PortalRun (portal=0x101027238, count=9223372036854775807, isTopLevel=<value temporarily
unavailable,due to optimizations>, dest=0x101006e60, altdest=0x101006e60, completionTag=0x7fff5fbfdea0 "") at
pquery.c:813
#15 0x00000001002364bd in exec_simple_query (query_string=0x101005a38 "create or replace function perl_elog(text)
returnsvoid language plperl as $$\n\n  my $msg = shift;\n  elog(NOTICE,$msg);\n\n$$;") at postgres.c:1018 
#16 0x0000000100237081 in PostgresMain (argc=2, argv=<value temporarily unavailable, due to optimizations>,
username=<valuetemporarily unavailable, due to optimizations>) at postgres.c:3924 
#17 0x00000001001e9bbc in ServerLoop () at postmaster.c:3605
#18 0x00000001001eab37 in PostmasterMain (argc=3, argv=0x100800680) at postmaster.c:1120
#19 0x000000010017db45 in main (argc=3, argv=0x100800680) at main.c:199

--


Robert Creager, Principal Software Engineer
Oracle Server Technologies
500 Eldorado Blvd, Bldg 5
Broomfield, CO, 80021
Phone: 303-272-6830
Email: Robert.Creager@Oracle.com

Oracle is committed to developing practices and products that help protect the environment