MIME-Version: 1.0
References: <CANiRfmsK36A0i8mnQtzaxhSm3CUCimPwJPp4WQNq53OdSNkgWg@mail.gmail.com>
 <Ze62CoRj9g3c1e9N@paquier.xyz>
In-Reply-To: <Ze62CoRj9g3c1e9N@paquier.xyz>
From: Kambam Vinay <vinaykambam@gmail.com>
Date: Sun, 17 Mar 2024 19:35:57 +0530
Message-ID: <CANiRfmtBUuMLJ5pn3PsDeKZcEHaJ1mbm9Fb5-LHsBWzmd5m=Ag@mail.gmail.com>
Subject: Re: Fix for timestamp lag issue from emit_log_hook when GUC
 log_line_prefix has '%m'
To: Michael Paquier <michael@paquier.xyz>
Cc: pgsql-hackers@postgresql.org
Content-Type: multipart/mixed; boundary="0000000000002b3eaf0613dbbe6b"
Archived-At: <https://www.postgresql.org/message-id/CANiRfmtBUuMLJ5pn3PsDeKZcEHaJ1mbm9Fb5-LHsBWzmd5m%3DAg%40mail.gmail.com>
Precedence: bulk

--0000000000002b3eaf0613dbbe6b
Content-Type: multipart/alternative; boundary="0000000000002b3ead0613dbbe69"

--0000000000002b3ead0613dbbe69
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

Thanks Michael for the review. Agree with your comment on the patch.
updated the patch with recommended change.

Thanks,
Vinay

On Mon, Mar 11, 2024 at 1:13=E2=80=AFPM Michael Paquier <michael@paquier.xy=
z> wrote:

> On Sat, Mar 09, 2024 at 09:09:39PM +0530, Kambam Vinay wrote:
> > 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 th=
e
> > next call to send_message_to_server_log(). Due to this, saved_timeval_s=
et
> > will be true during the execution of hook emit_log_hook() which prefixe=
s
> > the saved timestamp 'saved_timeval' from the previous log line (our hoo=
k
> > implementation calls log_line_prefix()).
> >
> > Attached patch sets the saved_timeval_set to false before executing the
> > emit_log_hook()
>
> Indeed.  If you rely on log_line_prefix() in your hook before the
> server side elog, the saved timestamp would not match with what could
> be computed in the follow-up send_message_to_server_log or
> send_message_to_frontend.
>
> Hmm.  Shouldn't we remove the forced reset of formatted_log_time for
> the 'm' case in log_status_format() and remove the reset done at the
> beginning of send_message_to_server_log()?  One problem with your
> patch is that we would still finish with a different saved_timeval in
> the hook and in send_message_to_server_log(), but we should do things
> so as the timestamps are the same for the whole duration of
> EmitErrorReport(), no?  It seems to me that a more correct solution
> would be to reset saved_timeval_set and formatted_log_time[0] once
> before the hook, at the beginning of EmitErrorReport().
> --
> Michael
>

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

<div dir=3D"ltr"><div>Thanks=C2=A0Michael for the review. Agree with your c=
omment on the patch. updated the patch with recommended change.=C2=A0</div>=
<div><br></div><div>Thanks,</div><div>Vinay</div><br><div class=3D"gmail_qu=
ote"><div dir=3D"ltr" class=3D"gmail_attr">On Mon, Mar 11, 2024 at 1:13=E2=
=80=AFPM Michael Paquier &lt;<a href=3D"mailto:michael@paquier.xyz">michael=
@paquier.xyz</a>&gt; wrote:<br></div><blockquote class=3D"gmail_quote" styl=
e=3D"margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);paddin=
g-left:1ex">On Sat, Mar 09, 2024 at 09:09:39PM +0530, Kambam Vinay wrote:<b=
r>
&gt; We observed a slight lag in timestamp for a few logs from the emit_log=
_hook<br>
&gt; hook implementation when the log_line_prefix GUC has &#39;%m&#39;.<br>
&gt; <br>
&gt; Upon debugging, we found that the saved_timeval_set variable is set to=
<br>
&gt; &#39;true&#39; in get_formatted_log_time() but is not reset to &#39;fa=
lse&#39; until the<br>
&gt; next call to send_message_to_server_log(). Due to this, saved_timeval_=
set<br>
&gt; will be true during the execution of hook emit_log_hook() which prefix=
es<br>
&gt; the saved timestamp &#39;saved_timeval&#39; from the previous log line=
 (our hook<br>
&gt; implementation calls log_line_prefix()).<br>
&gt; <br>
&gt; Attached patch sets the saved_timeval_set to false before executing th=
e<br>
&gt; emit_log_hook()<br>
<br>
Indeed.=C2=A0 If you rely on log_line_prefix() in your hook before the<br>
server side elog, the saved timestamp would not match with what could<br>
be computed in the follow-up send_message_to_server_log or<br>
send_message_to_frontend.<br>
<br>
Hmm.=C2=A0 Shouldn&#39;t we remove the forced reset of formatted_log_time f=
or<br>
the &#39;m&#39; case in log_status_format() and remove the reset done at th=
e<br>
beginning of send_message_to_server_log()?=C2=A0 One problem with your<br>
patch is that we would still finish with a different saved_timeval in<br>
the hook and in send_message_to_server_log(), but we should do things<br>
so as the timestamps are the same for the whole duration of<br>
EmitErrorReport(), no?=C2=A0 It seems to me that a more correct solution<br=
>
would be to reset saved_timeval_set and formatted_log_time[0] once<br>
before the hook, at the beginning of EmitErrorReport().<br>
--<br>
Michael<br>
</blockquote></div></div>

--0000000000002b3ead0613dbbe69--
--0000000000002b3eaf0613dbbe6b
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_ltvk8cf70>
X-Attachment-Id: f_ltvk8cf70

RnJvbSBkYjIyMWQwNjI3ODdiYjUxYjU2YmQ5MjEzM2M5NjMzYmYwYzM4YTFhIE1vbiBTZXAgMTcg
MDA6MDA6MDAgMjAwMQpGcm9tOiBWaW5heSBLYW1iYW0gPHZpbmF5a2FtYmFtQGdtYWlsLmNvbT4K
RGF0ZTogU2F0LCA5IE1hciAyMDI0IDE5OjUyOjEwICswNTMwClN1YmplY3Q6IFtQQVRDSF0gc2V0
IHNhdmVkX3RpbWV2YWxfc2V0IHRvIGZhbHNlIGJlZm9yZSBleGVjdXRpbmcKIGVtaXRfbG9nX2hv
b2soKQoKLS0tCiBzcmMvYmFja2VuZC91dGlscy9lcnJvci9lbG9nLmMgfCA4ICsrKy0tLS0tCiAx
IGZpbGUgY2hhbmdlZCwgMyBpbnNlcnRpb25zKCspLCA1IGRlbGV0aW9ucygtKQoKZGlmZiAtLWdp
dCBhL3NyYy9iYWNrZW5kL3V0aWxzL2Vycm9yL2Vsb2cuYyBiL3NyYy9iYWNrZW5kL3V0aWxzL2Vy
cm9yL2Vsb2cuYwppbmRleCA1MmJjMDEwNThjLi40ZTI1Yzc0YzQ3IDEwMDY0NAotLS0gYS9zcmMv
YmFja2VuZC91dGlscy9lcnJvci9lbG9nLmMKKysrIGIvc3JjL2JhY2tlbmQvdXRpbHMvZXJyb3Iv
ZWxvZy5jCkBAIC0xNjc4LDYgKzE2NzgsOSBAQCBFbWl0RXJyb3JSZXBvcnQodm9pZCkKIAlDSEVD
S19TVEFDS19ERVBUSCgpOwogCW9sZGNvbnRleHQgPSBNZW1vcnlDb250ZXh0U3dpdGNoVG8oZWRh
dGEtPmFzc29jX2NvbnRleHQpOwogCisJc2F2ZWRfdGltZXZhbF9zZXQgPSBmYWxzZTsKKwlmb3Jt
YXR0ZWRfbG9nX3RpbWVbMF0gPSAnXDAnOworCiAJLyoKIAkgKiBDYWxsIGhvb2sgYmVmb3JlIHNl
bmRpbmcgbWVzc2FnZSB0byBsb2cuICBUaGUgaG9vayBmdW5jdGlvbiBpcyBhbGxvd2VkCiAJICog
dG8gdHVybiBvZmYgZWRhdGEtPm91dHB1dF90b19zZXJ2ZXIsIHNvIHdlIG11c3QgcmVjaGVjayB0
aGF0IGFmdGVyd2FyZC4KQEAgLTI5NDgsOCArMjk1MSw2IEBAIGxvZ19zdGF0dXNfZm9ybWF0KFN0
cmluZ0luZm8gYnVmLCBjb25zdCBjaGFyICpmb3JtYXQsIEVycm9yRGF0YSAqZWRhdGEpCiAJCQkJ
CWFwcGVuZFN0cmluZ0luZm8oYnVmLCAiJWxkIiwgbG9nX2xpbmVfbnVtYmVyKTsKIAkJCQlicmVh
azsKIAkJCWNhc2UgJ20nOgotCQkJCS8qIGZvcmNlIGEgbG9nIHRpbWVzdGFtcCByZXNldCAqLwot
CQkJCWZvcm1hdHRlZF9sb2dfdGltZVswXSA9ICdcMCc7CiAJCQkJKHZvaWQpIGdldF9mb3JtYXR0
ZWRfbG9nX3RpbWUoKTsKIAogCQkJCWlmIChwYWRkaW5nICE9IDApCkBAIC0zMTUxLDkgKzMxNTIs
NiBAQCBzZW5kX21lc3NhZ2VfdG9fc2VydmVyX2xvZyhFcnJvckRhdGEgKmVkYXRhKQogCiAJaW5p
dFN0cmluZ0luZm8oJmJ1Zik7CiAKLQlzYXZlZF90aW1ldmFsX3NldCA9IGZhbHNlOwotCWZvcm1h
dHRlZF9sb2dfdGltZVswXSA9ICdcMCc7Ci0KIAlsb2dfbGluZV9wcmVmaXgoJmJ1ZiwgZWRhdGEp
OwogCWFwcGVuZFN0cmluZ0luZm8oJmJ1ZiwgIiVzOiAgIiwgXyhlcnJvcl9zZXZlcml0eShlZGF0
YS0+ZWxldmVsKSkpOwogCi0tIAoyLjM0LjEKCg==
--0000000000002b3eaf0613dbbe6b--