MIME-Version: 1.0
From: Kambam Vinay <vinaykambam@gmail.com>
Date: Sat, 9 Mar 2024 21:09:39 +0530
Message-ID: <CANiRfmsK36A0i8mnQtzaxhSm3CUCimPwJPp4WQNq53OdSNkgWg@mail.gmail.com>
Subject: Fix for timestamp lag issue from emit_log_hook when GUC
 log_line_prefix has '%m'
To: pgsql-hackers@postgresql.org
Content-Type: multipart/mixed; boundary="0000000000008e63ad06133c1e09"
Archived-At: <https://www.postgresql.org/message-id/CANiRfmsK36A0i8mnQtzaxhSm3CUCimPwJPp4WQNq53OdSNkgWg%40mail.gmail.com>
Precedence: bulk

--0000000000008e63ad06133c1e09
Content-Type: multipart/alternative; boundary="0000000000008e63ab06133c1e07"

--0000000000008e63ab06133c1e07
Content-Type: text/plain; charset="UTF-8"

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

--0000000000008e63ab06133c1e07
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr"><div>Hi,=C2=A0</div><div><br></div>We observed a slight la=
g in timestamp for a few logs from the emit_log_hook hook implementation wh=
en the log_line_prefix GUC has &#39;%m&#39;. <br><br>Upon debugging, we fou=
nd that the saved_timeval_set variable is set to &#39;true&#39; in get_form=
atted_log_time() but is not reset to &#39;false&#39; 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 times=
tamp &#39;saved_timeval&#39; from the previous log line (our hook implement=
ation calls log_line_prefix()).<br><br>Attached patch sets the saved_timeva=
l_set to false before executing the emit_log_hook()<br><div><br></div><div>=
Thanks,</div><div>Vinay</div></div>

--0000000000008e63ab06133c1e07--
--0000000000008e63ad06133c1e09
Content-Type: application/octet-stream; 
	name="0001-set-saved_timeval_set-to-false-before-executing-emit.patch"
Content-Disposition: attachment; 
	filename="0001-set-saved_timeval_set-to-false-before-executing-emit.patch"
Content-Transfer-Encoding: base64
Content-ID: <f_ltk9086p0>
X-Attachment-Id: f_ltk9086p0

RnJvbSBjOGVjZWEyMzc1ZWUzZWM0NjExN2FjMDZiMzg0ZjM5ZGE1NjA2NzBlIE1vbiBTZXAgMTcg
MDA6MDA6MDAgMjAwMQpGcm9tOiBWaW5heSBLYW1iYW0gPHZpbmF5a2FtYmFtQGdtYWlsLmNvbT4K
RGF0ZTogU2F0LCA5IE1hciAyMDI0IDE5OjUyOjEwICswNTMwClN1YmplY3Q6IFtQQVRDSF0gc2V0
IHNhdmVkX3RpbWV2YWxfc2V0IHRvIGZhbHNlIGJlZm9yZSBleGVjdXRpbmcKIGVtaXRfbG9nX2hv
b2soKQoKLS0tCiBzcmMvYmFja2VuZC91dGlscy9lcnJvci9lbG9nLmMgfCAxICsKIDEgZmlsZSBj
aGFuZ2VkLCAxIGluc2VydGlvbigrKQoKZGlmZiAtLWdpdCBhL3NyYy9iYWNrZW5kL3V0aWxzL2Vy
cm9yL2Vsb2cuYyBiL3NyYy9iYWNrZW5kL3V0aWxzL2Vycm9yL2Vsb2cuYwppbmRleCBlZDhhYTVj
OWZhLi5lNzM1ZjUxMjA3IDEwMDY0NAotLS0gYS9zcmMvYmFja2VuZC91dGlscy9lcnJvci9lbG9n
LmMKKysrIGIvc3JjL2JhY2tlbmQvdXRpbHMvZXJyb3IvZWxvZy5jCkBAIC0xNjk3LDYgKzE2OTcs
NyBAQCBFbWl0RXJyb3JSZXBvcnQodm9pZCkKIAkgKiBtZXNzYWdlIGlkZW50aWZpZXIuIE5vdGUg
dGhhdCB0aGUgb3JpZ2luYWwgdGV4dCBpcyBub3QgYXZhaWxhYmxlIGZvcgogCSAqIGRldGFpbCwg
ZGV0YWlsX2xvZywgaGludCBhbmQgY29udGV4dCB0ZXh0IGVsZW1lbnRzLgogCSAqLworCXNhdmVk
X3RpbWV2YWxfc2V0ID0gZmFsc2U7CiAJaWYgKGVkYXRhLT5vdXRwdXRfdG9fc2VydmVyICYmIGVt
aXRfbG9nX2hvb2spCiAJCSgqZW1pdF9sb2dfaG9vaykgKGVkYXRhKTsKIAotLSAKMi4zNC4xCgo=
--0000000000008e63ad06133c1e09--