On Tue, 22 Jan 2019 at 20:01, Imai, Yoshikazu
<imai.yoshik...@jp.fujitsu.com> wrote:
> I didn't use it yet, but I just used perf to clarify the difference of before
> and after the creation of the generic plan, and I noticed that usage of
> hash_seq_search() is increased about 3% in EXECUTE queries after the creation
> of the generic plan.
>
> What I understand so far is about 10,000 while loops at total (4098+4098+some
> extra) is needed in hash_seq_search() in EXECUTE query after the creation of
> the generic plan.
> 10,000 while loops takes about 10 microsec (of course, we can't estimate
> correct time), and the difference of the latency between 5th and 7th EXECUTE
> is about 8 microsec, I currently think this causes the difference.
>
> I don't know this problem relates to Amit-san's patch, but I'll continue to
> investigate it.
I had another thought... when you're making a custom plan you're only
grabbing locks on partitions that were not pruned (just 1 partition in
your case), but when making the generic plan, locks will be acquired
on all partitions (all 4000 of them). This likely means that when
building the generic plan for the first time that the
LockMethodLocalHash table is expanded to fit all those locks, and
since we never shrink those down again, it'll remain that size for the
rest of your run. I imagine the reason for the slowdown is that
during LockReleaseAll(), a sequential scan is performed over the
entire hash table. I see from looking at the hash_seq_search() code
that the value of max_bucket is pretty critical to how it'll perform.
The while ((curElem = segp[segment_ndx]) == NULL) loop will need to
run fewer times with a lower max_bucket.
I just did a quick and crude test by throwing the following line into
the end of hash_seq_init():
elog(NOTICE, "%s %u", hashp->tabname, hashp->hctl->max_bucket);
With a 5000 partition table I see:
postgres=# set plan_cache_mode = 'auto';
postgres=# prepare q1 (int) as select * from listp where a = $1;
postgres=# explain analyze execute q1(1);
NOTICE: Portal hash 15
NOTICE: LOCALLOCK hash 15
NOTICE: LOCALLOCK hash 15
...
<skip forward to the 6th execution>
postgres=# explain analyze execute q1(1);
NOTICE: LOCALLOCK hash 5002
NOTICE: Portal hash 15
NOTICE: LOCALLOCK hash 5002
NOTICE: LOCALLOCK hash 5002
QUERY PLAN
--------------------------------------------------------------------------------------------------------
Append (cost=0.00..41.94 rows=13 width=4) (actual time=0.005..0.005
rows=0 loops=1)
-> Seq Scan on listp1 (cost=0.00..41.88 rows=13 width=4) (actual
time=0.005..0.005 rows=0 loops=1)
Filter: (a = 1)
Planning Time: 440.822 ms
Execution Time: 0.017 ms
(5 rows)
I've not gone as far to try to recreate the performance drop you've
mentioned but I believe there's a very high chance that this is the
cause, and if so it's not for Amit to do anything with on this patch.
--
David Rowley http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
