Re: \timing interval

Corey Huinker <corey.huinker@gmail.com> writes:
> On Thu, Sep 1, 2016 at 3:01 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Well, that code's on the backend side so we're not going to just call it
>> in any case.  And I think we don't want to be quite so verbose as to go up
>> to hh:mm:ss.fff as soon as we get past 1 second.  However, comparing that
>> output to what I had suggests that maybe it's better to keep a leading
>> zero in two-digit fields, that is render times like "00:01.234",
>> "01:23.456", or "01:23:45.678" rather than suppressing the initial zero as
>> I had in my examples.  It's an extra character but I think it reinforces
>> the meaning.

> +1
> The larger jump in widths from no MM:SS to HH:MM:SS is a good visual cue.
> Jumping from MM:SS to H:MM:SS to HH:MM:SS would be more subtle and possibly
> confusing.

Attached is an updated patch that does it like that.  Sample output
(generated by forcing specific arguments to PrintTiming):

Time: 0.100 ms
Time: 1.200 ms
Time: 1001.200 ms (00:01.001)
Time: 12001.200 ms (00:12.001)
Time: 60001.200 ms (01:00.001)
Time: 720001.200 ms (12:00.001)
Time: 3660001.200 ms (01:01:00.001)
Time: 43920001.200 ms (12:12:00.001)
Time: 176460001.200 ms (2 01:01:00.001)
Time: 216720001.200 ms (2 12:12:00.001)
Time: 8816460001.200 ms (102 01:01:00.001)
Time: 8856720001.200 ms (102 12:12:00.001)

Barring objections I'll commit this soon.

            regards, tom lane

diff --git a/doc/src/sgml/ref/psql-ref.sgml b/doc/src/sgml/ref/psql-ref.sgml
index 8a66ce7..88e2f66 100644
*** a/doc/src/sgml/ref/psql-ref.sgml
--- b/doc/src/sgml/ref/psql-ref.sgml
*************** testdb=> <userinput>\setenv LESS -imx
*** 2789,2796 ****
         <term><literal>\timing [ <replaceable class="parameter">on</replaceable> | <replaceable
class="parameter">off</replaceable>]</literal></term> 
          <listitem>
          <para>
!          Without parameter, toggles a display of how long each SQL statement
!          takes, in milliseconds.  With parameter, sets same.
          </para>
         </listitem>
        </varlistentry>
--- 2789,2798 ----
         <term><literal>\timing [ <replaceable class="parameter">on</replaceable> | <replaceable
class="parameter">off</replaceable>]</literal></term> 
          <listitem>
          <para>
!          With a parameter, turns displaying of how long each SQL statement
!          takes on or off.  Without a parameter, toggles the display between
!          on and off.  The display is in milliseconds; intervals longer than
!          1 second are also shown in days/hours/minutes/seconds format.
          </para>
         </listitem>
        </varlistentry>
diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 7399950..a17f1de 100644
*** a/src/bin/psql/common.c
--- b/src/bin/psql/common.c
***************
*** 10,15 ****
--- 10,16 ----

  #include <ctype.h>
  #include <limits.h>
+ #include <math.h>
  #include <signal.h>
  #ifndef WIN32
  #include <unistd.h>                /* for write() */
*************** ClearOrSaveResult(PGresult *result)
*** 530,535 ****
--- 531,586 ----
      }
  }

+ /*
+  * Print microtiming output.  Always print raw milliseconds; if the interval
+  * is >= 1 second, also break it down into days/hours/minutes/seconds.
+  */
+ static void
+ PrintTiming(double elapsed_msec)
+ {
+     double        seconds;
+     double        minutes;
+     double        hours;
+     double        days;
+
+     if (elapsed_msec < 1000.0)
+     {
+         /* This is the traditional (pre-v10) output format */
+         printf(_("Time: %.3f ms\n"), elapsed_msec);
+         return;
+     }
+
+     /*
+      * Note: we could print just seconds, in a format like %06.3f, when the
+      * total is less than 1min.  But that's hard to interpret unless we tack
+      * on "s" or otherwise annotate it.  Forcing the display to include
+      * minutes seems like a better solution.
+      */
+     seconds = elapsed_msec / 1000.0;
+     minutes = floor(seconds / 60.0);
+     seconds -= 60.0 * minutes;
+     if (minutes < 60.0)
+     {
+         printf(_("Time: %.3f ms (%02d:%06.3f)\n"),
+                elapsed_msec, (int) minutes, seconds);
+         return;
+     }
+
+     hours = floor(minutes / 60.0);
+     minutes -= 60.0 * hours;
+     if (hours < 24.0)
+     {
+         printf(_("Time: %.3f ms (%02d:%02d:%06.3f)\n"),
+                elapsed_msec, (int) hours, (int) minutes, seconds);
+         return;
+     }
+
+     days = floor(hours / 24.0);
+     hours -= 24.0 * days;
+     printf(_("Time: %.3f ms (%.0f %02d:%02d:%06.3f)\n"),
+            elapsed_msec, days, (int) hours, (int) minutes, seconds);
+ }
+

  /*
   * PSQLexec
*************** PSQLexecWatch(const char *query, const p
*** 679,685 ****

      /* Possible microtiming output */
      if (pset.timing)
!         printf(_("Time: %.3f ms\n"), elapsed_msec);

      return 1;
  }
--- 730,736 ----

      /* Possible microtiming output */
      if (pset.timing)
!         PrintTiming(elapsed_msec);

      return 1;
  }
*************** SendQuery(const char *query)
*** 1332,1338 ****

      /* Possible microtiming output */
      if (pset.timing)
!         printf(_("Time: %.3f ms\n"), elapsed_msec);

      /* check for events that may occur during query execution */

--- 1383,1389 ----

      /* Possible microtiming output */
      if (pset.timing)
!         PrintTiming(elapsed_msec);

      /* check for events that may occur during query execution */