Skip site navigation (1) Skip section navigation (2)

Re: Microtiming patch for psql (reprise)

From: Peter Eisentraut <peter_e(at)gmx(dot)net>
To: Greg Sabino Mullane <greg(at)turnstep(dot)com>
Cc: <pgsql-patches(at)postgresql(dot)org>
Subject: Re: Microtiming patch for psql (reprise)
Date: 2001-12-02 11:42:14
Message-ID: Pine.LNX.4.30.0112011747350.759-100000@peter.localdomain (view raw or flat)
Thread:
Lists: pgsql-patches
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


In response to

pgsql-patches by date

Next:From: Anton BerezinDate: 2001-12-03 00:58:04
Subject: Add another AUTHTYPE for UNIX-domain connections
Previous:From: Bruce MomjianDate: 2001-11-30 19:25:05
Subject: Re: Microtiming patch for psql (reprise)

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group