Re: BUG #13493: pl/pgsql doesn't scale with cpus (PG9.3, 9.4)

On 2015-07-08 11:12:38 +0200, Andres Freund wrote:
> On 2015-07-07 21:13:04 -0400, Tom Lane wrote:
> > There is some discussion going on about improving the scalability of
> > snapshot acquisition, but nothing will happen in that line before 9.6
> > at the earliest.
>
> 9.5 should be less bad at it than 9.5, at least if it's mostly read-only
> ProcArrayLock acquisitions which sounds like it should be the case here.

test 3:
master:
1 clients: 3112.7
2 clients: 6806.7
4 clients: 13441.2
8 clients: 15765.4
16 clients: 21102.2

9.4:
1 clients: 2524.2
2 clients: 5903.2
4 clients: 11756.8
8 clients: 14583.3
16 clients: 19309.2

So there's an interesting "dip" between 4 and 8 clients. A perf profile
doesn't show any actual lock contention on master. Not that surprising,
there shouldn't be any exclusive locks here.

One interesting thing in exactly such cases is to consider intel's
turboboost. Disabling it (echo 0 >
/sys/devices/system/cpu/cpufreq/boost) gives us these results:
test 3:
master:
1 clients: 2926.6
2 clients: 6634.3
4 clients: 13905.2
8 clients: 15718.9

so that's not it in this case.

comparing stats between the 4 and 8 client runs shows (removing boring data):

4 clients:
90859.517328 task-clock (msec) # 3.428 CPUs utilized
109,655,985,749 stalled-cycles-frontend # 54.27% frontend cycles idle (27.79%)
62,906,918,008 stalled-cycles-backend # 31.14% backend cycles idle (27.78%)
219,063,494,214 instructions # 1.08 insns per cycle
# 0.50 stalled cycles per insn (33.32%)
41,664,400,828 branches # 458.558 M/sec (33.32%)
374,426,805 branch-misses # 0.90% of all branches (33.32%)
62,504,845,665 L1-dcache-loads # 687.928 M/sec (27.78%)
1,224,842,848 L1-dcache-load-misses # 1.96% of all L1-dcache hits (27.81%)
321,981,924 LLC-loads # 3.544 M/sec (22.33%)
23,219,438 LLC-load-misses # 7.21% of all LL-cache hits (5.52%)

26.507528305 seconds time elapsed

8 clients:
165168.247631 task-clock (msec) # 6.824 CPUs utilized
247,231,674,170 stalled-cycles-frontend # 67.04% frontend cycles idle (27.84%)
101,354,900,788 stalled-cycles-backend # 27.48% backend cycles idle (27.83%)
285,829,642,649 instructions # 0.78 insns per cycle
# 0.86 stalled cycles per insn (33.39%)
54,503,992,461 branches # 329.991 M/sec (33.39%)
761,911,056 branch-misses # 1.40% of all branches (33.38%)
81,373,091,784 L1-dcache-loads # 492.668 M/sec (27.74%)
4,419,307,036 L1-dcache-load-misses # 5.43% of all L1-dcache hits (27.72%)
510,940,577 LLC-loads # 3.093 M/sec (21.86%)
26,963,120 LLC-load-misses # 5.28% of all LL-cache hits (5.37%)

24.205675255 seconds time elapsed

It's quite visible that all caches have considerably worse
characteristics on the 8 clients case, and that "instructions per cycle"
has gone down considerably. Presumably because more frontend cycles were
idle, which in turn is probably caused by the higher cache miss
ratios. L1 going from 1.96% misses to 5.43% misses is quite a drastic
difference.

Now, looking at where cache misses happen:
4 clients:
+ 7.64% postgres postgres [.] AllocSetAlloc
+ 3.90% postgres postgres [.] LWLockAcquire
+ 3.40% postgres plpgsql.so [.] plpgsql_exec_function
+ 2.64% postgres postgres [.] GetCachedPlan
+ 2.20% postgres postgres [.] slot_deform_tuple
+ 2.16% postgres libc-2.19.so [.] _int_free
+ 2.08% postgres libc-2.19.so [.] __memcpy_sse2_unaligned

8 clients:
+ 6.34% postgres postgres [.] AllocSetAlloc
+ 4.89% postgres plpgsql.so [.] plpgsql_exec_function
+ 2.63% postgres libc-2.19.so [.] _int_free
+ 2.60% postgres libc-2.19.so [.] __memcpy_sse2_unaligned
+ 2.50% postgres postgres [.] ExecLimit
+ 2.47% postgres postgres [.] LWLockAcquire
+ 2.18% postgres postgres [.] ExecProject

So the characteristics interestingly change quite a bit between 4/8. I
reproduced this a number of times to make sure it's not just a temporary
issue.

The memcpy rising is mainly:
+ 80.27% SearchCatCache
+ 10.56% appendBinaryStringInfo
+ 6.51% socket_putmessage
+ 0.78% pgstat_report_activity

So at least on the hardware available to me right now this isn't caused
by actual lock contention.

Hm. I've a patch addressing the SearchCatCache memcpy() cost
somewhere...

Andres