PG源码分析系列:Pglog性能测试分析-阿里云开发者社区

开发者社区> jackgo> 正文

PG源码分析系列:Pglog性能测试分析

简介: title: PG源码分析系列一:Pglog性能测试分析 date: 2019-07-17 11:19:03 categories: - Postgresql - PgSource 这篇主要从现象出发,给出分析流程、结论。 1 相关参数 这两个参数打开后会增加大量的日志写入,一般生产环境上纠结的就是这两个参数了,其他日志参数使用的较少。 log_statement:有效值
+关注继续查看
title: PG源码分析系列一:Pglog性能测试分析
date: 2019-07-17 11:19:03
categories: 
- Postgresql
- PgSource

这篇主要从现象出发,给出分析流程、结论。

1 相关参数

这两个参数打开后会增加大量的日志写入,一般生产环境上纠结的就是这两个参数了,其他日志参数使用的较少。

  • log_statement:有效值是 none (off)、ddlmodall(所有语句),打开all后会记录大量日志

    14115 [local] postgres bench 2019-07-16 07:13:41 UTC 00000LOG:  execute P0_1: SELECT abalance FROM pgbench_accounts WHERE aid = $1;
    14115 [local] postgres bench 2019-07-16 07:13:41 UTC 00000DETAIL: parameters: $1 = '13660205'
  • log_duration:记录语句的持续时间

    14499 [local] postgres bench 2019-07-16 07:25:19 UTC 00000LOG:  execute P0_1: SELECT abalance FROM pgbench_accounts WHERE aid = $1;
    14499 [local] postgres bench 2019-07-16 07:25:19 UTC 00000DETAIL: parameters: $1 = '17685816'
    14499 [local] postgres bench 2019-07-16 07:25:19 UTC 00000LOG: duration: 0.055 ms

 

2 测试记录

  • 环境:64C(小规格上测不出来的,需要大并发引起log大量锁冲突)

  • 初始化:pgbench -i -s 200 bench

结果对比:

log_statement log_duration tps 下降%
none   166786.137539 0%
all off 141541.265184 15%
all on 96551.544436 42%

2.1 关闭审计日志

关闭审计日志,使用prepared协议,只做select尽量增加SQL执行数量,避免IO影响测试(IO一般都会是瓶颈)

alter system set logging_collector=on;
alter system set log_rotation_size='128MB';
alter system set log_statement='none';
select pg_reload_conf();

测试:tps = 166786.137539

pgbench -M prepared -c 64 -j 64 -P 1 -T 120 -r -v -S bench

transaction type: <builtin: select only>
scaling factor: 200
query mode: prepared
number of clients: 64
number of threads: 64
duration: 120 s
number of transactions actually processed: 20016075
latency average = 0.384 ms
latency stddev = 0.097 ms
tps = 166786.137539 (including connections establishing)
tps = 166823.430955 (excluding connections establishing)
script statistics:
- statement latencies in milliseconds:
        0.002 \set aid random(1, 100000 * :scale)
        0.386 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;

 

2.2 打开审计日志&关闭记录时间

alter system set logging_collector=on;
alter system set log_rotation_size='128MB';
alter system set log_statement='all';
alter system set log_duration='off';
select pg_reload_conf();

测试:tps = 141541.265184

pgbench -M prepared -c 64 -j 64 -P 1 -T 120 -r -v -S bench

transaction type: <builtin: select only>
scaling factor: 200
query mode: prepared
number of clients: 64
number of threads: 64
duration: 120 s
number of transactions actually processed: 16989391
latency average = 0.452 ms
latency stddev = 0.300 ms
tps = 141541.265184 (including connections establishing)
tps = 141568.228057 (excluding connections establishing)
script statistics:
- statement latencies in milliseconds:
        0.002 \set aid random(1, 100000 * :scale)
        0.466 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;

2.3 打开审计日志&打开记录时间

alter system set logging_collector=on;
alter system set log_rotation_size='128MB';
alter system set log_statement='all';
alter system set log_duration='on';
select pg_reload_conf();

测试:tps = 96551.544436

pgbench -M prepared -c 64 -j 64 -P 1 -T 120 -r -v -S bench

transaction type: <builtin: select only>
scaling factor: 200
query mode: prepared
number of clients: 64
number of threads: 64
duration: 120 s
number of transactions actually processed: 11589065
latency average = 0.662 ms
latency stddev = 3.185 ms
tps = 96551.544436 (including connections establishing)
tps = 96570.262659 (excluding connections establishing)
script statistics:
- statement latencies in milliseconds:
        0.002 \set aid random(1, 100000 * :scale)
        0.708 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;

3 PERF分析

3.1 两个日志参数打开

打开参数执行压测的同时开始perf收集5s数据

perf record -agv -- sleep 5

使用perf展示结果

perf report -v -n --showcpuutilization -g --stdio

使用gprof2dot处理数据图形化展示结果

perf script | c++filt | gprof2dot -f perf | dot -Tpng -o output.png

上半部分可以明显看到errfinish的占用率是比较高的,这个函数会刷审计日志,如果参数不打开的话这个函数占用时间非常少。继续看下这个函数为什么占用时间高:

直接看最后的部分

这里可以看到pipe_write函数在等mutex_lock,等锁占用了大量的时间(14%)。

完整的调用栈:

3.2 关闭日志时间参数

只打开log_statement='all'参数,为了是问题更明显,测试使用select 1增加日志的写入量!

pgbench -M prepared -c 64 -j 64 -P 1 -T 1200 -r -f ./s1.sql

对比一下select 1pgbench -S的效果

可以看到mutex锁竞争是明显的瓶颈。

select 1的完整调用栈

那么pipe的mutex锁是哪来的?pipe锁的机制是什么样的?下一篇继续分析。

 

版权声明:本文内容由阿里云实名注册用户自发贡献,版权归原作者所有,阿里云开发者社区不拥有其著作权,亦不承担相应法律责任。具体规则请查看《阿里云开发者社区用户服务协议》和《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容,填写侵权投诉表单进行举报,一经查实,本社区将立刻删除涉嫌侵权内容。

相关文章
理解和使用Oracle分析工具LogMiner
用LogMiner             理解和使用Oracle   8i分析工具LogMiner                 Oracle   LogMiner   是Oracle公司从产品8i以后提供的一个实际非常有用的分析工具,使用该工具可以轻松获得Oracle   重作日志文件(归档日志文件)中的具体内容,特别是,该工具可以分析出所有对于数据库操作的DML(insert、update、delete等)语句,另外还可分析得到一些必要的回滚SQL语句。
1174 0
一起谈.NET技术,在.NET Workflow 3.5中使用多线程提高工作流性能
  最近在工作上碰到一个性能问题,由于项目是基于SOA的架构,使得整个系统完全依赖于各种各样的Service,其中用于处理业务逻辑的Business Services全部都用.NET Workflow 3.5实现(历史原因,项目还没升级到Workflow 4)。
830 0
glogin.sql配置不当引起sqlplus hang的假象分析
不久前遇到的一个问题,"故障"现象如下:A主机上跑了两个单实例的数据库testa和testb,对testa实例进行例行重启时先shutdown immediate,然后再通过sqlplus '/as sysdba'连进去尝试重启时发现,sqlplus Ha...
887 0
使用application log 分析navigation target解析错误
Created by Jerry Wang, last modified on Sep 20, 2015
31 0
+关注
12
文章
0
问答
文章排行榜
最热
最新
相关电子书
更多
《2021云上架构与运维峰会演讲合集》
立即下载
《零基础CSS入门教程》
立即下载
《零基础HTML入门教程》
立即下载