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....
--
Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance
