[Pljava-dev] pljava hangs while running Java examples (anything to do with gc?)

Hi, guys,

Hope you can help me with this.

Installed pljava and when I try to run the examples - I get them to
run OK - I see the results and everything. There is a problem however.

I did play with 'select javatest.executeselect('whatever')' function
which retrieves about 400 rows each time it executes - no problems
there.

What I've noticed, however is that the following sequence hangs the
current backend process:

select javatest.executeselect('select * from ori.staff_v') -- OK,
returns about 400 rows
select javatest.executeselect('select * from ri.staff_v') -- note the
missing 'o' - forces sql exception
select javatest.executeselect('select * from ori.staff_v') -- HANGS -
never returns and I am forced to shut down pgAdmin and when run 'ps
-aux' I am getting this (note the last process as indicated with
'**'):

----------------------------------------------------------------------------------------
postgres 32189 0.0 0.5 18192 3044 pts/0 S 17:35 0:00
/usr/local/pg81/bin/postmaster -D /usr/local/pg81/data -i
postgres 32192 0.0 0.5 18192 3068 pts/0 S 17:35 0:00
postgres: writer process
postgres 32193 0.0 0.4 8980 2104 pts/0 S 17:35 0:00
postgres: stats buffer process
postgres 32194 0.0 0.4 8104 2228 pts/0 S 17:35 0:00
postgres: stats collector process
postgres 32196 0.0 1.1 19056 5836 pts/0 S 17:36 0:00
postgres: postgres postgres 10.14.139.148(4504) idle
postgres 32197 0.0 1.9 19612 10052 pts/0 S 17:36 0:00
postgres: postgres test 10.14.139.148(4505) idle
**postgres 32198 0.1 6.5 942056 33804 pts/0 S 17:36 0:01
postgres: postgres test 10.14.139.148(4506) SELECT
------------------------------------------------------------------------------------

After that I can't even shutdown postgres (only through the -immediate
option) - it is obviously waiting the last process to complete (and it
never does).

Something else which may be of help. When I run a group of queries at
random or use different functions from the javatest schema sometimes I
get pljava hanging (it is very unpredictable and intermittent) and
twice I managed to get an output from java GC (something like
"[DefNew: 8128K->309K(9088K), 0.0126900 secs] 8128K->309K(130112K),
0.0129060 secs") as a result of the query I was running before pljava
hangs (strange, I know).

I think something is happening when java GC kicks in. Anyway, the
first sequence of events *always* hangs at the 3rd step, so I am able
to successfully reproduce the error/bug whatever that is.

Now, to aide future help and advice I switched all output from
postgres to debug5 so here is the result (my system is Redhat Linux 8,
PG 8.1, Java 1.5.0_01 with 512MB ram and 512MB swap file). My notes
are marked with *** at the beginning of each line, so that you know
what is happening:

-----postgresql.conf - pljava options------------
dynamic_library_path = '$libdir:/usr/local/pg81/data/javalib'
custom_variable_classes = 'pljava'
pljava.vmoptions = '-Xms128M -Xmx512M
-Xloggc:/usr/local/pg81/data/javagc.log -XX:+PrintGCDetails
-XX:MaxPermSize=256m'
# I did try the option below but it didn't work
#pljava.vmoptions = '-Xms64M'
pljava.classpath = '/usr/local/pg81/data/javalib/pljava.jar'
-------------------------------------------------------------

-- postgresql log file - it is quite LONG-------
*** run pgAdmin and execute: 'select javatest.executeselect('select *
from ori.staff_v order by 1 asc') -- statement executed successfully
(1st time)
2005-12-21 17:36:39 GMT 32189 DEBUG: 00000: forked new backend,
pid=32198 socket=6
2005-12-21 17:36:39 GMT 32189 LOCATION: BackendStartup, postmaster.c:2519
2005-12-21 17:36:39 GMT 32198 /usr/local/pg81/bin/postmaster
2005-12-21 17:36:39 GMTLOG: 00000: connection received:
host=10.14.139.148 port=4506
2005-12-21 17:36:39 GMT 32198 /usr/local/pg81/bin/postmaster
2005-12-21 17:36:39 GMTLOCATION: BackendRun, postmaster.c:2698
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTDEBUG: 00000: received password packet
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTLOCATION: recv_password_packet, auth.c:736
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTLOG: 00000: connection authorized: user=postgres database=test
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTLOCATION: BackendRun, postmaster.c:2768
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTDEBUG: 00000: postmaster child[32198]: starting with (
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTLOCATION: BackendRun, postmaster.c:2846
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTDEBUG: 00000: postgres
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTLOCATION: BackendRun, postmaster.c:2849
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTDEBUG: 00000: -v196608
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTLOCATION: BackendRun, postmaster.c:2849
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTDEBUG: 00000: -p
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTLOCATION: BackendRun, postmaster.c:2849
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTDEBUG: 00000: test
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTLOCATION: BackendRun, postmaster.c:2849
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTDEBUG: 00000: )
2005-12-21 17:36:39 GMT 32198 authentication 2005-12-21 17:36:39
GMTLOCATION: BackendRun, postmaster.c:2851
2005-12-21 17:36:39 GMT 32198 startup 2005-12-21 17:36:39 GMTDEBUG:
00000: InitPostgres
2005-12-21 17:36:39 GMT 32198 startup 2005-12-21 17:36:39 GMTLOCATION:
PostgresMain, postgres.c:2895
2005-12-21 17:36:39 GMT 32198 startup 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransaction
2005-12-21 17:36:39 GMT 32198 startup 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:36:39 GMT 32198 startup 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 10513/1/0, nestlvl: 1, children: <>
2005-12-21 17:36:39 GMT 32198 startup 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:36:39 GMT 32198 startup 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransaction
2005-12-21 17:36:39 GMT 32198 startup 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:36:39 GMT 32198 startup 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: STARTED; state: INPROGR,
xid/subid/cid: 10513/1/0, nestlvl: 1, children: <>
2005-12-21 17:36:39 GMT 32198 startup 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransactionCommand
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
start_xact_command, postgres.c:1932
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS
encoding, datlastsysoid
FROM pg_database WHERE oid = 16391
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransaction
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS
encoding, datlastsysoid
FROM pg_database WHERE oid = 16391
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 10514/1/0, nestlvl: 1, children: <>
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS
encoding, datlastsysoid
FROM pg_database WHERE oid = 16391
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTDEBUG:
00000: ProcessUtility
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTLOCATION:
PortalRunUtility, pquery.c:952
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTSTATEMENT:
SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS
encoding, datlastsysoid
FROM pg_database WHERE oid = 16391
2005-12-21 17:36:39 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransactionCommand
2005-12-21 17:36:39 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
finish_xact_command, postgres.c:1955
2005-12-21 17:36:39 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS
encoding, datlastsysoid
FROM pg_database WHERE oid = 16391
2005-12-21 17:36:39 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransaction
2005-12-21 17:36:39 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:36:39 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS
encoding, datlastsysoid
FROM pg_database WHERE oid = 16391
2005-12-21 17:36:39 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: STARTED; state: INPROGR,
xid/subid/cid: 10514/1/1, nestlvl: 1, children: <>
2005-12-21 17:36:39 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:36:39 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
SET DateStyle=ISO;SELECT oid, pg_encoding_to_char(encoding) AS
encoding, datlastsysoid
FROM pg_database WHERE oid = 16391
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransactionCommand
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
start_xact_command, postgres.c:1932
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
set client_encoding to 'SQL_ASCII'
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransaction
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
set client_encoding to 'SQL_ASCII'
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 10515/1/0, nestlvl: 1, children: <>
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:36:39 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
set client_encoding to 'SQL_ASCII'
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTDEBUG:
00000: ProcessUtility
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTLOCATION:
PortalRunUtility, pquery.c:952
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTSTATEMENT:
set client_encoding to 'SQL_ASCII'
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransactionCommand
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTLOCATION:
finish_xact_command, postgres.c:1955
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTSTATEMENT:
set client_encoding to 'SQL_ASCII'
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransaction
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTSTATEMENT:
set client_encoding to 'SQL_ASCII'
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: STARTED; state: INPROGR,
xid/subid/cid: 10515/1/0, nestlvl: 1, children: <>
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:36:39 GMT 32198 SET 2005-12-21 17:36:39 GMTSTATEMENT:
set client_encoding to 'SQL_ASCII'
2005-12-21 17:37:03 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransactionCommand
2005-12-21 17:37:03 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
start_xact_command, postgres.c:1932
2005-12-21 17:37:03 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransaction
2005-12-21 17:37:03 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:37:03 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 10516/1/0, nestlvl: 1, children: <>
2005-12-21 17:37:03 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:37:03 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Not using integer_datetimes
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
checkIntTimeType,
/home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:515
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Added JVM option string "-Xms128M"
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
JVMOptList_add, /home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:413
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Added JVM option string "-Xmx512M"
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
JVMOptList_add, /home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:413
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Added JVM option string
"-Xloggc:/usr/local/pg81/data/javagc.log"
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
JVMOptList_add, /home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:413
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Added JVM option string "-XX:+PrintGCDetails"
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
JVMOptList_add, /home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:413
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Added JVM option string "-XX:MaxPermSize=256m"
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
JVMOptList_add, /home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:413
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Added JVM option string
"-Djava.class.path=/usr/local/pg81/data/javalib/pljava.jar"
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
JVMOptList_add, /home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:413
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Added JVM option string
"-Dsqlj.defaultconnection=jdbc:default:connection"
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
JVMOptList_add, /home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:413
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Added JVM option string "vfprintf"
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
JVMOptList_add, /home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:413
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Added JVM option string "-Xrs"
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
JVMOptList_add, /home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:413
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Creating JavaVM
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
initializeJavaVM,
/home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:616
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: JavaVM created
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
initializeJavaVM,
/home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:636
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Getting Backend class pljava.jar
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
initPLJavaClasses,
/home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:105
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Backend class was there
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
initPLJavaClasses,
/home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:107
2005-12-21 17:37:03 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: 21 Dec 05 17:37:04 org.postgresql.pljava.internal.Backend Using
SecurityManager for trusted language
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
Java_org_postgresql_pljava_internal_Backend__1log,
/home/postgres/pljava-1.2.0/src/C/pljava/Backend.c:826
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: prosrc =
"org.postgresql.pljava.example.ResultSetTest.executeSelect"
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
Function_init, /home/postgres/pljava-1.2.0/src/C/pljava/Function.c:249
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Obtaining classloader for schema javatest
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
Function_init, /home/postgres/pljava-1.2.0/src/C/pljava/Function.c:322
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Loading class org.postgresql.pljava.example.ResultSetTest
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
Function_init, /home/postgres/pljava-1.2.0/src/C/pljava/Function.c:329
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Obtaining method
org.postgresql.pljava.example.ResultSetTest.executeSelect
(Ljava/lang/String;)Ljava/util/Iterator;
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
Function_init, /home/postgres/pljava-1.2.0/src/C/pljava/Function.c:471
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransactionCommand
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
finish_xact_command, postgres.c:1955
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransaction
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: STARTED; state: INPROGR,
xid/subid/cid: 10516/1/5, nestlvl: 1, children: <>
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:37:04 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransactionCommand
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
start_xact_command, postgres.c:1932
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT typname FROM pg_type WHERE oid = 1043
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransaction
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT typname FROM pg_type WHERE oid = 1043
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 10517/1/0, nestlvl: 1, children: <>
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT typname FROM pg_type WHERE oid = 1043
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransactionCommand
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
finish_xact_command, postgres.c:1955
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT typname FROM pg_type WHERE oid = 1043
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransaction
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT typname FROM pg_type WHERE oid = 1043
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: STARTED; state: INPROGR,
xid/subid/cid: 10517/1/0, nestlvl: 1, children: <>
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT typname FROM pg_type WHERE oid = 1043
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransactionCommand
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
start_xact_command, postgres.c:1932
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT CASE WHEN typbasetype=0 THEN oid else typbasetype END AS
basetype
FROM pg_type WHERE oid=1043
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransaction
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT CASE WHEN typbasetype=0 THEN oid else typbasetype END AS
basetype
FROM pg_type WHERE oid=1043
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 10518/1/0, nestlvl: 1, children: <>
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:37:05 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT CASE WHEN typbasetype=0 THEN oid else typbasetype END AS
basetype
FROM pg_type WHERE oid=1043
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransactionCommand
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
finish_xact_command, postgres.c:1955
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT CASE WHEN typbasetype=0 THEN oid else typbasetype END AS
basetype
FROM pg_type WHERE oid=1043
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: CommitTransaction
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT CASE WHEN typbasetype=0 THEN oid else typbasetype END AS
basetype
FROM pg_type WHERE oid=1043
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: STARTED; state: INPROGR,
xid/subid/cid: 10518/1/0, nestlvl: 1, children: <>
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:37:05 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
SELECT CASE WHEN typbasetype=0 THEN oid else typbasetype END AS
basetype
FROM pg_type WHERE oid=1043
***now execute: 'select javatest.executeselect('select * from
ri.staff_v order by 1 asc') -- FORCES SQL exception
2005-12-21 17:39:16 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransactionCommand
2005-12-21 17:39:16 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
start_xact_command, postgres.c:1932
2005-12-21 17:39:16 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ri.staff_v order by 1
asc');
2005-12-21 17:39:16 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransaction
2005-12-21 17:39:16 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:39:16 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ri.staff_v order by 1
asc');
2005-12-21 17:39:16 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 10519/1/0, nestlvl: 1, children: <>
2005-12-21 17:39:16 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:39:16 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ri.staff_v order by 1
asc');
2005-12-21 17:39:16 GMT 32198 SELECT 2005-12-21 17:36:39 GMTDEBUG:
00000: Exception in function SPI_prepare
2005-12-21 17:39:16 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
Exception_throw_ERROR,
/home/postgres/pljava-1.2.0/src/C/pljava/Exception.c:159
2005-12-21 17:39:16 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ri.staff_v order by 1
asc');
org.postgresql.pljava.internal.ServerException: schema "ri" does not exist
at org.postgresql.pljava.internal.ExecutionPlan._prepare(Native Method)
at org.postgresql.pljava.internal.ExecutionPlan.prepare(ExecutionPlan.java:214)
at org.postgresql.pljava.jdbc.SPIStatement.execute(SPIStatement.java:88)
at org.postgresql.pljava.jdbc.SPIStatement.executeQuery(SPIStatement.java:168)
at org.postgresql.pljava.example.ResultSetTest.<init>(ResultSetTest.java:43)
at org.postgresql.pljava.example.ResultSetTest.executeSelect(ResultSetTest.java:30)
2005-12-21 17:39:16 GMT 32198 SELECT 2005-12-21 17:36:39 GMTERROR:
3F000: schema "ri" does not exist
2005-12-21 17:39:16 GMT 32198 SELECT 2005-12-21 17:36:39 GMTCONTEXT:
SQL statement "select * from ri.staff_v order by 1 asc"
2005-12-21 17:39:16 GMT 32198 SELECT 2005-12-21 17:36:39 GMTLOCATION:
LookupExplicitNamespace, namespace.c:1261
2005-12-21 17:39:16 GMT 32198 SELECT 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ri.staff_v order by 1
asc');
*** execute: 'select javatest.executeselect('select * from ori.staff_v
order by 1 asc') -- statement executed successfully (2nd time, but it
runs indefinitely
2005-12-21 17:39:49 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransactionCommand
2005-12-21 17:39:49 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
start_xact_command, postgres.c:1932
2005-12-21 17:39:49 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:39:49 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: StartTransaction
2005-12-21 17:39:49 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionState, xact.c:3930
2005-12-21 17:39:49 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
2005-12-21 17:39:49 GMT 32198 idle 2005-12-21 17:36:39 GMTDEBUG:
00000: name: unnamed; blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 10520/1/0, nestlvl: 1, children: <>
2005-12-21 17:39:49 GMT 32198 idle 2005-12-21 17:36:39 GMTLOCATION:
ShowTransactionStateRec, xact.c:3955
2005-12-21 17:39:49 GMT 32198 idle 2005-12-21 17:36:39 GMTSTATEMENT:
select javatest.executeselect('select * from ori.staff_v order by 1
asc');
*** hangs here!!!
*** this after restarting pgAdmin and reconnecting back to postgresql
2005-12-21 17:40:19 GMT 32189 DEBUG: 00000: forked new backend,
pid=32206 socket=6
2005-12-21 17:40:19 GMT 32189 LOCATION: BackendStartup, postmaster.c:2519
2005-12-21 17:40:19 GMT 32206 /usr/local/pg81/bin/postmaster
2005-12-21 17:40:19 GMTLOG: 00000: connection received:
host=10.14.139.148 port=4509
2005-12-21 17:40:19 GMT 32206 /usr/local/pg81/bin/postmaster
2005-12-21 17:40:19 GMTLOCATION: BackendRun, postmaster.c:2698
2005-12-21 17:40:19 GMT 32206 /usr/local/pg81/bin/postmaster
2005-12-21 17:40:19 GMTDEBUG: 00000: processing cancel request:
sending SIGINT to process 32198
2005-12-21 17:40:19 GMT 32206 /usr/local/pg81/bin/postmaster
2005-12-21 17:40:19 GMTLOCATION: processCancelRequest,
postmaster.c:1660
2005-12-21 17:40:19 GMT 32206 /usr/local/pg81/bin/postmaster
2005-12-21 17:40:19 GMTDEBUG: 00000: proc_exit(0)
2005-12-21 17:40:19 GMT 32206 /usr/local/pg81/bin/postmaster
2005-12-21 17:40:19 GMTLOCATION: proc_exit, ipc.c:95
2005-12-21 17:40:19 GMT 32206 /usr/local/pg81/bin/postmaster
2005-12-21 17:40:19 GMTDEBUG: 00000: shmem_exit(0)
2005-12-21 17:40:19 GMT 32206 /usr/local/pg81/bin/postmaster
2005-12-21 17:40:19 GMTLOCATION: shmem_exit, ipc.c:126
2005-12-21 17:40:19 GMT 32206 /usr/local/pg81/bin/postmaster
2005-12-21 17:40:19 GMTDEBUG: 00000: exit(0)
2005-12-21 17:40:19 GMT 32206 /usr/local/pg81/bin/postmaster
2005-12-21 17:40:19 GMTLOCATION: proc_exit, ipc.c:113
2005-12-21 17:40:19 GMT 32189 DEBUG: 00000: reaping dead processes
2005-12-21 17:40:19 GMT 32189 LOCATION: reaper, postmaster.c:2023
2005-12-21 17:40:19 GMT 32189 DEBUG: 00000: server process (PID
32206) exited with exit code 0
2005-12-21 17:40:19 GMT 32189 LOCATION: LogChildExit, postmaster.c:2418
-------------------------------------------------------------

Any ideas as to what is happening will be greately appreciated! I also
quickly browsed through the other threads and there was a guy called
'Eric E' who has experienced similar problems with this (don't know
whether this is related or not) - the thread name is 'PL/Java example
queries don't respond'

Michael