[pgpool-general: 6277] Re: pgpool does not reuse connections
Tatsuo Ishii
ishii at sraoss.co.jp
Mon Nov 12 21:38:34 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]
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
More information about the pgpool-general
mailing list