[pgpool-general: 6275] Re: pgpool does not reuse connections

Andrey Zhidenkov andrey.zhidenkov at gmail.com
Mon Nov 12 13:42:55 JST 2018 

Here is the debug log from pgpool:

2018-11-12 11:14:31 DEBUG: pid 29922: pool_read_message_length: slot:
0 length: 12
2018-11-12 11:14:31 DEBUG: pid 29922: pool_do_auth:
cp->info[i]:0x7f75457fb000 pid:80
2018-11-12 11:14:31 DEBUG: pid 29922: pool_send_auth_ok: send pid 80 to frontend
2018-11-12 11:14:31 DEBUG: pid 29922: select_load_balancing_node:
selected backend id is 0
2018-11-12 11:14:31 DEBUG: pid 29922: selected load balancing node: 0
2018-11-12 11:14:31 DEBUG: pid 29922: pool_unset_query_in_progress: done
2018-11-12 11:14:31 DEBUG: pid 29922: pool_unset_command_success: done
2018-11-12 11:14:31 DEBUG: pid 29922: pool_unset_writing_transaction: done
2018-11-12 11:14:31 DEBUG: pid 29922: pool_unset_failed_transaction: done
2018-11-12 11:14:31 DEBUG: pid 29922: pool_unset_transaction_isolation: done
2018-11-12 11:14:31 DEBUG: pid 29922:
pool_unset_skip_reading_from_backends: done
2018-11-12 11:14:31 DEBUG: pid 29922: pool_unset_ignore_till_sync: done
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_one_backend: read
kind from 0 th backend Z
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: kind: Z
from 0 th backend
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: read
kind from 0 th backend Z NUM_BACKENDS: 1
2018-11-12 11:14:31 DEBUG: pid 29922: ProcessBackendResponse: kind
from backend: Z
2018-11-12 11:14:31 DEBUG: pid 29922: pool_read_message_length: slot:
0 length: 5
2018-11-12 11:14:31 DEBUG: pid 29922: ReadyForQuery: transaction state:
2018-11-12 11:14:31 DEBUG: pid 29922: ProcessBackendResponse: Ready For Query
2018-11-12 11:14:31 DEBUG: pid 29922: ProcessFrontendResponse: kind
from frontend Q(51)
2018-11-12 11:14:31 DEBUG: pid 29922:
pool_unset_doing_extended_query_message: done
2018-11-12 11:14:31 DEBUG: pid 29922: statement2: SELECT n from
generate_series(1, 100) n
2018-11-12 11:14:31 DEBUG: pid 29922: pool_set_query_in_progress: done
2018-11-12 11:14:31 DEBUG: pid 29922:
pool_has_insertinto_or_locking_clause: returns 0
2018-11-12 11:14:31 DEBUG: pid 29922: send_to_where: 2 query: SELECT n
from generate_series(1, 100) n
2018-11-12 11:14:31 DEBUG: pid 29922: function_call_walker: function
name: generate_series
2018-11-12 11:14:31 DEBUG: pid 29922: pattern_compare:
black_function_list (^nextval$) not matched: generate_series
2018-11-12 11:14:31 DEBUG: pid 29922: pattern_compare:
black_function_list (^setval$) not matched: generate_series
2018-11-12 11:14:31 DEBUG: pid 29922: wait_for_query_response: waiting
for backend 0 completing the query
2018-11-12 11:14:31 DEBUG: pid 29922: detect_error: kind: T
2018-11-12 11:14:31 DEBUG: pid 29922: detect_error: kind: T
2018-11-12 11:14:31 DEBUG: pid 29922: detect_error: kind: T
2018-11-12 11:14:31 DEBUG: pid 29922: detect_error: kind: T
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_one_backend: read
kind from 0 th backend T
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: kind: T
from 0 th backend
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: read
kind from 0 th backend T NUM_BACKENDS: 1
2018-11-12 11:14:31 DEBUG: pid 29922: ProcessBackendResponse: kind
from backend: T
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_one_backend: read
kind from 0 th backend D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: kind: D
from 0 th backend
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: read
kind from 0 th backend D NUM_BACKENDS: 1
2018-11-12 11:14:31 DEBUG: pid 29922: ProcessBackendResponse: kind
from backend: D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_one_backend: read
kind from 0 th backend D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: kind: D
from 0 th backend
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: read
kind from 0 th backend D NUM_BACKENDS: 1
2018-11-12 11:14:31 DEBUG: pid 29922: ProcessBackendResponse: kind
from backend: D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_one_backend: read
kind from 0 th backend D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: kind: D
from 0 th backend
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: read
kind from 0 th backend D NUM_BACKENDS: 1
2018-11-12 11:14:31 DEBUG: pid 29922: ProcessBackendResponse: kind
from backend: D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_one_backend: read
kind from 0 th backend D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: kind: D
from 0 th backend
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: read
kind from 0 th backend D NUM_BACKENDS: 1
2018-11-12 11:14:31 DEBUG: pid 29922: ProcessBackendResponse: kind
from backend: D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_one_backend: read
kind from 0 th backend D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: kind: D
from 0 th backend
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: read
kind from 0 th backend D NUM_BACKENDS: 1
2018-11-12 11:14:31 DEBUG: pid 29922: ProcessBackendResponse: kind
from backend: D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_one_backend: read
kind from 0 th backend D
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: kind: D
from 0 th backend
2018-11-12 11:14:31 DEBUG: pid 29922: read_kind_from_backend: read
kind from 0 th backend D NUM_BACKENDS: 1
2018-11-12 11:14:31 DEBUG: pid 29922: ProcessBackendResponse: kind
from backend: D

I'm concerned about "detect_error: kind: T" messages. What does it
mean? Maybe that is the reason.
On Sun, Nov 11, 2018 at 6:40 AM Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
>
> > On Sat, Nov 10, 2018 at 4:20 AM Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
> >>
> >> > pgpool log is full of messages like these:
> >> >
> >> > pgpool_1    | 2018-11-09 14:53:26: pid 4618: LOG:  new connection received
> >> > pgpool_1    | 2018-11-09 14:53:26: pid 4618: DETAIL:  connecting
> >> > host=172.22.0.1 port=60030
> >>
> >> The log does not help too much (it's normal if you set log_connections
> >> to on).
> >
> > Yes, it's normal. But I suggest there should be less messages than
> > number of "client to pgpool" connections if connection cache is used.
>
> I don't understand what you mean. Connection cache is for between
> pgpool and PostgreSQL, not "client to pgpool" connections.
>
> >> Another possibility is, if the database is one of template0, template1,
> >> postgress or regression, connection cache is not created. Does your
> >> application use those database?  Also if client does not disconnect
> >> proper way (without sending terminate message 'X') then connection
> >> cache is not created.
> >
> > I know about this feature and I used it to force pgpool not to use
> > connection cache and compare the results then. This behavior is
> > observed on database with name different from you have enumerated.
> > Could you please point me to the place in pgpool source code where it
> > doesn't create the connection cache if 'X' terminate message was not
> > send?
>
> In src/protocol/child.c around line 477:
>
>                 if ((sp &&
>                          (!strcmp(sp->database, "template0") ||
>                           !strcmp(sp->database, "template1") ||
>                           !strcmp(sp->database, "postgres") ||
>                           !strcmp(sp->database, "regression"))) ||
>                         (*frontend != NULL &&
>                          ((*frontend)->socket_state == POOL_SOCKET_EOF ||
>                           (*frontend)->socket_state == POOL_SOCKET_ERROR)))
>                         cache_connection = false;
>
> If the socket to frontend is not in good state, which could happen if
> frontend exited abnormaly (did not issue a terminate message),
> cache_connection is set to false and connection cache to backend is
> removed.
>
>         if (cache_connection == false)
>         {
>                 pool_send_frontend_exits(backend);
>                 if (sp)
>                         pool_discard_cp(sp->user, sp->database, sp->major);
>         }
>
>
> >> Finally, if there are too many combinations of user/database (in your
> >> case more than 4 = max_pool), Pgpool-II needs to disconnect the oldest
> >> connection to create a new connection cache.
> >
> > No, all I use only one combination of user/database for testing.
> >
> >> Are one of them is your case?
>
> I remember more cases:
>
> child_life_time
> child_max_connections
> connection_life_time
>
> Depending on those parameters, pgpool will exit or close connections
> to backend. So new connections need to be created next time.
>
> >> Best regards,
> >> --
> >> Tatsuo Ishii
> >> SRA OSS, Inc. Japan
> >> English: http://www.sraoss.co.jp/index_en.php
> >> Japanese:http://www.sraoss.co.jp
> >>
> >> > I wrote test app on golang and succeeded to reproduce this on my local
> >> > machine. Go sql driver uses pq library, written on go from scratch and
> >> > it doesn't use postgres libpq C library. Would that cause the problem?
> >>
> >> No, as far as pq library strictly follows PostgreSQL's
> >> frontend/backend protocol.
> >>
> >> > (https://github.com/lib/pq/blob/master/conn.go#L820).
> >> > On Fri, Nov 9, 2018 at 8:54 PM Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
> >> >>
> >> >> > We have a problem at one of our environments with pgpool. It does not
> >> >> > use connection pool for some reason. Application written on golang (we
> >> >> > use gorm which uses package https://golang.org/pkg/database/sql/)
> >> >> > opens connections to pgpool and executes queries. Application executes
> >> >> > every transaction in a separate connection. In postgresql logs I see
> >> >> > that pgpool constantly connects and disconnects from postgres like as
> >> >> > if connection pool is not used. I tried to reproduce this situation
> >> >> > with pgbench (option --connect) but everything is OK with it. pgpool
> >> >> > works with pgbench as expected - it reuses all connections and doesn't
> >> >> > create a new one for each transaction.
> >> >> >
> >> >> > num_init_children = 100, max_pool =4. max_connections in postgres = 1000.
> >> >> >
> >> >> > We tried pgpool versions 3.3.4 and 3.7.5.
> >> >> >
> >> >> > Any ideas?
> >> >>
> >> >> No idea so far. Can you share pgpool log? 3.7.5 is preferable as 3.3
> >> >> is already EOL.
> >> >>
> >> >> Best regards,
> >> >> --
> >> >> Tatsuo Ishii
> >> >> SRA OSS, Inc. Japan
> >> >> English: http://www.sraoss.co.jp/index_en.php
> >> >> Japanese:http://www.sraoss.co.jp
> >> >
> >> >
> >> >
> >> > --
> >> > -
> >> > With best regards, Andrey Zhidenkov
> >
> >
> >
> > --
> > -
> > With best regards, Andrey Zhidenkov



-- 
-
With best regards, Andrey Zhidenkov

More information about the pgpool-general mailing list