Skip site navigation (1) Skip section navigation (2)

URGENT HELP about 'duration' stats

From: Camilo Porto <camiloporto(at)hotmail(dot)com>
To: <pgsql-hackers(at)postgresql(dot)org>
Subject: URGENT HELP about 'duration' stats
Date: 2007-10-27 02:46:42
Message-ID: BLU111-W521DC75D94C33D2F5034C0BC970@phx.gbl (view raw or flat)
Thread:
Lists: pgsql-hackers
Hi,

I
have been doing my master degree research  and  I am using Postgresql
8.2.5. I would appreciate if anyone could help me, ASAP, concerning the
following question:


How can I obtain the time spent by the Postgresql  EXECUTOR  during a given time interval? 
 
I am trying to get the above information in the following way::
 
Using
the BenchmarkSQL Software, I submit random transactions (by simulating
the TPC-C benchmark) during a time interval (say 30 seconds). 

PostgreSQL then generates statistics for each phase that
a SQL Command is executed. In thje following, it is shown the time
duration of the EXECUTE Phase of some SQL Command:
 
.
.
.
.
2007-10-11 15:49:
05.221 BRT [46994] LOG:  duration: 0.012 ms  execute S_1: BEGIN
2007-10-11
15:49:05.430 BRT [46994] LOG:  duration: 94.073 ms  execute
<unnamed>: 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-10-11
15:49:05.462 BRT [46994] LOG:  duration: 13.662 ms  execute
<unnamed>: SELECT d_next_o_id, d_tax FROM district WHERE d_id =
$1 AND d_w_id = $2 FO

R UPDATE
2007-10-11 15:49:05.562 BRT [46994] LOG:  duration:
98.818 ms  execute <unnamed>: INSERT INTO NEW_ORDER (no_o_id,
no_d_id, no_w_id) VALUES ( $1, $2, $3)
2007-10-11 15:49:05.579 BRT [46994] LOG:  duration: 
15.459 ms  execute <unnamed>: UPDATE district SET d_next_o_id = d_next_o_id + 1  WHERE d_id = $1 AND d_w 
_id = $2
2007-10-11
15:49:05.748 BRT [46994] LOG:  duration: 122.387 ms  execute
<unnamed>: INSERT INTO OORDER  (o_id, o_d_id, o_w_id, o_c_id,
o_entry_d, o_ol_cnt, o

_all_local) VALUES ($1, $2, $3, $4, $5, $6, $7) 
2007-10-11
15:49:05.779 BRT [46994] LOG:  duration: 29.787 ms  execute
<unnamed>: SELECT i_price, i_name , i_data FROM item WHERE i_id =
$1
2007-10-11 15:49:
05.846 BRT [46994] LOG:  duration: 64.963 ms  execute <unnamed>:
SELECT s_quantity, s_data, s_dist_01, s_dist_02, s_dist_03, s_dist_04,
s_d 
ist_05,        s_dist_06, s_dist_07, s_dist_08, s_dist_09, s_dist_10 FROM stock WHERE s_i_id = $1 AND s_w_id = $2 FOR UPDATE

2007-10-11 15:49:05.882 BRT [46994] LOG:  duration: 33.865 ms 
execute <unnamed>: SELECT i_price, i_name , i_data FROM item
WHERE i_id = $1 
2007-10-11 15:49:05.931 BRT [46994] LOG: 
duration: 48.075 ms  execute <unnamed>: SELECT s_quantity,
s_data, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_d

ist_05,        s_dist_06, s_dist_07, s_dist_08, s_dist_09, s_dist_10 FROM stock WHERE s_i_id = $1 AND s_w_id = $2 FOR UPDATE 
2007-10-11
15:49:05.962 BRT [46994] LOG:  duration: 28.782 ms  execute
<unnamed>: SELECT i_price, i_name , i_data FROM item WHERE i_id =
$1

2007-10-11
15:49:06.002 BRT [46994] LOG:  duration: 38.026 ms  execute
<unnamed>: SELECT s_quantity, s_data, s_dist_01, s_dist_02,
s_dist_03, s_dist_04, s_d 
ist_05,        s_dist_06, s_dist_07, s_dist_08, s_dist_09, s_dist_10 FROM stock WHERE s_i_id = $1 AND s_w_id = $2 FOR UPDATE

2007-10-11 15:49:06.027 BRT [46994] LOG:  duration: 23.220 ms 
execute <unnamed>: SELECT i_price, i_name , i_data FROM item
WHERE i_id = $1 
2007-10-11 15:49:06.043 BRT [46994] LOG: 
duration: 14.308 ms  execute <unnamed>: SELECT s_quantity,
s_data, s_dist_01, s_dist_02, s_dist_03, s_dist_04, s_d

ist_05,        s_dist_06, s_dist_07, s_dist_08, s_dist_09, s_dist_10 FROM stock WHERE s_i_id = $1 AND s_w_id = $2 FOR UPDATE 
.
.
.
.

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


1. Through the statements TIMESTAMP, I calculate the total time
interval in which all the statments had been executed: (END
TIMESTAMP(2007-10-11 15:49: 06.043) - BEGIN TIMESTAMP (2007-10-11
15:49:05.221))
2. Then I sum all the 'duration' fields of all
EXECUTOR Sections of all statements executed. This, in thesis, give me
the amount of time that the executor had been used during the total
time interval in which the statements had been executed)


The problem I have encountered is that the sum of executor's
duration time is, *sometimes*, bigger than the total time interval in
which the statements had been executed!! And this makes no sense!


In some tests I have done, I have found these results:
- Total Time interval which BenchmarkSQL submitted queries = 30 seconds

- sum of executor's duration time during this period of time = 2 minutes and 36 seconds!! (5x longer than total time) 


How could the sum of duration time of executor be longer than the sum of duration of the statements that use it?


Can anyone, please, help me to solve this? Many thanks, Camilo
_________________________________________________________________
Veja mapas e encontre as melhores rotas para fugir do trânsito com o Live Search Maps!
http://www.livemaps.com.br/index.aspx?tr=true

Responses

pgsql-hackers by date

Next:From: Tom LaneDate: 2007-10-27 03:06:22
Subject: Re: URGENT HELP about 'duration' stats
Previous:From: Greg SmithDate: 2007-10-27 02:39:12
Subject: Re: PANIC caused by open_sync on Linux

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group