Thread: puzzled by "commit" Logging statement duration

puzzled by "commit" Logging statement duration

From
"Day, David"
Date:

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

Re: puzzled by "commit" Logging statement duration

From
David G Johnston
Date:
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.