Re: Microtiming patch for psql (reprise)

Greg Sabino Mullane writes:

> Due to a renewed interest in this patch, I've written a
> version to patch against 7.2b3. It adds a timing to every
> successful query in psql, and is toggled with
> backslash-m.

I wonder whether it wouldn't be better to display the time in seconds
rather than in microseconds. For commands that execute "instantaneously",
the microsecond resolution is going to be pretty irrelevant considering
that you're measuring real elapsed time in the client for something that
the server does. For commands that take a while these numbers would soon
get huge and hard to disect. So I think seconds as the base unit and
three digits of resolution (milliseconds) would be enough.

For extra credit, you can make the display of the number locale-aware.

Some more comments below.

> *** ./src/bin/psql/command.c.orig Mon Nov 5 12:46:30 2001
> --- ./src/bin/psql/command.c Wed Nov 28 12:39:23 2001
> ***************
> *** 571,576 ****
> --- 571,579 ----
> free(opt2);
> }
>
> + /* \m -- toggle microsecond timing of queries */
> + else if (strcmp(cmd, "m") == 0)
> + success = do_pset("microtiming", NULL, &pset.popt, quiet);

\m is not a table printing option, so it doesn't belong under pset.
Please put the flag into the PsqlSettings struct (settings.h).

>
> /* \o -- set query output */
> else if (strcmp(cmd, "o") == 0 || strcmp(cmd, "out") == 0)
> ***************
> *** 1808,1813 ****
> --- 1811,1829 ----
> puts(gettext("Using pager is on."));
> else
> puts(gettext("Using pager is off."));
> + }
> + }
> +
> + /* 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.");

Needs to have gettext() around the strings, but shouldn't be in pset
anyway.

> }
> }
>
> *** ./src/bin/psql/common.c.orig Mon Nov 5 12:46:30 2001
> --- ./src/bin/psql/common.c Wed Nov 28 12:37:55 2001
> ***************
> *** 11,16 ****
> --- 11,17 ----
>
> #include <errno.h>
> #include <stdarg.h>
> + #include <sys/time.h>
> #ifdef HAVE_TERMIOS_H
> #include <termios.h>
> #endif
> ***************
> *** 406,411 ****
> --- 407,415 ----
> bool success = false;
> PGresult *results;
> PGnotify *notify;
> + struct timeval before,after;
> + struct timezone tz;
> +
>
> if (!pset.db)
> {
> ***************
> *** 435,441 ****
> }
>
> cancelConn = pset.db;
> ! results = PQexec(pset.db, query);
> if (PQresultStatus(results) == PGRES_COPY_IN)
> copy_in_state = true;
> /* keep cancel connection for copy out state */
> --- 439,447 ----
> }
>
> cancelConn = pset.db;
> ! if (pset.popt.topt.microtiming) { gettimeofday(&before, &tz); }
> ! results = PQexec(pset.db, query);
> ! if (pset.popt.topt.microtiming) { gettimeofday(&after, &tz); }

Please observe indentation and brace style.

> if (PQresultStatus(results) == PGRES_COPY_IN)
> copy_in_state = true;
> /* keep cancel connection for copy out state */
> ***************
> *** 563,568 ****
> --- 569,579 ----
>
> 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);

"TOTAL TIME" is more commonly spelled "Total time". Also, putting a unit
specification after the number should prevent a gratuitous flood of
questions. Thus, I suggest

Total time: 1.002345s

> }
>
> return success;
> *** ./src/bin/psql/help.c.orig Thu Oct 25 01:49:54 2001
> --- ./src/bin/psql/help.c Wed Nov 28 12:37:16 2001
> ***************
> *** 217,222 ****
> --- 217,223 ----
> 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));

Needs to have _() around the string (equivalent to gettext()).

> fprintf(fout, _(" \\o FILENAME send all query results to file or |pipe\n"));
> fprintf(fout, _(" \\p show the content of the current query buffer\n"));
> fprintf(fout, _(" \\pset VAR set table output option (VAR := {format|border|expanded|\n"
> *** ./src/bin/psql/print.h.orig Mon Nov 5 12:46:31 2001
> --- ./src/bin/psql/print.h Wed Nov 28 12:23:27 2001
> ***************
> *** 35,40 ****
> --- 35,42 ----

Not a printing option. The idea here was that print.[hc] would be a
mostly independent module for displaying tables.

> 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 Mon Nov 5 12:46:31 2001
> --- ./src/bin/psql/startup.c Wed Nov 28 12:39:45 2001
> ***************
> *** 343,348 ****
> --- 343,349 ----
> {"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'},
> ***************
> *** 374,387 ****
> 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)
> --- 375,388 ----
> 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)
> ***************
> *** 427,432 ****
> --- 428,436 ----
> case 'l':
> options->action = ACT_LIST_DB;
> break;
> + case 'm':
> + pset.popt.topt.microtiming = true;
> + break;
> case 'n':
> options->no_readline = true;
> break;
> *** ./src/bin/psql/tab-complete.c.orig Mon Nov 5 12:46:31 2001
> --- ./src/bin/psql/tab-complete.c Wed Nov 28 12:37:36 2001
> ***************
> *** 273,279 ****
> "\\connect", "\\copy", "\\d", "\\da", "\\dd", "\\df", "\\di",
> "\\dl", "\\do", "\\dp", "\\ds", "\\dS", "\\dt", "\\dT", "\\dv",
> "\\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
> --- 273,279 ----
> "\\connect", "\\copy", "\\d", "\\da", "\\dd", "\\df", "\\di",
> "\\dl", "\\do", "\\dp", "\\ds", "\\dS", "\\dt", "\\dT", "\\dv",
> "\\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
> ***************
> *** 750,758 ****
> 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);
> }
> --- 750,758 ----
> 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

Users don't care how you measure time. They assume it works. ;-)

> + 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><replaceable class="parameter">command</replaceable>} ]</term>
>
> <listitem>

--
Peter Eisentraut peter_e(at)gmx(dot)net