Subject: pg_dump verbose start and stop times?

From: Ron Johnson <[email-masked]>
Date: Thu, 29 May 2025 16:37:50 -0400

https://www.postgresql.org/docs/15/app-pgdump.html
"
Specifies verbose mode. This will cause pg_dump to output detailed object
comments and start/stop times to the dump file, and progress messages to
standard error.
"

But I don't see any timing messages.  What am I misunderstanding in the
docs?

$ pg_dump -V
pg_dump (PostgreSQL) 16.9
$ postgres -V
postgres (PostgreSQL) 16.9
$ pg_dump -Fp -v ccoremultid > ~/ccoremultid.sql
pg_dump: last built-in OID is 16383
pg_dump: reading extensions
pg_dump: identifying extension members
pg_dump: reading schemas
pg_dump: reading user-defined tables
pg_dump: reading user-defined functions
pg_dump: reading user-defined types
pg_dump: reading procedural languages
pg_dump: reading user-defined aggregate functions
pg_dump: reading user-defined operators
pg_dump: reading user-defined access methods
pg_dump: reading user-defined operator classes
pg_dump: reading user-defined operator families
pg_dump: reading user-defined text search parsers
pg_dump: reading user-defined text search templates
pg_dump: reading user-defined text search dictionaries
pg_dump: reading user-defined text search configurations
pg_dump: reading user-defined foreign-data wrappers
pg_dump: reading user-defined foreign servers
pg_dump: reading default privileges
pg_dump: reading user-defined collations
pg_dump: reading user-defined conversions
pg_dump: reading type casts
pg_dump: reading transforms
pg_dump: reading table inheritance information
pg_dump: reading event triggers
pg_dump: finding extension tables
pg_dump: finding inheritance relationships
pg_dump: reading column info for interesting tables
pg_dump: flagging inherited columns in subtables
pg_dump: reading partitioning data
pg_dump: reading indexes
pg_dump: flagging indexes in partitioned tables
pg_dump: reading extended statistics
pg_dump: reading constraints
pg_dump: reading triggers
pg_dump: reading rewrite rules
pg_dump: reading policies
pg_dump: reading row-level security policies
pg_dump: reading publications
pg_dump: reading publication membership of tables
pg_dump: reading publication membership of schemas
pg_dump: reading subscriptions
pg_dump: reading large objects
pg_dump: reading dependency data
pg_dump: saving encoding = UTF8
pg_dump: saving standard_conforming_strings = on
pg_dump: saving search_path =
pg_dump: creating SCHEMA "dba"
pg_dump: creating EXTENSION "pgstattuple"
pg_dump: creating COMMENT "EXTENSION pgstattuple"
pg_dump: creating FUNCTION "dba.get_fk_referenced_by(text)"
pg_dump: creating FUNCTION "dba.get_fk_references(text)"
pg_dump: creating VIEW "dba.aggregate_cache_hits"
pg_dump: creating VIEW "dba.all_indices"
pg_dump: creating VIEW "dba.all_indices_types"
pg_dump: creating VIEW "dba.latest_vacuum_and_analyze"
pg_dump: creating VIEW "dba.analyze_levels"
pg_dump: creating TABLE "dba.index_bloat_1stg"
pg_dump: creating TABLE "dba.index_bloat_2stg"
pg_dump: creating VIEW "dba.index_cache_hits"
pg_dump: creating VIEW "dba.latest_toast_vacuum"
pg_dump: creating TABLE "dba.pre_analyze_hot"
pg_dump: creating VIEW "dba.statio_tables"
pg_dump: creating TABLE "dba.table_bloat_1stg"
pg_dump: creating TABLE "dba.table_bloat_2stg"
pg_dump: creating VIEW "dba.table_cache_hits"
pg_dump: creating VIEW "dba.toast_cache_hits"
pg_dump: creating TABLE "dba.track_analyze_hot"
pg_dump: creating VIEW "dba.v_parents_and_loners"
pg_dump: creating VIEW "dba.v_relations"
pg_dump: creating VIEW "dba.v_table_size"
pg_dump: processing data for table "dba.index_bloat_1stg"
pg_dump: dumping contents of table "dba.index_bloat_1stg"
pg_dump: processing data for table "dba.index_bloat_2stg"
pg_dump: dumping contents of table "dba.index_bloat_2stg"
pg_dump: processing data for table "dba.pre_analyze_hot"
pg_dump: dumping contents of table "dba.pre_analyze_hot"
pg_dump: processing data for table "dba.table_bloat_1stg"
pg_dump: dumping contents of table "dba.table_bloat_1stg"
pg_dump: processing data for table "dba.table_bloat_2stg"
pg_dump: dumping contents of table "dba.table_bloat_2stg"
pg_dump: processing data for table "dba.track_analyze_hot"
pg_dump: dumping contents of table "dba.track_analyze_hot"
pg_dump: creating CONSTRAINT "dba.index_bloat_1stg index_bloat_1stg_pkey"
pg_dump: creating CONSTRAINT "dba.index_bloat_2stg index_bloat_2stg_pkey"
pg_dump: creating CONSTRAINT "dba.pre_analyze_hot pre_analyze_hot_pkey"
pg_dump: creating CONSTRAINT "dba.table_bloat_1stg table_bloat_1stg_pkey"
pg_dump: creating CONSTRAINT "dba.table_bloat_2stg table_bloat_2stg_pkey"
pg_dump: creating CONSTRAINT "dba.track_analyze_hot track_analyze_hot_pkey"
pg_dump: creating ACL "SCHEMA dba"
pg_dump: creating ACL "dba.TABLE all_indices"
pg_dump: creating ACL "dba.TABLE all_indices_types"
pg_dump: creating ACL "dba.TABLE latest_vacuum_and_analyze"
pg_dump: creating ACL "dba.TABLE analyze_levels"
pg_dump: creating ACL "dba.TABLE latest_toast_vacuum"
pg_dump: creating ACL "dba.TABLE v_relations"

-- 
Death to <Redacted>, and butter sauce.
Don't boil me, I'm still alive.
<Redacted> lobster!

---

From: "David G. Johnston" <[email-masked]>
Date: Thu, 29 May 2025 13:42:16 -0700

> But I don't see any timing messages.  What am I misunderstanding in the

It says there the times end up in the dump file, which you redirected and
didn’t show the contents of.

David J.

---

From: Ron Johnson <[email-masked]>
Date: Thu, 29 May 2025 20:51:49 -0400

On Thu, May 29, 2025 at 4:42 PM David G. Johnston <
[email-masked]> wrote:

>> Specifies verbose mode. This will cause pg_dump to output detailed
>> object comments and start/stop times to the dump file, and progress
>> messages to standard error.
>> "
>>

The non-sense of putting start and stop times in the dump file while not
putting them in stderr must have caused my brain to skip over "to the dump
file".

Honestly, who cares if start and stop times are in the dump file?  stderr
is where a DBA wants to see timings.

---

From: Laurenz Albe <[email-masked]>
Date: Fri, 30 May 2025 07:45:00 +0200

On Thu, 2025-05-29 at 20:51 -0400, Ron Johnson wrote:
> Honestly, who cares if start and stop times are in the dump file?  stderr is where a DBA wants to see timings.

I guess everybody has different preferences.
These days, few DBAs stare at the screen, waiting for a report on the console
when the job is done.

Yours,
Laurenz Albe

---

From: hubert depesz lubaczewski <[email-masked]>
Date: Fri, 30 May 2025 12:09:48 +0200

> is where a DBA wants to see timings.

=$ date >&2; pg_dump …; date >&2

That's all you need.

Whether pg_dump does what you want, or not, is not really important
given how easy it is to fix the thing yourself.

And the assumption that: "it doesn't do what *I* want, so it's
non-sense", is slightly exaggerating commonality of your experience.

Best regards,

depesz

---

From: Ron Johnson <[email-masked]>
Date: Fri, 30 May 2025 08:39:43 -0400

On Fri, May 30, 2025 at 1:45 AM Laurenz Albe <[email-masked]>
wrote:

> > Honestly, who cares if start and stop times are in the dump file?
> stderr is where a DBA wants to see timings.
>

Unix has had stderr redirection for 35(?) years. Mailing lists are for
small reproducers, not for 2MB of output from "real" backups.

---

From: Ron Johnson <[email-masked]>
Date: Fri, 30 May 2025 08:54:24 -0400

> =$ date >&2; pg_dump …; date >&2

That (poorly) tells me how long the whole dump took.  Heck, it requires you
to manually do the math yourself.  Useful information like how long it took
to dump each table (even more importantly: how long it took for pg_restore
to copy each table, and create each index) is not shown.

> given how easy it is to fix the thing yourself.

And yet it's not possible to show how long it takes to copy each object .
This, at least, does the math to show the grand elapsed time, and puts an
easily greppable string in the cron job's stdout+stderr log file:

time_it()
{
    local ActionLabel=$1
    shift
    date +"%n%F %T TIMEIT $ActionLabel started.%n"
    START_SECS=$(date +"%s")
    $@
    local RC=$? ; echo "TIMEIT Return Code = $RC"
    FINISH_SECS=$(date +"%s")
    ET=$(echo "scale=2;(${FINISH_SECS} - ${START_SECS})/60" | bc)
    date +"%n%F %T TIMEIT $ActionLabel finished. Elapsed time: ${ET}
minutes."
    return $RC
}

time_it DUMP_$DB pg_dump -j ${Threads} -Z${ZLvl} -v -C -Fd --file=$DB $DB
2> ${DB}_pgdump.log

> non-sense", is slightly exaggerating commonality of your experience.

The pgbackrest developer seems to think it's sensical to put timestamps in
each detail line.  They're right.

---

From: hubert depesz lubaczewski <[email-masked]>
Date: Fri, 30 May 2025 15:48:08 +0200

> time_it DUMP_$DB pg_dump -j ${Threads} -Z${ZLvl} -v -C -Fd --file=$DB $DB

You do know that you could have just done:

time pg_dump …

without the time_it function?

And if you'd want to write your own function, assuming you're running
not-so-ancient bash, you could have just used $EPOCHREALTIME and not the
date +… ?

Best regards,

depesz

---

From: Ron Johnson <[email-masked]>
Date: Fri, 30 May 2025 11:02:23 -0400

> without the time_it function?

Without the easily greppable string that shows what action it performed.
That's why I wrote the function: to have a standard, constant string to
grep.

> not-so-ancient bash, you could have just used $EPOCHREALTIME and not the

RHEL 8 is apparently ancient.

When all my RHEL 7 and 8 servers are retired, I might change it to use
$EPOCHREALTIME.  Or maybe not;  ancient, forgotten servers lurk everywhere,
and this probably works on RHEL 6.