Обсуждение: long running insert statement
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....
On Thu, 1 Oct 2009, Gerd König wrote:
> Trigger NotReceivedTransport_Delete: time=24658.394 calls=1
Yeah, it's pretty obvious this is the problem.
> 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)
Maybe it's cached this time.
In any case, you have a bitmap index scan which is fetching 6347 rows and
then filtering that down to zero. Assuming one seek per row, that means
6347 disc seeks, which is about 3.8 ms per seek - better than you would
expect from a disc. This means that the time taken is quite reasonable for
what you are asking it to do.
To fix this, I suggest creating an index on NotReceivedTransport(SId, CId,
ShipperTransportNumber). Then, the index will be able to immediately see
that there are no rows to delete.
Matthew
--
"We have always been quite clear that Win95 and Win98 are not the systems to
use if you are in a hostile security environment." "We absolutely do recognize
that the Internet is a hostile environment." Paul Leach <paulle@microsoft.com>
=?ISO-8859-2?Q?Gerd_K=F6nig?= <koenig@transporeon.com> writes:
> 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..?!?
There are two possible explanations for the time difference:
1. The second time around, the relevant rows were already in cache.
2. You might not actually be testing the same plan. The query that's
being executed by the trigger function is parameterized. The manual
equivalent would look about like this:
prepare foo(int,int,text) as
DELETE FROM "NotReceivedTransport" WHERE "SId" =
$1 AND "CId" = $2 AND "ShipperTransportNumber" = $3;
explain analyze execute foo(11479,11479,'100432');
(Note that I'm guessing as to the parameter data types.)
It seems possible that without knowledge of the exact Cid value being
searched for, the planner would choose not to use the index on that
column. As Matthew already noted, this index is pretty marginal for
this query anyway, and the planner might well only want to use it for
less-common Cid values.
I agree with Matthew's solution --- an index better adapted to this
query will probably be worth its maintenance overhead. But if you
want to understand the behavior you were seeing in trying to
investigate, I think it's one of the two issues above.
regards, tom lane
Hello Matthew, hello Tom, thanks for your reply. ...and yes, the hint with the newly created index solved the problem. kind regards...GERD... Tom Lane wrote: > =?ISO-8859-2?Q?Gerd_K=F6nig?= <koenig@transporeon.com> writes: >> 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..?!? > > There are two possible explanations for the time difference: > > 1. The second time around, the relevant rows were already in cache. > > 2. You might not actually be testing the same plan. The query that's > being executed by the trigger function is parameterized. The manual > equivalent would look about like this: > > prepare foo(int,int,text) as > DELETE FROM "NotReceivedTransport" WHERE "SId" = > $1 AND "CId" = $2 AND "ShipperTransportNumber" = $3; > > explain analyze execute foo(11479,11479,'100432'); > > (Note that I'm guessing as to the parameter data types.) > > It seems possible that without knowledge of the exact Cid value being > searched for, the planner would choose not to use the index on that > column. As Matthew already noted, this index is pretty marginal for > this query anyway, and the planner might well only want to use it for > less-common Cid values. > > I agree with Matthew's solution --- an index better adapted to this > query will probably be worth its maintenance overhead. But if you > want to understand the behavior you were seeing in trying to > investigate, I think it's one of the two issues above. > > regards, tom lane > -- /===============================\ | Gerd König | - Infrastruktur - | | TRANSPOREON GmbH | Pfarrer-Weiss-Weg 12 | DE - 89077 Ulm | | Tel: +49 [0]731 16906 16 | Fax: +49 [0]731 16906 99 | Web: www.transporeon.com | \===============================/ Bleiben Sie auf dem Laufenden. Jetzt den Transporeon Newsletter abonnieren! http://www.transporeon.com/unternehmen_newsletter.shtml TRANSPOREON GmbH, Amtsgericht Ulm, HRB 722056 Geschäftsf.: Peter Förster, Roland Hötzl, Marc-Oliver Simon