Re: dbt2 NOTPM numbers

Hi,

Heikki Linnakangas wrote:
> I still suspect there's something wrong with plans, I doubt you can get
> that bad performance unless it's doing something really stupid.

Agreed, but I'm still looking for that really stupid thing... AFAICT,
there are really no seqscans..., see the pg_stat_user_tables below.

> I'd
> suggest setting log_min_duration_statement = 5000, and seeing what you
> get. Also check pg_stat_user_table.seq_scan just to be extra sure
> there's no seq scans.

I've also added some of the log messages for min_duration_statement
below. Both were taken after two or three test runs.

I'm really wondering, if the RAID 6 of the ARECA 1260 hurts so badly.
That would be disappointing, IMO. I'll try if I can reconfigure it to do
RAID 1+0, and then test again. (Unfortunately the box has already been
shipped to the customer, so that's getting tricky to do via ssh..:-( ).

Regards

Markus

*** pg_stat_user_tables ***

relid | schemaname | relname | seq_scan | seq_tup_read | idx_scan |
idx_tup_fetch | n_tup_ins | n_tup_upd | n_tup_del | last_vacuum |
last_autovacuum | last_analyze | last_autoanalyze
-------+------------+------------+----------+--------------+----------+---------------+-----------+-----------+-----------+-------------+-------------------------------+--------------+-------------------------------
16390 | public | district | 0 | 0 | 206335 |
206335 | 0 | 100771 | 0 | |
2007-06-05 15:40:44.39573+02 | | 2007-06-05 15:39:41.636736+02
16396 | public | new_order | 0 | 0 | 91860 |
41402317 | 51372 | 0 | 45844 | |
| |
16400 | public | order_line | 0 | 0 | 101195 |
933197 | 538442 | 436140 | 0 | |
| |
16402 | public | item | 0 | 0 | 538942 |
538442 | 0 | 0 | 0 | |
| |
16404 | public | stock | 0 | 0 | 1093528 |
1077782 | 0 | 538442 | 0 | |
| |
16394 | public | history | 0 | 0 | |
| 49399 | 0 | 0 | |
| |
16388 | public | warehouse | 0 | 0 | 150170 |
150170 | 0 | 49399 | 0 | |
2007-06-05 15:39:41.059572+02 | | 2007-06-05 15:38:39.976122+02
16398 | public | orders | 0 | 0 | 96490 |
96519 | 51372 | 45930 | 0 | |
| |
16392 | public | customer | 0 | 0 | 233263 |
599917 | 0 | 95329 | 0 | |
| |

*** database log snippet ***

2007-06-05 15:42:09 CEST LOG: duration: 6020.820 ms statement: SELECT
* FROM order_status(1747, 291, 3, '')
2007-06-05 15:42:09 CEST LOG: duration: 688.730 ms statement: SELECT
payment(47, 2, 1533, 47, 2, '', 4295.460000)
2007-06-05 15:42:09 CEST LOG: duration: 5923.518 ms statement: SELECT
payment(319, 8, 0, 319, 8, 'OUGHTATIONEING', 2331.470000)
2007-06-05 15:42:09 CEST LOG: duration: 6370.433 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 6463.583 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 6358.047 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 6114.972 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 6193.684 ms statement: SELECT
payment(96, 10, 0, 96, 10, 'ESEOUGHTBAR', 997.050000)
2007-06-05 15:42:09 CEST LOG: duration: 6375.163 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 6139.613 ms statement: SELECT
payment(454, 8, 0, 454, 8, 'ANTIOUGHTEING', 1575.110000)
2007-06-05 15:42:09 CEST LOG: duration: 6336.462 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 6420.227 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 6447.025 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 15549.277 ms statement: SELECT
delivery(124, 7)
2007-06-05 15:42:09 CEST LOG: duration: 1432.199 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 6478.086 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 1405.925 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:09 CEST LOG: duration: 8399.567 ms statement: SELECT
delivery(374, 4)
2007-06-05 15:42:10 CEST LOG: duration: 657.939 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:10 CEST LOG: duration: 1159.131 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:10 CEST LOG: duration: 840.907 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:10 CEST LOG: duration: 616.234 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:10 CEST LOG: duration: 1115.098 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:10 CEST LOG: duration: 1332.445 ms statement: SELECT
payment(465, 6, 0, 465, 6, 'ABLEESEESE', 4660.790000)
2007-06-05 15:42:10 CEST LOG: duration: 855.661 ms statement: SELECT
payment(267, 6, 0, 267, 6, 'OUGHTEINGOUGHT', 4214.080000)
2007-06-05 15:42:10 CEST LOG: duration: 580.983 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:10 CEST LOG: duration: 883.528 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:10 CEST LOG: duration: 7757.581 ms statement: SELECT
delivery(126, 6)
2007-06-05 15:42:10 CEST LOG: duration: 537.642 ms statement: SELECT
payment(493, 2, 0, 493, 2, 'BARBARANTI', 2881.500000)
2007-06-05 15:42:10 CEST LOG: duration: 1035.529 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:10 CEST LOG: duration: 1007.521 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:11 CEST LOG: duration: 1088.356 ms statement: FETCH
ALL IN mycursor
2007-06-05 15:42:11 CEST LOG: duration: 1749.507 ms statement: SELECT
delivery(442, 5)