pgbench transaction timestamps
This patch changes the way pgbench outputs its latency log files so that
every transaction gets a timestamp and notes which transaction type was
executed. It's a one-line change that just dumps some additional
information that was already sitting in that area of code. I also made a
couple of documentation corrections and clarifications on some of the more
confusing features of pgbench.
It's straightforward to parse log files in this format to analyze what
happened during the test at a higher level than was possible with the
original format. You can find some rough sample code to convert this
latency format into CVS files and then into graphs at
http://www.westnet.com/~gsmith/content/postgresql/pgbench.htm which I'll
be expanding on once I get all my little patches sent in here.
If you recall the earlier version of this patch I submitted, it added a
cleanup feature that did a vacuum and checkpoint after the test was
finished and reported two TPS results. The idea was to quantify how much
of a hit the eventual table maintenance required to clean up after the
test would take. While those things do influence results and cause some
of the run-to-run variation in TPS (checkpoints are particularly visible
in the graphs), after further testing I concluded running a VACUUM VERBOSE
and CHECKPOINT in a script afterwards and analyzing the results was more
useful than integrating something into pgbench itself.
--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD
Attachments:
pgbench-timestamp.txttext/plain; CHARSET=US-ASCII; NAME=pgbench-timestamp.txtDownload
Index: contrib/pgbench/README.pgbench
===================================================================
RCS file: /projects/cvsroot/pgsql/contrib/pgbench/README.pgbench,v
retrieving revision 1.15
diff -c -r1.15 README.pgbench
*** contrib/pgbench/README.pgbench 21 Oct 2006 06:31:28 -0000 1.15
--- contrib/pgbench/README.pgbench 1 Apr 2007 00:57:48 -0000
***************
*** 94,103 ****
default is 1. NOTE: scaling factor should be at least
as large as the largest number of clients you intend
to test; else you'll mostly be measuring update contention.
-D varname=value
! Define a variable. It can be refereed to by a script
! provided by using -f option. Multile -D options are allowed.
-U login
Specify db user's login name if it is different from
--- 94,107 ----
default is 1. NOTE: scaling factor should be at least
as large as the largest number of clients you intend
to test; else you'll mostly be measuring update contention.
+ Regular (not initializing) runs using one of the
+ built-in tests will detect scale based on the number of
+ branches in the database. For custom (-f) runs it can
+ be manually specified with this parameter.
-D varname=value
! Define a variable. It can be refered to by a script
! provided by using -f option. Multiple -D options are allowed.
-U login
Specify db user's login name if it is different from
***************
*** 139,147 ****
with the name "pgbench_log.xxx", where xxx is the PID
of the pgbench process. The format of the log is:
! client_id transaction_no time
! where time is measured in microseconds.
-d
debug option.
--- 143,157 ----
with the name "pgbench_log.xxx", where xxx is the PID
of the pgbench process. The format of the log is:
! client_id transaction_no time file_no time-epoch time-us
! where time is measured in microseconds, , the file_no is
! which test file was used (useful when multiple were
! specified with -f), and time-epoch/time-us are a
! UNIX epoch format timestamp followed by an offset
! in microseconds (suitable for creating a ISO 8601
! timestamp with a fraction of a second) of when
! the transaction completed.
-d
debug option.
***************
*** 163,168 ****
--- 173,180 ----
(7) end;
+ If you specify -N, (4) and (5) aren't included in the transaction.
+
o -f option
This supports for reading transaction script from a specified
Index: contrib/pgbench/pgbench.c
===================================================================
RCS file: /projects/cvsroot/pgsql/contrib/pgbench/pgbench.c,v
retrieving revision 1.62
diff -c -r1.62 pgbench.c
*** contrib/pgbench/pgbench.c 13 Mar 2007 09:06:35 -0000 1.62
--- contrib/pgbench/pgbench.c 1 Apr 2007 00:57:49 -0000
***************
*** 461,467 ****
diff = (int) (now.tv_sec - st->txn_begin.tv_sec) * 1000000.0 +
(int) (now.tv_usec - st->txn_begin.tv_usec);
! fprintf(LOGFILE, "%d %d %.0f\n", st->id, st->cnt, diff);
}
if (commands[st->state]->type == SQL_COMMAND)
--- 461,468 ----
diff = (int) (now.tv_sec - st->txn_begin.tv_sec) * 1000000.0 +
(int) (now.tv_usec - st->txn_begin.tv_usec);
! fprintf(LOGFILE, "%d %d %.0f %d %ld %ld\n",
! st->id, st->cnt, diff, st->use_file, now.tv_sec,now.tv_usec);
}
if (commands[st->state]->type == SQL_COMMAND)
Your patch has been added to the PostgreSQL unapplied patches list at:
http://momjian.postgresql.org/cgi-bin/pgpatches
It will be applied as soon as one of the PostgreSQL committers reviews
and approves it.
---------------------------------------------------------------------------
Greg Smith wrote:
This patch changes the way pgbench outputs its latency log files so that
every transaction gets a timestamp and notes which transaction type was
executed. It's a one-line change that just dumps some additional
information that was already sitting in that area of code. I also made a
couple of documentation corrections and clarifications on some of the more
confusing features of pgbench.It's straightforward to parse log files in this format to analyze what
happened during the test at a higher level than was possible with the
original format. You can find some rough sample code to convert this
latency format into CVS files and then into graphs at
http://www.westnet.com/~gsmith/content/postgresql/pgbench.htm which I'll
be expanding on once I get all my little patches sent in here.If you recall the earlier version of this patch I submitted, it added a
cleanup feature that did a vacuum and checkpoint after the test was
finished and reported two TPS results. The idea was to quantify how much
of a hit the eventual table maintenance required to clean up after the
test would take. While those things do influence results and cause some
of the run-to-run variation in TPS (checkpoints are particularly visible
in the graphs), after further testing I concluded running a VACUUM VERBOSE
and CHECKPOINT in a script afterwards and analyzing the results was more
useful than integrating something into pgbench itself.--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD
Content-Description:
[ Attachment, skipping... ]
---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend
--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
Tatsuo, would you please comment on this patch too?
---------------------------------------------------------------------------
Greg Smith wrote:
This patch changes the way pgbench outputs its latency log files so that
every transaction gets a timestamp and notes which transaction type was
executed. It's a one-line change that just dumps some additional
information that was already sitting in that area of code. I also made a
couple of documentation corrections and clarifications on some of the more
confusing features of pgbench.It's straightforward to parse log files in this format to analyze what
happened during the test at a higher level than was possible with the
original format. You can find some rough sample code to convert this
latency format into CVS files and then into graphs at
http://www.westnet.com/~gsmith/content/postgresql/pgbench.htm which I'll
be expanding on once I get all my little patches sent in here.If you recall the earlier version of this patch I submitted, it added a
cleanup feature that did a vacuum and checkpoint after the test was
finished and reported two TPS results. The idea was to quantify how much
of a hit the eventual table maintenance required to clean up after the
test would take. While those things do influence results and cause some
of the run-to-run variation in TPS (checkpoints are particularly visible
in the graphs), after further testing I concluded running a VACUUM VERBOSE
and CHECKPOINT in a script afterwards and analyzing the results was more
useful than integrating something into pgbench itself.--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD
Content-Description:
[ Attachment, skipping... ]
---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend
--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
Tatsuo, would you please comment on this patch too?
No problem. I will come up with a comment by the end of this week.
--
Tatsuo Ishii
SRA OSS, Inc. Japan
Show quoted text
---------------------------------------------------------------------------
Greg Smith wrote:
This patch changes the way pgbench outputs its latency log files so that
every transaction gets a timestamp and notes which transaction type was
executed. It's a one-line change that just dumps some additional
information that was already sitting in that area of code. I also made a
couple of documentation corrections and clarifications on some of the more
confusing features of pgbench.It's straightforward to parse log files in this format to analyze what
happened during the test at a higher level than was possible with the
original format. You can find some rough sample code to convert this
latency format into CVS files and then into graphs at
http://www.westnet.com/~gsmith/content/postgresql/pgbench.htm which I'll
be expanding on once I get all my little patches sent in here.If you recall the earlier version of this patch I submitted, it added a
cleanup feature that did a vacuum and checkpoint after the test was
finished and reported two TPS results. The idea was to quantify how much
of a hit the eventual table maintenance required to clean up after the
test would take. While those things do influence results and cause some
of the run-to-run variation in TPS (checkpoints are particularly visible
in the graphs), after further testing I concluded running a VACUUM VERBOSE
and CHECKPOINT in a script afterwards and analyzing the results was more
useful than integrating something into pgbench itself.--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MDContent-Description:
[ Attachment, skipping... ]
---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://www.enterprisedb.com+ If your life is a hard drive, Christ can be your backup. +
Tatsuo, would you please comment on this patch too?
No problem. I will come up with a comment by the end of this week.
Here are comments.
1) latency log file format extention looks usefull (-x option).
2) it seems the "cleanup feature" (-X option) was withdrawed by the
author, but the patches still include the feature. So I'm confused.
--
Tatsuo Ishii
SRA OSS, Inc. Japan
Show quoted text
---------------------------------------------------------------------------
Greg Smith wrote:
This patch changes the way pgbench outputs its latency log files so that
every transaction gets a timestamp and notes which transaction type was
executed. It's a one-line change that just dumps some additional
information that was already sitting in that area of code. I also made a
couple of documentation corrections and clarifications on some of the more
confusing features of pgbench.It's straightforward to parse log files in this format to analyze what
happened during the test at a higher level than was possible with the
original format. You can find some rough sample code to convert this
latency format into CVS files and then into graphs at
http://www.westnet.com/~gsmith/content/postgresql/pgbench.htm which I'll
be expanding on once I get all my little patches sent in here.If you recall the earlier version of this patch I submitted, it added a
cleanup feature that did a vacuum and checkpoint after the test was
finished and reported two TPS results. The idea was to quantify how much
of a hit the eventual table maintenance required to clean up after the
test would take. While those things do influence results and cause some
of the run-to-run variation in TPS (checkpoints are particularly visible
in the graphs), after further testing I concluded running a VACUUM VERBOSE
and CHECKPOINT in a script afterwards and analyzing the results was more
useful than integrating something into pgbench itself.--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MDContent-Description:
[ Attachment, skipping... ]
---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://www.enterprisedb.com+ If your life is a hard drive, Christ can be your backup. +
On Fri, 6 Apr 2007, Tatsuo Ishii wrote:
1) latency log file format extention looks usefull (-x option).
2) it seems the "cleanup feature" (-X option) was withdrawed by the
author, but the patches still include the feature. So I'm confused.The patch I sent to the mailing list pulled that feature out; I haven't
updated the version on my web page yet. If you looked at the one on my
web page it's still running the old version.The version attached to this message is the final version I submitted.
The code change is one line, the documentation fixes are longer.
patch committed. Thanks.
--
Tatsuo Ishii
SRA OSS, Inc. Japan
Import Notes
Reply to msg id not found: Pine.GSO.4.64.0704060040130.11244@westnet.com
FYI, patch applied by Tatsuo. Thanks.
---------------------------------------------------------------------------
Greg Smith wrote:
This patch changes the way pgbench outputs its latency log files so that
every transaction gets a timestamp and notes which transaction type was
executed. It's a one-line change that just dumps some additional
information that was already sitting in that area of code. I also made a
couple of documentation corrections and clarifications on some of the more
confusing features of pgbench.It's straightforward to parse log files in this format to analyze what
happened during the test at a higher level than was possible with the
original format. You can find some rough sample code to convert this
latency format into CVS files and then into graphs at
http://www.westnet.com/~gsmith/content/postgresql/pgbench.htm which I'll
be expanding on once I get all my little patches sent in here.If you recall the earlier version of this patch I submitted, it added a
cleanup feature that did a vacuum and checkpoint after the test was
finished and reported two TPS results. The idea was to quantify how much
of a hit the eventual table maintenance required to clean up after the
test would take. While those things do influence results and cause some
of the run-to-run variation in TPS (checkpoints are particularly visible
in the graphs), after further testing I concluded running a VACUUM VERBOSE
and CHECKPOINT in a script afterwards and analyzing the results was more
useful than integrating something into pgbench itself.--
* Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD
Content-Description:
[ Attachment, skipping... ]
---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend
--
Bruce Momjian <bruce@momjian.us> http://momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +