Horton

Thread

Commits

  1. autovacuum: Improve wording in a couple places

  1. Isn't it better with "autovacuum worker...." instead of "worker took too long to start; canceled" specific to "auto

    Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> — 2021-10-27T16:26:37Z

    Hi,

Is there a specific reason that we have a generic WARNING "worker took
too long to start; canceled" for an autovacuum worker? Isn't it better
with "autovacuum worker took too long to start; canceled"? It is
confusing to see the generic message in the server logs while
debugging an issue for a user who doesn't know the internals of
autovacuum code.

To be more informative about the message, how about the following:
1) ereport(WARNING,
                    (errmsg( "worker took too long to start"),
                     errdetail("Previous attempt to start autovacuum
worker was failed, canceled.")));
or
2) ereport(WARNING,
                    (errmsg( "worker took too long to start, canceled"),
                     errdetail("The postmaster couldn't start an
autovacuum worker.")));
or
3) ereport(WARNING,
                    (errmsg( "worker took too long to start, canceled"),
                     errdetail("Previous attempt to start autovacuum
worker was failed.")));
or
4) elog(WARNING, "postmaster couldn't start an autovacuum worker");

Thoughts?

Regards,
Bharath Rupireddy.

  2. Re: Isn't it better with "autovacuum worker...." instead of "worker took too long to start; canceled" specific to "auto

    Nathan Bossart <bossartn@amazon.com> — 2021-10-27T19:05:10Z

    On 10/27/21, 9:29 AM, "Bharath Rupireddy" <bharath.rupireddyforpostgres@gmail.com> wrote:
> Is there a specific reason that we have a generic WARNING "worker took
> too long to start; canceled" for an autovacuum worker? Isn't it better
> with "autovacuum worker took too long to start; canceled"? It is
> confusing to see the generic message in the server logs while
> debugging an issue for a user who doesn't know the internals of
> autovacuum code.

It looks like it has been this way for a while [0].  I don't know if
I've ever seen this message before, and from the comments near it, it
sounds like it is expected to rarely happen.

> To be more informative about the message, how about the following:

My vote is to just change it to

        ereport(WARNING,
                (errmsg("autovacuum worker took too long to start; canceled")));

and call it a day.  If we wanted to add errdetail(), I think we should
make sure it is providing useful context, but I'm not sure what that
might look like.

Nathan

[0] https://git.postgresql.org/gitweb/?p=postgresql.git;a=commit;h=bae0b56

  3. Re: Isn't it better with "autovacuum worker...." instead of "worker took too long to start; canceled" specific to "auto

    Justin Pryzby <pryzby@telsasoft.com> — 2021-10-27T19:26:11Z

    On Wed, Oct 27, 2021 at 07:05:10PM +0000, Bossart, Nathan wrote:
> On 10/27/21, 9:29 AM, "Bharath Rupireddy" <bharath.rupireddyforpostgres@gmail.com> wrote:
> > Is there a specific reason that we have a generic WARNING "worker took
> > too long to start; canceled" for an autovacuum worker? Isn't it better
> > with "autovacuum worker took too long to start; canceled"? It is
> > confusing to see the generic message in the server logs while
> > debugging an issue for a user who doesn't know the internals of
> > autovacuum code.
> 
> It looks like it has been this way for a while [0].  I don't know if
> I've ever seen this message before, and from the comments near it, it
> sounds like it is expected to rarely happen.

I was surprised to see that I have only two logs for this in the last 8 weeks.

> > To be more informative about the message, how about the following:
> 
> My vote is to just change it to
> 
>         ereport(WARNING,
>                 (errmsg("autovacuum worker took too long to start; canceled")));
> 
> and call it a day.  If we wanted to add errdetail(), I think we should
> make sure it is providing useful context, but I'm not sure what that
> might look like.

I think that's fine.

Note that the backend_type is illuminating for those who use CSV logs, or use
P13+ and log_line_prefix += %b (see 70a7b4776).

session_line           | 1
error_severity         | WARNING
message                | worker took too long to start; canceled
backend_type           | autovacuum launcher

-- 
Justin

  4. Re: Isn't it better with "autovacuum worker...." instead of "worker took too long to start; canceled" specific to "auto

    Kyotaro Horiguchi <horikyota.ntt@gmail.com> — 2021-10-28T01:41:43Z

    At Wed, 27 Oct 2021 14:26:11 -0500, Justin Pryzby <pryzby@telsasoft.com> wrote in 
> On Wed, Oct 27, 2021 at 07:05:10PM +0000, Bossart, Nathan wrote:
> > My vote is to just change it to
> > 
> >         ereport(WARNING,
> >                 (errmsg("autovacuum worker took too long to start; canceled")));
> > 
> > and call it a day.  If we wanted to add errdetail(), I think we should
> > make sure it is providing useful context, but I'm not sure what that
> > might look like.
> 
> I think that's fine.

+1

> Note that the backend_type is illuminating for those who use CSV logs, or use
> P13+ and log_line_prefix += %b (see 70a7b4776).
> 
> session_line           | 1
> error_severity         | WARNING
> message                | worker took too long to start; canceled
> backend_type           | autovacuum launcher

Yeah, the additional "autovacuum" is not noisy at all even in that
context. Some other messages are prefixed with "autovacuum".

   "could not fork autovacuum worker process: %m"
   "autovacuum worker started without a worker entry"

By a quick look all occurances of "laucher" are prefixed with
"autovacuum" or "logical replcaion", which seems fine.

As a related topic, autovacuum.c has another use of bare "worker"s.

>	tmpcxt = AllocSetContextCreate(CurrentMemoryContext,
>								   "Start worker tmp cxt",
>								   ALLOCSET_DEFAULT_SIZES);

>	AutovacMemCxt = AllocSetContextCreate(TopMemoryContext,
>										  "AV worker",
>										  ALLOCSET_DEFAULT_SIZES);

I'm not sure the former needs to be fixed, but the latter is actually
visible to users via pg_log_backend_memory_contexts().

LOG:  level: 1; AV worker: 8192 total in 1 blocks; 7928 free (0 chunks); 264 used

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

  5. Re: Isn't it better with "autovacuum worker...." instead of "worker took too long to start; canceled" specific to "auto

    Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> — 2021-10-28T02:43:58Z

    On Thu, Oct 28, 2021 at 7:11 AM Kyotaro Horiguchi
<horikyota.ntt@gmail.com> wrote:
>
> At Wed, 27 Oct 2021 14:26:11 -0500, Justin Pryzby <pryzby@telsasoft.com> wrote in
> > On Wed, Oct 27, 2021 at 07:05:10PM +0000, Bossart, Nathan wrote:
> > > My vote is to just change it to
> > >
> > >         ereport(WARNING,
> > >                 (errmsg("autovacuum worker took too long to start; canceled")));
> > >
> > > and call it a day.  If we wanted to add errdetail(), I think we should
> > > make sure it is providing useful context, but I'm not sure what that
> > > might look like.
> >
> > I think that's fine.
>
> +1

Done.

> > Note that the backend_type is illuminating for those who use CSV logs, or use
> > P13+ and log_line_prefix += %b (see 70a7b4776).
> >
> > session_line           | 1
> > error_severity         | WARNING
> > message                | worker took too long to start; canceled
> > backend_type           | autovacuum launcher
>
> Yeah, the additional "autovacuum" is not noisy at all even in that
> context. Some other messages are prefixed with "autovacuum".
>
>    "could not fork autovacuum worker process: %m"
>    "autovacuum worker started without a worker entry"
>
> By a quick look all occurances of "laucher" are prefixed with
> "autovacuum" or "logical replcaion", which seems fine.
>
> As a related topic, autovacuum.c has another use of bare "worker"s.
>
> >       tmpcxt = AllocSetContextCreate(CurrentMemoryContext,
> >                                                                  "Start worker tmp cxt",
> >                                                                  ALLOCSET_DEFAULT_SIZES);
>
> >       AutovacMemCxt = AllocSetContextCreate(TopMemoryContext,
> >                                                                                 "AV worker",
> >                                                                                 ALLOCSET_DEFAULT_SIZES);
>
> I'm not sure the former needs to be fixed, but the latter is actually
> visible to users via pg_log_backend_memory_contexts().
>
> LOG:  level: 1; AV worker: 8192 total in 1 blocks; 7928 free (0 chunks); 264 used

Good catch. I've seen the use of "AV" in some of the mem context
names, why that? Let's be specific and say "Autovacuum". Attached
patch does that. Please review it.

Regards,
Bharath Rupireddy.

  6. Re: Isn't it better with "autovacuum worker...." instead of "worker took too long to start; canceled" specific to "auto

    Dilip Kumar <dilipbalaut@gmail.com> — 2021-10-28T04:22:19Z

    On Thu, Oct 28, 2021 at 8:14 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
>
> > LOG:  level: 1; AV worker: 8192 total in 1 blocks; 7928 free (0 chunks); 264 used
>
> Good catch. I've seen the use of "AV" in some of the mem context
> names, why that? Let's be specific and say "Autovacuum". Attached
> patch does that. Please review it.

+1, the error message and other improvements look good.

-- 
Regards,
Dilip Kumar
EnterpriseDB: http://www.enterprisedb.com

  7. Re: Isn't it better with "autovacuum worker...." instead of "worker took too long to start; canceled" specific to "auto

    Masahiko Sawada <sawada.mshk@gmail.com> — 2021-10-28T07:11:16Z

    On Thu, Oct 28, 2021 at 11:44 AM Bharath Rupireddy
<bharath.rupireddyforpostgres@gmail.com> wrote:
>
> On Thu, Oct 28, 2021 at 7:11 AM Kyotaro Horiguchi
> <horikyota.ntt@gmail.com> wrote:
> >
> > At Wed, 27 Oct 2021 14:26:11 -0500, Justin Pryzby <pryzby@telsasoft.com> wrote in
> > > On Wed, Oct 27, 2021 at 07:05:10PM +0000, Bossart, Nathan wrote:
> > > > My vote is to just change it to
> > > >
> > > >         ereport(WARNING,
> > > >                 (errmsg("autovacuum worker took too long to start; canceled")));
> > > >
> > > > and call it a day.  If we wanted to add errdetail(), I think we should
> > > > make sure it is providing useful context, but I'm not sure what that
> > > > might look like.
> > >
> > > I think that's fine.
> >
> > +1
>
> Done.
>
> > > Note that the backend_type is illuminating for those who use CSV logs, or use
> > > P13+ and log_line_prefix += %b (see 70a7b4776).
> > >
> > > session_line           | 1
> > > error_severity         | WARNING
> > > message                | worker took too long to start; canceled
> > > backend_type           | autovacuum launcher
> >
> > Yeah, the additional "autovacuum" is not noisy at all even in that
> > context. Some other messages are prefixed with "autovacuum".
> >
> >    "could not fork autovacuum worker process: %m"
> >    "autovacuum worker started without a worker entry"
> >
> > By a quick look all occurances of "laucher" are prefixed with
> > "autovacuum" or "logical replcaion", which seems fine.
> >
> > As a related topic, autovacuum.c has another use of bare "worker"s.
> >
> > >       tmpcxt = AllocSetContextCreate(CurrentMemoryContext,
> > >                                                                  "Start worker tmp cxt",
> > >                                                                  ALLOCSET_DEFAULT_SIZES);
> >
> > >       AutovacMemCxt = AllocSetContextCreate(TopMemoryContext,
> > >                                                                                 "AV worker",
> > >                                                                                 ALLOCSET_DEFAULT_SIZES);
> >
> > I'm not sure the former needs to be fixed, but the latter is actually
> > visible to users via pg_log_backend_memory_contexts().
> >
> > LOG:  level: 1; AV worker: 8192 total in 1 blocks; 7928 free (0 chunks); 264 used
>
> Good catch. I've seen the use of "AV" in some of the mem context
> names, why that? Let's be specific and say "Autovacuum". Attached
> patch does that. Please review it.

+1. The patch looks good to me too.

Regards,

-- 
Masahiko Sawada
EDB:  https://www.enterprisedb.com/

  8. Re: Isn't it better with "autovacuum worker...." instead of "worker took too long to start; canceled" specific to "auto

    Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com> — 2021-10-28T12:41:59Z

    On Thu, Oct 28, 2021 at 12:41 PM Masahiko Sawada <sawada.mshk@gmail.com> wrote:
>
> On Thu, Oct 28, 2021 at 11:44 AM Bharath Rupireddy
> <bharath.rupireddyforpostgres@gmail.com> wrote:
> >
> > On Thu, Oct 28, 2021 at 7:11 AM Kyotaro Horiguchi
> > <horikyota.ntt@gmail.com> wrote:
> > >
> > > At Wed, 27 Oct 2021 14:26:11 -0500, Justin Pryzby <pryzby@telsasoft.com> wrote in
> > > > On Wed, Oct 27, 2021 at 07:05:10PM +0000, Bossart, Nathan wrote:
> > > > > My vote is to just change it to
> > > > >
> > > > >         ereport(WARNING,
> > > > >                 (errmsg("autovacuum worker took too long to start; canceled")));
> > > > >
> > > > > and call it a day.  If we wanted to add errdetail(), I think we should
> > > > > make sure it is providing useful context, but I'm not sure what that
> > > > > might look like.
> > > >
> > > > I think that's fine.
> > >
> > > +1
> >
> > Done.
> >
> > > > Note that the backend_type is illuminating for those who use CSV logs, or use
> > > > P13+ and log_line_prefix += %b (see 70a7b4776).
> > > >
> > > > session_line           | 1
> > > > error_severity         | WARNING
> > > > message                | worker took too long to start; canceled
> > > > backend_type           | autovacuum launcher
> > >
> > > Yeah, the additional "autovacuum" is not noisy at all even in that
> > > context. Some other messages are prefixed with "autovacuum".
> > >
> > >    "could not fork autovacuum worker process: %m"
> > >    "autovacuum worker started without a worker entry"
> > >
> > > By a quick look all occurances of "laucher" are prefixed with
> > > "autovacuum" or "logical replcaion", which seems fine.
> > >
> > > As a related topic, autovacuum.c has another use of bare "worker"s.
> > >
> > > >       tmpcxt = AllocSetContextCreate(CurrentMemoryContext,
> > > >                                                                  "Start worker tmp cxt",
> > > >                                                                  ALLOCSET_DEFAULT_SIZES);
> > >
> > > >       AutovacMemCxt = AllocSetContextCreate(TopMemoryContext,
> > > >                                                                                 "AV worker",
> > > >                                                                                 ALLOCSET_DEFAULT_SIZES);
> > >
> > > I'm not sure the former needs to be fixed, but the latter is actually
> > > visible to users via pg_log_backend_memory_contexts().
> > >
> > > LOG:  level: 1; AV worker: 8192 total in 1 blocks; 7928 free (0 chunks); 264 used
> >
> > Good catch. I've seen the use of "AV" in some of the mem context
> > names, why that? Let's be specific and say "Autovacuum". Attached
> > patch does that. Please review it.
>
> +1. The patch looks good to me too.

Thanks all for reviewing this. Here's the CF entry -
https://commitfest.postgresql.org/35/3378/

Regards,
Bharath Rupireddy.

  9. Re: Isn't it better with "autovacuum worker...." instead of "worker took too long to start; canceled" specific to "auto

    Nathan Bossart <bossartn@amazon.com> — 2021-11-10T19:45:23Z

    On 10/28/21, 5:42 AM, "Bharath Rupireddy" <bharath.rupireddyforpostgres@gmail.com> wrote:
> Thanks all for reviewing this. Here's the CF entry -
> https://commitfest.postgresql.org/35/3378/

I've marked this one as ready-for-committer.

Nathan

  10. Re: Isn't it better with "autovacuum worker...." instead of "worker took too long to start; canceled" specific to "auto

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2021-11-22T16:25:45Z

    On 2021-Oct-28, Bharath Rupireddy wrote:

> Thanks all for reviewing this. Here's the CF entry -
> https://commitfest.postgresql.org/35/3378/

Thanks, pushed.  I changed a couple of things though -- notably changed
the elog() to ereport() as suggested by Nathan early on, but never
materialized in the submitted patch.  I also changed the wording of the
context names, since the proposed ones weren't much more satisfactory
than the existing ones.

-- 
Álvaro Herrera           39°49'30"S 73°17'W  —  https://www.EnterpriseDB.com/
"Every machine is a smoke machine if you operate it wrong enough."
https://twitter.com/libseybieda/status/1541673325781196801