Improve logging.
authorHeikki Linnakangas <heikki.linnakangas@iki.fi>
Fri, 9 Jan 2015 17:28:10 +0000 (19:28 +0200)
committerHeikki Linnakangas <heikki.linnakangas@iki.fi>
Fri, 16 Jan 2015 11:46:58 +0000 (13:46 +0200)
Remove verbose mode, and replace it with --progress and --debug options.
With --progress, calculate and print totals.

doc/src/sgml/ref/pg_rewind.sgml
src/bin/pg_rewind/copy_fetch.c
src/bin/pg_rewind/filemap.c
src/bin/pg_rewind/filemap.h
src/bin/pg_rewind/libpq_fetch.c
src/bin/pg_rewind/logging.c
src/bin/pg_rewind/logging.h
src/bin/pg_rewind/pg_rewind.c
src/bin/pg_rewind/pg_rewind.h

index 7f22dd567ce536e66fabe3ddd7ead514e5210c07..b06b713c18382753be36693c56a3420d2625697d 100644 (file)
@@ -120,9 +120,35 @@ PostgreSQL documentation
      </varlistentry>
 
      <varlistentry>
-      <term><option>-v</option></term>
-      <term><option>--verbose</option></term>
-      <listitem><para>Enable verbose progress information</para></listitem>
+      <term><option>-P</option></term>
+      <term><option>--progress</option></term>
+      <listitem>
+       <para>
+        Enables progress reporting. Turning this on will deliver an approximate
+        progress report while copying data over from the source cluster.
+       </para>
+      </listitem>
+     </varlistentry>
+
+     <varlistentry>
+      <term><option>-P</option></term>
+      <term><option>--progress</option></term>
+      <listitem>
+       <para>
+        Enables progress reporting. Turning this on will deliver an approximate
+        progress report while copying data over from the source cluster.
+       </para>
+      </listitem>
+     </varlistentry>
+
+     <varlistentry>
+      <term><option>--debug</option></term>
+      <listitem>
+       <para>
+        Print verbose debugging output that is mostly useful for developers
+        debugging pg_rewind.
+       </para>
+      </listitem>
      </varlistentry>
 
      <varlistentry>
index d3226a4d48240e1df12b698af5b6c9f1bb37d61c..5a14c7338bd309138f460eb5d65044bb16194df5 100644 (file)
@@ -200,6 +200,10 @@ write_file_range(char *buf, off_t begin, size_t size)
        int                     writeleft;
        char       *p;
 
+       /* update progress report */
+       fetch_done += size;
+       progress_report(false);
+
        if (dry_run)
                return;
 
index 90245a33627aeff4f029b7db492954b0b3fe76a3..c3e669d1d7884c1dd6c3293ea839ab8ce067efd1 100644 (file)
@@ -154,8 +154,9 @@ process_remote_file(const char *path, file_type_t type, size_t newsize,
                        if (!exists || !isRelDataFile(path))
                        {
                                /*
-                                * File exists in source, but not in target. Or it's a non-data
-                                * file that we have no special processing for. Copy it in toto.
+                                * File exists in source, but not in target. Or it's a
+                                * non-data file that we have no special processing for. Copy
+                                * it in toto.
                                 *
                                 * An exception: PG_VERSIONs should be identical, but avoid
                                 * overwriting it for paranoia.
@@ -230,7 +231,6 @@ process_remote_file(const char *path, file_type_t type, size_t newsize,
        map->nlist++;
 }
 
-
 /*
  * Callback for processing local file list.
  *
@@ -358,16 +358,24 @@ process_block_change(ForkNumber forknum, RelFileNode rnode, BlockNumber blkno)
                switch (entry->action)
                {
                        case FILE_ACTION_NONE:
-                       case FILE_ACTION_COPY_TAIL:
                        case FILE_ACTION_TRUNCATE:
                                /* skip if we're truncating away the modified block anyway */
                                if ((blkno_inseg + 1) * BLCKSZ <= entry->newsize)
                                        datapagemap_add(&entry->pagemap, blkno_inseg);
                                break;
 
+                       case FILE_ACTION_COPY_TAIL:
+                               /*
+                                * skip the modified block is part of the "tail" that we're
+                                * copying anyway.
+                                */
+                               if ((blkno_inseg + 1) * BLCKSZ <= entry->oldsize)
+                                       datapagemap_add(&entry->pagemap, blkno_inseg);
+                               break;
+
                        case FILE_ACTION_COPY:
                        case FILE_ACTION_REMOVE:
-                               return;
+                               break;
 
                        case FILE_ACTION_CREATE:
                                pg_fatal("unexpected page modification for directory or symbolic link \"%s\"", entry->path);
@@ -378,7 +386,7 @@ process_block_change(ForkNumber forknum, RelFileNode rnode, BlockNumber blkno)
                /*
                 * If we don't have any record of this file in the file map, it means
                 * that it's a relation that doesn't exist in the remote system, and
-                * it was also subsequently removed in the local system, too. We can
+                * it was subsequently removed in the local system, too. We can
                 * safely ignore it.
                 */
        }
@@ -445,6 +453,51 @@ action_to_str(file_action_t action)
        }
 }
 
+/*
+ * Calculate the totals needed for progress reports.
+ */
+void
+calculate_totals(void)
+{
+       file_entry_t *entry;
+       int                     i;
+       filemap_t  *map = filemap;
+
+       map->total_size = 0;
+       map->fetch_size = 0;
+
+       for (i = 0; i < filemap->narray; i++)
+       {
+               entry = filemap->array[i];
+
+               if (entry->type != FILE_TYPE_REGULAR)
+                       continue;
+
+               map->total_size += entry->newsize;
+
+               if (entry->action == FILE_ACTION_COPY)
+               {
+                       map->fetch_size += entry->newsize;
+                       continue;
+               }
+
+               if (entry->action == FILE_ACTION_COPY_TAIL)
+                       map->fetch_size += (entry->newsize - entry->oldsize);
+
+               if (entry->pagemap.bitmapsize > 0)
+               {
+                       datapagemap_iterator_t *iter;
+                       BlockNumber blk;
+
+                       iter = datapagemap_iterate(&entry->pagemap);
+                       while (datapagemap_next(iter, &blk))
+                               map->fetch_size += BLCKSZ;
+
+                       pg_free(iter);
+               }
+       }
+}
+
 void
 print_filemap(void)
 {
index 1ce82a433b7731ad209b9d23342dc504811f408e..abb1d6f6ab82524b372cd5298457ed4b8e7c9c2a 100644 (file)
@@ -79,6 +79,13 @@ struct filemap_t
         */
        file_entry_t **array;
        int                     narray;
+
+       /*
+        * Summary information. total_size is the total size of the source cluster,
+        * and fetch_size is the number of bytes that needs to be copied.
+        */
+       uint64          total_size;
+       uint64          fetch_size;
 };
 
 typedef struct filemap_t filemap_t;
@@ -87,6 +94,7 @@ extern filemap_t * filemap;
 
 extern filemap_t *filemap_create(void);
 
+extern void calculate_totals(void);
 extern void print_filemap(void);
 
 /* Functions for populating the filemap */
index d509e53d0ea569c4410947fa4431194e7fcba1a4..57cb6a6e706706dae100ce20c6350472dd69727e 100644 (file)
@@ -50,7 +50,7 @@ libpqConnect(const char *connstr)
                pg_fatal("could not connect to remote server: %s\n",
                                 PQerrorMessage(conn));
 
-       pg_log(PG_VERBOSE, "connected to remote server\n");
+       pg_log(PG_PROGRESS, "connected to remote server\n");
 
        /*
         * Check that the server is not in hot standby mode. There is no
@@ -122,7 +122,7 @@ libpqGetCurrentXlogInsertLocation(void)
 }
 
 /*
- * Get a file list.
+ * Get a list of all files in the data directory.
  */
 void
 libpqProcessFileList(void)
@@ -187,7 +187,7 @@ libpqProcessFileList(void)
        }
 }
 
-/*
+/*----
  * Runs a query, which returns pieces of files from the remote source data
  * directory, and overwrites the corresponding parts of target files with
  * the received parts. The result set is expected to be of format:
@@ -195,7 +195,7 @@ libpqProcessFileList(void)
  * path                text    -- path in the data directory, e.g "base/1/123"
  * begin       int4    -- offset within the file
  * chunk       bytea   -- file content
- *
+ *----
  */
 static void
 receiveFileChunks(const char *sql)
@@ -205,13 +205,11 @@ receiveFileChunks(const char *sql)
        if (PQsendQueryParams(conn, sql, 0, NULL, NULL, NULL, NULL, 1) != 1)
                pg_fatal("could not send query: %s\n", PQerrorMessage(conn));
 
-       pg_log(PG_VERBOSE, "getting chunks: %s\n", sql);
+       pg_log(PG_DEBUG, "getting file chunks");
 
        if (PQsetSingleRowMode(conn) != 1)
                pg_fatal("could not set libpq connection to single row mode\n");
 
-       pg_log(PG_VERBOSE, "sent query\n");
-
        while ((res = PQgetResult(conn)) != NULL)
        {
                char   *filename;
@@ -274,7 +272,7 @@ receiveFileChunks(const char *sql)
 
                chunk = PQgetvalue(res, 0, 2);
 
-               pg_log(PG_VERBOSE, "received chunk for file \"%s\", off %d, len %d\n",
+               pg_log(PG_DEBUG, "received chunk for file \"%s\", off %d, len %d\n",
                           filename, chunkoff, chunksize);
 
                open_target_file(filename, false);
@@ -313,7 +311,7 @@ libpqGetFile(const char *filename, size_t *filesize)
        memcpy(result, PQgetvalue(res, 0, 0), len);
        result[len] = '\0';
 
-       pg_log(PG_VERBOSE, "fetched file \"%s\", length %d\n", filename, len);
+       pg_log(PG_DEBUG, "fetched file \"%s\", length %d\n", filename, len);
 
        if (filesize)
                *filesize = len;
@@ -377,12 +375,14 @@ libpq_executeFileMap(filemap_t *map)
        for (i = 0; i < map->narray; i++)
        {
                entry = map->array[i];
+
+               /* If this is a relation file, copy the modified blocks */
                execute_pagemap(&entry->pagemap, entry->path);
 
                switch (entry->action)
                {
                        case FILE_ACTION_NONE:
-                               /* ok, do nothing.. */
+                               /* nothing else to do */
                                break;
 
                        case FILE_ACTION_COPY:
@@ -420,7 +420,7 @@ libpq_executeFileMap(filemap_t *map)
                                         PQresultErrorMessage(res));
        }
 
-       /* Ok, we've sent the file list. Now receive the files */
+       /* Ok, we've sent the file list. Now receive the files. */
        sql =
                "-- fetch all the blocks listed in the temp table.\n"
                "SELECT path, begin, \n"
index 6f8c1e0350c6ed08543d322e80a49fd6ac78f26e..2df98f6029bc835343e8d611940b608dc837c73b 100644 (file)
 #include "postgres_fe.h"
 
 #include <unistd.h>
+#include <time.h>
 
+#include "pg_rewind.h"
 #include "logging.h"
 
+#include "pgtime.h"
+
+/* Progress counters */
+uint64 fetch_size;
+uint64 fetch_done;
+
+static pg_time_t last_progress_report = 0;
+
 #define QUERY_ALLOC                    8192
 
 #define MESSAGE_WIDTH          60
 
-LogOpts                log_opts;
-
 static
 __attribute__((format(PG_PRINTF_ATTRIBUTE, 2, 0)))
 void
@@ -30,27 +38,16 @@ pg_log_v(eLogType type, const char *fmt, va_list ap)
 
        switch (type)
        {
-               case PG_VERBOSE:
-                       if (log_opts.verbose)
+               case PG_DEBUG:
+                       if (debug)
                                printf("%s", _(message));
                        break;
 
-               case PG_STATUS:
-                       /* for output to a display, do leading truncation and append \r */
-                       if (isatty(fileno(stdout)))
-                               /* -2 because we use a 2-space indent */
-                               printf("  %s%-*.*s\r",
-                               /* prefix with "..." if we do leading truncation */
-                                          strlen(message) <= MESSAGE_WIDTH - 2 ? "" : "...",
-                                          MESSAGE_WIDTH - 2, MESSAGE_WIDTH - 2,
-                               /* optional leading truncation */
-                                          strlen(message) <= MESSAGE_WIDTH - 2 ? message :
-                                          message + strlen(message) - MESSAGE_WIDTH + 3 + 2);
-                       else
-                               printf("  %s\n", _(message));
+               case PG_PROGRESS:
+                       if (showprogress)
+                               printf("%s", _(message));
                        break;
 
-               case PG_REPORT:
                case PG_WARNING:
                        printf("%s", _(message));
                        break;
@@ -92,3 +89,52 @@ pg_fatal(const char *fmt,...)
 }
 
 
+/*
+ * Print a progress report based on the global variables.
+ *
+ * Progress report is written at maximum once per second, unless the
+ * force parameter is set to true.
+ */
+void
+progress_report(bool force)
+{
+       int                     percent;
+       char            fetch_done_str[32];
+       char            fetch_size_str[32];
+       pg_time_t       now;
+
+       if (!showprogress)
+               return;
+
+       now = time(NULL);
+       if (now == last_progress_report && !force)
+               return;                                 /* Max once per second */
+
+       last_progress_report = now;
+       percent = fetch_size ? (int) ((fetch_done) * 100 / fetch_size) : 0;
+
+       /*
+        * Avoid overflowing past 100% or the full size. This may make the total
+        * size number change as we approach the end of the backup (the estimate
+        * will always be wrong if WAL is included), but that's better than having
+        * the done column be bigger than the total.
+        */
+       if (percent > 100)
+               percent = 100;
+       if (fetch_done > fetch_size)
+               fetch_size = fetch_done;
+
+       /*
+        * Separate step to keep platform-dependent format code out of
+        * translatable strings.  And we only test for INT64_FORMAT availability
+        * in snprintf, not fprintf.
+        */
+       snprintf(fetch_done_str, sizeof(fetch_done_str), INT64_FORMAT,
+                        fetch_done / 1024);
+       snprintf(fetch_size_str, sizeof(fetch_size_str), INT64_FORMAT,
+                        fetch_size / 1024);
+
+       pg_log(PG_PROGRESS, "%*s/%s kB (%d%%) copied\r",
+                  (int) strlen(fetch_size_str), fetch_done_str, fetch_size_str,
+                  percent);
+}
index 688d1bc52f242829ae41bba22da411aacb358ac9..d264725c577c2dc0023452a081afd462d6b68234 100644 (file)
 #ifndef PG_REWIND_LOGGING_H
 #define PG_REWIND_LOGGING_H
 
+/* progress counters */
+extern uint64 fetch_size;
+extern uint64 fetch_done;
+
 /*
  * Enumeration to denote pg_log modes
  */
 typedef enum
 {
-       PG_VERBOSE,
-       PG_STATUS,
-       PG_REPORT,
+       PG_DEBUG,
+       PG_PROGRESS,
        PG_WARNING,
        PG_FATAL
 } eLogType;
 
-/*
- * LogOpts
- */
-typedef struct
-{
-       FILE       *internal;           /* internal log FILE */
-       bool            verbose;                /* TRUE -> be verbose in messages */
-       bool            retain;                 /* retain log files on success */
-} LogOpts;
-
 extern void
 pg_log(eLogType type, const char *fmt,...)
 __attribute__((format(PG_PRINTF_ATTRIBUTE, 2, 3)));
@@ -41,4 +34,6 @@ extern void
 pg_fatal(const char *fmt,...)
 __attribute__((format(PG_PRINTF_ATTRIBUTE, 1, 2), noreturn));
 
+extern void progress_report(bool force);
+
 #endif
index 3cb2c80ab8e8149764e2a259f9915926cb293b8c..350747e849c12d128895b4e0ef4dcc81d0351c49 100644 (file)
@@ -42,12 +42,14 @@ static ControlFileData ControlFile_source;
 
 const char *progname;
 
+/* Configuration options */
 char *datadir_target = NULL;
 char *datadir_source = NULL;
 char *connstr_source = NULL;
 
-bool verbose;
-bool dry_run;
+bool debug = false;
+bool showprogress = false;
+bool dry_run = false;
 
 static void
 usage(const char *progname)
@@ -61,8 +63,9 @@ usage(const char *progname)
        printf("                 source data directory to sync with\n");
        printf("  --source-server=CONNSTR\n");
        printf("                 source server to sync with\n");
-       printf("  -v             write a lot of progress messages\n");
+       printf("  -P, --progress write progress messages\n");
        printf("  -n, --dry-run  stop before modifying anything\n");
+       printf("  --debug        write a lot of debug messages\n");
        printf("  -V, --version  output version information, then exit\n");
        printf("  -?, --help     show this help, then exit\n");
        printf("\n");
@@ -80,7 +83,8 @@ main(int argc, char **argv)
                {"source-server", required_argument, NULL, 2},
                {"version", no_argument, NULL, 'V'},
                {"dry-run", no_argument, NULL, 'n'},
-               {"verbose", no_argument, NULL, 'v'},
+               {"progress", no_argument, NULL, 'P'},
+               {"debug", no_argument, NULL, 3},
                {NULL, 0, NULL, 0}
        };
        int                     option_index;
@@ -99,10 +103,6 @@ main(int argc, char **argv)
 
        progname = get_progname(argv[0]);
 
-       /* Set default parameter values */
-       verbose = false;
-       dry_run = false;
-
        /* Process command-line arguments */
        if (argc > 1)
        {
@@ -118,22 +118,26 @@ main(int argc, char **argv)
                }
        }
 
-       while ((c = getopt_long(argc, argv, "D:vn", long_options, &option_index)) != -1)
+       while ((c = getopt_long(argc, argv, "D:NnP", long_options, &option_index)) != -1)
        {
                switch (c)
                {
                        case '?':
                                fprintf(stderr, _("Try \"%s --help\" for more information.\n"), progname);
                                exit(1);
-                       case ':':
-                               exit(1);
-                       case 'v':
-                               verbose = true;
+
+                       case 'P':
+                               showprogress = true;
                                break;
+
                        case 'n':
                                dry_run = true;
                                break;
 
+                       case 3:
+                               debug = true;
+                               break;
+
                        case 'D':       /* -D or --target-pgdata */
                                datadir_target = pg_strdup(optarg);
                                break;
@@ -192,7 +196,7 @@ main(int argc, char **argv)
         * to do.
         */
        if (ControlFile_target.checkPointCopy.ThisTimeLineID == ControlFile_source.checkPointCopy.ThisTimeLineID)
-               pg_fatal("source and target cluster are both on the same timeline.\n");
+               pg_fatal("source and target cluster are on the same timeline.\n");
 
        findCommonAncestorTimeline(&divergerec, &lastcommontli);
        printf("The servers diverged at WAL position %X/%X on timeline %u.\n",
@@ -241,10 +245,12 @@ main(int argc, char **argv)
                   chkpttli);
 
        /*
-        * Build the filemap, by comparing the remote and local data directories
+        * Build the filemap, by comparing the remote and local data directories.
         */
        (void) filemap_create();
+       pg_log(PG_PROGRESS, "reading source file list\n");
        fetchRemoteFileList();
+       pg_log(PG_PROGRESS, "reading target file list\n");
        traverse_datadir(datadir_target, &process_local_file);
 
        /*
@@ -254,21 +260,41 @@ main(int argc, char **argv)
         * record. XXX: If we supported rewinding a server that was not shut
         * down cleanly, we would need to replay until the end of WAL here.
         */
+       pg_log(PG_PROGRESS, "reading WAL in target\n");
        extractPageMap(datadir_target, chkptrec, lastcommontli,
                                   ControlFile_target.checkPoint);
-
        filemap_finalize();
 
-       /* XXX: this is probably too verbose even in verbose mode */
-       if (verbose)
+       if (showprogress)
+               calculate_totals();
+
+       /* this is too verbose even for verbose mode */
+       if (debug)
                print_filemap();
 
        /*
-        * Ok, we're ready to start copying things over. Once we start modifying
-        * things, there is no turning back!
+        * Ok, we're ready to start copying things over.
         */
+       if (showprogress)
+       {
+               pg_log(PG_PROGRESS, "Need to copy %lu MB (total source directory size is %lu MB)\n",
+                          (unsigned long) (filemap->fetch_size / (1024 * 1024)),
+                          (unsigned long) (filemap->total_size / (1024 * 1024)));
+
+               fetch_size = filemap->fetch_size;
+               fetch_done = 0;
+       }
+
+       /*
+        * This is the point of no return. Once we start copying things, we have
+        * modified the target directory and there is no turning back!
+        */
+
        executeFileMap();
 
+       progress_report(true);
+
+       pg_log(PG_PROGRESS, "\ncreating backup label and updating control file\n");
        createBackupLabel(chkptredo, chkpttli, chkptrec);
 
        /*
index 064b1c25336b4d84a314cad21c4021770c8395a2..6320a403f0c8e9ad1f47565b5fa8be61cc8520e5 100644 (file)
@@ -23,7 +23,8 @@
 extern char *datadir_target;
 extern char *datadir_source;
 extern char *connstr_source;
-extern bool verbose;
+extern bool debug;
+extern bool showprogress;
 extern bool dry_run;
 
 /* in parsexlog.c */