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
