psql microsecond timing patch - Mailing list pgsql-patches

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

This is a small patch to allow you to time your queries in
psql. Myself and some others have been using it and find it
useful for telling how long an actual specific query takes,
as opposed to EXPLAIN which just does an estimate. Using the
two together is a good way to tweak sql and indices. Even
if not deemed useful, it should be good practice in learning
to submit patches. :)

(I called it "microsecond timing" because "m" was one of the
few letters still available as a backslash command that
had some mnemonic potential.)

Thanks,
Greg Sabino Mullane
greg@turnstep.com 200109270943
PGP Key: 0x14964AC8

-----BEGIN PGP SIGNATURE-----
Comment: http://www.turnstep.com/pgp.html

iQA/AwUBO7NHE7ybkGcUlkrIEQIq9wCfSSsozUx5U55EPUsuBz5XZErfcIEAnAu7
FrtN+K+rtXIgTmRn9MABLC3i
=UXkx
-----END PGP SIGNATURE-----
*** ./src/bin/psql/command.c.orig    Sun Sep 16 21:07:53 2001
--- ./src/bin/psql/command.c    Sun Sep 16 20:13:08 2001
***************
*** 521,526 ****
--- 521,529 ----
          free(opt2);
      }

+     /* \m -- toggle microsecond timing of queries */
+     else if (strcmp(cmd, "m") == 0)
+         success = do_pset("microtiming", NULL, &pset.popt, quiet);

      /* \o -- set query output */
      else if (strcmp(cmd, "o") == 0 || strcmp(cmd, "out") == 0)
***************
*** 1751,1756 ****
--- 1754,1771 ----
          }
      }

+     /* toggle showing of query speed */
+     else if (strcmp(param, "m") == 0 || strcmp(param, "microtiming") == 0)
+     {
+         popt->topt.microtiming = !popt->topt.microtiming;
+         if (!quiet)
+         {
+             if (popt->topt.microtiming)
+                 puts("Microsecond timing is on.");
+             else
+                 puts("Microsecond timing is off.");
+         }
+     }

      else
      {
*** ./src/bin/psql/common.c.orig    Sun Sep 16 21:07:53 2001
--- ./src/bin/psql/common.c    Mon Sep 24 12:22:26 2001
***************
*** 11,16 ****
--- 11,17 ----

  #include <errno.h>
  #include <stdarg.h>
+ #include <sys/time.h>
  #ifdef HAVE_TERMIOS_H
  #include <termios.h>
  #endif
***************
*** 377,382 ****
--- 378,385 ----
      bool        success = false;
      PGresult   *results;
      PGnotify   *notify;
+     struct timeval before,after;
+     struct timezone tz;

      if (!pset.db)
      {
***************
*** 406,412 ****
--- 409,419 ----
      }

      cancelConn = pset.db;
+
+     if (pset.popt.topt.microtiming) { gettimeofday(&before, &tz); }
      results = PQexec(pset.db, query);
+     if (pset.popt.topt.microtiming) { gettimeofday(&after, &tz); }
+
      if (PQresultStatus(results) == PGRES_COPY_IN)
          copy_in_state = true;
      /* keep cancel connection for copy out state */
***************
*** 534,539 ****
--- 541,551 ----

          if (results)
              PQclear(results);
+     }
+
+     /* Possible microtiming output */
+     if (pset.popt.topt.microtiming  && success) {
+         printf("TOTAL TIME: %f\n",((after.tv_sec-before.tv_sec)*1000000 + after.tv_usec - before.tv_usec) /
1000000.0);
      }

      return success;
*** ./src/bin/psql/help.c.orig    Sun Sep 16 21:07:53 2001
--- ./src/bin/psql/help.c    Sun Sep 16 20:13:10 2001
***************
*** 218,223 ****
--- 218,224 ----
      fprintf(fout, " \\l             list all databases\n");
      fprintf(fout, " \\lo_export, \\lo_import, \\lo_list, \\lo_unlink\n"
              "                large object operations\n");
+     fprintf(fout, " \\m             toggle microsecond timing of queries (currently %s)\n",
ON(pset.popt.topt.microtiming));
      fprintf(fout, " \\o [file]      send all query results to [file], or |pipe\n");
      fprintf(fout, " \\p             show the content of the current query buffer\n");
      fprintf(fout, " \\pset <opt>    set table output  <opt> = {format|border|expanded|fieldsep|\n"
*** ./src/bin/psql/print.h.orig    Mon Sep 24 11:59:33 2001
--- ./src/bin/psql/print.h    Mon Sep 24 12:24:28 2001
***************
*** 35,40 ****
--- 35,41 ----
      char       *recordSep;        /* record separator for unaligned text
                                   * mode */
      char       *tableAttr;        /* attributes for HTML <table ...> */
+     bool        microtiming;    /* show query time in microseconds */
  } printTableOpt;


*** ./src/bin/psql/startup.c.orig    Sun Sep 16 21:07:53 2001
--- ./src/bin/psql/startup.c    Mon Sep 24 12:26:52 2001
***************
*** 332,337 ****
--- 332,338 ----
          {"host", required_argument, NULL, 'h'},
          {"html", no_argument, NULL, 'H'},
          {"list", no_argument, NULL, 'l'},
+         {"microtiming", no_argument, NULL, 'm'},
          {"no-readline", no_argument, NULL, 'n'},
          {"output", required_argument, NULL, 'o'},
          {"port", required_argument, NULL, 'p'},
***************
*** 364,377 ****
      memset(options, 0, sizeof *options);

  #ifdef HAVE_GETOPT_LONG
!     while ((c = getopt_long(argc, argv, "aAc:d:eEf:F:h:Hlno:p:P:qR:sStT:uU:v:VWxX?", long_options, &optindex)) != -1)
  #else                            /* not HAVE_GETOPT_LONG */

      /*
       * Be sure to leave the '-' in here, so we can catch accidental long
       * options.
       */
!     while ((c = getopt(argc, argv, "aAc:d:eEf:F:h:Hlno:p:P:qR:sStT:uU:v:VWxX?-")) != -1)
  #endif     /* not HAVE_GETOPT_LONG */
      {
          switch (c)
--- 365,378 ----
      memset(options, 0, sizeof *options);

  #ifdef HAVE_GETOPT_LONG
!     while ((c = getopt_long(argc, argv, "aAc:d:eEf:F:h:Hlmno:p:P:qR:sStT:uU:v:VWxX?", long_options, &optindex)) !=
-1)
  #else                            /* not HAVE_GETOPT_LONG */

      /*
       * Be sure to leave the '-' in here, so we can catch accidental long
       * options.
       */
!     while ((c = getopt(argc, argv, "aAc:d:eEf:F:h:Hlmno:p:P:qR:sStT:uU:v:VWxX?-")) != -1)
  #endif     /* not HAVE_GETOPT_LONG */
      {
          switch (c)
***************
*** 416,421 ****
--- 417,425 ----
                  break;
              case 'l':
                  options->action = ACT_LIST_DB;
+                 break;
+             case 'm':
+                 pset.popt.topt.microtiming = true;
                  break;
              case 'n':
                  options->no_readline = true;
*** ./src/bin/psql/tab-complete.c.orig    Sun Sep 16 21:07:53 2001
--- ./src/bin/psql/tab-complete.c    Sun Sep 16 20:13:13 2001
***************
*** 260,266 ****
      static char *backslash_commands[] = {
          "\\connect", "\\copy", "\\d", "\\di", "\\di", "\\ds", "\\dS", "\\dv",
          "\\da", "\\df", "\\do", "\\dt", "\\e", "\\echo", "\\encoding",
!         "\\g", "\\h", "\\i", "\\l",
          "\\lo_import", "\\lo_export", "\\lo_list", "\\lo_unlink",
          "\\o", "\\p", "\\pset", "\\q", "\\qecho", "\\r", "\\set", "\\t", "\\unset",
          "\\x", "\\w", "\\z", "\\!", NULL
--- 260,266 ----
      static char *backslash_commands[] = {
          "\\connect", "\\copy", "\\d", "\\di", "\\di", "\\ds", "\\dS", "\\dv",
          "\\da", "\\df", "\\do", "\\dt", "\\e", "\\echo", "\\encoding",
!         "\\g", "\\h", "\\i", "\\l", "\\m",
          "\\lo_import", "\\lo_export", "\\lo_list", "\\lo_unlink",
          "\\o", "\\p", "\\pset", "\\q", "\\qecho", "\\r", "\\set", "\\t", "\\unset",
          "\\x", "\\w", "\\z", "\\!", NULL
***************
*** 719,726 ****
          COMPLETE_WITH_LIST(sql_commands);
      else if (strcmp(prev_wd, "\\pset") == 0)
      {
!         char       *my_list[] = {"format", "border", "expanded", "null", "fieldsep",
!             "tuples_only", "title", "tableattr", "pager",
          "recordsep", NULL};

          COMPLETE_WITH_LIST(my_list);
--- 719,727 ----
          COMPLETE_WITH_LIST(sql_commands);
      else if (strcmp(prev_wd, "\\pset") == 0)
      {
!         char       *my_list[] = {"format", "border", "expanded", "microtiming",
!                                  "null", "fieldsep","tuples_only", "title",
!                                  "tableattr", "pager",
          "recordsep", NULL};

          COMPLETE_WITH_LIST(my_list);
*** ./doc/src/sgml/ref/psql-ref.sgml.orig    Thu Sep 27 09:03:20 2001
--- ./doc/src/sgml/ref/psql-ref.sgml    Thu Sep 27 09:02:26 2001
***************
*** 738,743 ****
--- 738,758 ----


        <varlistentry>
+         <term><literal>\m</literal></term>
+         <listitem>
+         <para>
+         This toggles a display of how long each query takes to complete
+         in seconds, down to a microsecond resolution. This uses your
+         system's <command>gettimeofday</command> function to get an
+         approximate measurement of how long a query takes to run. This is
+         useful as a way to measure the relative speeds of different queries
+         as you tweak the SQL and indices.
+         </para>
+         </listitem>
+       </varlistentry>
+
+
+       <varlistentry>
          <term><literal>\o</literal> [ {<replaceable class="parameter">filename</replaceable> |
<literal>|</literal><replaceableclass="parameter">command</replaceable>} ]</term> 

          <listitem>