Re: dbt2 NOTPM numbers - Mailing list pgsql-performance

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)