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: starting logical replication worker for subscription "hoge_sub"
[7047]: LOG: starting logical replication worker for subscription "hoge_sub"
[7049]: LOG: logical replication synchronization worker finished processing
pgbench_accounts started
[7047]: LOG: starting logical replication worker for subscription "hoge_sub"
[7051]: LOG: logical replication synchronization worker finished processing
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 synchronization worker finished processing
pgbench_history started
[7057]: LOG: logical replication synchronization worker finished processing
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
Attachments:
log_message_improvement_for_logical_repl.patchapplication/octet-stream; name=log_message_improvement_for_logical_repl.patchDownload
diff --git a/src/backend/replication/logical/launcher.c b/src/backend/replication/logical/launcher.c
index 09c87d7..247a8c8 100644
--- a/src/backend/replication/logical/launcher.c
+++ b/src/backend/replication/logical/launcher.c
@@ -259,9 +259,14 @@ logicalrep_worker_launch(Oid dbid, Oid subid, const char *subname, Oid userid,
int nsyncworkers;
TimestampTz now;
- ereport(LOG,
- (errmsg("starting logical replication worker for subscription \"%s\"",
- subname)));
+ if (OidIsValid(relid))
+ ereport(LOG,
+ (errmsg("starting logical replication synchronization worker for subscription \"%s\", relation %u",
+ subname, relid)));
+ else
+ ereport(LOG,
+ (errmsg("starting logical replication apply worker for subscription \"%s\"",
+ subname)));
/* Report this after the initial starting message for consistency. */
if (max_replication_slots == 0)
diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c
index 7e51076..69786df 100644
--- a/src/backend/replication/logical/tablesync.c
+++ b/src/backend/replication/logical/tablesync.c
@@ -133,7 +133,8 @@ finish_sync_worker(void)
logicalrep_worker_wakeup(MyLogicalRepWorker->subid, InvalidOid);
ereport(LOG,
- (errmsg("logical replication synchronization worker finished processing")));
+ (errmsg("logical replication synchronization worker for relation %u finished processing",
+ MyLogicalRepWorker->relid)));
/* Stop gracefully */
walrcv_disconnect(wrconn);
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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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
Attachments:
log_message_improvement_for_logical_repl_v2.patchapplication/octet-stream; name=log_message_improvement_for_logical_repl_v2.patchDownload
diff --git a/src/backend/replication/logical/launcher.c b/src/backend/replication/logical/launcher.c
index 09c87d7..faad393 100644
--- a/src/backend/replication/logical/launcher.c
+++ b/src/backend/replication/logical/launcher.c
@@ -245,7 +245,8 @@ logicalrep_worker_find(Oid subid, Oid relid, bool only_running)
}
/*
- * Start new apply background worker.
+ * Start new apply background worker or table sync background worker
+ * if relid is valid.
*/
void
logicalrep_worker_launch(Oid dbid, Oid subid, const char *subname, Oid userid,
@@ -259,9 +260,14 @@ logicalrep_worker_launch(Oid dbid, Oid subid, const char *subname, Oid userid,
int nsyncworkers;
TimestampTz now;
- ereport(LOG,
- (errmsg("starting logical replication worker for subscription \"%s\"",
- subname)));
+ if (OidIsValid(relid))
+ ereport(LOG,
+ (errmsg("starting logical replication synchronization worker for subscription \"%s\", relation %u",
+ subname, relid)));
+ else
+ ereport(LOG,
+ (errmsg("starting logical replication apply worker for subscription \"%s\"",
+ subname)));
/* Report this after the initial starting message for consistency. */
if (max_replication_slots == 0)
diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c
index 7e51076..69786df 100644
--- a/src/backend/replication/logical/tablesync.c
+++ b/src/backend/replication/logical/tablesync.c
@@ -133,7 +133,8 @@ finish_sync_worker(void)
logicalrep_worker_wakeup(MyLogicalRepWorker->subid, InvalidOid);
ereport(LOG,
- (errmsg("logical replication synchronization worker finished processing")));
+ (errmsg("logical replication synchronization worker for relation %u finished processing",
+ MyLogicalRepWorker->relid)));
/* Stop gracefully */
walrcv_disconnect(wrconn);
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
--
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/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
Attachments:
0001-Improve-logical-replication-worker-log-messages.patchinvalid/octet-stream; name=0001-Improve-logical-replication-worker-log-messages.patchDownload
From 37c345310f38951a22484dbfeb31fdc795e12c44 Mon Sep 17 00:00:00 2001
From: Peter Eisentraut <peter_e@gmx.net>
Date: Wed, 17 May 2017 22:24:32 -0400
Subject: [PATCH] Improve logical replication worker log messages
---
src/backend/replication/logical/launcher.c | 2 +-
src/backend/replication/logical/tablesync.c | 5 ++++-
src/backend/replication/logical/worker.c | 4 ++--
3 files changed, 7 insertions(+), 4 deletions(-)
diff --git a/src/backend/replication/logical/launcher.c b/src/backend/replication/logical/launcher.c
index 4e2c350dc7..b956052014 100644
--- a/src/backend/replication/logical/launcher.c
+++ b/src/backend/replication/logical/launcher.c
@@ -260,7 +260,7 @@ logicalrep_worker_launch(Oid dbid, Oid subid, const char *subname, Oid userid,
int nsyncworkers;
TimestampTz now;
- ereport(LOG,
+ ereport(DEBUG1,
(errmsg("starting logical replication worker for subscription \"%s\"",
subname)));
diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c
index 1e3753b8fe..d69fc7086d 100644
--- a/src/backend/replication/logical/tablesync.c
+++ b/src/backend/replication/logical/tablesync.c
@@ -133,8 +133,11 @@ finish_sync_worker(void)
/* Find the main apply worker and signal it. */
logicalrep_worker_wakeup(MyLogicalRepWorker->subid, InvalidOid);
+ StartTransactionCommand();
ereport(LOG,
- (errmsg("logical replication synchronization worker finished processing")));
+ (errmsg("logical replication table synchronization worker for subscription \"%s\", table \"%s\" has finished",
+ MySubscription->name, get_rel_name(MyLogicalRepWorker->relid))));
+ CommitTransactionCommand();
/* Stop gracefully */
walrcv_disconnect(wrconn);
diff --git a/src/backend/replication/logical/worker.c b/src/backend/replication/logical/worker.c
index 7d1787db5c..11cbcf18e5 100644
--- a/src/backend/replication/logical/worker.c
+++ b/src/backend/replication/logical/worker.c
@@ -1516,10 +1516,10 @@ ApplyWorkerMain(Datum main_arg)
(Datum) 0);
if (am_tablesync_worker())
- elog(LOG, "logical replication sync for subscription %s, table %s started",
+ elog(LOG, "logical replication table synchronization worker for subscription \"%s\", table \"%s\" has started",
MySubscription->name, get_rel_name(MyLogicalRepWorker->relid));
else
- elog(LOG, "logical replication apply for subscription %s started",
+ elog(LOG, "logical replication apply worker for subscription \"%s\" has started",
MySubscription->name);
CommitTransactionCommand();
--
2.13.0
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
--
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 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
--
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 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]/messages/by-id/20170404140717.GA2675809@tornado.leadboat.com 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]: /messages/by-id/20170404140717.GA2675809@tornado.leadboat.com
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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
--
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 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
--
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/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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
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
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers