Re: [Monetdb-developers] MonetDB: default - implement timing per server response for resu...
On Thu, Jul 15, 2010 at 03:25:39PM +0200, Fabian Groffen wrote:
Changeset: dfcab86b0cb0 for MonetDB URL: http://dev.monetdb.org/hg/MonetDB?cmd=changeset;node=dfcab86b0cb0 Modified Files: clients/ChangeLog clients/src/mapiclient/mclient.mx Branch: default Log Message:
implement timing per server response for results and updates for SQL formatter
[...]
diff -r df828b8fc84c -r dfcab86b0cb0 clients/src/mapiclient/mclient.mx --- a/clients/src/mapiclient/mclient.mx Thu Jul 15 15:09:22 2010 +0200 +++ b/clients/src/mapiclient/mclient.mx Thu Jul 15 15:11:07 2010 +0200 @@ -342,6 +342,26 @@ } }
+static char htimbuf[32]; +static char * +timerHuman() +{ + long t = t1 - t0; + + if (t / 1000 < 950) { + snprintf(htimbuf, 32, "%ld.%03ldms", t / 1000, t % 1000); + return(htimbuf); + } + t /= 1000; + if (t / 1000 < 60) { + snprintf(htimbuf, 32, "%ld.%02lds", t / 1000, t % 1000); + return(htimbuf); + } + t /= 1000; + snprintf(htimbuf, 32, "%ldm %lds", t / 60, t % 60); + return(htimbuf); +} + /* The Mapi library eats away the comment lines, which we need to * detect end of debugging. We overload the routine to our liking. */
[...] While I like the new timing feature as well as the convenient formatting for human readability, I am wondering about two potential changes / extensions: (a) While the time formatting is convenient for human readbility, it might be less convenient for automatic (post-)processing, e.g., creating performance figures. For that, plain unformatted microseconds (in addition to the human-readable format) might be more convenient. (b) The "old" (still existing) "Timer" information is sent to stderr, thus, one can seem the Timer output without the need to grep through (potentially large) output, e.g., by simply redirecting the output to a file or even /dev/null --- obviously, aligning stderr & stdout in case of large multi-query scripts is then left to the user. The new timing output goes (together with the queries status summary like how many result tuples were produced) to stdout (only). (c) As the announcement (changelog) says, the new timing output is only produced with the "sql" formatter (i.e., not with, e.g., "raw" or "test", and hence, also not by default with `-s <sql-statement>` (unless one explicitly requests `-f sql`). For (a) & (b) would it be an option to consider to also send the plain unformatted times in microseconds to stderr to (better) support automatic post-processing of the timings? To cover also (c), we could consider doing that with all formatters, not only with "sql". ... just some ideas to think about and discuss ... Stefan -- | Dr. Stefan Manegold | mailto:Stefan.Manegold@cwi.nl | | CWI, P.O.Box 94079 | http://www.cwi.nl/~manegold/ | | 1090 GB Amsterdam | Tel.: +31 (20) 592-4212 | | The Netherlands | Fax : +31 (20) 592-4199 |
On 2010-07-16 16:27, Stefan Manegold wrote:
On Thu, Jul 15, 2010 at 03:25:39PM +0200, Fabian Groffen wrote:
Changeset: dfcab86b0cb0 for MonetDB URL: http://dev.monetdb.org/hg/MonetDB?cmd=changeset;node=dfcab86b0cb0 Modified Files: clients/ChangeLog clients/src/mapiclient/mclient.mx Branch: default Log Message:
implement timing per server response for results and updates for SQL formatter
[...]
diff -r df828b8fc84c -r dfcab86b0cb0 clients/src/mapiclient/mclient.mx --- a/clients/src/mapiclient/mclient.mx Thu Jul 15 15:09:22 2010 +0200 +++ b/clients/src/mapiclient/mclient.mx Thu Jul 15 15:11:07 2010 +0200 @@ -342,6 +342,26 @@ } }
+static char htimbuf[32]; +static char * +timerHuman() +{ + long t = t1 - t0; + + if (t / 1000 < 950) { + snprintf(htimbuf, 32, "%ld.%03ldms", t / 1000, t % 1000); + return(htimbuf); + } + t /= 1000; + if (t / 1000 < 60) { + snprintf(htimbuf, 32, "%ld.%02lds", t / 1000, t % 1000); + return(htimbuf); + } + t /= 1000; + snprintf(htimbuf, 32, "%ldm %lds", t / 60, t % 60); + return(htimbuf); +} + /* The Mapi library eats away the comment lines, which we need to * detect end of debugging. We overload the routine to our liking. */
[...]
While I like the new timing feature as well as the convenient formatting for human readability, I am wondering about two potential changes / extensions:
(a) While the time formatting is convenient for human readbility, it might be less convenient for automatic (post-)processing, e.g., creating performance figures. For that, plain unformatted microseconds (in addition to the human-readable format) might be more convenient.
(b) The "old" (still existing) "Timer" information is sent to stderr, thus, one can seem the Timer output without the need to grep through (potentially large) output, e.g., by simply redirecting the output to a file or even /dev/null --- obviously, aligning stderr & stdout in case of large multi-query scripts is then left to the user.
fflush(stdout); right before printing the time, then fflush(stderr); after.
The new timing output goes (together with the queries status summary like how many result tuples were produced) to stdout (only).
(c) As the announcement (changelog) says, the new timing output is only produced with the "sql" formatter (i.e., not with, e.g., "raw" or "test", and hence, also not by default with `-s <sql-statement>` (unless one explicitly requests `-f sql`).
For (a) & (b) would it be an option to consider to also send the plain unformatted times in microseconds to stderr to (better) support automatic post-processing of the timings?
To cover also (c), we could consider doing that with all formatters, not only with "sql".
... just some ideas to think about and discuss ...
Stefan
-- Sjoerd Mullender
On Fri, Jul 16, 2010 at 05:20:07PM +0200, Sjoerd Mullender wrote:
On 2010-07-16 16:27, Stefan Manegold wrote:
On Thu, Jul 15, 2010 at 03:25:39PM +0200, Fabian Groffen wrote:
Changeset: dfcab86b0cb0 for MonetDB URL: http://dev.monetdb.org/hg/MonetDB?cmd=changeset;node=dfcab86b0cb0 Modified Files: clients/ChangeLog clients/src/mapiclient/mclient.mx Branch: default Log Message:
implement timing per server response for results and updates for SQL formatter
[...]
diff -r df828b8fc84c -r dfcab86b0cb0 clients/src/mapiclient/mclient.mx --- a/clients/src/mapiclient/mclient.mx Thu Jul 15 15:09:22 2010 +0200 +++ b/clients/src/mapiclient/mclient.mx Thu Jul 15 15:11:07 2010 +0200 @@ -342,6 +342,26 @@ } }
+static char htimbuf[32]; +static char * +timerHuman() +{ + long t = t1 - t0; + + if (t / 1000 < 950) { + snprintf(htimbuf, 32, "%ld.%03ldms", t / 1000, t % 1000); + return(htimbuf); + } + t /= 1000; + if (t / 1000 < 60) { + snprintf(htimbuf, 32, "%ld.%02lds", t / 1000, t % 1000); + return(htimbuf); + } + t /= 1000; + snprintf(htimbuf, 32, "%ldm %lds", t / 60, t % 60); + return(htimbuf); +} + /* The Mapi library eats away the comment lines, which we need to * detect end of debugging. We overload the routine to our liking. */
[...]
While I like the new timing feature as well as the convenient formatting for human readability, I am wondering about two potential changes / extensions:
(a) While the time formatting is convenient for human readbility, it might be less convenient for automatic (post-)processing, e.g., creating performance figures. For that, plain unformatted microseconds (in addition to the human-readable format) might be more convenient.
(b) The "old" (still existing) "Timer" information is sent to stderr, thus, one can seem the Timer output without the need to grep through (potentially large) output, e.g., by simply redirecting the output to a file or even /dev/null --- obviously, aligning stderr & stdout in case of large multi-query scripts is then left to the user.
fflush(stdout); right before printing the time, then fflush(stderr); after.
what I ment was seding stdout to one file and stderr to another onen, and then afterwards find out in which timer output in stderr-file matches which query output in stdout-file ... Stefan
The new timing output goes (together with the queries status summary like how many result tuples were produced) to stdout (only).
(c) As the announcement (changelog) says, the new timing output is only produced with the "sql" formatter (i.e., not with, e.g., "raw" or "test", and hence, also not by default with `-s <sql-statement>` (unless one explicitly requests `-f sql`).
For (a) & (b) would it be an option to consider to also send the plain unformatted times in microseconds to stderr to (better) support automatic post-processing of the timings?
To cover also (c), we could consider doing that with all formatters, not only with "sql".
... just some ideas to think about and discuss ...
Stefan
-- Sjoerd Mullender
------------------------------------------------------------------------------ This SF.net email is sponsored by Sprint What will you do first with EVO, the first 4G phone? Visit sprint.com/first -- http://p.sf.net/sfu/sprint-com-first
_______________________________________________ Monetdb-developers mailing list Monetdb-developers@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/monetdb-developers
-- | Dr. Stefan Manegold | mailto:Stefan.Manegold@cwi.nl | | CWI, P.O.Box 94079 | http://www.cwi.nl/~manegold/ | | 1090 GB Amsterdam | Tel.: +31 (20) 592-4212 | | The Netherlands | Fax : +31 (20) 592-4199 |
While I like the new timing feature as well as the convenient formatting for human readability, I am wondering about two potential changes / extensions:
(a) While the time formatting is convenient for human readbility, it might be less convenient for automatic (post-)processing, e.g., creating performance figures. For that, plain unformatted microseconds (in addition to the human-readable format) might be more convenient.
mtest will never see it, becuase it either uses the raw formatting, or the special test-formatter which is designed to avoid differing output. This timing information is only available in the one and only output formatter that ordinary users should use. (That's why it displays ordinary time.)
(b) The "old" (still existing) "Timer" information is sent to stderr, thus, one can seem the Timer output without the need to grep through (potentially large) output, e.g., by simply redirecting the output to a file or even /dev/null --- obviously, aligning stderr & stdout in case of large multi-query scripts is then left to the user. The new timing output goes (together with the queries status summary like how many result tuples were produced) to stdout (only).
The old timer is left untouched. I disagree it should go to stderr (the other day I found a roommate who didn't really like that either, incidentially she happened to be the source of inspiration for implementing the "new" timer). It is just meta information about what the user sees. This is meant for ordinary users, not power users who need microsecond precision of 5 flavours for their experiments. Of course discarding the output, and only looking at the timing is highly questionable, since that superb time you got might be actually from the time that the server didn't do much e.g. due to some concurrency problem... But then, this completely falls under the aforementioned experiments setting, which this "new" timer doesn't even try to address.
(c) As the announcement (changelog) says, the new timing output is only produced with the "sql" formatter (i.e., not with, e.g., "raw" or "test", and hence, also not by default with `-s <sql-statement>` (unless one explicitly requests `-f sql`).
Just don't use -s, use the client interactively. A normal user should never be confronted with raw output in my opinion.
For (a) & (b) would it be an option to consider to also send the plain unformatted times in microseconds to stderr to (better) support automatic post-processing of the timings?
No. Just don't overdo it. It was never necessary in the past (isn't -t just an XQuery-oriented feature?), and it doesn't make sense to me in the near future either. If you want to monitor the time it takes to query something, you should have hooked it up in your application anyway, since it's trivial.
To cover also (c), we could consider doing that with all formatters, not only with "sql".
No. For that you already have your -t switch to the client.
participants (3)
-
Fabian Groffen -
Sjoerd Mullender -
Stefan Manegold