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

Andrey Zhidenkov andrey.zhidenkov at gmail.com
Tue Nov 13 00:38:02 JST 2018


Thank you for your answer, Tatsuo.

I've reported this issue in pgpool-II bugtracker:
https://www.pgpool.net/mantisbt/view.php?id=444
On Mon, Nov 12, 2018 at 7:38 PM Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
>
> > Is seems that I finally found the root cause of the problem. It turned
> > out that startup packet contents are not identical while they lengths
> > are equal and we fail at this assertion:
> >
> > else if (memcmp(sp->startup_packet,
> > MASTER_CONNECTION(backend)->sp->startup_packet, sp->len) != 0)
> > {
> >   ereport(DEBUG1, (errmsg("selecting backend connection"),
> > errdetail("connection exists but startup packet contents is not
> > identical")));
> >   found = 0;
> > }
> >
> > https://github.com/pgpool/pgpool2/blob/master/src/protocol/child.c#L2242
> >
> > It seems that Golang pg driver sorts connection parameters in a
> > different way. I've added logging of startup packet contents and got
> > this:
> >
> > 2018-11-12 16:19:15 DEBUG: pid 24403: Startup packet 1:
> > [0][3][0][0]user[0]postgres[0]client_encoding[0]UTF8[0]datestyle[0]ISO[2c][20]MDY[0]extra_float_digits[0]2[0]database[0]test[0][0]
> > 2018-11-12 16:19:15 DEBUG: pid 24403: Startup packet 2:
> > [0][3][0][0]client_encoding[0]UTF8[0]datestyle[0]ISO[2c][20]MDY[0]extra_float_digits[0]2[0]database[0]test[0]user[0]postgres[0][0]
>
> Interesting. So go lang dirver sorts out parameters in random order in
> startup packets. I've never seen such drivers before.
>
> > The questions are:
> > 1) Is connection arguments order is specified in libpq/protocol?
>
> No.
>
> > 2) Why this order is important to pgpool if all params are identical?
>
> Sort order is not important for Pgpool-II. But Pgpool-II simply
> comapres the startup packet contents byte-to-byte because it's cheap
> and simple (and we have had no complains from field until today).
>
> > On Mon, Nov 12, 2018 at 11:42 AM Andrey Zhidenkov
> > <andrey.zhidenkov at gmail.com> wrote:
> >>
> >> 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
> >
> >
> >
> > --
> > -
> > With best regards, Andrey Zhidenkov



-- 
-
With best regards, Andrey Zhidenkov


More information about the pgpool-general mailing list