从pgbench性能测试结果中发现SQL延迟的规律

偶然从网友的这篇博客中发现pgbench的TPC-B测试结果中有一个比较奇怪的地方
http://blog.chinaunix.net/uid-20802110-id-4889543.html
-------------------------------------------
-bash-4.1$ /usr/pgsql-9.4/bin/pgbench -c 800 -t 5 -j 4  -r pgbench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
query mode: simple
number of clients: 800
number of threads: 4
number of transactions per client: 5
number of transactions actually processed: 4000/4000
latency average: 0.000 ms
tps = 217.188339 (including connections establishing)
tps = 243.570070 (excluding connections establishing)
statement latencies in milliseconds:
0.007152 \set nbranches 1 * :scale
0.001217 \set ntellers 10 * :scale
0.000891 \set naccounts 100000 * :scale
0.001649 \setrandom aid 1 :naccounts
0.000924 \setrandom bid 1 :nbranches
0.000974 \setrandom tid 1 :ntellers
0.002318 \setrandom delta -5000 5000
43.159543 BEGIN;
67.412356 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
19.172284 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
2483.177474 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;                          -----延迟非常明显，可以从此入手
37.104961 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
0.466527 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
3.609726 END;
-------------------------------------------

为什么说它奇怪？因为这个大的延迟无疑应该是高并发争用导致的。但是pgbench_tellers中有10条记录，pgbench_branches中只有一条记录，按道理对pgbench_branches的争用比pgbench_tellers还厉害，为什么pgbench_branches反而很快呢？


于是，我在自己的环境中，逐步增加并发数再现了一下这个问题。

并发数为1

[chenhj@node2 ~]$ pgbench -c 1 -j 1 -t 10 -r pgbench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
query mode: simple
number of clients: 1
number of threads: 1
number of transactions per client: 10
number of transactions actually processed: 10/10
tps = 701.016474 (including connections establishing)
tps = 792.832792 (excluding connections establishing)
statement latencies in milliseconds:
    0.002800    \set nbranches 1 * :scale
    0.000500    \set ntellers 10 * :scale
    0.000400    \set naccounts 100000 * :scale
    0.000600    \setrandom aid 1 :naccounts
    0.000600    \setrandom bid 1 :nbranches
    0.000500    \setrandom tid 1 :ntellers
    0.000400    \setrandom delta -5000 5000
    0.052700    BEGIN;
    0.272300    UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
    0.139800    SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
    0.157700    UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
    0.133500    UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
    0.118500    INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
    0.369200    END;

除了pgbench_accounts外稍微慢点以外，其它几个表的更新时间差不多。

并发数为4

[chenhj@node2 ~]$ pgbench -c 4 -j 4 -t 10 -r pgbench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
query mode: simple
number of clients: 4
number of threads: 4
number of transactions per client: 10
number of transactions actually processed: 40/40
tps = 1271.779219 (including connections establishing)
tps = 1460.440323 (excluding connections establishing)
statement latencies in milliseconds:
0.002700    \set nbranches 1 * :scale
0.000500    \set ntellers 10 * :scale
0.000425    \set naccounts 100000 * :scale
0.000675    \setrandom aid 1 :naccounts
0.000425    \setrandom bid 1 :nbranches
0.000325    \setrandom tid 1 :ntellers
0.000600    \setrandom delta -5000 5000
0.081725    BEGIN;
0.248250    UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
0.136400    SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
0.436850    UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
0.961600    UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
0.111075    INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
0.462825    END;

现在最慢的是pgbench_branches，因为4个并发连接都要争抢它。但是总体的tps比1并发时提高了不少。

并发数为10

[chenhj@node2 ~]$ pgbench -c 10 -j 10 -t 10 -r pgbench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
query mode: simple
number of clients: 10
number of threads: 10
number of transactions per client: 10
number of transactions actually processed: 100/100
tps = 1318.322040 (including connections establishing)
tps = 1517.142190 (excluding connections establishing)
statement latencies in milliseconds:
    0.002500    \set nbranches 1 * :scale
    0.000550    \set ntellers 10 * :scale
    0.000480    \set naccounts 100000 * :scale
    0.000570    \setrandom aid 1 :naccounts
    0.000440    \setrandom bid 1 :nbranches
    0.000350    \setrandom tid 1 :ntellers
    0.000600    \setrandom delta -5000 5000
    0.069060    BEGIN;
    0.270230    UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
    0.276860    SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
    1.880150    UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
    2.661570    UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
    0.175470    INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
    0.419380    END;

现在最慢的还是pgbench_branches，但pgbench_tellers也明显慢了起来。总体的tps和并发数为4时相比有所增加，但不明显。（测试用的环境是VM，分配给VM的CPU是2核)。

并发数为20
点击(此处)折叠或打开

[chenhj@node2 ~]$ pgbench -c 20 -j 10 -t 10 -r pgbench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
query mode: simple
number of clients: 20
number of threads: 10
number of transactions per client: 10
number of transactions actually processed: 200/200
tps = 1294.808465 (including connections establishing)
tps = 1499.957626 (excluding connections establishing)
statement latencies in milliseconds:
    0.002695    \set nbranches 1 * :scale
    0.000545    \set ntellers 10 * :scale
    0.000550    \set naccounts 100000 * :scale
    0.000640    \setrandom aid 1 :naccounts
    0.000450    \setrandom bid 1 :nbranches
    0.000605    \setrandom tid 1 :ntellers
    0.000505    \setrandom delta -5000 5000
    0.200460    BEGIN;
    0.386675    UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
    0.238615    SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
    5.735790    UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
    3.869125    UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
    0.116305    INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
    0.516330    END;

现在最慢的变成pgbench_tellers了，总体的tps也开始下降。

并发数为100

[chenhj@node2 ~]$ pgbench -c 100 -j 10 -t 10 -r pgbench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
query mode: simple
number of clients: 100
number of threads: 10
number of transactions per client: 10
number of transactions actually processed: 1000/1000
tps = 994.032821 (including connections establishing)
tps = 1175.266424 (excluding connections establishing)
statement latencies in milliseconds:
    0.002603    \set nbranches 1 * :scale
    0.000715    \set ntellers 10 * :scale
    0.000610    \set naccounts 100000 * :scale
    0.000682    \setrandom aid 1 :naccounts
    0.000485    \setrandom bid 1 :nbranches
    0.000488    \setrandom tid 1 :ntellers
    0.000547    \setrandom delta -5000 5000
    0.364759    BEGIN;
    0.730818    UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
    0.322968    SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
    63.065841    UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
    7.542918    UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
    0.152586    INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
    0.740661    END;

pgbench_tellers越发慢的明显了。

并发数为500

[chenhj@node2 ~]$ pgbench -c 500 -j 10 -t 10 -r pgbench
starting vacuum...end.
transaction type: TPC-B (sort of)
scaling factor: 1
query mode: simple
number of clients: 500
number of threads: 10
number of transactions per client: 10
number of transactions actually processed: 5000/5000
tps = 396.234567 (including connections establishing)
tps = 414.176788 (excluding connections establishing)
statement latencies in milliseconds:
    0.003855    \set nbranches 1 * :scale
    0.001171    \set ntellers 10 * :scale
    0.000693    \set naccounts 100000 * :scale
    0.000980    \setrandom aid 1 :naccounts
    0.000886    \setrandom bid 1 :nbranches
    0.000596    \setrandom tid 1 :ntellers
    0.000603    \setrandom delta -5000 5000
    0.746502    BEGIN;
    7.766349    UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
    1.093415    SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
    1002.415717    UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
    22.612090    UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
    0.213186    INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
    1.627372    END;

不仅对pgbench_tellers的更新慢的离谱，总的tps也下降的非常厉害，还不到峰值时的3分之1。（这也说明了，控制好到达DB的连接数多么重要。）

那么，为什么更新pgbench_tellers比更新pgbench_branches还慢呢？稍微想了想，终于明白了。
更新pgbench_tellers的SQL语句在更新pgbench_branches的SQL语句前面执行，所以pgbench_tellers已经帮pgbench_branches挡住了绝大部分的并发。导致实际到达pgbench_branches的并发数不是500而只有10，所以pgbench_branches的更新很快。下面验证一下这个假设。

把pgbench的TCP-B测试SQL写到一个脚本里再测

[chenhj@node2 ~]$ cat test.sql
\set nbranches 1 * :scale
\set ntellers 10 * :scale
\set naccounts 100000 * :scale
\setrandom aid 1 :naccounts
\setrandom bid 1 :nbranches
\setrandom tid 1 :ntellers
\setrandom delta -5000 5000
BEGIN;
UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
END;
[chenhj@node2 ~]$ pgbench -c 500 -j 10 -t 10 -r -f test.sql pgbench
starting vacuum...end.
transaction type: Custom query
scaling factor: 1
query mode: simple
number of clients: 500
number of threads: 10
number of transactions per client: 10
number of transactions actually processed: 5000/5000
tps = 386.651133 (including connections establishing)
tps = 403.524141 (excluding connections establishing)
statement latencies in milliseconds:
    0.002743 \set nbranches 1 * :scale
    0.000700 \set ntellers 10 * :scale
    0.001121 \set naccounts 100000 * :scale
    0.000941 \setrandom aid 1 :naccounts
    0.000488 \setrandom bid 1 :nbranches
    0.000479 \setrandom tid 1 :ntellers
    0.000695 \setrandom delta -5000 5000
    0.669572 BEGIN;
    7.178750 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
    1.119658 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
    1010.879585 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
    23.284097 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
    0.176437 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
    1.609216 END;

测试结果和之前没有用脚本时一致。

把脚本中的更新pgbench_branches的SQL语句移到更新pgbench_tellers的SQL语句的前面再测

[chenhj@node2 ~]$ cat test2.sql
\set nbranches 1 * :scale
\set ntellers 10 * :scale
\set naccounts 100000 * :scale
\setrandom aid 1 :naccounts
\setrandom bid 1 :nbranches
\setrandom tid 1 :ntellers
\setrandom delta -5000 5000
BEGIN;
UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
END;
[chenhj@node2 ~]$ pgbench -c 500 -j 10 -t 10 -r -f test2.sql pgbench
starting vacuum...end.
transaction type: Custom query
scaling factor: 1
query mode: simple
number of clients: 500
number of threads: 10
number of transactions per client: 10
number of transactions actually processed: 5000/5000
tps = 228.028143 (including connections establishing)
tps = 233.288608 (excluding connections establishing)
statement latencies in milliseconds:
    0.004425    \set nbranches 1 * :scale
    0.000828    \set ntellers 10 * :scale
    0.001644    \set naccounts 100000 * :scale
    0.000938    \setrandom aid 1 :naccounts
    0.000534    \setrandom bid 1 :nbranches
    0.000507    \setrandom tid 1 :ntellers
    0.000540    \setrandom delta -5000 5000
    1.262434    BEGIN;
    9.896378    UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
    1.454215    SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
    1880.677017    UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
    0.879294    UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
    0.291396    INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CURRENT_TIMESTAMP);
    4.006580    END;

现在最慢的SQL变成pgbench_branches的更新了，验证了我的猜测，也算是真相大白了。但是，从测试结果中还可以发现，先更新pgbench_branches比后更新pgbench_branches相比，总体的tps又有一个大幅度的下降，从403降到233。如果反过来考虑这件事，就是，调整SQL的执行顺序有时候也可以作为一种性能调优的手段。