puzzled by "commit" Logging statement duration

From: "Day, David" <dday(at)redcom(dot)com>
To: "pgsql-general(at)postgresql(dot)org" <pgsql-general(at)postgresql(dot)org>
Subject: puzzled by "commit" Logging statement duration
Date: 2014-09-02 20:19:41
Message-ID: 401084E5E73F4241A44F3C9E6FD79428010D4AA104@exch-01
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

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

Responses

Browse pgsql-general by date

  From Date Subject
Next Message David G Johnston 2014-09-02 22:24:12 Re: puzzled by "commit" Logging statement duration
Previous Message David G Johnston 2014-09-02 18:59:40 Re: Question about gin index not used on a tsv column