Обсуждение: 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.