long running insert statement

Поиск
Список
Период
Сортировка
От Gerd König
Тема long running insert statement
Дата
Msg-id 4AC45829.9030405@transporeon.com
обсуждение исходный текст
Ответы Re: long running insert statement
Re: long running insert statement
Список pgsql-performance
Hello,

we're currently facing long running insert statements with durations ~15sec (far
too long...) and I've no idea what's the reason for this issue.

An "explain analyze" of the insert statement tells me:
############ SNIP #########################################################
begin;
BEGIN
tisys=# explain analyze INSERT INTO "Transport" ("MasterCurrency",
"Timestamp", "Id", "Number", "DeliveryNumbers", "Plant", "Weight",
"WeightNet", "WeightTara", "WeightUnit", "Length", "LengthUnit", "Volume",
"VolumeUnit", "Distance", "DistanceUnit", "Zone",
"TransportationMeansDescription", "Archived", "Compressed",
"TransportationModeId", "TransportationMeansId", "SId",
"CId", "TransportAssignmentModeId", "TransportStatusId",
"TransportBookingStatusId", "CGId") VALUES ('EUR', '2009-09-25
11:44:04.000000', 136, '432', '516', 'Standard', '16000', '0', '0', 'kg', '9',
'm', '22', 'cbm', '0', '', '0', 'Tautliner', FALSE, FALSE, 2, 2400, 6138, 11479,
10, 60, NULL,NULL);
                                     QUERY PLAN
------------------------------------------------------------------------------------
 Result  (cost=0.00..0.05 rows=1 width=0) (actual time=0.026..0.027 rows=1 loops=1)
 Trigger NotReceivedTransport_Delete: time=24658.394 calls=1
 Trigger for constraint transport_c_id: time=69.148 calls=1
 Trigger for constraint transport_cg_id: time=0.152 calls=1
 Trigger for constraint transport_s_id: time=0.220 calls=1
 Trigger for constraint transport_transportassignmentmode_id: time=0.369 calls=1
 Trigger for constraint transport_transportationmeans_id: time=0.344 calls=1
 Trigger for constraint transport_transportationmode_id: time=0.296 calls=1
 Trigger for constraint transport_transportstatus_id: time=0.315 calls=1
 Trigger for constraint transport_transportbookingstatus_id: time=0.006 calls=1
 Total runtime: 25453.821 ms
(11 rows)

tisys=# rollback;
ROLLBACK
############# SNIP END #####################################################

This output tells me that the trigger is the problem, but inside the trigger
there's only one delete statement =>
############## SNIP ########################################################
CREATE OR REPLACE FUNCTION "NotReceivedTransport_Delete"()
  RETURNS trigger AS
$BODY$
BEGIN
    IF (NEW."TransportStatusId" = 60) THEN
        DELETE FROM "NotReceivedTransport" WHERE "SId" =
NEW."SId" AND "CId" = NEW."CId" AND "ShipperTransportNumber" = NEW."Number";
    END IF;
    RETURN NEW;
END;
$BODY$
  LANGUAGE 'plpgsql' VOLATILE
  COST 100;
############### SNIP END ####################################################

afterwards I tried to explain analyze this delete statement and got =>
############## SNIP ########################################################
explain analyze DELETE FROM "NotReceivedTransport" WHERE
"SId" = 11479 AND "CId" = 11479 AND
"ShipperTransportNumber" = '100432';
                                                                         QUERY PLAN
----------------------------------------------------------------------------------
 Bitmap Heap Scan on "NotReceivedTransport"  (cost=20.35..3939.16 rows=1
width=6) (actual time=94.625..94.625 rows=0 loops=1)
   Recheck Cond: ("CId" = 11479)
   Filter: (("SId" = 11479) AND (("ShipperTransportNumber")::text
= '100432'::text))
   ->  Bitmap Index Scan on notreceivedtransport_index_cid
(cost=0.00..20.35 rows=1060 width=0) (actual time=2.144..2.144 rows=6347 loops=1)
         Index Cond: ("CarrierCustomerId" = 11479)
 Total runtime: 94.874 ms
(6 rows)
############## SNIP END ####################################################


I'm quite sure that the difference from 94ms (explain of the delete statement)
to 24s (duration in the trigger) is not only due to some overhead in trigger
handling...but I've no idea what else we can check..?!?

We're using postgresql 8.3.7 on openSuse 10.3 64bit and a snippet of vmstat
looks like:
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa
3  0    856 114472  62800 7530800    0    0    53    54    0    0  4  0 93  3
1  1    856 114264  62820 7530920    0    0    56   956 2641 2822 15  0 80  5
1  1    856 114264  62828 7530936    0    0     8   632 2433 2586 16  0 80  3
0  0    856 114140  62836 7530944    0    0     0   424 1980 2085 14  0 82  3
0  0    856 114140  62840 7530952    0    0     0   488 1915 2008  4  0 92  4
3  0    856 114264  62852 7530972    0    0    40   700 2009 2149 16  0 80  4
2  0    856 113456  62864 7530992    0    0     8   724 2576 2669  6  1 90  3
2  0    856 132664  62872 7531008    0    0     8   804 2580 2764 19  1 76  3
2  1    856 132180  62876 7531020    0    0     0   760 2545 2782 19  1 77  4
1  0    856 124896  62888 7531044    0    0    24   512 2943 3128  9  1 86  3
1  0    856 121948  62900 7531240    0    0   232   716 2005 2063  5  1 88  6

waiting for I/O doesn't seem to be the problem..?!?!

any help appreciated....GERD....

В списке pgsql-performance по дате отправления:

Предыдущее
От: Tom Lane
Дата:
Сообщение: Re: CPU cost of operators
Следующее
От: S Arvind
Дата:
Сообщение: Confusion on shared buffer