[pgpool-hackers: 4539] Re: New feature: log_backend_messages

[Tatsuo Ishii]

>> Hi Peng,
>> 
>> Thank you for the feedback.
>> 
>>> Hi Ishii-san,
>>> 
>>> Thank you for your proposal.
>>> I think it is a useful feature for debugging.
>>> 
>>>> One thing maybe better to think about the feature is, whether we want to show the log line:
>>>> 2024-11-25 13:50:43.735: pgproto pid 325721: LOG:  DataRow message from backend 0
>>> 
>>> Yes, I agree with you to log messages using the message instead of the message kind.
>> 
>> Ok, attached is the patch to implement it.  The log messages look like
>> below.
>> 
>> One thing I am wondering is, when a particular message is repeating,
>> pgpool will not print the log immediately, just keep the number of
>> messages while the same message type keeps on arriving. Once a
>> different message type arrives, pgpool prints like:
>> 
>> 2024-11-27 17:08:35.245: pgproto pid 487733: LOG: last ParameterStatus message from backend 0 repeated 13 times
>> 
>> But what if the pgpool session terminates before the next different
>> message arrives? pgpool print nothing. Thought?
> 
> After thinking more, maybe this is not a practical issue because
> DataRow messages are always followed by CommandComplete or
> ErrorResponse. Same thing can be said to ParameterStatus
> messages. They are follwed by BackendKeyData or ErrorResponse. Also
> this is applied to CopyData. The only case these are broken is, the
> child process is killed while counting the number of messages.  Maybe
> we could make log_backend_messages to take not only just on or off,
> but something like:
> 
> off: the default
> terse: current patch behavior (e.g. "last DataRow message from backend 0 repeated 7 times")
> verbose: log each message as soon as it is detected. This never miss
> 	 log messages even when the child process is killed, but could produce lots of log lines.

If we go the direction, we should allow to change the
log_backend_messages value using "pgpool set" command to make
testing/debugging easier: i.e. we set the value to terse or off in
normal circumstance, once we need to testing/debugging we run "pgpool
set log_backend_messages to verbose".

>> =========================== Log messages with log_backend_messages =========================
>> 
>> 2024-11-27 17:08:35.244: child pid 487733: LOG:  AuthenticationRequest message from backend 0
>> 2024-11-27 17:08:35.244: child pid 487733: LOG:  AuthenticationRequest message from backend 1
>> 2024-11-27 17:08:35.244: child pid 487733: LOG:  AuthenticationRequest message from backend 2
>> 2024-11-27 17:08:35.244: child pid 487733: LOG:  ParameterStatus message from backend 0
>> 2024-11-27 17:08:35.244: child pid 487733: LOG:  ParameterStatus message from backend 1
>> 2024-11-27 17:08:35.244: child pid 487733: LOG:  ParameterStatus message from backend 2
>> 2024-11-27 17:08:35.244: child pid 487733: LOG:  ParameterStatus "TimeZone": node 1 message length 17 is different from main node message length 24
>> 2024-11-27 17:08:35.244: child pid 487733: LOG:  ParameterStatus "TimeZone": node 1 message length 17 is different from main node message length 24
>> 2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  last ParameterStatus message from backend 0 repeated 13 times
>> 2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  BackendKeyData message from backend 0
>> 2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  last ParameterStatus message from backend 1 repeated 13 times
>> 2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  BackendKeyData message from backend 1
>> 2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  last ParameterStatus message from backend 2 repeated 13 times
>> 2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  BackendKeyData message from backend 2
>> 2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  ReadyForQuery message from backend 0
>> 2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  ReadyForQuery message from backend 1
>> 2024-11-27 17:08:35.245: pgproto pid 487733: LOG:  ReadyForQuery message from backend 2
>> 2024-11-27 17:08:35.246: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: SELECT pg_catalog.version()
>> 2024-11-27 17:08:35.247: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: BEGIN
>> 2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  CommandComplete message from backend 0
>> 2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  ReadyForQuery message from backend 0
>> 2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Parse: INSERT INTO t1 VALUES(1)
>> 2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Bind: INSERT INTO t1 VALUES(1)
>> 2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Execute: INSERT INTO t1 VALUES(1)
>> 2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Parse: SELECT * FROM t1
>> 2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Bind: SELECT * FROM t1
>> 2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: Execute: SELECT * FROM t1
>> 2024-11-27 17:08:35.248: pgproto pid 487733: LOG:  ParseComplete message from backend 0
>> 2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  BindComplete message from backend 0
>> 2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  CommandComplete message from backend 0
>> 2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  ParseComplete message from backend 0
>> 2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  BindComplete message from backend 0
>> 2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  DataRow message from backend 0
>> 2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  last DataRow message from backend 0 repeated 7 times
>> 2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  CommandComplete message from backend 0
>> 2024-11-27 17:08:35.249: pgproto pid 487733: LOG:  ReadyForQuery message from backend 0
>> 2024-11-27 17:08:35.250: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: END
>> 2024-11-27 17:08:35.251: pgproto pid 487733: LOG:  CommandComplete message from backend 0
>> 2024-11-27 17:08:35.251: pgproto pid 487733: LOG:  ReadyForQuery message from backend 0
>> 2024-11-27 17:08:35.251: pgproto pid 487733: LOG:  DB node id: 0 backend pid: 487750 statement: DISCARD ALL
>> 2024-11-27 17:08:35.251: pgproto pid 487733: LOG:  CommandComplete message from backend 0
>> 2024-11-27 17:08:35.251: pgproto pid 487733: LOG:  ReadyForQuery message from backend 0
> _______________________________________________
> pgpool-hackers mailing list
> pgpool-hackers at pgpool.net
> http://www.pgpool.net/mailman/listinfo/pgpool-hackers