puzzled by "commit" Logging statement duration
Hoping for a teachable moment :+)
With options enabled to log statement execution times in the postgres log file I observe:
2014-09-02T12:47:38.107808-04:00 alabama local0 info postgres[37874]: [702-1] user=ace_db_client,db=ace_db LOG: duration: 0.040 ms statement: BEGIN
2014-09-02T12:47:38.108714-04:00 alabama local0 info postgres[37874]: [703-1] user=ace_db_client,db=ace_db LOG: duration: 0.595 ms statement: SELECT log.table_maintenance()
2014-09-02T12:47:38.218759-04:00 alabama local0 info postgres[37874]: [704-1] user=ace_db_client,db=ace_db LOG: duration: 109.639 ms statement: COMMIT
Why is the commit duration so large in [704-1] and the work was done ? in [703-1]
Detail:
I have a client application attaching to a postgres 9.3 server and periodically invoking a server side function ( log.table_maintenace)
Autocommit is enabled for the session, would not any commit work have completed on the return from the select ?
( I thought functions were auto-commit ? , I also note that the table_maintenance function returns VOID.
Client side code: C++ using the libpqxx library.
int log_table_maint(pqxx::work &t, const IpmPtr ipm ) {
int err = 0;
try {
t.exec("SELECT log.table_maintenance()");
t.commit();
}
catch ( const std::exception &e ) {
t.abort();
err = status = DB_STAT_FAIL;
}
return err;
}
When attached locally to the server and running the same command from the psql shell I observe:
ace_db=# explain analyze select log.table_maintenance();
QUERY PLAN
------------------------------------------------------------------------------------
Result (cost=0.00..0.26 rows=1 width=0) (actual time=1.433..1.439 rows=1 loops=1)
Total runtime: 1.550 ms
(2 rows)
A bit puzzled
Thanks for any thoughts or illumination.
Regards
Dave Day
Day, David wrote
Hoping for a teachable moment :+)
2-3 of them apparently...
Why is the commit duration so large in [704-1] and the work was done ? in
[703-1]
greatly simplified but:
COMMIT means - "write to disk"; this is expensive. In a transaction (see
below) the statements can be run fairly quickly because they are not
guaranteed to be written to disk until you issue a commit.
Autocommit is enabled for the session, would not any commit work have
completed on the return from the select ?
( I thought functions were auto-commit ? , I also note that the
table_maintenance function returns VOID.
You issued an explicit BEGIN - it doesn't matter what you auto-commit mode
is set to at this point. It may be your middleware that is sending the
BEGIN, not you, but the end result is the same.
When attached locally to the server and running the same command from the
psql shell I observe:ace_db=# explain analyze select log.table_maintenance();
QUERY PLAN
------------------------------------------------------------------------------------
Result (cost=0.00..0.26 rows=1 width=0) (actual time=1.433..1.439 rows=1
loops=1)
Total runtime: 1.550 ms
(2 rows)
If you mean to compare the 1.55ms to the 109+ms that is going to be
difficult since you haven't setup a controlled experiment; or more
specifically at minimum run the queries many times and calculate an average
value to compare.
David J.
--
View this message in context: http://postgresql.1045698.n5.nabble.com/puzzled-by-commit-Logging-statement-duration-tp5817447p5817474.html
Sent from the PostgreSQL - general mailing list archive at Nabble.com.
--
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general