From: michael.zintakis at googlemail.com (Michael Zintakis) Date: Wed, 21 Dec 2005 20:10:02 +0000 Subject: [Pljava-dev] pljava hangs while running Java examples (anything to do with gc?) Message-ID: <71622ed30512211210h43202271t481e8a6ba2d8ef8a@mail.gmail.com> 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.(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