What does 'elapsed' exact means in PostgreSQL Log Statistics

Hi,

I am engaged in a master degree project and i need the answer to the following question:

How much time the EXECUTOR of PostgreSQL spent during a determined time interval?

My Scenario is like this:

PostgreSQL 7.4 with the following parameters:
- log_duration = true
- log_pid = true
- log_statement = true
- log_timestamp = true
- log_parser_stats = true
- log_planner_stats = true
- log_executor_stats = true

- stats_start_colector = true
- stats_command_string = true
- stats_block_level = true

Using the BenchmarkSQL Software, I submit random transaction (simluating the TPC-C benchmark) during a time interval (say 30-45 seconds)

PostgreSQL then generate statistics for each phase which an SQL Command is executed (PARSER, REWRITE, PLANNER, EXECUTOR), like the log section below:

2007-09-27 15:07:25 [9269] LOG: sentença: SELECT c_discount, c_last, c_credit, w_tax FROM customer, warehouse WHERE w_id = $1 AND w_id = c_w_id AND c_d_id
= $2 AND c_id = $3
2007-09-27 15:07:25 [9269] LOG: PARSER STATISTICS
DETALHE: ! system usage stats:
! 0.000073 elapsed 0.000000 user 0.000000 system sec
! [0.000999 user 0.001999 sys total]
! 0/0 [0/0] filesystem blocks in/out
! 0/26 [0/490] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/0 [2/1] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
2007-09-27 15:07:25 [9269] LOG: PARSE ANALYSIS STATISTICS
DETALHE: ! system usage stats:
! 0.001513 elapsed 0.001000 user 0.001000 system sec
! [0.001999 user 0.002999 sys total]
! 0/0 [0/0] filesystem blocks in/out
! 0/149 [0/640] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/0 [2/1] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 40 read, 0 written, buffer hit rate = 75.00%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
2007-09-27 15:07:25 [9269] LOG: REWRITER STATISTICS
DETALHE: ! system usage stats:
! 0.000016 elapsed 0.000000 user 0.000000 system sec
! [0.001999 user 0.002999 sys total]
! 0/0 [0/0] filesystem blocks in/out
! 0/2 [0/644] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/0 [2/1] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
2007-09-27 15:07:25 [9269] LOG: PLANNER STATISTICS
DETALHE: ! system usage stats:
! 0.001496 elapsed 0.001000 user 0.000000 system sec
! [0.002999 user 0.002999 sys total]
! 0/0 [0/0] filesystem blocks in/out
! 0/109 [0/754] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/1 [2/2] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 26 read, 0 written, buffer hit rate = 81.56%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written
2007-09-27 15:07:25 [9269] LOG: EXECUTOR STATISTICS
DETALHE: ! system usage stats:
! 0.022129 elapsed 0.000000 user 0.002000 system sec
! [0.002999 user 0.005999 sys total]
! 0/0 [0/0] filesystem blocks in/out
! 0/186 [0/966] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 2/0 [4/2] voluntary/involuntary context switches
! buffer usage stats:
! Shared blocks: 94 read, 0 written, buffer hit rate = 0.00%
! Local blocks: 0 read, 0 written, buffer hit rate = 0.00%
! Direct blocks: 0 read, 0 written

Trying to answer my initial question, I do something like this:

1. Through the Commands TIMESTAMP, I calculate the total time interval where all the commands had been executed. (END TIMESTAMP - BEGIN TIMESTAMP)
2. Then I sum all the 'elapsed' fields of all EXECUTOR Sections of all commands executed. This, in thesis, give me the amount of time that the executor had been used during the total time interval where the commands had been executed)

The problem I have encountered is that the sum of executor's elapsed time is bigger, sometimes, than the total time interval where the commands had been executed!! In some tests I did, I found this results:
- Total Time interval which BenchmarkSQL submitted queries = 30 seconds
- sum of executor's elapsed time during this period of time = 2 minutes and 36 seconds

Let me show you how I am interpreting the 'elapsed' number generated by PostgreSQL, according to the funtcion 'ShowUsage()' (see: http://doxygen.postgresql.org/postgres_8c.html#7f657058d4a936c22d076d31bf786828)
As I could see, the 'timeval' struct definition has 2 fields: tv_sec (save the seconds of the time) and tv_usec (save the microseconds of the time) (see: http://www.gnu.org/software/libc/manual/html_node/Elapsed-Time.html)
I did not understand the meaning of the 'if' clause "if (elapse_t.tv_usec < Save_t.tv_usec)" presenting in the code of ShowUsage() (lines 3827 - 3831).
According to the 'timeval' struct definition, a interpreting the 'elapsed' numer as <timeInSeconds>.<timeInMicroseconds> and converting this number to milliseconds, I make the following calculation:
timeInMillis = [(<timeInSeconds> * 1000) + (<timeInMicroseconds> / 1000)].

Am I correct? The really means of elapsed time in EXECUTOR stats is <second>.<microseconds>? I had submitted this questio to other lists and someone answered that the number elapsed is already in milliseconds. Is that true?
Supose I am correct, how can the sum of elapsed time of executor be bigger than the sum of duration of the commands tha use it?

Can anyone, please, help me to solve this?

[Camilo Porto]

_________________________________________________________________
Conheça o Windows Live Spaces, a rede de relacionamentos conectada ao Messenger!
http://spaces.live.com/signup.aspx