Обсуждение: [HACKERS] Improvement in log message of logical replication worker
Hi, When I created a subscription with copydata option that corresponds to a publication that includes several tables, I got the following log messages. [7019] LOG: starting logical replication worker for subscription "hoge_sub" [7047] LOG: logical replication apply for subscription hoge_sub started [7047] LOG: starting logical replication worker for subscription "hoge_sub" [7049] LOG: logical replication sync for subscription hoge_sub, table pgbench_accounts started [7047] LOG: starting logical replication worker for subscription "hoge_sub" [7051] LOG: logical replication sync for subscription hoge_sub, table pgbench_branches started [7049] LOG: logical replication synchronization worker finished processing [7051] LOG: logical replication synchronization worker finished processing [7047] LOG: starting logical replication worker for subscription "hoge_sub" [7047] LOG: starting logical replication worker for subscription "hoge_sub" [7056] LOG: logical replication sync for subscription hoge_sub, table pgbench_history started [7057] LOG: logical replication sync for subscription hoge_sub, table pgbench_tellers started [7056] LOG: logical replication synchronization worker finished processing [7057] LOG: logical replication synchronization worker finished processing PID 7019 is a logical replication launcher, PID 7047 is a apply worker and other processes are table sync worker. I set max_sync_workers_per_subscription = 2. I got same log messages 'starting logical replication worker for subscription' total 5 times but actually 4 of them mean to launch table sync worker and another one means apply worker. We cannot distinguish them. Also, I got same log messages 'logical replication synchronization worker finished processing' total 4 times but I think it's better to show the table name in finish log message as well. Any thoughts? Attached small patch adds relid to these log messages if it's valid. I'd like to propose it for PG10 if possible, but since It's not a bug and not an open item we can add it to next CF. Regards, -- Masahiko Sawada NIPPON TELEGRAPH AND TELEPHONE CORPORATION NTT Open Source Software Center -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Вложения
On Fri, May 12, 2017 at 12:30 AM, Masahiko Sawada <sawada.mshk@gmail.com> wrote: > Attached small patch adds relid to these log messages if it's valid. > I'd like to propose it for PG10 if possible, but since It's not a bug > and not an open item we can add it to next CF. To me, it seems completely reasonable to add this as an open item. -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
On Wed, May 17, 2017 at 4:08 AM, Robert Haas <robertmhaas@gmail.com> wrote: > On Fri, May 12, 2017 at 12:30 AM, Masahiko Sawada <sawada.mshk@gmail.com> wrote: >> Attached small patch adds relid to these log messages if it's valid. >> I'd like to propose it for PG10 if possible, but since It's not a bug >> and not an open item we can add it to next CF. > > To me, it seems completely reasonable to add this as an open item. > Okay, added this to the open items. Regards, -- Masahiko Sawada NIPPON TELEGRAPH AND TELEPHONE CORPORATION NTT Open Source Software Center
On Wed, May 17, 2017 at 11:33 AM, Masahiko Sawada <sawada.mshk@gmail.com> wrote: > On Wed, May 17, 2017 at 4:08 AM, Robert Haas <robertmhaas@gmail.com> wrote: >> On Fri, May 12, 2017 at 12:30 AM, Masahiko Sawada <sawada.mshk@gmail.com> wrote: >>> Attached small patch adds relid to these log messages if it's valid. >>> I'd like to propose it for PG10 if possible, but since It's not a bug >>> and not an open item we can add it to next CF. >> >> To me, it seems completely reasonable to add this as an open item. >> > > Okay, added this to the open items. > Attached minor updated patch. BTW, why should max_replication_slots be set more than 0 even on the subscriber side? It's documented but I could not understand reason.. Regards, -- Masahiko Sawada NIPPON TELEGRAPH AND TELEPHONE CORPORATION NTT Open Source Software Center -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Вложения
On 5/17/17 05:15, Masahiko Sawada wrote: > BTW, why should max_replication_slots be set more than 0 even on the > subscriber side? It's documented but I could not understand reason. Because that setting also controls replication origin tracking slots. -- Peter Eisentraut http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On 5/12/17 00:30, Masahiko Sawada wrote: > I got same log messages 'starting logical replication worker for > subscription' total 5 times but actually 4 of them mean to launch > table sync worker and another one means apply worker. We cannot > distinguish them. Also, I got same log messages 'logical replication > synchronization worker finished processing' total 4 times but I think > it's better to show the table name in finish log message as well. Any > thoughts? Yeah, that's quite a lot of messages for normal operation. I've been playing around with it a little bit and came up with the attached patch that produced a slightly reduced log volume and more consistent messages. I think we don't need a message from the launcher that it will launch a worker and then the worker also reporting that it started, so I downgraded the former to DEBUG1. A more radical solution would be to downgrade all these messages to DEBUG1. We want to avoid showing OIDs in user-facing messages, but it's not always easy to look up the names. See the patch for one solution. -- Peter Eisentraut http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Вложения
On Thu, May 18, 2017 at 11:29 AM, Peter Eisentraut <peter.eisentraut@2ndquadrant.com> wrote: > On 5/12/17 00:30, Masahiko Sawada wrote: >> I got same log messages 'starting logical replication worker for >> subscription' total 5 times but actually 4 of them mean to launch >> table sync worker and another one means apply worker. We cannot >> distinguish them. Also, I got same log messages 'logical replication >> synchronization worker finished processing' total 4 times but I think >> it's better to show the table name in finish log message as well. Any >> thoughts? > > Yeah, that's quite a lot of messages for normal operation. I've been > playing around with it a little bit and came up with the attached patch > that produced a slightly reduced log volume and more consistent messages. > > I think we don't need a message from the launcher that it will launch a > worker and then the worker also reporting that it started, so I > downgraded the former to DEBUG1. Agreed. Autovacuum launcher also doesn't emit such log message. > A more radical solution would be to > downgrade all these messages to DEBUG1. > > We want to avoid showing OIDs in user-facing messages, but it's not > always easy to look up the names. See the patch for one solution. > The patch looks good to me. There are some log messages saying just 'logical replication worker for subscription ...' in reread_subscription but should we add 'apply' to these messages in order for user to distinguish between apply worker and table sync worker? Regards, -- Masahiko Sawada NIPPON TELEGRAPH AND TELEPHONE CORPORATION NTT Open Source Software Center
On Thu, May 18, 2017 at 1:00 AM, Peter Eisentraut <peter.eisentraut@2ndquadrant.com> wrote: > On 5/17/17 05:15, Masahiko Sawada wrote: >> BTW, why should max_replication_slots be set more than 0 even on the >> subscriber side? It's documented but I could not understand reason. > > Because that setting also controls replication origin tracking slots. > Thanks! I understood the reason. Regards, -- Masahiko Sawada NIPPON TELEGRAPH AND TELEPHONE CORPORATION NTT Open Source Software Center
On Thu, May 18, 2017 at 12:36:46PM +0900, Masahiko Sawada wrote: > On Thu, May 18, 2017 at 11:29 AM, Peter Eisentraut > <peter.eisentraut@2ndquadrant.com> wrote: > > On 5/12/17 00:30, Masahiko Sawada wrote: > >> I got same log messages 'starting logical replication worker for > >> subscription' total 5 times but actually 4 of them mean to launch > >> table sync worker and another one means apply worker. We cannot > >> distinguish them. Also, I got same log messages 'logical replication > >> synchronization worker finished processing' total 4 times but I think > >> it's better to show the table name in finish log message as well. Any > >> thoughts? > > > > Yeah, that's quite a lot of messages for normal operation. I've been > > playing around with it a little bit and came up with the attached patch > > that produced a slightly reduced log volume and more consistent messages. > > > > I think we don't need a message from the launcher that it will launch a > > worker and then the worker also reporting that it started, so I > > downgraded the former to DEBUG1. > > Agreed. Autovacuum launcher also doesn't emit such log message. > > > A more radical solution would be to > > downgrade all these messages to DEBUG1. > > > > We want to avoid showing OIDs in user-facing messages, but it's not > > always easy to look up the names. See the patch for one solution. > > > > The patch looks good to me. > There are some log messages saying just 'logical replication worker > for subscription ...' in reread_subscription but should we add 'apply' > to these messages in order for user to distinguish between apply > worker and table sync worker? [Action required within three days. This is a generic notification.] The above-described topic is currently a PostgreSQL 10 open item. Peter, since you committed the patch believed to have created it, you own this open item. If some other commit is more relevant or if this does not belong as a v10 open item, please let us know. Otherwise, please observe the policy on open item ownership[1] and send a status update within three calendar days of this message. Include a date for your subsequent status update. Testers may discover new open items at any time, and I want to plan to get them all fixed well in advance of shipping v10. Consequently, I will appreciate your efforts toward speedy resolution. Thanks. [1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com
Umm, just skimming here -- this patch shows some LOG messages using elog() rather than ereport(), which seems bogus to me. Also:"logical replication table synchronization worker for subscription \"%s\", table \"%s\" has started" surely there is a more convenient name than "logical replication table synchronization worker" for this process? I think just getting rid of the words "logical replication" there would be sufficient, since we don't have the concept of "table synchronization worker" in any other context. More generally, the overall wording of this message seems a bit off. How about something along the lines of "starting synchronization for table \"%s\" in subscription \"%s\"" ? -- Álvaro Herrera https://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On 5/17/17 23:36, Masahiko Sawada wrote: > The patch looks good to me. > There are some log messages saying just 'logical replication worker > for subscription ...' in reread_subscription but should we add 'apply' > to these messages in order for user to distinguish between apply > worker and table sync worker? done and done -- Peter Eisentraut http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On 5/20/17 00:58, Alvaro Herrera wrote: > Umm, just skimming here -- this patch shows some LOG messages using > elog() rather than ereport(), which seems bogus to me. Fixed that. > Also: > "logical replication table synchronization worker for subscription \"%s\", table \"%s\" has started" > surely there is a more convenient name than "logical replication table > synchronization worker" for this process? I think just getting rid of > the words "logical replication" there would be sufficient, since we > don't have the concept of "table synchronization worker" in any other > context. We could look into that, but then we'd have a review all the log messages so they are consistent. > More generally, the overall wording of this message seems a bit off. > How about something along the lines of > "starting synchronization for table \"%s\" in subscription \"%s\"" > ? There is of course a difference between "starting" and "has started". We used to have both of these messages, now we only have the latter by default. -- Peter Eisentraut http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Wed, May 24, 2017 at 7:04 PM, Peter Eisentraut <peter.eisentraut@2ndquadrant.com> wrote: > On 5/17/17 23:36, Masahiko Sawada wrote: >> The patch looks good to me. >> There are some log messages saying just 'logical replication worker >> for subscription ...' in reread_subscription but should we add 'apply' >> to these messages in order for user to distinguish between apply >> worker and table sync worker? > > done and done > Thank you! Regards, -- Masahiko Sawada NIPPON TELEGRAPH AND TELEPHONE CORPORATION NTT Open Source Software Center