Fix for timestamp lag issue from emit_log_hook when GUC log_line_prefix has '%m'

Kambam Vinay <vinaykambam@gmail.com>

From: Kambam Vinay <vinaykambam@gmail.com>
To: pgsql-hackers@postgresql.org
Date: 2024-03-09T15:39:39Z
Lists: pgsql-hackers

Attachments

Hi,

We observed a slight lag in timestamp for a few logs from the emit_log_hook
hook implementation when the log_line_prefix GUC has '%m'.

Upon debugging, we found that the saved_timeval_set variable is set to
'true' in get_formatted_log_time() but is not reset to 'false' until the
next call to send_message_to_server_log(). Due to this, saved_timeval_set
will be true during the execution of hook emit_log_hook() which prefixes
the saved timestamp 'saved_timeval' from the previous log line (our hook
implementation calls log_line_prefix()).

Attached patch sets the saved_timeval_set to false before executing the
emit_log_hook()

Thanks,
Vinay

Commits

  1. Coordinate emit_log_hook and all log destinations to share the same timeval