Uploaded image for project: 'Apache HAWQ'
  1. Apache HAWQ
  2. HAWQ-738

Allocate query resource twice in function call through jdbc

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Resolved
    • Affects Version/s: 2.0.0.0-incubating
    • Fix Version/s: 2.0.0.0-incubating
    • Component/s: Core
    • Labels:
      None

      Description

      It allocates query resource twice in function call through jdbc, one in parse, and the other in bind. Though the same thing works with psql.

      Use runme.sh in attached bug.zip to reproduce the issue. It may raise below error on host with limited resource (i.e., low memory, etc).

      [gpadmin@localhost debug]$ ./runme.sh 
      
      java -classpath /home/gpadmin/debug/Bug.jar:/home/gpadmin/debug/gpdb.jar Bug localhost 5432 gpadmin gpadmin changeme
      gpServer: hdp23
      gpPort: 5432
      gpDatabase: gpadmin
      gpUserName: gpadmin
      gpPassword: changeme
      DriverManager.getConnection("jdbc:postgresql://hdp23:5432/gpadmin")
          trying sun.jdbc.odbc.JdbcOdbcDriver
      *Driver.connect (jdbc:postgresql://hdp23:5432/gpadmin)
          trying org.postgresql.Driver
      getConnection returning org.postgresql.Driver
      strSQL: DROP TABLE IF EXISTS public.debug;
      CREATE TABLE public.debug
      (id int, foo_bar text)
      DISTRIBUTED RANDOMLY;
      strSQL: INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i;
      strSQL: CREATE OR REPLACE FUNCTION public.fn_debug() RETURNS text AS
      $$
      DECLARE
      	v_return text;
      BEGIN
      	SELECT foo_bar
      	INTO v_return
      	FROM public.debug
      	WHERE id = 1;
      
      	RETURN v_return;
      END;
      $$
      LANGUAGE plpgsql;
      strSQL: SELECT public.fn_debug()
      org.postgresql.util.PSQLException: ERROR: failed to acquire resource from resource manager, session 32 deadlock is detected (pquery.c:804)
      	at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2102)
      	at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1835)
      	at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
      	at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:500)
      	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:374)
      	at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:254)
      	at Bug.getFunctionResults(Bug.java:144)
      	at Bug.main(Bug.java:41)
      SQLException: SQLState(XX000)
      ERROR: failed to acquire resource from resource manager, session 32 deadlock is detected (pquery.c:804)
      Exception in thread "main" java.sql.SQLException: ERROR: failed to acquire resource from resource manager, session 32 deadlock is detected (pquery.c:804)
      	at Bug.main(Bug.java:49)
      

      while the expected result is as below:

      [gpadmin@localhost hawq_bug]$ ./runme.sh
      java -classpath /home/gpadmin/huor/hawq_bug/Bug.jar:/home/gpadmin/huor/hawq_bug/gpdb.jar Bug localhost 5432 gptest gpadmin changeme
      gpServer: localhost
      gpPort: 5432
      gpDatabase: gptest
      gpUserName: gpadmin
      gpPassword: changeme
      DriverManager.getConnection("jdbc:postgresql://localhost:5432/gptest")
          trying sun.jdbc.odbc.JdbcOdbcDriver
      *Driver.connect (jdbc:postgresql://localhost:5432/gptest)
          trying org.postgresql.Driver
      getConnection returning org.postgresql.Driver
      strSQL: DROP TABLE IF EXISTS public.debug;
      CREATE TABLE public.debug
      (id int, foo_bar text)
      DISTRIBUTED RANDOMLY;
      SQLWarning:
      strSQL: INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i;
      strSQL: CREATE OR REPLACE FUNCTION public.fn_debug() RETURNS text AS
      $$
      DECLARE
          v_return text;
      BEGIN
          SELECT foo_bar
          INTO v_return
          FROM public.debug
          WHERE id = 1;
      
          RETURN v_return;
      END;
      $$
      LANGUAGE plpgsql;
      strSQL: SELECT public.fn_debug()
      output: foo_1
      

      If you look into the pg_log on master, you can see it allocate query resource twice for the function call:

      rhuo-mbp:jdbc rhuo$ cat hawq-2016-05-14_000000.csv
      2016-05-16 13:50:50.255504 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:51:20.275204 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:51:50.291712 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:52:20.300825 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:52:50.313270 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:52:54.579579 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,0,con521,,seg-10000,,,,,"LOG","00000","getLocalTmpDirFromMasterConfig session_id:521 tmpdir:/data/master_tmp",,,,,,,0,,"postinit.c",465,
      2016-05-16 13:52:54.693462 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,103517,con521,cmd7,seg-10000,,,x103517,sx1,"LOG","00000","ConnID 507. Registered in HAWQ resource manager (By OID)",,,,,,"INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i;",0,,"rmcomm_QD2RM.c",609,
      2016-05-16 13:52:54.693695 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 507. Expect query resource (256 MB, 0.250000 CORE) x 1 ( MIN 1 ) resource after adjusting based on queue NVSEG limits.",,,,,,,0,,"resqueuemanager.c",1913,
      2016-05-16 13:52:54.693711 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Latency of getting resource allocated is 73us",,,,,,,0,,"resqueuemanager.c",4375,
      2016-05-16 13:52:54.693719 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource water mark changes from (0 MB, 0.000000 CORE) to (256 MB, 0.250000 CORE)",,,,,,,0,,"resqueuemanager.c",2550,
      2016-05-16 13:52:54.693769 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,103517,con521,cmd7,seg-10000,,,x103517,sx1,"LOG","00000","ConnID 507. Acquired resource from resource manager, (256 MB, 0.250000 CORE) x 1.",,,,,,"INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i;",0,,"rmcomm_QD2RM.c",868,
      2016-05-16 13:52:54.694119 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,103517,con521,cmd7,seg-10000,,,x103517,sx1,"LOG","00000","data locality ratio: 0.000; virtual segment number: 1; different host number: 1; virtual segment number per host(avg/min/max): (1/1/1); segment size(avg/min/max): (0.000 B/0 B/0 B); segment size with penalty(avg/min/max): (0.000 B/0 B/0 B); continuity(avg/min/max): (0.000/0.000/0.000).",,,,,,"INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i;",0,,"cdbdatalocality.c",3396,
      2016-05-16 13:52:54.811026 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 507. Returned resource.",,,,,,,0,,"requesthandler.c",562,
      2016-05-16 13:52:54.811146 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,103517,con521,cmd8,seg-1,,,x103517,sx1,"LOG","00000","ConnID 507. Returned resource to resource manager.",,,,,,"INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i;",0,,"rmcomm_QD2RM.c",951,
      2016-05-16 13:52:54.811247 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"WARNING","01000","Resource manager finds possible not handled resource request from ConnID 507.",,,,,,,0,,"requesthandler.c",282,
      2016-05-16 13:52:54.811272 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 507. Connection is unregistered.",,,,,,,0,,"requesthandler.c",300,
      2016-05-16 13:52:54.811634 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,103517,con521,cmd8,seg-1,,,x103517,sx1,"LOG","00000","ConnID 507. Unregistered from HAWQ resource manager.",,,,,,"INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i;",0,,"rmcomm_QD2RM.c",661,
      2016-05-16 13:52:54.820168 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,103521,con521,cmd10,seg-1,,,x103521,sx1,"LOG","00000","ConnID 508. Registered in HAWQ resource manager (By OID)",,,,,,"SELECT public.fn_debug()",0,,"rmcomm_QD2RM.c",609,
      2016-05-16 13:52:54.820419 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 508. Expect query resource (256 MB, 0.250000 CORE) x 6 ( MIN 6 ) resource after adjusting based on queue NVSEG limits.",,,,,,,0,,"resqueuemanager.c",1913,
      2016-05-16 13:52:54.820437 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Latency of getting resource allocated is 73us",,,,,,,0,,"resqueuemanager.c",4375,
      2016-05-16 13:52:54.820446 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource water mark changes from (256 MB, 0.250000 CORE) to (1536 MB, 1.500000 CORE)",,,,,,,0,,"resqueuemanager.c",2550,
      2016-05-16 13:52:54.820495 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,103521,con521,cmd10,seg-1,,,x103521,sx1,"LOG","00000","ConnID 508. Acquired resource from resource manager, (256 MB, 0.250000 CORE) x 6.",,,,,,"SELECT public.fn_debug()",0,,"rmcomm_QD2RM.c",868,
      2016-05-16 13:52:54.823416 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,103521,con521,cmd11,seg-1,,,x103521,sx1,"LOG","00000","data locality ratio: 1.000; virtual segment number: 6; different host number: 1; virtual segment number per host(avg/min/max): (6/6/6); segment size(avg/min/max): (424.000 B/0 B/2544 B); segment size with penalty(avg/min/max): (424.000 B/0 B/2544 B); continuity(avg/min/max): (0.167/0.000/1.000).",,,,,"SQL statement ""SELECT foo_bar FROM public.debug WHERE id = 1""
      PL/pgSQL function ""fn_debug"" line 4 at SQL statement","SELECT public.fn_debug()",0,,"cdbdatalocality.c",3396,
      2016-05-16 13:52:54.898230 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 508. Returned resource.",,,,,,,0,,"requesthandler.c",562,
      2016-05-16 13:52:54.898336 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,103521,con521,cmd12,seg-1,,,x103521,sx1,"LOG","00000","ConnID 508. Returned resource to resource manager.",,,,,,"SELECT public.fn_debug()",0,,"rmcomm_QD2RM.c",951,
      2016-05-16 13:52:54.898428 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"WARNING","01000","Resource manager finds possible not handled resource request from ConnID 508.",,,,,,,0,,"requesthandler.c",282,
      2016-05-16 13:52:54.898441 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 508. Connection is unregistered.",,,,,,,0,,"requesthandler.c",300,
      2016-05-16 13:52:54.898598 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,103521,con521,cmd12,seg-1,,,x103521,sx1,"LOG","00000","ConnID 508. Unregistered from HAWQ resource manager.",,,,,,"SELECT public.fn_debug()",0,,"rmcomm_QD2RM.c",661,
      2016-05-16 13:52:54.906284 EDT,"gpadmin","gpadmin",p29743,th424065152,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,0,con521,cmd12,seg-1,,,,,"LOG","00000","Clean up communication to resource manager now.",,,,,,,0,,"rmcomm_QD2RM.c",460,
      2016-05-16 13:52:54.993569 EDT,"gpadmin","gpadmin",p29743,th-248940800,"192.168.175.129","26084",2016-05-16 13:52:54 EDT,0,con521,cmd12,seg-1,,,,,"LOG","00000","generateResourceRefreshHeartBeat exits.",,,,,,,0,,,,
      2016-05-16 13:53:02.031115 EDT,"gpadmin","gpadmin",p29774,th424065152,"[local]",,2016-05-16 13:53:02 EDT,0,con523,,seg-10000,,,,,"LOG","00000","getLocalTmpDirFromMasterConfig session_id:523 tmpdir:/data/master_tmp",,,,,,,0,,"postinit.c",465,
      2016-05-16 13:53:20.332840 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:53:39.463663 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,0,con524,,seg-10000,,,,,"LOG","00000","getLocalTmpDirFromMasterConfig session_id:524 tmpdir:/data/master_tmp",,,,,,,0,,"postinit.c",465,
      2016-05-16 13:53:39.545968 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,103526,con524,cmd2,seg-10000,,,x103526,sx1,"LOG","00000","ConnID 509. Registered in HAWQ resource manager (By OID)",,,,,,"INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i",0,,"rmcomm_QD2RM.c",609,
      2016-05-16 13:53:39.546149 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 509. Expect query resource (256 MB, 0.250000 CORE) x 1 ( MIN 1 ) resource after adjusting based on queue NVSEG limits.",,,,,,,0,,"resqueuemanager.c",1913,
      2016-05-16 13:53:39.546165 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Latency of getting resource allocated is 50us",,,,,,,0,,"resqueuemanager.c",4375,
      2016-05-16 13:53:39.546218 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,103526,con524,cmd2,seg-10000,,,x103526,sx1,"LOG","00000","ConnID 509. Acquired resource from resource manager, (256 MB, 0.250000 CORE) x 1.",,,,,,"INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i",0,,"rmcomm_QD2RM.c",868,
      2016-05-16 13:53:39.546502 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,103526,con524,cmd2,seg-10000,,,x103526,sx1,"LOG","00000","data locality ratio: 0.000; virtual segment number: 1; different host number: 1; virtual segment number per host(avg/min/max): (1/1/1); segment size(avg/min/max): (0.000 B/0 B/0 B); segment size with penalty(avg/min/max): (0.000 B/0 B/0 B); continuity(avg/min/max): (0.000/0.000/0.000).",,,,,,"INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i",0,,"cdbdatalocality.c",3396,
      2016-05-16 13:53:39.661720 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 509. Returned resource.",,,,,,,0,,"requesthandler.c",562,
      2016-05-16 13:53:39.661832 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,103526,con524,cmd3,seg-1,,,x103526,sx1,"LOG","00000","ConnID 509. Returned resource to resource manager.",,,,,,"INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i",0,,"rmcomm_QD2RM.c",951,
      2016-05-16 13:53:39.661935 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"WARNING","01000","Resource manager finds possible not handled resource request from ConnID 509.",,,,,,,0,,"requesthandler.c",282,
      2016-05-16 13:53:39.661950 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 509. Connection is unregistered.",,,,,,,0,,"requesthandler.c",300,
      2016-05-16 13:53:39.662270 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,103526,con524,cmd3,seg-1,,,x103526,sx1,"LOG","00000","ConnID 509. Unregistered from HAWQ resource manager.",,,,,,"INSERT INTO public.debug
      SELECT i, 'foo_' || i from generate_series(1,100) AS i",0,,"rmcomm_QD2RM.c",661,
      
      
      -----------------------------------------------------------------------------------------------------------------------------------
      First time query resource allocate for function call "SELECT public.fn_debug()": successful
      -----------------------------------------------------------------------------------------------------------------------------------
      2016-05-16 13:53:39.667859 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,103530,con524,cmd4,seg-1,,,x103530,sx1,"LOG","00000","ConnID 510. Registered in HAWQ resource manager (By OID)",,,,,,"SELECT public.fn_debug()",0,,"rmcomm_QD2RM.c",609,
      2016-05-16 13:53:39.668054 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 510. Expect query resource (256 MB, 0.250000 CORE) x 6 ( MIN 6 ) resource after adjusting based on queue NVSEG limits.",,,,,,,0,,"resqueuemanager.c",1913,
      2016-05-16 13:53:39.668081 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Latency of getting resource allocated is 57us",,,,,,,0,,"resqueuemanager.c",4375,
      2016-05-16 13:53:39.668131 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,103530,con524,cmd4,seg-1,,,x103530,sx1,"LOG","00000","ConnID 510. Acquired resource from resource manager, (256 MB, 0.250000 CORE) x 6.",,,,,,"SELECT public.fn_debug()",0,,"rmcomm_QD2RM.c",868,
      
      -----------------------------------------------------------------------------------------------------------------------------------
      Second time query resource allocate for function call "SELECT public.fn_debug()": failed
      -----------------------------------------------------------------------------------------------------------------------------------
      2016-05-16 13:53:39.668333 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,103530,con524,cmd4,seg-1,,,x103530,sx1,"LOG","00000","ConnID 511. Registered in HAWQ resource manager (By OID)",,,,,,"SELECT public.fn_debug()",0,,"rmcomm_QD2RM.c",609,
      2016-05-16 13:53:39.668501 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 511. Expect query resource (256 MB, 0.250000 CORE) x 6 ( MIN 6 ) resource after adjusting based on queue NVSEG limits.",,,,,,,0,,"resqueuemanager.c",1913,
      2016-05-16 13:53:39.668516 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Locking resource and stop forced GRM container breathe out.",,,,,,,0,,"resqueuemanager.c",3532,
      2016-05-16 13:53:39.712340 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,103530,con524,cmd4,seg-1,,,x103530,sx1,"ERROR","XX000","failed to acquire resource from resource manager, session 524 deadlock is detected (pquery.c:804)",,,,,,"SELECT public.fn_debug()",0,,"pquery.c",804,"Stack trace:
      1    0x87463a postgres errstart (elog.c:497)
      2    0x7b47e9 postgres AllocateResource (pquery.c:804)
      3    0x727888 postgres planner (planner.c:550)
      4    0x7add1e postgres pg_plan_query (postgres.c:845)
      5    0x7ae437 postgres <symbol not found> (postgres.c:917)
      6    0x7b1682 postgres PostgresMain (postgres.c:5014)
      7    0x763f23 postgres <symbol not found> (postmaster.c:5889)
      8    0x76467d postgres <symbol not found> (postmaster.c:2169)
      9    0x7664ae postgres PostmasterMain (postmaster.c:6519)
      10   0x6c072a postgres main (main.c:226)
      11   0x7f1915021d5d libc.so.6 __libc_start_main (??:0)
      12   0x4a14e9 postgres <symbol not found> (??:0)
      "
      2016-05-16 13:53:39.712775 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 510. Returned resource.",,,,,,,0,,"requesthandler.c",562,
      
      2016-05-16 13:53:39.713056 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,0,con524,cmd4,seg-1,,,,,"LOG","00000","ConnID 510. Returned resource to resource manager.",,,,,,,0,,"rmcomm_QD2RM.c",951,
      2016-05-16 13:53:39.713253 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"WARNING","01000","Resource manager finds possible not handled resource request from ConnID 510.",,,,,,,0,,"requesthandler.c",282,
      2016-05-16 13:53:39.713269 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","ConnID 510. Connection is unregistered.",,,,,,,0,,"requesthandler.c",300,
      2016-05-16 13:53:39.713352 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,0,con524,cmd4,seg-1,,,,,"LOG","00000","ConnID 510. Unregistered from HAWQ resource manager.",,,,,,,0,,"rmcomm_QD2RM.c",661,
      2016-05-16 13:53:39.714932 EDT,"gpadmin","gpadmin",p30112,th424065152,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,0,con524,cmd4,seg-1,,,,,"LOG","00000","Clean up communication to resource manager now.",,,,,,,0,,"rmcomm_QD2RM.c",460,
      2016-05-16 13:53:39.745897 EDT,"gpadmin","gpadmin",p30112,th-248940800,"192.168.175.129","26129",2016-05-16 13:53:39 EDT,0,con524,cmd4,seg-1,,,,,"LOG","00000","generateResourceRefreshHeartBeat exits.",,,,,,,0,,,,
      2016-05-16 13:53:50.339646 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:54:20.375091 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:54:50.390263 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:55:20.406517 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:55:50.411268 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:56:20.440662 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:56:50.476459 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:57:20.524175 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:57:50.540684 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:58:20.557625 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:58:40.018311 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource water mark changes from (1536 MB, 1.500000 CORE) to (0 MB, 0.000000 CORE)",,,,,,,0,,"resqueuemanager.c",2550,
      2016-05-16 13:58:50.580164 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      2016-05-16 13:59:20.635568 EDT,,,p4522,th424065152,,,,0,con4,,seg-10000,,,,,"LOG","00000","Resource manager adjusts segment hdp23.localdomain original resource capacity from (2048 MB, 48 CORE) to (2048 MB, 2 CORE)",,,,,,,0,,"resourcepool.c",4688,
      

        Issue Links

          Activity

          Hide
          huor Ruilong Huo added a comment - - edited

          Root cause analysis:

          1. It uses exec_parse_message and exec_bind_message and allocate query resource twice in parse and bind phases accordingly when using jdbc to call the function: SELECT public.fn_debug(). Thus query resource is allocated twice in function call through jdbc.

          Breakpoint 1, AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746
          746		QueryResource	*resource = NULL;
          (gdb) bt
          #0  AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746
          #1  0x0000000000840778 in resource_negotiator (parse=0x1fdca10, cursorOptions=0, boundParams=0x0, resourceLife=QRL_NONE, result=0x7fff33059928) at planner.c:550
          #2  0x000000000083fe10 in planner (parse=0x1fdca10, cursorOptions=0, boundParams=0x0, resourceLife=QRL_NONE) at planner.c:340
          #3  0x00000000008ec421 in pg_plan_query (querytree=0x1fdca10, boundParams=0x0, resource_life=QRL_NONE) at postgres.c:843
          #4  0x00000000008ec52c in pg_plan_queries (querytrees=0x20104c0, boundParams=0x0, needSnapshot=0 '\000', resource_life=QRL_NONE) at postgres.c:917
          #5  0x00000000008ee42d in exec_parse_message (query_string=0x1f299c9 "SELECT public.fn_debug()", stmt_name=0x1f299c8 "", paramTypes=0x0, numParams=0) at postgres.c:2036
          #6  0x00000000008f347f in PostgresMain (argc=4, argv=0x1e5c0b0, username=0x1e5bc80 "gpadmin") at postgres.c:4989
          #7  0x0000000000899221 in BackendRun (port=0x1e2fc80) at postmaster.c:5889
          #8  0x00000000008986b0 in BackendStartup (port=0x1e2fc80) at postmaster.c:5484
          #9  0x00000000008926dd in ServerLoop () at postmaster.c:2163
          #10 0x000000000089179e in PostmasterMain (argc=9, argv=0x1e46940) at postmaster.c:1454
          #11 0x00000000007ab50a in main (argc=9, argv=0x1e46940) at main.c:226
          (gdb) c
          Continuing.
          
          Breakpoint 1, AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746
          746		QueryResource	*resource = NULL;
          (gdb) bt
          #0  AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746
          #1  0x0000000000840778 in resource_negotiator (parse=0x1f62b10, cursorOptions=0, boundParams=0x0, resourceLife=QRL_ONCE, result=0x7fff33059888) at planner.c:550
          #2  0x000000000083fe10 in planner (parse=0x1f62b10, cursorOptions=0, boundParams=0x0, resourceLife=QRL_ONCE) at planner.c:340
          #3  0x00000000008ec421 in pg_plan_query (querytree=0x1f62b10, boundParams=0x0, resource_life=QRL_ONCE) at postgres.c:843
          #4  0x00000000008ec52c in pg_plan_queries (querytrees=0x1f629f8, boundParams=0x0, needSnapshot=0 '\000', resource_life=QRL_ONCE) at postgres.c:917
          #5  0x00000000008ef1dc in exec_bind_message (input_message=0x7fff33059d70) at postgres.c:2451
          #6  0x00000000008f34a7 in PostgresMain (argc=4, argv=0x1e5c0b0, username=0x1e5bc80 "gpadmin") at postgres.c:5013
          #7  0x0000000000899221 in BackendRun (port=0x1e2fc80) at postmaster.c:5889
          #8  0x00000000008986b0 in BackendStartup (port=0x1e2fc80) at postmaster.c:5484
          #9  0x00000000008926dd in ServerLoop () at postmaster.c:2163
          #10 0x000000000089179e in PostmasterMain (argc=9, argv=0x1e46940) at postmaster.c:1454
          #11 0x00000000007ab50a in main (argc=9, argv=0x1e46940) at main.c:226
          

          2. It uses exec_simple_query and allocate query resource there only once when using psql/libpq to call the function: SELECT public.fn_debug()

          Breakpoint 1, AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746
          746		QueryResource	*resource = NULL;
          (gdb) bt
          #0  AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746
          #1  0x0000000000840778 in resource_negotiator (parse=0x30ea350, cursorOptions=0, boundParams=0x0, resourceLife=QRL_ONCE, result=0x7fff46953248) at planner.c:550
          #2  0x000000000083fe10 in planner (parse=0x30ea350, cursorOptions=0, boundParams=0x0, resourceLife=QRL_ONCE) at planner.c:340
          #3  0x00000000008ec421 in pg_plan_query (querytree=0x30ea350, boundParams=0x0, resource_life=QRL_ONCE) at postgres.c:843
          #4  0x00000000008ec52c in pg_plan_queries (querytrees=0x3125ab8, boundParams=0x0, needSnapshot=0 '\000', resource_life=QRL_ONCE) at postgres.c:917
          #5  0x00000000008edb53 in exec_simple_query (query_string=0x30e92f8 "SELECT public.fn_debug();", seqServerHost=0x0, seqServerPort=-1) at postgres.c:1677
          #6  0x00000000008f2b84 in PostgresMain (argc=4, argv=0x2fdae80, username=0x2fdac80 "gpadmin") at postgres.c:4760
          #7  0x0000000000899221 in BackendRun (port=0x2faec80) at postmaster.c:5889
          #8  0x00000000008986b0 in BackendStartup (port=0x2faec80) at postmaster.c:5484
          #9  0x00000000008926dd in ServerLoop () at postmaster.c:2163
          #10 0x000000000089179e in PostmasterMain (argc=9, argv=0x2fc5940) at postmaster.c:1454
          #11 0x00000000007ab50a in main (argc=9, argv=0x2fc5940) at main.c:226
          
          Show
          huor Ruilong Huo added a comment - - edited Root cause analysis: 1. It uses exec_parse_message and exec_bind_message and allocate query resource twice in parse and bind phases accordingly when using jdbc to call the function: SELECT public.fn_debug(). Thus query resource is allocated twice in function call through jdbc. Breakpoint 1, AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746 746 QueryResource *resource = NULL; (gdb) bt #0 AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746 #1 0x0000000000840778 in resource_negotiator (parse=0x1fdca10, cursorOptions=0, boundParams=0x0, resourceLife=QRL_NONE, result=0x7fff33059928) at planner.c:550 #2 0x000000000083fe10 in planner (parse=0x1fdca10, cursorOptions=0, boundParams=0x0, resourceLife=QRL_NONE) at planner.c:340 #3 0x00000000008ec421 in pg_plan_query (querytree=0x1fdca10, boundParams=0x0, resource_life=QRL_NONE) at postgres.c:843 #4 0x00000000008ec52c in pg_plan_queries (querytrees=0x20104c0, boundParams=0x0, needSnapshot=0 '\000', resource_life=QRL_NONE) at postgres.c:917 #5 0x00000000008ee42d in exec_parse_message (query_string=0x1f299c9 "SELECT public.fn_debug()", stmt_name=0x1f299c8 "", paramTypes=0x0, numParams=0) at postgres.c:2036 #6 0x00000000008f347f in PostgresMain (argc=4, argv=0x1e5c0b0, username=0x1e5bc80 "gpadmin") at postgres.c:4989 #7 0x0000000000899221 in BackendRun (port=0x1e2fc80) at postmaster.c:5889 #8 0x00000000008986b0 in BackendStartup (port=0x1e2fc80) at postmaster.c:5484 #9 0x00000000008926dd in ServerLoop () at postmaster.c:2163 #10 0x000000000089179e in PostmasterMain (argc=9, argv=0x1e46940) at postmaster.c:1454 #11 0x00000000007ab50a in main (argc=9, argv=0x1e46940) at main.c:226 (gdb) c Continuing. Breakpoint 1, AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746 746 QueryResource *resource = NULL; (gdb) bt #0 AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746 #1 0x0000000000840778 in resource_negotiator (parse=0x1f62b10, cursorOptions=0, boundParams=0x0, resourceLife=QRL_ONCE, result=0x7fff33059888) at planner.c:550 #2 0x000000000083fe10 in planner (parse=0x1f62b10, cursorOptions=0, boundParams=0x0, resourceLife=QRL_ONCE) at planner.c:340 #3 0x00000000008ec421 in pg_plan_query (querytree=0x1f62b10, boundParams=0x0, resource_life=QRL_ONCE) at postgres.c:843 #4 0x00000000008ec52c in pg_plan_queries (querytrees=0x1f629f8, boundParams=0x0, needSnapshot=0 '\000', resource_life=QRL_ONCE) at postgres.c:917 #5 0x00000000008ef1dc in exec_bind_message (input_message=0x7fff33059d70) at postgres.c:2451 #6 0x00000000008f34a7 in PostgresMain (argc=4, argv=0x1e5c0b0, username=0x1e5bc80 "gpadmin") at postgres.c:5013 #7 0x0000000000899221 in BackendRun (port=0x1e2fc80) at postmaster.c:5889 #8 0x00000000008986b0 in BackendStartup (port=0x1e2fc80) at postmaster.c:5484 #9 0x00000000008926dd in ServerLoop () at postmaster.c:2163 #10 0x000000000089179e in PostmasterMain (argc=9, argv=0x1e46940) at postmaster.c:1454 #11 0x00000000007ab50a in main (argc=9, argv=0x1e46940) at main.c:226 2. It uses exec_simple_query and allocate query resource there only once when using psql/libpq to call the function: SELECT public.fn_debug() Breakpoint 1, AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746 746 QueryResource *resource = NULL; (gdb) bt #0 AllocateResource (life=QRL_ONCE, slice_size=3, iobytes=134217728, max_target_segment_num=6, min_target_segment_num=6, vol_info=0x0, vol_info_size=0) at pquery.c:746 #1 0x0000000000840778 in resource_negotiator (parse=0x30ea350, cursorOptions=0, boundParams=0x0, resourceLife=QRL_ONCE, result=0x7fff46953248) at planner.c:550 #2 0x000000000083fe10 in planner (parse=0x30ea350, cursorOptions=0, boundParams=0x0, resourceLife=QRL_ONCE) at planner.c:340 #3 0x00000000008ec421 in pg_plan_query (querytree=0x30ea350, boundParams=0x0, resource_life=QRL_ONCE) at postgres.c:843 #4 0x00000000008ec52c in pg_plan_queries (querytrees=0x3125ab8, boundParams=0x0, needSnapshot=0 '\000', resource_life=QRL_ONCE) at postgres.c:917 #5 0x00000000008edb53 in exec_simple_query (query_string=0x30e92f8 "SELECT public.fn_debug();", seqServerHost=0x0, seqServerPort=-1) at postgres.c:1677 #6 0x00000000008f2b84 in PostgresMain (argc=4, argv=0x2fdae80, username=0x2fdac80 "gpadmin") at postgres.c:4760 #7 0x0000000000899221 in BackendRun (port=0x2faec80) at postmaster.c:5889 #8 0x00000000008986b0 in BackendStartup (port=0x2faec80) at postmaster.c:5484 #9 0x00000000008926dd in ServerLoop () at postmaster.c:2163 #10 0x000000000089179e in PostmasterMain (argc=9, argv=0x2fc5940) at postmaster.c:1454 #11 0x00000000007ab50a in main (argc=9, argv=0x2fc5940) at main.c:226
          Hide
          githubbot ASF GitHub Bot added a comment -

          GitHub user huor opened a pull request:

          https://github.com/apache/incubator-hawq/pull/659

          HAWQ-738. Allocate query resource twice in function call through jdbc

          Root cause analysis:

          1. It uses exec_parse_message and exec_bind_message and allocate query resource twice in parse and bind phases accordingly when using jdbc to call the function: SELECT public.fn_debug(). Thus query resource is allocated twice in function call through jdbc.

          2. It uses exec_simple_query and allocate query resource there on once when using psql/libpq to call the function: SELECT public.fn_debug().

          The resolution is to do not allocate query resource in parse, and only allocate query resource in bind.

          You can merge this pull request into a Git repository by running:

          $ git pull https://github.com/huor/incubator-hawq huor_jdbc

          Alternatively you can review and apply these changes as the patch at:

          https://github.com/apache/incubator-hawq/pull/659.patch

          To close this pull request, make a commit to your master/trunk branch
          with (at least) the following in the commit message:

          This closes #659


          commit e02d0e0f313832f1d0998efc1c59aaad2d421364
          Author: Ruilong Huo <rhuo@pivotal.io>
          Date: 2016-05-17T06:52:39Z

          HAWQ-738. Allocate query resource twice in function call through jdbc


          Show
          githubbot ASF GitHub Bot added a comment - GitHub user huor opened a pull request: https://github.com/apache/incubator-hawq/pull/659 HAWQ-738 . Allocate query resource twice in function call through jdbc Root cause analysis: 1. It uses exec_parse_message and exec_bind_message and allocate query resource twice in parse and bind phases accordingly when using jdbc to call the function: SELECT public.fn_debug(). Thus query resource is allocated twice in function call through jdbc. 2. It uses exec_simple_query and allocate query resource there on once when using psql/libpq to call the function: SELECT public.fn_debug(). The resolution is to do not allocate query resource in parse, and only allocate query resource in bind. You can merge this pull request into a Git repository by running: $ git pull https://github.com/huor/incubator-hawq huor_jdbc Alternatively you can review and apply these changes as the patch at: https://github.com/apache/incubator-hawq/pull/659.patch To close this pull request, make a commit to your master/trunk branch with (at least) the following in the commit message: This closes #659 commit e02d0e0f313832f1d0998efc1c59aaad2d421364 Author: Ruilong Huo <rhuo@pivotal.io> Date: 2016-05-17T06:52:39Z HAWQ-738 . Allocate query resource twice in function call through jdbc
          Hide
          githubbot ASF GitHub Bot added a comment -

          Github user jiny2 commented on the pull request:

          https://github.com/apache/incubator-hawq/pull/659#issuecomment-219636646

          +1 LGTM.

          Show
          githubbot ASF GitHub Bot added a comment - Github user jiny2 commented on the pull request: https://github.com/apache/incubator-hawq/pull/659#issuecomment-219636646 +1 LGTM.
          Hide
          githubbot ASF GitHub Bot added a comment -

          Github user zhangh43 commented on the pull request:

          https://github.com/apache/incubator-hawq/pull/659#issuecomment-219645706

          +1

          Show
          githubbot ASF GitHub Bot added a comment - Github user zhangh43 commented on the pull request: https://github.com/apache/incubator-hawq/pull/659#issuecomment-219645706 +1
          Hide
          githubbot ASF GitHub Bot added a comment -

          Github user asfgit closed the pull request at:

          https://github.com/apache/incubator-hawq/pull/659

          Show
          githubbot ASF GitHub Bot added a comment - Github user asfgit closed the pull request at: https://github.com/apache/incubator-hawq/pull/659
          Hide
          huor Ruilong Huo added a comment -

          Reopening to add the fix version.

          Show
          huor Ruilong Huo added a comment - Reopening to add the fix version.
          Hide
          GodenYao Goden Yao added a comment -

          reopen to update version to 2.0.0.0-incubating

          Show
          GodenYao Goden Yao added a comment - reopen to update version to 2.0.0.0-incubating
          Hide
          GodenYao Goden Yao added a comment -

          close reopened again - resolution (resolved) is done through bulk edit - may not be accurate, please refer to history to see the last resolution for sure.

          Show
          GodenYao Goden Yao added a comment - close reopened again - resolution (resolved) is done through bulk edit - may not be accurate, please refer to history to see the last resolution for sure.

            People

            • Assignee:
              huor Ruilong Huo
              Reporter:
              huor Ruilong Huo
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development