起步

由于我在新项目里引入了 python 的 async 语法，在连接 pg 数据库时用到了 asyncpg 这个异步包。多日来，从线上得到了一些反馈。简单说来就是：数据库存在暂时无法修复的 bug，使得一些 sql 成为 “禁用 sql”，从应用层看没有执行过 “禁用 sql” ，但在监控器上发现执行了 “禁用 sql”。

我简单跟踪了 asyncpg 源码，没有发现 asyncpg 包内部执行了 “禁用 sql ”，但同事仍对这个第三方包质疑。因为不懂得，所以不仁慈，可我必须做点什么为 asyncpg 洗冤……

如何洗冤？

起初我也盼望着 asyncpg 提供一个类似 sqlalchemy 的 echo 参数，将所有执行的 sql 都以日志方式打印出来。不过翻遍文档，没有找到。

之后我想到，本地起一个 pg 数据库，将慢查询时间设置为 0，也就是记录所有执行的 sql。这样一来，不管 asyncpg 内部搞了多少小动作，都会暴露在阳光下。

操作

为简单起见，我是在 centos7 上运行一个 pg 9.4 的容器：

$ docker run -v /var/lib/postgresql/data:/var/lib/postgresql/data --name postgres-rp -e POSTGRES_PASSWORD=password -p 54321:5432 -d postgres:9.4

• -v /var/lib/postgresql/data:/var/lib/postgresql/data 这个挂载很重要，可以让你很方便地修改 pg 配置。
• 默认 root 用户名为 postgres；这里我的密码就直接是 password。
• 由于宿主机的 5432 端口已被占用，于是我映射到了 54321。

打开 pg 的配置文件：

$ vim /var/lib/postgresql/data/postgresql.conf

追加 or 修改内容为如下：

log_min_duration_statement = 0
log_statement = 'all'

重启容器使其生效。

连接数据库，随便执行几个 sql。再 docker logs [container_id] ，可以看到执行的 sql 日志了。

LOG:  duration: 0.076 ms  statement: select 1
LOG:  duration: 0.102 ms  statement: select 2
LOG:  duration: 0.081 ms  statement: select 3
LOG:  duration: 0.344 ms  statement: select * from test

通过 docker logs 查看日志有点麻烦，我们可以对日志重定向：

$ docker logs -f [container_id] &> pg.log &

之后就可以愉快地 tail -f pg.log 查看日志了。

最后

借助 pg 的慢查询，对 asyncpg 执行的 sql 进行分析，确实没有 “禁用 sql”，说明 asyncpg 光明磊落。可是线上那些 “禁用 sql” 从何而来？此刻不得而知，我也和我的同事积极排查中。