View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000468Pgpool-IIBugpublic2019-02-23 04:342019-04-02 13:21
Reporteralexpereira Assigned Tot-ishii  
PriorityurgentSeveritymajorReproducibilityalways
Status resolvedResolutionopen 
PlatformLinuxOSUbuntuOS Version18.04
Product Version4.0.2 
Target Version4.0.5 
Summary0000468: When doing a query using cursor, a memory leak happens
DescriptionWhen doing a query using cursor (100 in 100 lines - total: 85000 lines), a memory leak happens:

2019-02-22 18:40:02: pid 13: LOG: Backend status file /var/log/pgpool/pgpool_status does not exist
2019-02-22 18:40:02: pid 13: LOG: Setting up socket for 0.0.0.0:9999
2019-02-22 18:40:02: pid 13: LOG: Setting up socket for :::9999
2019-02-22 18:40:02: pid 13: LOG: find_primary_node_repeatedly: waiting for finding a primary node
2019-02-22 18:40:02: pid 13: LOG: pgpool-II successfully started. version 4.0.2 (torokiboshi)
2019-02-22 18:40:02: pid 13: LOG: node status[0]: 0
2019-02-22 18:40:02: pid 13: LOG: node status[1]: 0
2019-02-22 18:40:42: pid 160: LOG: md5 authentication successful with frontend
2019-02-22 18:40:42: pid 157: LOG: md5 authentication successful with frontend
[root@ip-10-1-254-6 ec2-user]# docker logs 3161971a50ba
2019-02-22 18:40:02: pid 13: LOG: Backend status file /var/log/pgpool/pgpool_status does not exist
2019-02-22 18:40:02: pid 13: LOG: Setting up socket for 0.0.0.0:9999
2019-02-22 18:40:02: pid 13: LOG: Setting up socket for :::9999
2019-02-22 18:40:02: pid 13: LOG: find_primary_node_repeatedly: waiting for finding a primary node
2019-02-22 18:40:02: pid 13: LOG: pgpool-II successfully started. version 4.0.2 (torokiboshi)
2019-02-22 18:40:02: pid 13: LOG: node status[0]: 0
2019-02-22 18:40:02: pid 13: LOG: node status[1]: 0
2019-02-22 18:40:42: pid 160: LOG: md5 authentication successful with frontend
2019-02-22 18:40:42: pid 157: LOG: md5 authentication successful with frontend
TopMemoryContext: 16779400 total in 12 blocks; 8253752 free (946 chunks); 8525648 used
  pgpool_child_main_loop: 3779640 total in 3 blocks; 12944 free (10 chunks); 3766696 used
    child_query_process: 0 total in 0 blocks; 0 free (0 chunks); 0 used
      QueryContextMemoryContext: 107568 total in 13 blocks; 7304 free (2 chunks); 100264 used
      QueryContextMemoryContext: 190528 total in 14 blocks; 6488 free (2 chunks); 184040 used
      QueryContextMemoryContext: 183112 total in 12 blocks; 6760 free (2 chunks); 176352 used
      QueryContextMemoryContext: 184488 total in 12 blocks; 5224 free (3 chunks); 179264 used
      QueryContextMemoryContext: 191216 total in 12 blocks; 7416 free (2 chunks); 183800 used
      QueryContextMemoryContext: 190256 total in 12 blocks; 6504 free (1 chunks); 183752 used
      QueryContextMemoryContext: 192584 total in 12 blocks; 7800 free (2 chunks); 184784 used
      QueryContextMemoryContext: 186816 total in 10 blocks; 4632 free (1 chunks); 182184 used
      QueryContextMemoryContext: 194056 total in 12 blocks; 5816 free (1 chunks); 188240 used
      QueryContextMemoryContext: 194184 total in 12 blocks; 4408 free (1 chunks); 189776 used
      QueryContextMemoryContext: 186088 total in 10 blocks; 5944 free (2 chunks); 180144 used
      QueryContextMemoryContext: 199096 total in 12 blocks; 5944 free (2 chunks); 193152 used
      QueryContextMemoryContext: 191272 total in 12 blocks; 6760 free (2 chunks); 184512 used
      QueryContextMemoryContext: 187968 total in 10 blocks; 3864 free (1 chunks); 184104 used
      QueryContextMemoryContext: 186680 total in 10 blocks; 4888 free (1 chunks); 181792 used
      QueryContextMemoryContext: 185560 total in 10 blocks; 7336 free (2 chunks); 178224 used
      QueryContextMemoryContext: 194232 total in 12 blocks; 6760 free (2 chunks); 187472 used
      QueryContextMemoryContext: 185608 total in 10 blocks; 7240 free (2 chunks); 178368 used
      QueryContextMemoryContext: 186680 total in 10 blocks; 5960 free (2 chunks); 180720 used
      QueryContextMemoryContext: 187736 total in 10 blocks; 3864 free (1 chunks); 183872 used
      QueryContextMemoryContext: 191712 total in 12 blocks; 4760 free (0 chunks); 186952 used
      QueryContextMemoryContext: 186128 total in 10 blocks; 5464 free (1 chunks); 180664 used
      QueryContextMemoryContext: 198584 total in 12 blocks; 6024 free (1 chunks); 192560 used
      QueryContextMemoryContext: 198688 total in 14 blocks; 7032 free (2 chunks); 191656 used
      QueryContextMemoryContext: 185632 total in 10 blocks; 7016 free (2 chunks); 178616 used
      QueryContextMemoryContext: 192536 total in 12 blocks; 7784 free (2 chunks); 184752 used
      QueryContextMemoryContext: 177368 total in 10 blocks; 7256 free (2 chunks); 170112 used
      QueryContextMemoryContext: 186272 total in 12 blocks; 5432 free (1 chunks); 180840 used
      QueryContextMemoryContext: 184584 total in 12 blocks; 6984 free (2 chunks); 177600 used
      QueryContextMemoryContext: 186368 total in 12 blocks; 4888 free (1 chunks); 181480 used
      QueryContextMemoryContext: 184568 total in 12 blocks; 6968 free (2 chunks); 177600 used
      QueryContextMemoryContext: 186640 total in 12 blocks; 4408 free (1 chunks); 182232 used
      QueryContextMemoryContext: 184304 total in 12 blocks; 7784 free (2 chunks); 176520 used
      QueryContextMemoryContext: 184240 total in 12 blocks; 7896 free (2 chunks); 176344 used
      QueryContextMemoryContext: 177816 total in 10 blocks; 6200 free (2 chunks); 171616 used
      QueryContextMemoryContext: 177600 total in 10 blocks; 6728 free (1 chunks); 170872 used
      QueryContextMemoryContext: 184520 total in 12 blocks; 6984 free (2 chunks); 177536 used
      QueryContextMemoryContext: 177640 total in 10 blocks; 5928 free (1 chunks); 171712 used
      QueryContextMemoryContext: 177176 total in 10 blocks; 7256 free (2 chunks); 169920 used
      QueryContextMemoryContext: 177616 total in 10 blocks; 6440 free (2 chunks); 171176 used
      QueryContextMemoryContext: 177328 total in 10 blocks; 7352 free (2 chunks); 169976 used
      QueryContextMemoryContext: 177336 total in 10 blocks; 7352 free (2 chunks); 169984 used
      QueryContextMemoryContext: 177624 total in 10 blocks; 6008 free (1 chunks); 171616 used
      QueryContextMemoryContext: 177616 total in 10 blocks; 6008 free (1 chunks); 171608 used
      QueryContextMemoryContext: 178008 total in 10 blocks; 5432 free (1 chunks); 172576 used
      QueryContextMemoryContext: 184784 total in 12 blocks; 6520 free (2 chunks); 178264 used
      QueryContextMemoryContext: 184592 total in 12 blocks; 7304 free (2 chunks); 177288 used
      QueryContextMemoryContext: 184584 total in 12 blocks; 6984 free (2 chunks); 177600 used
      QueryContextMemoryContext: 185536 total in 12 blocks; 6248 free (1 chunks); 179288 used
      QueryContextMemoryContext: 187904 total in 14 blocks; 7352 free (2 chunks); 180552 used
      QueryContextMemoryContext: 184848 total in 12 blocks; 5800 free (1 chunks); 179048 used
      QueryContextMemoryContext: 187472 total in 12 blocks; 6248 free (1 chunks); 181224 used
      QueryContextMemoryContext: 184704 total in 12 blocks; 5432 free (1 chunks); 179272 used
      QueryContextMemoryContext: 177112 total in 10 blocks; 5944 free (2 chunks); 171168 used
      QueryContextMemoryContext: 185328 total in 12 blocks; 4408 free (1 chunks); 180920 used
      QueryContextMemoryContext: 184216 total in 12 blocks; 6248 free (1 chunks); 177968 used
      QueryContextMemoryContext: 188424 total in 14 blocks; 6968 free (2 chunks); 181456 used
      QueryContextMemoryContext: 184376 total in 12 blocks; 5688 free (1 chunks); 178688 used
      QueryContextMemoryContext: 193200 total in 14 blocks; 6488 free (2 chunks); 186712 used
      QueryContextMemoryContext: 177216 total in 10 blocks; 6248 free (1 chunks); 170968 used
      QueryContextMemoryContext: 191680 total in 14 blocks; 6536 free (2 chunks); 185144 used
      QueryContextMemoryContext: 186696 total in 14 blocks; 6536 free (2 chunks); 180160 used
      QueryContextMemoryContext: 181160 total in 12 blocks; 6760 free (2 chunks); 174400 used
      QueryContextMemoryContext: 184432 total in 12 blocks; 6744 free (1 chunks); 177688 used
      QueryContextMemoryContext: 176880 total in 10 blocks; 6440 free (2 chunks); 170440 used
      QueryContextMemoryContext: 181192 total in 12 blocks; 6248 free (2 chunks); 174944 used
      QueryContextMemoryContext: 176592 total in 10 blocks; 7336 free (2 chunks); 169256 used
      QueryContextMemoryContext: 181880 total in 12 blocks; 4920 free (1 chunks); 176960 used
      QueryContextMemoryContext: 179272 total in 10 blocks; 3704 free (1 chunks); 175568 used
      QueryContextMemoryContext: 185272 total in 12 blocks; 6760 free (2 chunks); 178512 used
      QueryContextMemoryContext: 176624 total in 10 blocks; 6824 free (1 chunks); 169800 used
      QueryContextMemoryContext: 176576 total in 10 blocks; 7016 free (2 chunks); 169560 used
      QueryContextMemoryContext: 184272 total in 12 blocks; 5944 free (2 chunks); 178328 used
      QueryContextMemoryContext: 176952 total in 10 blocks; 6200 free (2 chunks); 170752 used
      QueryContextMemoryContext: 176664 total in 10 blocks; 7016 free (2 chunks); 169648 used
      QueryContextMemoryContext: 177248 total in 10 blocks; 5432 free (1 chunks); 171816 used
      QueryContextMemoryContext: 190024 total in 12 blocks; 5432 free (1 chunks); 184592 used
      QueryContextMemoryContext: 187816 total in 14 blocks; 7560 free (2 chunks); 180256 used
      QueryContextMemoryContext: 196520 total in 14 blocks; 6488 free (2 chunks); 190032 used
      QueryContextMemoryContext: 184288 total in 10 blocks; 4744 free (0 chunks); 179544 used
      QueryContextMemoryContext: 189840 total in 12 blocks; 6488 free (2 chunks); 183352 used
      QueryContextMemoryContext: 185376 total in 10 blocks; 3704 free (1 chunks); 181672 used
      QueryContextMemoryContext: 195344 total in 12 blocks; 4456 free (1 chunks); 190888 used
      QueryContextMemoryContext: 200016 total in 14 blocks; 7352 free (2 chunks); 192664 used
      QueryContextMemoryContext: 196768 total in 14 blocks; 6488 free (2 chunks); 190280 used
      QueryContextMemoryContext: 193768 total in 14 blocks; 7304 free (2 chunks); 186464 used
      QueryContextMemoryContext: 194592 total in 14 blocks; 6488 free (2 chunks); 188104 used
      QueryContextMemoryContext: 189248 total in 12 blocks; 7800 free (2 chunks); 181448 used
      QueryContextMemoryContext: 202696 total in 14 blocks; 6488 free (2 chunks); 196208 used
      QueryContextMemoryContext: 190232 total in 12 blocks; 5736 free (1 chunks); 184496 used
      QueryContextMemoryContext: 187280 total in 12 blocks; 6248 free (1 chunks); 181032 used
      QueryContextMemoryContext: 182784 total in 10 blocks; 6536 free (2 chunks); 176248 used
      QueryContextMemoryContext: 184928 total in 10 blocks; 2840 free (0 chunks); 182088 used
      QueryContextMemoryContext: 188272 total in 12 blocks; 6792 free (2 chunks); 181480 used
      QueryContextMemoryContext: 184592 total in 10 blocks; 3864 free (1 chunks); 180728 used
      QueryContextMemoryContext: 182576 total in 10 blocks; 7336 free (2 chunks); 175240 used
      QueryContextMemoryContext: 195376 total in 12 blocks; 6024 free (1 chunks); 189352 used
      QueryContextMemoryContext: 191912 total in 12 blocks; 5688 free (1 chunks); 186224 used
      QueryContextMemoryContext: 188904 total in 12 blocks; 6760 free (2 chunks); 182144 used
      QueryContextMemoryContext: 189584 total in 12 blocks; 3944 free (0 chunks); 185640 used
      30517 more child contexts containing 4681055320 total in 328763 blocks; 185183704 free (37185 chunks); 4495871616 used
    SessionContext: 1714072 total in 99 blocks; 19224 free (528 chunks); 1694848 used
  hba parser context: 7168 total in 3 blocks; 3416 free (2 chunks); 3752 used
  ErrorContext: 8192 total in 1 blocks; 8152 free (5 chunks); 40 used
Grand total: 4721877848 bytes in 330036 blocks; 194100344 free (38831 chunks); 4527777504 used
2019-02-22 18:47:32: pid 157: ERROR: out of memory
2019-02-22 18:47:32: pid 157: DETAIL: Failed on request of size 84112.
2019-02-22 18:47:32: pid 157: WARNING: packet kind of backend 1 ['C'] does not match with master/majority nodes packet kind ['2']
2019-02-22 18:47:32: pid 157: FATAL: failed to read kind from backend
2019-02-22 18:47:32: pid 157: DETAIL: kind mismatch among backends. Possible last query was: " DISCARD ALL" kind details are: 0[2] 1[C]
2019-02-22 18:47:32: pid 157: HINT: check data consistency among db nodes
2019-02-22 18:47:32: pid 13: LOG: child process with pid: 157 exits with status 512
2019-02-22 18:47:32: pid 13: LOG: fork a new child process with pid: 197
2019-02-22 18:47:33: pid 160: ERROR: unable to read data from frontend
2019-02-22 18:47:33: pid 160: DETAIL: EOF encountered with frontend
TagsNo tags attached.

Activities

alexpereira

2019-02-23 04:34

reporter  

pgpool.conf (5,407 bytes)

t-ishii

2019-02-25 09:50

developer   ~0002404

There's a fix for a memory leak case in Pgpool-II 4.0.3. Please try it out.
If you still have a memory leak issue, please provide a test case so that I could reproduce it.

alexpereira

2019-02-26 06:25

reporter   ~0002405

Same problem in version 4.0.3. I'll create a test case

alexpereira

2019-02-28 07:37

reporter   ~0002410

I discovered this problem happens when we use batch inserts. However, performing batch inserts directly to Postgres we do not have the memory leak.

Step by step:

- Create table pgpool_test in Postgres database:

CREATE TABLE public.pgpool_test (
    "name" varchar NULL,
    description varchar NULL,
    reviews varchar NULL,
    price float8 NULL,
    "timestamp" varchar NULL
);

- Install JAVA 8 in Linux
- Add all permissions in table pgpool_test (INSERT, SELECT ...)
- Modify file pgpool_test.sh with access to pgpool
    Example:

    export DATABASE=test
    export USERNAME=admin
    export PASSWORD=12345
    export HOST=localhost:9999 <--- PGPOOL ACCESS

- RUN pgpool_test.sh
pgpool-tester.jar (1,770,744 bytes)
pgpool_tester.sh (134 bytes)

t-ishii

2019-02-28 07:55

developer   ~0002411

Can you share pgpool-test.java?
It would be nice if you share a pgpool.log with log_client_messages = on so that I could reproduce the issue using pgproto.
(pgproto is a standard test tool for developers.)

alexpereira

2019-02-28 23:21

reporter   ~0002412

I am sending the Java project and the log you requested.

Jar file in /target/deployment/pgpool-tester.jar
pgpool-tester.tar.gz (1,619,246 bytes)

alexpereira

2019-02-28 23:40

reporter   ~0002413

I forgot to send the pgpool.log:
https://mega.nz/#!un43mSxQ!9B-KUgG9ctRfhjT9kpwvdXobtLYhhC_-nZHa2dGiD1A

t-ishii

2019-03-01 08:54

developer   ~0002414

It appeared that what you are actually doing is:

Parse (some insert message)
bind
Execute
Parse (another insert message)
bind
Execute
:
:
(repeat many times)

So no cursor is involved here.

Anyway unfortunately this is not good usage pattern for Pgpool-II because Pgpool-II needs to keep all the information those queries (thus consume memory) until "Sync" message is sent from client. This behavior of the JDBC driver is not terribly following PostgreSQL's frontend/backend protoocl IMO:

"At completion of each series of extended-query messages, the frontend should issue a Sync message."
https://www.postgresql.org/docs/11/protocol-flow.html#PROTOCOL-FLOW-EXT-QUERY

So there's not too much what Pgpool-II can do here. Sorry.

alexpereira

2019-03-08 01:13

reporter   ~0002425

For each 100 batch insert messages, the SYNC instruction is sent in the last query. Why memory was not cleaned? Should each insert send SYNC?

"At completion of each series of extended-query messages, the frontend should issue a Sync message."
pgpool.log (734,383 bytes)

alexpereira

2019-03-20 01:40

reporter   ~0002436

Waiting for an answer.

t-ishii

2019-03-20 07:25

developer   ~0002437

Last edited: 2019-03-20 07:26

 As said earlier "100 batch" is not a recommended behavior of clients from the PostgreSQL doc and Pgpool-II's point of view.
In other word, for each execute message clients should issue sync.

In the mean time I am looking for a way to mitigate the memory problem in "batch". But it will take some time because I can spend little time for this (I have other high priority tasks).

t-ishii

2019-03-20 16:07

developer   ~0002438

I was able to find spare time and created a patch to deal with your problem. As far as I concern, your test program runs successfully after applying the patch. Please try it out.
batch-memory-leak.diff (4,767 bytes)    


 batch-memory-leak.diff (4,767 bytes)   
			




	




		
		
		

		

		

			 t-ishii		

		

						2019-03-28 14:18					

		

			developer			 
									
				~0002475			
					

				

		

		

				

		

			
	
	I have committed the patch to master branch. I am going to mark this issue as "resolved" unless you find that the patch does not fix the problem.	




	














	

		
		

	
		

	

		

						Issue History		

		

			
							
		

	

	

	

	

	

		
			

				
					Date Modified				
				
					Username				
				
					Field				
				
					Change				
			

		
	
		
				

				
					2019-02-23 04:34				
				
					alexpereira				
				
					New Issue				
				
									
			

				

				
					2019-02-23 04:34				
				
					alexpereira				
				
					File Added: pgpool.conf				
				
									
			

				

				
					2019-02-25 09:33				
				
					administrator				
				
					Assigned To				
				
					 => t-ishii				
			

				

				
					2019-02-25 09:33				
				
					administrator				
				
					Status				
				
					new => assigned				
			

				

				
					2019-02-25 09:33				
				
					administrator				
				
					Description Updated				
				
									
			

				

				
					2019-02-25 09:50				
				
					t-ishii				
				
					Note Added: 0002404				
				
									
			

				

				
					2019-02-25 09:50				
				
					t-ishii				
				
					Status				
				
					assigned => feedback				
			

				

				
					2019-02-26 06:25				
				
					alexpereira				
				
					Note Added: 0002405				
				
									
			

				

				
					2019-02-26 06:25				
				
					alexpereira				
				
					Status				
				
					feedback => assigned				
			

				

				
					2019-02-28 07:37				
				
					alexpereira				
				
					File Added: pgpool-tester.jar				
				
									
			

				

				
					2019-02-28 07:37				
				
					alexpereira				
				
					File Added: pgpool_tester.sh				
				
									
			

				

				
					2019-02-28 07:37				
				
					alexpereira				
				
					Note Added: 0002410				
				
									
			

				

				
					2019-02-28 07:55				
				
					t-ishii				
				
					Note Added: 0002411				
				
									
			

				

				
					2019-02-28 23:21				
				
					alexpereira				
				
					File Added: pgpool-tester.tar.gz				
				
									
			

				

				
					2019-02-28 23:21				
				
					alexpereira				
				
					Note Added: 0002412				
				
									
			

				

				
					2019-02-28 23:40				
				
					alexpereira				
				
					Note Added: 0002413				
				
									
			

				

				
					2019-03-01 08:54				
				
					t-ishii				
				
					Note Added: 0002414				
				
									
			

				

				
					2019-03-08 01:13				
				
					alexpereira				
				
					File Added: pgpool.log				
				
									
			

				

				
					2019-03-08 01:13				
				
					alexpereira				
				
					Note Added: 0002425				
				
									
			

				

				
					2019-03-20 01:40				
				
					alexpereira				
				
					Note Added: 0002436				
				
									
			

				

				
					2019-03-20 07:25				
				
					t-ishii				
				
					Note Added: 0002437				
				
									
			

				

				
					2019-03-20 07:26				
				
					t-ishii				
				
					Note Edited: 0002437				
				
									
			

				

				
					2019-03-20 16:07				
				
					t-ishii				
				
					File Added: batch-memory-leak.diff				
				
									
			

				

				
					2019-03-20 16:07				
				
					t-ishii				
				
					Note Added: 0002438				
				
									
			

				

				
					2019-03-20 16:07				
				
					t-ishii				
				
					Status				
				
					assigned => feedback				
			

				

				
					2019-03-28 14:18				
				
					t-ishii				
				
					Note Added: 0002475				
				
									
			

				

				
					2019-04-02 13:21				
				
					t-ishii				
				
					Status				
				
					feedback => resolved				
			

				

				
					2019-04-02 13:21				
				
					t-ishii				
				
					Target Version				
				
					 => 4.0.5