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

Andrey Zhidenkov andrey.zhidenkov at gmail.com
Mon Nov 12 18:32:36 JST 2018 

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]

The questions are:
1) Is connection arguments order is specified in libpq/protocol?
2) Why this order is important to pgpool if all params are identical?
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

More information about the pgpool-general mailing list