diff --git a/src/bin/pg_basebackup/pg_subscriber.c b/src/bin/pg_basebackup/pg_subscriber.c index 355738c..290be7c 100644 --- a/src/bin/pg_basebackup/pg_subscriber.c +++ b/src/bin/pg_basebackup/pg_subscriber.c @@ -675,13 +675,66 @@ create_all_logical_replication_slots(PrimaryInfo *primary, get_subscription_name(perdb->oid, (int) getpid(), replslotname, NAMEDATALEN); + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("creating a replication slot %s start: %s", replslotname, timebuf); + } + /* Create replication slot on publisher. */ if (create_logical_replication_slot(conn, false, perdb) == NULL && !dry_run) return false; + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("creating a replication slot %s end: %s", replslotname, timebuf); + } + + + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("creating a publication start: %s", timebuf); + } + /* Also create a publication */ create_publication(conn, primary, perdb); + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("creating a publication end: %s", timebuf); + } + disconnect_database(conn); } @@ -839,6 +892,19 @@ wait_for_end_recovery(const char *base_conninfo, const char *dbname) if (conn == NULL) exit(1); + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("creating a wait_for start: %s", timebuf); + } + for (cnt = 0; cnt < wait_seconds * WAITS_PER_SEC; cnt++) { bool in_recovery; @@ -875,6 +941,19 @@ wait_for_end_recovery(const char *base_conninfo, const char *dbname) pg_usleep(USEC_PER_SEC / WAITS_PER_SEC); } + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("creating a wait_for stop: %s", timebuf); + } + disconnect_database(conn); /* @@ -1059,6 +1138,19 @@ create_subscription(PGconn *conn, StandbyInfo *standby, char *base_conninfo, pg_log_debug("command is: %s", str->data); + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("creating a subscription %s start: %s", subname, timebuf); + } + if (!dry_run) { res = PQexec(conn, str->data); @@ -1071,6 +1163,19 @@ create_subscription(PGconn *conn, StandbyInfo *standby, char *base_conninfo, } } + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("creating a subscription %s end: %s", subname, timebuf); + } + /* for cleanup purposes */ perdb->made_subscription = true; @@ -1277,8 +1382,35 @@ start_standby_server(StandbyInfo *standby, unsigned short subport, pg_ctl_cmd = psprintf("\"%s/pg_ctl\" start -D \"%s\" -s -o \"-p %d\" -l \"%s\"", standby->bindir, standby->pgdata, subport, server_start_log); + + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("pg_ctl start begin: %s", timebuf); + } + rc = system(pg_ctl_cmd); pg_ctl_status(pg_ctl_cmd, rc, 1); + + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("pg_ctl start end: %s", timebuf); + } } static char * @@ -1723,8 +1855,38 @@ main(int argc, char **argv) pg_ctl_cmd = psprintf("\"%s/pg_ctl\" stop -D \"%s\" -s", standby.bindir, standby.pgdata); + + + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("pg_ctl stop begin: %s", timebuf); + } + + rc = system(pg_ctl_cmd); pg_ctl_status(pg_ctl_cmd, rc, 0); + + + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("pg_ctl stop end: %s", timebuf); + } } /* @@ -1756,6 +1918,7 @@ main(int argc, char **argv) consistent_lsn = create_logical_replication_slot(conn, true, &dbarr.perdb[0]); + /* * Write recovery parameters. * @@ -1856,9 +2019,36 @@ main(int argc, char **argv) pg_ctl_cmd = psprintf("\"%s/pg_ctl\" stop -D \"%s\" -s", standby.bindir, standby.pgdata); + + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("pg_ctl stop for subscriber begin: %s", timebuf); + } + rc = system(pg_ctl_cmd); pg_ctl_status(pg_ctl_cmd, rc, 0); + { + char timebuf[128]; + struct timeval time; + time_t tt; + + gettimeofday(&time, NULL); + tt = (time_t) time.tv_sec; + strftime(timebuf, sizeof(timebuf), "%H%M%S", localtime(&tt)); + snprintf(timebuf + strlen(timebuf), sizeof(timebuf) - strlen(timebuf), + ".%03d", (int) (time.tv_usec / 1000)); + pg_log_warning("pg_ctl stop for subscriber end: %s", timebuf); + } + /* * Change system identifier. */