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

This is the second time I've had this happen in the last week or so. I have a 'regular' postgresql server running, and then test test setup (both llvm ang gcc). It's chewing up 1 core on my MBP, never completing.

502 229 1 0 0:00.50 ?? 0:00.60 /Library/PostgreSQL/8.3/bin/postgres -D /Library/PostgreSQL/8.3/data
502 266 229 0 0:08.32 ?? 0:11.86 postgres: logger process
502 268 229 0 0:24.49 ?? 0:55.88 postgres: writer process
502 269 229 0 0:23.02 ?? 0:36.82 postgres: wal writer process
502 270 229 0 0:06.40 ?? 0:09.12 postgres: autovacuum launcher process
502 271 229 0 0:06.87 ?? 0:07.78 postgres: stats collector process
501 24638 1 0 0:06.74 ?? 0:07.63 /Volumes/High Usage/usr/local/src/build-farm-4.4/builds/HEAD/inst/bin/postgres -D data-C
501 24640 24638 0 0:18.91 ?? 0:43.89 postgres: writer process
501 24641 24638 0 0:17.83 ?? 0:27.99 postgres: wal writer process
501 24642 24638 0 0:09.80 ?? 0:21.99 postgres: autovacuum launcher process
501 24643 24638 0 0:48.59 ?? 0:59.91 postgres: stats collector process
501 24698 24638 0 2116:52.81 ?? 2456:38.81 postgres: Robert pl_regression [local] CREATE FUNCTION

Robert(at)dhcp-brm-bl5-204-2e-east-10-135-77-175:/Volumes/High Usage/usr/local/src/build-farm-4.4/builds/HEAD
% ls -altr
total 24
drwxr-xr-x 9 Robert staff 306B Dec 10 22:31 ../
-rw-r--r-- 1 Robert staff 11B May 31 13:05 polecat.last.success.snap
-rw-r--r-- 1 Robert staff 0B Jun 1 09:18 builder.LCK
-rw-r--r-- 1 Robert staff 11B Jun 1 09:19 polecat.last.status
-rw-r--r-- 1 Robert staff 11B Jun 1 09:19 polecat.last.run.snap
drwxr-xr-x 16 Robert staff 544B Jun 1 09:19 pgsql/
drwxr-xr-x 18 Robert staff 612B Jun 1 09:20 pgsql.2569/
drwxr-xr-x 10 Robert staff 340B Jun 1 09:27 ./
drwxr-xr-x 10 Robert staff 340B Jun 1 09:28 inst/
drwxr-xr-x 16 Robert staff 544B Jun 1 09:28 polecat.lastrun-logs/

Robert(at)dhcp-brm-bl5-204-2e-east-10-135-77-175:/Volumes/High Usage/usr/local/src/build-farm-4.4/builds/HEAD/polecat.lastrun-logs
% ls -altr
total 8760
-rw-r--r-- 1 Robert staff 40B Jun 1 09:19 githead.log
-rw-r--r-- 1 Robert staff 918B Jun 1 09:19 SCM-checkout.log
-rw-r--r-- 1 Robert staff 16K Jun 1 09:20 configure.log
-rw-r--r-- 1 Robert staff 324K Jun 1 09:20 config.log
-rw-r--r-- 1 Robert staff 257K Jun 1 09:25 make.log
-rw-r--r-- 1 Robert staff 1.8M Jun 1 09:26 check.log
-rw-r--r-- 1 Robert staff 50K Jun 1 09:27 make-contrib.log
drwxr-xr-x 10 Robert staff 340B Jun 1 09:27 ../
-rw-r--r-- 1 Robert staff 40K Jun 1 09:27 make-install.log
-rw-r--r-- 1 Robert staff 26K Jun 1 09:27 install-contrib.log
-rw-r--r-- 1 Robert staff 1.3K Jun 1 09:27 initdb-C.log
-rw-r--r-- 1 Robert staff 534B Jun 1 09:27 startdb-C-1.log
-rw-r--r-- 1 Robert staff 1.7M Jun 1 09:27 install-check-C.log
-rw-r--r-- 1 Robert staff 299B Jun 1 09:28 stopdb-C-1.log
-rw-r--r-- 1 Robert staff 534B Jun 1 09:28 startdb-C-2.log

cat startdb-C-2.log
waiting for server to start.... done
server started
=========== db log file ==========
[4de65a8c.603f:1] LOG: database system was shut down at 2011-06-01 09:28:01 MDT
[4de65a8c.6042:1] LOG: autovacuum launcher started
[4de65a8c.603e:1] LOG: database system is ready to accept connections
[4de65a8d.6044:1] LOG: connection received: host=[local]
[4de65a8d.6044:2] LOG: connection authorized: user=Robert database=postgres
[4de65a8d.6044:3] LOG: disconnection: session time: 0:00:00.009 user=Robert database=postgres host=[local]

Robert(at)dhcp-brm-bl5-204-2e-east-10-135-77-175:/Volumes/High Usage/usr/local/src/build-farm-4.4/builds/HEAD/inst
% tail -n 100 !$
tail -n 100 logfile
while (@arrays > 0) {
my $el = shift @arrays;
if (is_array_ref($el)) {
push @arrays, @$el;
} else {
$result .= $el;
}
}
return $result.' '.$array_arg;
$$ LANGUAGE plperl;
[4de65a8f.6076:16] LOG: statement: select plperl_concat('{"NULL","NULL","NULL''"}');
[4de65a8f.6076:17] LOG: statement: select plperl_concat('{{NULL,NULL,NULL}}');
[4de65a8f.6076:18] LOG: statement: select plperl_concat('{"hello"," ","world!"}');
[4de65a8f.6076:19] LOG: statement: CREATE TYPE foo AS (bar INTEGER, baz TEXT);
[4de65a8f.6076:20] LOG: statement: CREATE OR REPLACE FUNCTION plperl_array_of_rows(foo[]) RETURNS TEXT AS $$
my $array_arg = shift;
my $result = "";

for my $row_ref (@$array_arg) {
die "not a hash reference" unless (ref $row_ref eq "HASH");
$result .= $row_ref->{bar}." items of ".$row_ref->{baz}.";";
}
return $result .' '. $array_arg;
$$ LANGUAGE plperl;
[4de65a8f.6076:21] LOG: statement: select plperl_array_of_rows(ARRAY[ ROW(2, 'coffee'), ROW(0, 'sugar')]::foo[]);
[4de65a8f.6076:22] LOG: statement: CREATE TYPE rowfoo AS (bar INTEGER, baz INTEGER[]);
[4de65a8f.6076:23] LOG: statement: CREATE OR REPLACE FUNCTION plperl_sum_row_elements(rowfoo) RETURNS TEXT AS $$
my $row_ref = shift;
my $result;

if (ref $row_ref ne 'HASH') {
$result = 0;
}
else {
$result = $row_ref->{bar};
die "not an array reference".ref ($row_ref->{baz})
unless (is_array_ref($row_ref->{baz}));
# process a single-dimensional array
foreach my $elem (@{$row_ref->{baz}}) {
$result += $elem unless ref $elem;
}
}
return $result;
$$ LANGUAGE plperl;
[4de65a8f.6076:24] LOG: statement: select plperl_sum_row_elements(ROW(1, ARRAY[2,3,4,5,6,7,8,9,10])::rowfoo);
[4de65a8f.6076:25] LOG: statement: CREATE TYPE rowbar AS (foo rowfoo[]);
[4de65a8f.6076:26] LOG: statement: CREATE OR REPLACE FUNCTION plperl_sum_array_of_rows(rowbar) RETURNS TEXT AS $$
my $rowfoo_ref = shift;
my $result = 0;

if (ref $rowfoo_ref eq 'HASH') {
my $row_array_ref = $rowfoo_ref->{foo};
if (is_array_ref($row_array_ref)) {
foreach my $row_ref (@{$row_array_ref}) {
if (ref $row_ref eq 'HASH') {
$result += $row_ref->{bar};
die "not an array reference".ref ($row_ref->{baz})
unless (is_array_ref($row_ref->{baz}));
foreach my $elem (@{$row_ref->{baz}}) {
$result += $elem unless ref $elem;
}
}
else {
die "element baz is not a reference to a rowfoo";
}
}
} else {
die "not a reference to an array of rowfoo elements"
}
} else {
die "not a reference to type rowbar";
}
return $result;
$$ LANGUAGE plperl;
[4de65a8f.6076:27] LOG: statement: select plperl_sum_array_of_rows(ROW(ARRAY[ROW(1, ARRAY[2,3,4,5,6,7,8,9,10])::rowfoo,
ROW(11, ARRAY[12,13,14,15,16,17,18,19,20])::rowfoo])::rowbar);
[4de65a8f.6076:28] LOG: statement: CREATE OR REPLACE FUNCTION plperl_arrays_out(OUT INTEGER[]) AS $$
return [[1,2,3],[4,5,6]];
$$ LANGUAGE plperl;
[4de65a8f.6076:29] LOG: statement: select plperl_arrays_out();
[4de65a8f.6076:30] LOG: statement: CREATE OR REPLACE FUNCTION plperl_arrays_inout(INTEGER[]) returns INTEGER[] AS $$
return shift;
$$ LANGUAGE plperl;
[4de65a8f.6076:31] LOG: statement: select plperl_arrays_inout('{{1}, {2}, {3}}');
[4de65a8f.6076:32] LOG: statement: create or replace function perl_setof_array(integer[]) returns setof integer[] language plperl as $$
my $arr = shift;
for my $r (@$arr) {
return_next $r;
}
return undef;
$$;
[4de65a8f.6076:33] LOG: statement: select perl_setof_array('{{1}, {2}, {3}}');
[4de65a8f.6076:34] LOG: disconnection: session time: 0:00:00.076 user=Robert database=pl_regression host=[local]
[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.

Later,
Rob

--

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

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

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

On Jun 6, 2011, at 7:29 PM, Andrew Dunstan <andrew(at)dunslane(dot)net> wrote:

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

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 ()
#2 0x00000001007bb680 in plperl_init_interp () at plperl.c:781
#3 0x00000001007bc17a in _PG_init () at plperl.c:443
#4 0x0000000100301da6 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 0x00000001003026f5 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 0x0000000100304c10 in fmgr_info_C_lang [inlined] () at /Volumes/High Usage/usr/local/src/build-farm-4.4/builds/HEAD/pgsql.2569/src/backend/utils/fmgr/fmgr.c:349
#7 0x0000000100304c10 in fmgr_info_cxt_security (functionId=41321, finfo=0x7fff5fbfd410, mcxt=<value temporarily unavailable, due to optimizations>, ignore_security=<value temporarily unavailable, due to optimizations>) at fmgr.c:280
#8 0x0000000100305e00 in OidFunctionCall1Coll (functionId=<value temporarily unavailable, due to optimizations>, collation=0, arg1=41426) at fmgr.c:1585
#9 0x000000010009e493 in ProcedureCreate (procedureName=0x101006550 "bar", procNamespace=2200, replace=1 '\001', returnsSet=0 '\0', returnType=23, languageObjectId=41322, languageValidator=41321, prosrc=0x101006748 "\n #die 'BANG!'; # causes server process to exit(2)\n # alternative - causes server process to exit(255)\n spi_exec_query(\"invalid sql statement\");\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:652
#10 0x00000001001046be in CreateFunction (stmt=0x101006a48, queryString=0x101005a38 "CREATE OR REPLACE FUNCTION bar() RETURNS integer AS $$\n #die 'BANG!'; # causes server process to exit(2)\n # alternative - causes server process to exit(255)\n spi_exec_query(\"invalid sql state"...) at functioncmds.c:942
#11 0x000000010023633b in MemoryContextSwitchTo [inlined] () at /Volumes/High Usage/usr/local/src/build-farm-4.4/builds/HEAD/pgsql.2569/src/include/utils/palloc.h:1184
#12 0x000000010023633b in PortalRunUtility (portal=0x101027238, utilityStmt=0x101006a48, isTopLevel=<value temporarily unavailable, due to optimizations>, dest=0x101006df0, completionTag=0x7fff5fbfdea0 "") at pquery.c:1192
#13 0x0000000100237af5 in PortalRunMulti (portal=0x101027238, isTopLevel=<value temporarily unavailable, due to optimizations>, dest=0x101006df0, altdest=0x101006df0, completionTag=0x7fff5fbfdea0 "") at pquery.c:1315
#14 0x00000001002384a8 in PortalRun (portal=0x101027238, count=9223372036854775807, isTopLevel=<value temporarily unavailable, due to optimizations>, dest=0x101006df0, altdest=0x101006df0, completionTag=0x7fff5fbfdea0 "") at pquery.c:813
#15 0x000000010023445d in exec_simple_query (query_string=0x101005a38 "CREATE OR REPLACE FUNCTION bar() RETURNS integer AS $$\n #die 'BANG!'; # causes server process to exit(2)\n # alternative - causes server process to exit(255)\n spi_exec_query(\"invalid sql state"...) at postgres.c:1018
#16 0x0000000100235021 in PostgresMain (argc=2, argv=<value temporarily unavailable, due to optimizations>, username=<value temporarily unavailable, due to optimizations>) at postgres.c:3924
#17 0x00000001001e845c in ServerLoop () at postmaster.c:3600
#18 0x00000001001e93c1 in PostmasterMain (argc=3, argv=0x100800680) at postmaster.c:1115
#19 0x000000010017c4f5 in main (argc=3, argv=0x100800680) at main.c:199
(gdb) quit
The program is running. Quit anyway (and detach it)? (y or n) Detaching from program: `/Volumes/High Usage/usr/local/src/build-farm-4.4/builds/HEAD/inst/bin/postgres', process 24698.
>

Andrew Dunstan <andrew(at)dunslane(dot)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/07/2011 12:35 AM, Tom Lane wrote:
> Andrew Dunstan<andrew(at)dunslane(dot)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(at)dunslane(dot)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(dot)Creager(at)oracle(dot)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(at)gmail(dot)com> writes:
> On Mon, Jun 6, 2011 at 21:16, Robert Creager <Robert(dot)Creager(at)oracle(dot)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(at)dunslane(dot)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(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Alex Hunsaker <badalex(at)gmail(dot)com> writes:
>> On Mon, Jun 6, 2011 at 21:16, Robert Creager <Robert(dot)Creager(at)oracle(dot)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(at)gmail(dot)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(at)sss(dot)pgh(dot)pa(dot)us> wrote:
> Alex Hunsaker <badalex(at)gmail(dot)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(at)gmail(dot)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

On Jun 7, 2011, at 12:42 PM, Alex Hunsaker <badalex(at)gmail(dot)com> wrote:

> On Tue, Jun 7, 2011 at 12:22, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> Alex Hunsaker <badalex(at)gmail(dot)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

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

Copyright 1987-2008, Larry Wall

Perl may be copied only under the terms of either the Artistic License or the
GNU General Public License, which may be found in the Perl 5 source kit.

Complete documentation for Perl, including FAQ lists, should be found on
this system using "man perl" or "perldoc perl". If you have access to the
Internet, point your browser at http://www.perl.org/, the Perl Home Page.

/usr/bin/perl -V
Summary of my perl5 (revision 5 version 10 subversion 0) configuration:
Platform:
osname=darwin, osvers=10.0, archname=darwin-thread-multi-2level
uname='darwin neige.apple.com 10.0 darwin kernel version 10.0.0d8: tue may 5 19:29:59 pdt 2009; root:xnu-1437.2~2release_i386 i386 '
config_args='-ds -e -Dprefix=/usr -Dccflags=-g -pipe -Dldflags= -Dman3ext=3pm -Duseithreads -Duseshrplib -Dinc_version_list=none -Dcc=gcc-4.2'
hint=recommended, useposix=true, d_sigaction=define
useithreads=define, usemultiplicity=define
useperlio=define, d_sfio=undef, uselargefiles=define, usesocks=undef
use64bitint=define, use64bitall=define, uselongdouble=undef
usemymalloc=n, bincompat5005=undef
Compiler:
cc='gcc-4.2', ccflags ='-arch x86_64 -arch i386 -arch ppc -g -pipe -fno-common -DPERL_DARWIN -fno-strict-aliasing -I/usr/local/include',
optimize='-Os',
cppflags='-g -pipe -fno-common -DPERL_DARWIN -fno-strict-aliasing -I/usr/local/include'
ccversion='', gccversion='4.2.1 (Apple Inc. build 5646)', gccosandvers=''
intsize=4, longsize=8, ptrsize=8, doublesize=8, byteorder=12345678
d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=16
ivtype='long', ivsize=8, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8
alignbytes=8, prototype=define
Linker and Libraries:
ld='gcc-4.2 -mmacosx-version-min=10.6', ldflags ='-arch x86_64 -arch i386 -arch ppc -L/usr/local/lib'
libpth=/usr/local/lib /usr/lib
libs=-ldbm -ldl -lm -lutil -lc
perllibs=-ldl -lm -lutil -lc
libc=/usr/lib/libc.dylib, so=dylib, useshrplib=true, libperl=libperl.dylib
gnulibc_version=''
Dynamic Linking:
dlsrc=dl_dlopen.xs, dlext=bundle, d_dlsymun=undef, ccdlflags=' '
cccdlflags=' ', lddlflags='-arch x86_64 -arch i386 -arch ppc -bundle -undefined dynamic_lookup -L/usr/local/lib'

Characteristics of this binary (from libperl):
Compile-time options: MULTIPLICITY PERL_DONT_CREATE_GVSV
PERL_IMPLICIT_CONTEXT PERL_MALLOC_WRAP USE_64_BIT_ALL
USE_64_BIT_INT USE_ITHREADS USE_LARGE_FILES
USE_PERLIO USE_REENTRANT_API
Locally applied patches:
/Library/Perl/Updates/<version> comes before system perl directories
installprivlib and installarchlib points to the Updates directory
Built under darwin
Compiled at Jun 24 2009 00:35:27
@INC:
/Library/Perl/Updates/5.10.0/darwin-thread-multi-2level
/Library/Perl/Updates/5.10.0
/System/Library/Perl/5.10.0/darwin-thread-multi-2level
/System/Library/Perl/5.10.0
/Library/Perl/5.10.0/darwin-thread-multi-2level
/Library/Perl/5.10.0
/Network/Library/Perl/5.10.0/darwin-thread-multi-2level
/Network/Library/Perl/5.10.0
/Network/Library/Perl
/System/Library/Perl/Extras/5.10.0/darwin-thread-multi-2level
/System/Library/Perl/Extras/5.10.0
.

Robert Creager <Robert(dot)Creager(at)Oracle(dot)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(at)gmail(dot)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(at)commandprompt(dot)com>
The PostgreSQL Company - Command Prompt, Inc.
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

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

> Robert Creager <Robert(dot)Creager(at)Oracle(dot)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 <Robert(dot)Creager(at)Oracle(dot)com> writes:
> On Jun 7, 2011, at 3:01 PM, Tom Lane wrote:
>> Robert Creager <Robert(dot)Creager(at)Oracle(dot)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 11:32 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>
> 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 ...
>

I've renamed /opt/local so it's not picked up, and change HEAD to build every 6 hours. Won't prove it doesn't happen though... If it appears to work for a bit, I can move /opt/local back and see what happens.

I'll see about setting up my iMac at home for the build farm for another Apple machine.

Anything you'd like to change, or run, or something else?

Later,
Rob

On Tue, Jun 7, 2011 at 12:42, Alex Hunsaker <badalex(at)gmail(dot)com> wrote:
> On Tue, Jun 7, 2011 at 12:22, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>> Alex Hunsaker <badalex(at)gmail(dot)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.

On Jun 8, 2011, at 9:13 AM, Robert Creager wrote:

> I've renamed /opt/local so it's not picked up, and change HEAD to build every 6 hours. Won't prove it doesn't happen though... If it appears to work for a bit, I can move /opt/local back and see what happens.

Gack. ccache is in /opt/local/bin... I've reverted for now, keep the 6 hour force build, and will re-work my config and put ccache somewhere else.

Sigh,
Rob
--

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

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

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) returns void 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=<value temporarily 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

--