Message-ID: <5179E77B.7050601@catalyst.net.nz>
Date: Fri, 26 Apr 2013 14:33:31 +1200
From: Mark Kirkwood <mark.kirkwood@catalyst.net.nz>
User-Agent: Mozilla/5.0 (X11; Linux x86_64;
	rv:17.0) Gecko/20130404 Thunderbird/17.0.5
MIME-Version: 1.0
To: "pgsql-performance@postgresql.org" <pgsql-performance@postgresql.org>
Subject: In progress INSERT wrecks plans on table
Content-Type: multipart/mixed; boundary="------------080001020208050405080401"
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

This is a multi-part message in MIME format.
--------------080001020208050405080401
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit

Recently we encountered the following unhappy sequence of events:

1/ system running happily
2/ batch load into table begins
3/ very quickly (some) preexisting queries on said table go orders of 
magnitude slower
4/ database instance becomes unresponsive
5/ application outage

After looking down a few false leads, We've isolated the cause to the 
following:

The accumulating in-progress row changes are such that previously 
optimal plans are optimal no longer. Now this situation will fix itself 
when the next autoanalyze happens (and new plan will be chosen) - 
however that cannot occur until the batch load is completed and 
committed (approx 70 seconds). However during that time there is enough 
of a performance degradation for queries still using the old plan to 
cripple the server.

Now that we know what is happening we can work around it. But I'm 
wondering - is there any way (or if not should there be one) to let 
postgres handle this automatically? I experimented with a quick hack to 
src/backend/commands/analyze.c (attached) that lets another session's 
ANALYZE see in progress rows - which works but a) may cause other 
problems and b) does not help autoaanalyze which has to wait for COMMIT 
+ stats message.

I've attached a (synthetic) test case that shows the issue, I'll 
reproduce the output below to hopefully make the point obvious:


                Table "public.plan"
  Column |            Type             | Modifiers
--------+-----------------------------+-----------
  id     | integer                     | not null
  typ    | integer                     | not null
  dat    | timestamp without time zone |
  val    | text                        | not null
Indexes:
     "plan_id" UNIQUE, btree (id)
     "plan_dat" btree (dat)
     "plan_typ" btree (typ)


[Session 1]
EXPLAIN ANALYZE
SELECT * FROM plan
WHERE typ = 3 AND dat IS NOT NULL;
                                                      QUERY PLAN
---------------------------------------------------------------------------------------------------------------------
  Index Scan using plan_dat on plan  (cost=0.00..265.47 rows=55 
width=117) (actual time=0.130..4.409 rows=75 loops=1)
    Index Cond: (dat IS NOT NULL)
    Filter: (typ = 3)
    Rows Removed by Filter: 5960
  Total runtime: 4.440 ms
(5 rows)

[Session 2]

BEGIN;
INSERT INTO plan
SELECT id + 2000001,typ,current_date + id * '1 seconds'::interval ,val
FROM plan
;

[Session 1]
EXPLAIN ANALYZE
SELECT * FROM plan
WHERE typ = 3 AND dat IS NOT NULL;

                                                       QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------
  Index Scan using plan_dat on plan  (cost=0.00..551.35 rows=91 
width=117) (actual time=0.131..202.699 rows=75 loops=1)
    Index Cond: (dat IS NOT NULL)
    Filter: (typ = 3)
    Rows Removed by Filter: 5960
  Total runtime: 202.729 ms
(5 rows)
[Session 2]
COMMIT;

[Session 1...wait for autoanalyze to finish then]

EXPLAIN ANALYZE
SELECT * FROM plan
WHERE typ = 3 AND dat IS NOT NULL;
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------
  Bitmap Heap Scan on plan  (cost=407.87..44991.95 rows=10116 width=117) 
(actual time=2.692..6.582 rows=75 loops=1)
    Recheck Cond: (typ = 3)
    Filter: (dat IS NOT NULL)
    Rows Removed by Filter: 19925
    ->  Bitmap Index Scan on plan_typ  (cost=0.00..405.34 rows=20346 
width=0) (actual time=2.573..2.573 rows=20000 loops=1)
          Index Cond: (typ = 3)
  Total runtime: 6.615 ms


Regards

Mark

--------------080001020208050405080401
Content-Type: application/gzip;
 name="plan.tar.gz"
Content-Transfer-Encoding: base64
Content-Disposition: attachment;
 filename="plan.tar.gz"

H4sIAITieVEAA+1cTXPbxhnedOq22iZumt7b17Q6oiwaAkACDKUoE1mGY85I
lCVRiZwm44GIlYQJCDAAKFmpnU5P7UzaH9BpZzrTQy+95A+000tmeuyxnR5a
33ppT/049NJ3F4BIUSIpeURKnuxjPwa4u1jsx/O+uwtj0fJsf5aMFiqibBj8
qJUNrfuYgWi6VjSLpqbjuappmqkTMEZcLoF2FNshAGkFUbwbsqhfOmfbHkdx
xo0W7/+osceathJ95I3kHryDzVKpb/9rRrGn/4taCftfHUlpevAF7/+ldWux
bkF98c6yBVwMNE8BXAeqtbr1trUOtdU61DaXlwsYHB+2Tg137Bjq1RVro764
8oAH7Nse1K2t+lEqOj1PL7uqEqdA2P9HbRYejsz8h9u/Wj6yf61kcPtXDVPa
/zhgbT1YXqzWYLG2uPzwPYtuWMvWUh1uAb23vrqSeIR371vrljD+BShiyrvC
4KsbR9YtbfuFhbB/13fYYxaNygMMtX9TE/ZvmGYJE3L7L+J0Udr/GJCO/5u1
6tqmhYP7XWtLGP0jnAKs1sRp3nVw9E4TdqXgDiFLguenpuGOIkuD53IWcNUg
7F/Bfru7YinRQWsU9xhs/8Vj6z88ov3rZb0o7X8c2Fbfqa5AWSnyH68S8tmz
w7VH6vvkl2iow5okwz5z7H3WGHqvT7IMZx22z7ygNetszwoBJvq7gOpISEj0
xSukqGvCrd7M3YBvvbZ52QWSkJCQkJCQkJCQkBgj4tZL5Ad4/FL6ezk9vtRz
lJCQkJCQkJCQkJCQkJCQeHFhO4S89WVCfnKNiP//z9b/f/0GIb9D/hZ5gHyI
3EJeR/7+OiG/QP4c+RhpIV9DPnuFkM+QP0K+g1xBFpDfRP7nZUL+jfwX8u/I
PyE/R/4KuYb8y9cJ2UFaSBX5KvK/lJB/Iv+BfIb8G/LPyD8gf4g8QLaRMXIP
uYW0kDnkDeQfJzAM+exrWGbkb5CfIlvIXeQO8j3kOnIN+R3kt5HXkf/7KpYR
+WPky8iffYWQT5A28i3k59hev0b+9FrSdp9eu8xelJCQeOEB9SC2PQjbfuw2
2RyYiqkZ0IwIZKjyN3VhKfCdOcinb2RP8+jbbwLcceOm3UrTbDRsHwK/86om
5BtBFC+oiqoqSkk1lGIJwuAgWtDVYsmEA9eJ9xbUacjbjbiNpeBFWNAVo1xU
FHHIUiPAC4JWtKCJW69jMKyzZrDPHNg+hHuuF7NwDrRKRTd4giwg3/PaeHI1
a+yxxocn65TW5j7Df7ork1WkpJaV18tYlVKloikVIymepmpaVhlNK5+ojlnR
FcVUjNf1JH3Z6NTl9uWh08PnxNqmtf4QHiwv1o4Fk+Hv7JOjV/2P3vTv3Q1A
yPc2WBS52PKaoigHthvDThCC3Y4D27e9w48ZxAHsuL4b7UG8x/wPCFlaXVmp
1uc7l+oYmE+6Z/qExHVVV8p6JRV5PykZFVM9pqRu6R+ziZMS6zKHduT6u50X
k3sElViGYWhKMRVTReurJFXRitgmvPhmpXJltPScOuqjIi6kC1JSR0iohnnS
SZhe6zowA3qyHaCANys02mHI/Jh3FMMojL8FUxpErIEdHU3Nzbk+SoFvNCvg
P6Ra27DW63x32mqS7x3r7WptnpxRhiV0I+rVEaFuGkqpnKjKMAaKkDtzdOdX
RYLPJ8D++rsoT3ZMf6KQuWxkzMF2HDIm+nO6KwpvcxTF9y50RblOLt0yUchS
uM40qSb7aOaI2ACJeAIxexz3q/UT8IMY/LbnEVGn5ALs2Ci2my3s9XgvaMci
BD4OfIaxRDSESMj1v8vCoTmj5ZzrgqwnZwb2c3csQd177aaPuXShfthiPfdY
CRx3x2VhBKTn/nV722PYuO1tz20ovI1zhPjBARYLBe3zYgctbAhsVmEtboR2
xByFYFPFEdhwy2cHt06k2QnavoNd1E7GLRyhIHEbzBdGyEI3cERwPvCwA9/F
IUz8TN0JZtEImi2PoQ+yfQeSsQ3dAv/BR8F9uwF7dgQha9heo+2hsxL5JRsr
YJuhw8J7tCPvkFclLZ9CNlyeK6ojiqFhRwyCHeBFRmcQBvwV+SgrQtP+kBfV
xgi2n+aUZkPIwhCgIjsZNvZsbMhIlJ2XjjcBGcfr90P2fxmaWcr2f6imyfd/
66qpyf0f48AwgdBhEqP0QrRMB9oLpRdmmfRCPQY9g4+idLizo+d3ofT8jpqe
dzCg5x1u6FkHMnreIZJmg6tozUHDcFeC3iG8K6p34KeUds0RaN990efaFt2v
WgMxYDJE+3bzKEEvY/rK227gpJonODEV54GD5u+038SfZkuDLhnoH1CaLCNo
7/KCXsyypWuT/fwo9Pd8AhygwMsR4HNI8GKW8WMSYechSB8Zps9UuiVyxucx
9DI9WX8pXZaOEi2N/dGiUMTpDzqPKeg0eQ18vMoTXNKj344kTn0ofULk2cNs
Kj8BcIUg1n9eYDuj+/zPGb7/o3a+/1HU+frP1OX6byxYWn3wMPF9YjiYmkUX
ZKuzTrvZElvzFfw9Bfm71nIVRyBrHaYKUwXhnGBqSn7O44WHsH/bGaX5n+H7
f9nzH0M1kuc/Jfn9v/FgXOubeSp9xVWEsP9d5nO3r7RG9/3PAd9/xRWYkY3/
ZV03ku9/lqT9jwM3b8y2o3B22/VnWyz06E38Q9sRgygO3UY8L84P7JA//Yxw
Ado8hEnHDXGK3z1VmJoXEW6agK8WMEXiN9Qkzm83HzluFLt+I8Y4LQvnaR/h
rbsjkwxmj1+UJEcflJwEnnN0jgVJA4MGLoV3djAPvtgpZqGtMNjGsrVC9E6Q
Q7mzkPsvLv73/RzGBC3m5+/dL0DuTVG/o7lPbhqePAHHZZDP4bKKP43kaSGL
n4PJGzmcB9HJZOGDteIr8vykK35gm8AbSX34+czMNHyf0gl3R6T47qnVx+t4
qokJnuXMzDydeEopTKQ15s0jKj6R1gsDQtt38tp0skoXeadRb3SahGeZLdh4
g/Ee1NHSbqul23oJVHVO/FWnklyeAvOw509ek8Unz5aSFr13H3KTboGXq8DT
FR6PAaLjntKGF2A5se/kZFRCQkJCQkJCQkJCQkJCQkJCQkJCQkJCQkJCQuKL
jf8D2gDf2wB4AAA=

--------------080001020208050405080401
Content-Type: text/x-patch;
 name="analyze.c.diff"
Content-Transfer-Encoding: 7bit
Content-Disposition: attachment;
 filename="analyze.c.diff"

*** analyze.c.orig	2013-04-26 10:40:06.634942283 +1200
--- analyze.c	2013-04-26 11:36:13.537404101 +1200
***************
*** 1173,1183 ****
  					 * has to adjust the numbers we send to the stats
  					 * collector to make this come out right.)
  					 */
! 					if (TransactionIdIsCurrentTransactionId(HeapTupleHeaderGetXmin(targtuple.t_data)))
! 					{
! 						sample_it = true;
! 						liverows += 1;
! 					}
  					break;
  
  				case HEAPTUPLE_DELETE_IN_PROGRESS:
--- 1173,1181 ----
  					 * has to adjust the numbers we send to the stats
  					 * collector to make this come out right.)
  					 */
! 					/* Amend so insert in progress tuples are counted */
! 					sample_it = true;
! 					liverows += 1;
  					break;
  
  				case HEAPTUPLE_DELETE_IN_PROGRESS:

--------------080001020208050405080401
Content-Type: text/plain
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
MIME-Version: 1.0


-- 
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance

--------------080001020208050405080401--