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

时间：2015-03-18 02:22:39 阅读：311 评论：0 收藏：0 [点我收藏+]

偶然从网友的这篇博客中发现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的执行顺序有时候也可以作为一种性能调优的手段。

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

原文：http://blog.chinaunix.net/uid-20726500-id-4897249.html

踩

(0)

评论一句话评论（0）

分享档案

更多>

2021年09月23日 (328)
2021年09月24日 (313)
2021年09月17日 (191)
2021年09月15日 (369)
2021年09月16日 (411)
2021年09月13日 (439)
2021年09月11日 (398)
2021年09月12日 (393)
2021年09月10日 (160)
2021年09月08日 (222)