Why are wait events not reported even though it reads/writes a timeline history file?

On 2020/04/24 11:29, Masahiro Ikeda wrote:

Hi,

There are two unexpected codes for me about wait events for timeline history file.
Please let me know your thoughts whether if we need to change.

1. readTimeLineHistory() function in timeline.c

The readTimeLineHistory() reads a timeline history file,
but it doesn't report “WAIT_EVENT_TIMELINE_HISTORY_READ".

Yeah, this sounds strange.

In my understanding, sscanf() is blocking read.
So, it's important to report a wait event.

Shouldn't the wait event be reported during fgets() rather than sscanf()?

2. writeTimeLineHistory() function in timeline.c

The writeTimeLineHistory() function may write a timeline history file twice,
but it reports “WAIT_EVENT_TIMELINE_HISTORY_WRITE" only once.

It makes sense to report a wait event twice, because both of them use write().

Yes.

I attached a patch to mention the code line number.

I checked the commit log which "WAIT_EVENT_TIMELINE_HISTORY_READ" and
"WAIT_EVENT_TIMELINE_HISTORY_WRITE" are committed and the discussion about it.
But I can't find the reason.

Please give me your comments.
If we need to change, I can make a patch to fix them.

Thanks! I agree to fix those issues.

By the way, which is correct "timeline's history file" or "timeline history file"?
The timeline.c has both. In my understanding, the latter is correct. If so, I will modify together.

Maybe both are correct?? I have no strong opinion about this.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On 2020-04-27 12:25, Fujii Masao wrote:

On 2020/04/24 11:29, Masahiro Ikeda wrote:

Hi,

There are two unexpected codes for me about wait events for timeline
history file.
Please let me know your thoughts whether if we need to change.

1. readTimeLineHistory() function in timeline.c

The readTimeLineHistory() reads a timeline history file,
but it doesn't report “WAIT_EVENT_TIMELINE_HISTORY_READ".

Yeah, this sounds strange.

In my understanding, sscanf() is blocking read.
So, it's important to report a wait event.

Shouldn't the wait event be reported during fgets() rather than
sscanf()?

2. writeTimeLineHistory() function in timeline.c

The writeTimeLineHistory() function may write a timeline history file
twice,
but it reports “WAIT_EVENT_TIMELINE_HISTORY_WRITE" only once.

It makes sense to report a wait event twice, because both of them use
write().

Yes.

I attached a patch to mention the code line number.

I checked the commit log which "WAIT_EVENT_TIMELINE_HISTORY_READ" and
"WAIT_EVENT_TIMELINE_HISTORY_WRITE" are committed and the discussion
about it.
But I can't find the reason.

Please give me your comments.
If we need to change, I can make a patch to fix them.

Thanks! I agree to fix those issues.

Thanks for the comments. I attach a patch to fix those issues.
Please review it.

By the way, which is correct "timeline's history file" or "timeline
history file"?
The timeline.c has both. In my understanding, the latter is correct.
If so, I will modify together.

Maybe both are correct?? I have no strong opinion about this.

OK, I didn't fix it at this time.

Regards,
--
Masahiro Ikeda

On 2020/04/28 11:10, Masahiro Ikeda wrote:

On 2020-04-27 12:25, Fujii Masao wrote:

On 2020/04/24 11:29, Masahiro Ikeda wrote:

Hi,

There are two unexpected codes for me about wait events for timeline history file.
Please let me know your thoughts whether if we need to change.

1. readTimeLineHistory() function in timeline.c

The readTimeLineHistory() reads a timeline history file,
but it doesn't report “WAIT_EVENT_TIMELINE_HISTORY_READ".

Yeah, this sounds strange.

In my understanding, sscanf() is blocking read.
So, it's important to report a wait event.

Shouldn't the wait event be reported during fgets() rather than sscanf()?

2. writeTimeLineHistory() function in timeline.c

The writeTimeLineHistory() function may write a timeline history file twice,
but it reports “WAIT_EVENT_TIMELINE_HISTORY_WRITE" only once.

It makes sense to report a wait event twice, because both of them use write().

Yes.

I attached a patch to mention the code line number.

I checked the commit log which "WAIT_EVENT_TIMELINE_HISTORY_READ" and
"WAIT_EVENT_TIMELINE_HISTORY_WRITE" are committed and the discussion about it.
But I can't find the reason.

Please give me your comments.
If we need to change, I can make a patch to fix them.

Thanks! I agree to fix those issues.

Thanks for the comments. I attach a patch to fix those issues.
Please review it.

Thanks for the patch!

         prevend = InvalidXLogRecPtr;
+       pgstat_report_wait_start(WAIT_EVENT_TIMELINE_HISTORY_READ);
         while (fgets(fline, sizeof(fline), fd) != NULL)
         {
                 /* skip leading whitespace and check for # comment */
@@ -172,6 +173,7 @@ readTimeLineHistory(TimeLineID targetTLI)

/* we ignore the remainder of each line */
}
+ pgstat_report_wait_end();

Isn't it safer to report the wait event during fgets() rather than putting
those calls around the whole loop, like other code does? For example,
writeTimeLineHistory() reports the wait event during read() rather than
whole loop.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On Tue, Apr 28, 2020 at 02:49:00PM +0900, Fujii Masao wrote:

Isn't it safer to report the wait event during fgets() rather than putting
those calls around the whole loop, like other code does? For example,
writeTimeLineHistory() reports the wait event during read() rather than
whole loop.

Yeah, I/O wait events should be taken only during the duration of the
system calls. Particularly here, you may finish with an elog() that
causes the wait event to be set longer than it should, leading to a
rather incorrect state if a snapshot of pg_stat_activity is taken.
--
Michael

On 2020-04-28 15:09, Michael Paquier wrote:

On Tue, Apr 28, 2020 at 02:49:00PM +0900, Fujii Masao wrote:

Isn't it safer to report the wait event during fgets() rather than
putting
those calls around the whole loop, like other code does? For example,
writeTimeLineHistory() reports the wait event during read() rather
than
whole loop.

Yeah, I/O wait events should be taken only during the duration of the
system calls. Particularly here, you may finish with an elog() that
causes the wait event to be set longer than it should, leading to a
rather incorrect state if a snapshot of pg_stat_activity is taken.
--

Thanks for your comments.

I fixed it to report the wait event during fgets() only.
Please review the v2 patch I attached.

Regard,
--
Masahiro Ikeda

On 2020/04/28 17:42, Masahiro Ikeda wrote:

On 2020-04-28 15:09, Michael Paquier wrote:

On Tue, Apr 28, 2020 at 02:49:00PM +0900, Fujii Masao wrote:

Isn't it safer to report the wait event during fgets() rather than putting
those calls around the whole loop, like other code does? For example,
writeTimeLineHistory() reports the wait event during read() rather than
whole loop.

Yeah, I/O wait events should be taken only during the duration of the
system calls.� Particularly here, you may finish with an elog() that
causes the wait event to be set longer than it should, leading to a
rather incorrect state if a snapshot of pg_stat_activity is taken.
--

Thanks for your comments.

I fixed it to report the wait event during fgets() only.
Please review the v2 patch I attached.

Thanks for updating the patch! Here are the review comments from me.

+		char	   *result;
+		pgstat_report_wait_start(WAIT_EVENT_TIMELINE_HISTORY_READ);
+		result = fgets(fline, sizeof(fline), fd);
+		pgstat_report_wait_end();
+		if (result == NULL)
+			break;
+
  		/* skip leading whitespace and check for # comment */
  		char	   *ptr;

Since the variable name "result" has been already used in this function,
it should be renamed.

The code should not be inject into the variable declaration block.

When reading this patch, I found that IO-error in fgets() has not
been checked there. Though this is not the issue that you reported,
but it seems better to fix it together. So what about adding
the following code?

if (ferror(fd))
ereport(ERROR,
(errcode_for_file_access(),
errmsg("could not read file \"%s\": %m", path)));

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On 2020-05-01 00:25, Fujii Masao wrote:

On 2020/04/28 17:42, Masahiro Ikeda wrote:

On 2020-04-28 15:09, Michael Paquier wrote:

On Tue, Apr 28, 2020 at 02:49:00PM +0900, Fujii Masao wrote:

Isn't it safer to report the wait event during fgets() rather than
putting
those calls around the whole loop, like other code does? For
example,
writeTimeLineHistory() reports the wait event during read() rather
than
whole loop.

Yeah, I/O wait events should be taken only during the duration of the
system calls.  Particularly here, you may finish with an elog() that
causes the wait event to be set longer than it should, leading to a
rather incorrect state if a snapshot of pg_stat_activity is taken.
--

Thanks for your comments.

I fixed it to report the wait event during fgets() only.
Please review the v2 patch I attached.

Thanks for updating the patch! Here are the review comments from me.

+		char	   *result;
+		pgstat_report_wait_start(WAIT_EVENT_TIMELINE_HISTORY_READ);
+		result = fgets(fline, sizeof(fline), fd);
+		pgstat_report_wait_end();
+		if (result == NULL)
+			break;
+
/* skip leading whitespace and check for # comment */
char	   *ptr;

Since the variable name "result" has been already used in this
function,
it should be renamed.

Sorry for that.

I thought to rename it, but I changed to use feof()
for clarify the difference from ferror().

The code should not be inject into the variable declaration block.

Thanks for the comment.
I moved the code block after the variable declaration block.

When reading this patch, I found that IO-error in fgets() has not
been checked there. Though this is not the issue that you reported,
but it seems better to fix it together. So what about adding
the following code?

if (ferror(fd))
ereport(ERROR,
(errcode_for_file_access(),
errmsg("could not read file \"%s\": %m", path)));

Thanks, I agree your comment.
I added the above code to the v3 patch I attached.

Regards,
--
Masahiro Ikeda
NTT DATA CORPORATION

On 2020/05/01 10:07, Masahiro Ikeda wrote:

On 2020-05-01 00:25, Fujii Masao wrote:

On 2020/04/28 17:42, Masahiro Ikeda wrote:

On 2020-04-28 15:09, Michael Paquier wrote:

On Tue, Apr 28, 2020 at 02:49:00PM +0900, Fujii Masao wrote:

Isn't it safer to report the wait event during fgets() rather than putting
those calls around the whole loop, like other code does? For example,
writeTimeLineHistory() reports the wait event during read() rather than
whole loop.

Yeah, I/O wait events should be taken only during the duration of the
system calls.  Particularly here, you may finish with an elog() that
causes the wait event to be set longer than it should, leading to a
rather incorrect state if a snapshot of pg_stat_activity is taken.
--

Thanks for your comments.

I fixed it to report the wait event during fgets() only.
Please review the v2 patch I attached.

Thanks for updating the patch! Here are the review comments from me.

+        char       *result;
+        pgstat_report_wait_start(WAIT_EVENT_TIMELINE_HISTORY_READ);
+        result = fgets(fline, sizeof(fline), fd);
+        pgstat_report_wait_end();
+        if (result == NULL)
+            break;
+
         /* skip leading whitespace and check for # comment */
         char       *ptr;

Since the variable name "result" has been already used in this function,
it should be renamed.

Sorry for that.

I thought to rename it, but I changed to use feof()
for clarify the difference from ferror().

The code should not be inject into the variable declaration block.

Thanks for the comment.
I moved the code block after the variable declaration block.

When reading this patch, I found that IO-error in fgets() has not
been checked there. Though this is not the issue that you reported,
but it seems better to fix it together. So what about adding
the following code?

    if (ferror(fd))
        ereport(ERROR,
            (errcode_for_file_access(),
             errmsg("could not read file \"%s\": %m", path)));

Thanks, I agree your comment.
I added the above code to the v3 patch I attached.

Thanks for updating the patch! It looks good to me.

I applied cosmetic changes to the patch (attached). Barring any objection,
I will push this patch (also back-patch to v10 where wait-event for timeline
file was added).

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On Fri, May 01, 2020 at 12:04:56PM +0900, Fujii Masao wrote:

I applied cosmetic changes to the patch (attached). Barring any objection,
I will push this patch (also back-patch to v10 where wait-event for timeline
file was added).

Sorry for arriving late to the party. I have one tiny comment.

+		pgstat_report_wait_start(WAIT_EVENT_TIMELINE_HISTORY_READ);
+		res = fgets(fline, sizeof(fline), fd);
+		pgstat_report_wait_end();
+		if (ferror(fd))
+			ereport(ERROR,
+					(errcode_for_file_access(),
+					 errmsg("could not read file \"%s\": %m", path)));
+		if (res == NULL)
+			break;

It seems to me that there is no point to check ferror() if fgets()
does not return NULL, no?
--
Michael

On 2020/05/02 11:24, Michael Paquier wrote:

On Fri, May 01, 2020 at 12:04:56PM +0900, Fujii Masao wrote:

I applied cosmetic changes to the patch (attached). Barring any objection,
I will push this patch (also back-patch to v10 where wait-event for timeline
file was added).

Sorry for arriving late to the party. I have one tiny comment.

+		pgstat_report_wait_start(WAIT_EVENT_TIMELINE_HISTORY_READ);
+		res = fgets(fline, sizeof(fline), fd);
+		pgstat_report_wait_end();
+		if (ferror(fd))
+			ereport(ERROR,
+					(errcode_for_file_access(),
+					 errmsg("could not read file \"%s\": %m", path)));
+		if (res == NULL)
+			break;

It seems to me that there is no point to check ferror() if fgets()
does not return NULL, no?

Yeah, so I updated the patch so that ferror() is called only
when fgets() returns NULL. Attached is the updated version of
the patch.

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

On Thu, May 07, 2020 at 04:51:16PM +0900, Fujii Masao wrote:

Yeah, so I updated the patch so that ferror() is called only
when fgets() returns NULL. Attached is the updated version of
the patch.

Thanks for the new patch. LGTM.
--
Michael

On 2020/05/07 21:24, Michael Paquier wrote:

On Thu, May 07, 2020 at 04:51:16PM +0900, Fujii Masao wrote:

Yeah, so I updated the patch so that ferror() is called only
when fgets() returns NULL. Attached is the updated version of
the patch.

Thanks for the new patch. LGTM.

Pushed. Thanks!

Regards,

--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION