MIME-Version: 1.0
References: 
 <CANzqJaDPKWHUTnJMbwY2qqDk8YPSP=-b7dJbBGKbBLYnqkFjiQ@mail.gmail.com>
 <CAKFQuwb_V35L1VYAevfon9ZbHPUxFcwhY1Ei07MNSm_5_Z-QjA@mail.gmail.com>
 <CANzqJaBbTaQyNvAmuBU9oZTcKMUk+2JyNFpPnDELzKVFiQ5PfQ@mail.gmail.com>
 <aDmD7C-CTAesqkPl@depesz.com>
In-Reply-To: <aDmD7C-CTAesqkPl@depesz.com>
From: Ron Johnson <ronljohnsonjr@gmail.com>
Date: Fri, 30 May 2025 08:54:24 -0400
Message-ID: 
 <CANzqJaDVuTUxG+=gWiP0+qPqgEaKXJNxnEj9vyLi+2G3KWROUQ@mail.gmail.com>
Subject: Re: pg_dump verbose start and stop times?
To: Pgsql-admin <pgsql-admin@lists.postgresql.org>
Content-Type: multipart/alternative; boundary="00000000000093f4fc063659eac8"
Archived-At: 
 <https://www.postgresql.org/message-id/CANzqJaDVuTUxG%2B%3DgWiP0%2BqPqgEaKXJNxnEj9vyLi%2B2G3KWROUQ%40mail.gmail.com>
Precedence: bulk

--00000000000093f4fc063659eac8
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

On Fri, May 30, 2025 at 6:09=E2=80=AFAM hubert depesz lubaczewski <depesz@d=
epesz.com>
wrote:

> On Thu, May 29, 2025 at 08:51:49PM -0400, Ron Johnson wrote:
> > The non-sense of putting start and stop times in the dump file while no=
t
> > 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?  stde=
rr
> > is where a DBA wants to see timings.
>
> =3D$ date >&2; pg_dump =E2=80=A6; date >&2
>
> That's all you need.
>

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.


> Whether pg_dump does what you want, or not, is not really important
> 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=3D$1
    shift
    date +"%n%F %T TIMEIT $ActionLabel started.%n"
    START_SECS=3D$(date +"%s")
    $@
    local RC=3D$? ; echo "TIMEIT Return Code =3D $RC"
    FINISH_SECS=3D$(date +"%s")
    ET=3D$(echo "scale=3D2;(${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=3D$DB $DB
2> ${DB}_pgdump.log


> And the assumption that: "it doesn't do what *I* want, so it's
> 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.

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

--00000000000093f4fc063659eac8
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr"><div dir=3D"ltr">On Fri, May 30, 2025 at 6:09=E2=80=AFAM h=
ubert depesz lubaczewski &lt;<a href=3D"mailto:depesz@depesz.com">depesz@de=
pesz.com</a>&gt; wrote:</div><div class=3D"gmail_quote gmail_quote_containe=
r"><blockquote class=3D"gmail_quote" style=3D"margin:0px 0px 0px 0.8ex;bord=
er-left:1px solid rgb(204,204,204);padding-left:1ex">On Thu, May 29, 2025 a=
t 08:51:49PM -0400, Ron Johnson wrote:<br>
&gt; The non-sense of putting start and stop times in the dump file while n=
ot<br>
&gt; putting them in stderr must have caused my brain to skip over &quot;to=
 the dump<br>
&gt; file&quot;.<br>
&gt; <br>
&gt; Honestly, who cares if start and stop times are in the dump file?=C2=
=A0 stderr<br>
&gt; is where a DBA wants to see timings.<br>
<br>
=3D$ date &gt;&amp;2; pg_dump =E2=80=A6; date &gt;&amp;2<br>
<br>
That&#39;s all you need.<br></blockquote><div><br></div><div>That (poorly) =
tells me how long the whole dump took.=C2=A0 Heck, it requires you to manua=
lly do the math yourself.=C2=A0 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.</div><div>=C2=A0</di=
v><blockquote class=3D"gmail_quote" style=3D"margin:0px 0px 0px 0.8ex;borde=
r-left:1px solid rgb(204,204,204);padding-left:1ex">Whether pg_dump does wh=
at you want, or not, is not really important<br>
given how easy it is to fix the thing yourself.<br></blockquote><div><br></=
div><div>And yet it&#39;s not possible to show how long it takes to copy ea=
ch=C2=A0object .=C2=A0 This, at least, does the math to show the grand elap=
sed=C2=A0time, and puts an easily greppable string in the cron job&#39;s=C2=
=A0stdout+stderr log file:</div><div><br></div><div><font face=3D"monospace=
">time_it()<br>{<br>=C2=A0 =C2=A0 local ActionLabel=3D$1<br>=C2=A0 =C2=A0 s=
hift<br>=C2=A0 =C2=A0 date +&quot;%n%F %T TIMEIT $ActionLabel started.%n&qu=
ot;<br>=C2=A0 =C2=A0 START_SECS=3D$(date +&quot;%s&quot;)<br>=C2=A0 =C2=A0 =
$@<br>=C2=A0 =C2=A0 local RC=3D$? ; echo &quot;TIMEIT Return Code =3D $RC&q=
uot;<br>=C2=A0 =C2=A0 FINISH_SECS=3D$(date +&quot;%s&quot;)<br>=C2=A0 =C2=
=A0 ET=3D$(echo &quot;scale=3D2;(${FINISH_SECS} - ${START_SECS})/60&quot; |=
 bc)<br>=C2=A0 =C2=A0 date +&quot;%n%F %T TIMEIT $ActionLabel finished. Ela=
psed time: ${ET} minutes.&quot;<br>=C2=A0 =C2=A0 return $RC<br>}</font></di=
v><div><font face=3D"monospace"><br></font></div><div><font face=3D"monospa=
ce">time_it DUMP_$DB pg_dump -j ${Threads} -Z${ZLvl} -v -C -Fd --file=3D$DB=
 $DB 2&gt; ${DB}_pgdump.log</font></div><div><br></div><div>=C2=A0</div><bl=
ockquote class=3D"gmail_quote" style=3D"margin:0px 0px 0px 0.8ex;border-lef=
t:1px solid rgb(204,204,204);padding-left:1ex">And the assumption that: &qu=
ot;it doesn&#39;t do what *I* want, so it&#39;s<br>
non-sense&quot;, is slightly exaggerating commonality of your experience.<b=
r></blockquote><div><br></div><div>The pgbackrest developer seems to think =
it&#39;s sensical to put timestamps in each detail line.=C2=A0 They&#39;re =
right.</div><div><br></div></div><span class=3D"gmail_signature_prefix">-- =
</span><br><div dir=3D"ltr" class=3D"gmail_signature"><div dir=3D"ltr">Deat=
h to &lt;Redacted&gt;, and butter sauce.<div>Don&#39;t boil me, I&#39;m sti=
ll alive.<br><div><div>&lt;Redacted&gt; lobster!</div></div></div></div></d=
iv></div>

--00000000000093f4fc063659eac8--