插件介绍

在进行postgres的服务端编程的时候，常常会发现pg的函数和存储过程是一个黑盒，内部的任何问题都有可能造成性能瓶颈。通常会遇到以下情况：

  1. 出现问题的语句，其实执行地非常快，但是调用过次数多导致变慢
  2. 随机出现的性能瓶颈问题
  3. 生产系统上出现了性能问题（尽管我们不愿意直接上生产系统排查）

以上的出现的性能问题只能采取人肉分析（分析schema、统计信息、SQL语句）、断点（pldebugger）的形式进行排查，排查时间长且不直观、问题时隐时现（甚至对于问题1，根本无法排查出来），因此需要有一个更好的排查方式，同时具备良好的展示方式，来帮助我们找到性能瓶颈的点。

plprofiler（https://github.com/bigsql/plprofiler）提供了一个简洁的postgres函数和存储过程的性能采集方式，用于发现pg的函数和存储过程性能瓶颈，从而让dba和开发人员能够进行针对性地对函数和存储过程、schema等进行优化。

为方便表达，后面统称 函数和存储过程 为 函数。

基本原理

在执行函数/语句前后加入钩子函数，进入的时候记录时间，出来的时候记录时间，两者相减即可得到该函数/语句的执行时间。

注意一下，这里的时间是Wall-Clock time，即真实时间，区分于CPU时间。例如pg_sleep(10)，真实时间为10s，cpu时间只有0.001s。这里，该函数的真实时间为10s。

后续所有的数据分析都会基于这部分数据进行，分析运行时间的基本原理是：
self_time = total_time - children_time

基于该算式可以得到该函数的实际消耗时间。例如上述的pg_sleep(10)函数，它不包含语句粒度的子调用，因此children_time为0s，计算得到self_time是10s。

火焰图

plprofiler使用了火焰图作为其展示方式，需要搭配其python客户端使用，可以自动生成火焰图。

火焰图出自Brendan Gregg之手，感兴趣的话可以了解一下他的博客和书籍

火焰图是一个可视化地进行性能分析的利器。性能问题同样遵循着二八定律，即大部分的性能瓶颈是由少部分的问题导致的，因此，基于这个前提，找到导致大部分瓶颈的少部分问题成为了性能优化的关键。

火焰图
http://www.brendangregg.com/FlameGraphs/cpu-mysql-updated.svg

上图是Brendan Gregg博客的示例，这是一个mysql内核的CPU火焰图。

火焰图是可以用鼠标进行交互的，有需要的话可以点击上述链接，进行交互操作

可以看一下这个火焰图，X轴显示该层的总体堆栈，按字母顺序排序，Y轴显示堆栈深度，从底部的零开始计数。每个矩形代表一个栈帧。矩形越宽，它在堆栈中出现的频率就越高。顶部边缘显示了on-CPU的内容，在它下面是它的父函数。颜色通常不重要，它只是随机选择的，用来以区分矩形。

在该CPU火焰图中，矩形宽度对应着CPU的周期，矩形越宽，代表消耗的CPU周期越多（描述的并不完全准确，因为该图是基于采样的，但是采样足够多，基本上可以认为是正确的）。可以观察到该图中大部分的性能消耗主要是在两处row_search_for_mysql函数内，可以点击该函数，继续放大视图查找性能瓶颈点从而发现问题。

发现导致性能瓶颈的头部问题后，就可以针对这些头部问题进行优化操作。大部分情况下，优化完这部分问题后，性能瓶颈就能够得到消除。如果还是存在问题，就重复以上流程，因此一个性能优化的工作可以按照以下范式进行：

  1. 1. 发现性能瓶颈
  2. 2. 找到头部问题
  3. 3. 消除头部问题
  4. 4. 重新观测性能表现，如果存在问题，回到1

在plprofiler的火焰图中，区别于CPU火焰图，矩形宽度的含义略有变化，代表的是在该函数内的停留时间，即上面所述的Wall-Clock time。同样区别于CPU火焰图，产生的火焰图可以基于采样也可以基于统计，看在性能分析时候所使用的参数，具体可见官方文档。

 CPU火焰图plprofiler火焰图
矩形宽度CPU周期真实时间
统计形式采样采样或统计（取决于参数）

基本使用

这里的例子摘自官方README，先从https://github.com/bigsql/plprofiler获取源码。

准备

首先导出环境变量，为了运行demo，你只需要修改这部分内容：

  1. export PGHOST=localhost
  2. export PGPORT=5432
  3. export PGUSER=postgres
  4. export PGPASSWORD=password
  5. export PGDATABASE=pgbench_plprofiler
  6. export PLPROFILER_PATH=/path-to-plprofiler/
  7. export USE_PGXS=1
  8. export PATH=/path-to-pgsql/bin:$PATH

进入到源码目录下，安装服务端插件和客户端插件。

  1. cd $PLPROFILER_PATH
  2. make install #sudo make install
  3. cd $PLPROFILER_PATH/python-plprofiler
  4. python setup.py install #sudo python setup.py install

创建数据库，创建插件。

  1. psql postgres
  2. > CREATE DATABASE pgbench_plprofiler;
  3. > \c pgbench_plprofiler
  4. > CREATE EXTENSION plprofiler;

准备表、数据和函数。

  1. cd $PLPROFILER_PATH/examples
  2. bash prepdb.sh

进行分析

运行plprofiler命令进行性能分析：

  1. plprofiler run --command "SELECT tpcb(1, 2, 3, -42)" --output tpcb-test1.html

编辑
命令完成后，会进入编辑界面，你可以在这里编辑输出网页的标题、长宽、描述等信息。可以不用编辑，直接退出，在执行命令的路径下，可以看到输出的网页 tpcb-test1.html，使用浏览器打开这个网页。
优化前
网页的最上方是火焰图，下面是函数列表，再下面是各个函数的签名以及执行时间的详细信息，从火焰图中我们可以发现最影响性能的函数是tpcb_fetch_abalance。继而我们可以分析出，是由于没有创建索引导致性能很差。（尽管tpcb_upd_accounts性能也很差，但它有可能只是它的子函数的受害者，我们需要优化完子函数再观察情况）。

我们可以创建索引完成这次优化：

  1. psql
  2. > CREATE INDEX pgbench_accounts_aid_idx ON pgbench_accounts (aid);

再次运行plprofiler命令进行性能分析，得到以下结果：
![优化后]](/monthly/pic/202003/2020-03-zhuyuan-result-after.png)
可以看到火焰图发生了变化，tpcb_fetch_abalance不再是性能瓶颈，新的性能瓶颈出现了。由于优化了tpcb_fetch_abalance，可以在下面看到tpcb_upd_accounts的执行时间也大大缩短了，它确实只是子函数的受害者。

如果符合期望，这次的优化可能就到此为止了。如果仍然不满足，那可以用新的火焰图继续分析出性能瓶颈。

总结：

可以看到plprofiler不能告诉我们该如何去做优化，它只能告诉我们在pg里的一个复杂的函数中，到底是哪一行出现了性能问题，得到这个信息后，我们再针对性地对这一行进行优化，有可能是索引问题，有可能是SQL问题，需要具体问题具体分析。 但是很多时候我们仅仅是难以发现是哪一行，这时候需要使用plprofiler，当发现哪一行存在问题后，问题往往很快就能解决了。

实现分析

钩子函数

plprofiler主要是通过插件的形式，hook函数和存储过程的执行的关键路径进行实现的。
PG内核的说明：src/pl/plpgsql/src/plpgsql.h:1061

结构体为PLpgSQL_plugin，主要有5个钩子函数：

  1. void    (*func_setup) (PLpgSQL_execstate *estate, PLpgSQL_function *func);
  2. void    (*func_beg) (PLpgSQL_execstate *estate, PLpgSQL_function *func);
  3. void    (*func_end) (PLpgSQL_execstate *estate, PLpgSQL_function *func);
  4. void    (*stmt_beg) (PLpgSQL_execstate *estate, PLpgSQL_stmt *stmt);
  5. void    (*stmt_end) (PLpgSQL_execstate *estate, PLpgSQL_stmt *stmt);

func_setup函数在调用函数的时候进行调用，在初始化函数定义的局部参数之前。
func_beg函数在调用函数的时候进行调用，在初始化函数定义的局部参数之后。
func_end函数在调用函数结束的时候进行调用。
stmt_beg函数在调用语句之前进行调用。
stmt_end函数在调用语句之后进行调用。

在开始钩子函数中，会获取当前开始时间、以及哪一行，在结束钩子函数中，会获取当前结束时间，并将该行的信息统计记录下来。

为了完成数据的记录和分析，还有部分辅助的数据结构，包括函数的信息、调用链等。这些数据结构的内容和关系如下：
数据结构

数据收集

数据收集部分以stmt的开始和结束为例。

  1. static void
  2. profiler_stmt_beg(PLpgSQL_execstate *estate, PLpgSQL_stmt *stmt)
  3. {
  4.     profilerLineInfo   *line_info;
  5.     profilerInfo       *profiler_info;
  7.     /* 检查profiler是否启用 */
  8.     if (!profiler_active)
  9.         return;
  11.     /* plugin_info储存的是profilerInfo信息，即当前函数的执行信息，如果为空，则说明是匿名代码块 */
  12.     /* Ignore anonymous code block. */
  13.     if (estate->plugin_info == NULL)
  14.         return;
  16.     /* Set the start time of the statement */
  17.     profiler_info = (profilerInfo *)estate->plugin_info;
  18.     if (stmt->lineno < profiler_info->line_count)
  19.     {
  20.         line_info = profiler_info->line_info + stmt->lineno;
  21.         /* 在这里记录开始时间 */
  22.         INSTR_TIME_SET_CURRENT(line_info->start_time);
  23.     }
  25.     /* Check the call graph stack. */
  26.     callgraph_check(profiler_info->fn_oid);
  27. }
  1. static void
  2. profiler_stmt_end(PLpgSQL_execstate *estate, PLpgSQL_stmt *stmt)
  3. {
  4.     ...
  6.     /* 如果没有新数据，就不进行分析，防止每次都进行分析 */
  7.     /* Tell collect_data() that new information has arrived locally. */
  8.     have_new_local_data = true;
  10.     /* 计算经历的时间，记录最大时间、总时间，增加执行次数 */
  11.     INSTR_TIME_SET_CURRENT(end_time);
  12.     INSTR_TIME_SUBTRACT(end_time, line_info->start_time);
  14.     elapsed = INSTR_TIME_GET_MICROSEC(end_time);
  16.     if (elapsed > line_info->us_max)
  17.         line_info->us_max = elapsed;
  19.     line_info->us_total += elapsed;
  20.     line_info->exec_count++;
  21. }

数据分析

分析部分主要是profiler_collect_data函数，该函数会在func_end结束时运行，意味着每执行一次pl/pgSQL函数会收集一次的数据，或者通过手动触发。

可以看到收集了两部分数据：

  1. 调用图数据，即callGraphEntry，对应了火焰图的原始数据
  2. 行统计数据，即linestatsEntry，对应了每个函数的统计数据
  1. static int32
  2. profiler_collect_data(void)
  3. {
  4.     ...
  5.     /* 如果没有新数据，就不进行分析，防止每次都进行分析 */
  6.     if (!have_new_local_data)
  7.         return 0;
  8.     have_new_local_data = false;
  10.     /* 分析前需要获取hash table锁 */
  11.     LWLockAcquire(plpss->lock, LW_SHARED);
  13.     /* 1.将调用图数据分析进入共享内存 */
  14.     hash_seq_init(&hash_seq, callgraph_hash);
  15.     while ((cge1 = hash_seq_search(&hash_seq)) != NULL)
  16.     {
  17.         /* 将cge1导入callgraph_hash，并将相关信息记录进去 */
  18.         ...
  19.         cge2->callCount += cge1->callCount;
  20.         cge2->totalTime += cge1->totalTime;
  21.         cge2->childTime += cge1->childTime;
  22.         cge2->selfTime  += cge1->selfTime;
  24.         /* 清空已经记录过的信息 */
  25.         cge1->callCount = 0;
  26.         cge1->totalTime = 0;
  27.         cge1->childTime = 0;
  28.         cge1->selfTime = 0;
  29.         ...
  30.     }
  32.     /* 2.将行统计数据导入共享内存 */
  33.     hash_seq_init(&hash_seq, functions_hash);
  34.     while ((lse1 = hash_seq_search(&hash_seq)) != NULL)
  35.     {
  36.         /* 将cge1导入functions_hash，并将相关信息记录进去 */
  37.         ...
  38.         for (i = 0; i < lse1->line_count && i < lse2->line_count; i++)
  39.         {
  40.             /* 更新每一行的最大执行时间、总执行时间、执行次数 */
  41.             if (lse1->line_info[i].us_max > lse2->line_info[i].us_max)
  42.                 lse2->line_info[i].us_max = lse1->line_info[i].us_max;
  43.             lse2->line_info[i].us_total += lse1->line_info[i].us_total;
  44.             lse2->line_info[i].exec_count += lse1->line_info[i].exec_count;
  45.         }
  46.         ...
  47.     }
  49.     ...
  50. }

对外接口

对外接口比较多，主要是将数据吐给前端，也比较乏善可陈，仅在这里列出，不做具体分析。

接口名称INOUT描述
pl_profiler_callgraph_localSETOF recordOUT stack oid[], OUT call_count bigint, OUT us_total bigint, OUT us_children bigint, OUT us_self bigintReturns the content of the local call graph hash table as a set of rows.
pl_profiler_callgraph_overflowboolean Return the flag callgraph_overflow from the shared state.
pl_profiler_callgraph_sharedSETOF recordOUT stack oid[], OUT call_count bigint, OUT us_total bigint, OUT us_children bigint, OUT us_self bigintReturns the content of the shared call graph hash table as a set of rows.
pl_profiler_collect_datainteger SQL level callable function to collect profiling data from the local tables into the shared hash tables.
pl_profiler_func_oids_localoid[] Returns an array of all function Oids that we have linestat information for in the local hash table.
pl_profiler_func_oids_sharedoid[] Returns an array of all function Oids that we have linestat information for in the shared hash table.
pl_profiler_funcs_sourceSETOF recordfunc_oids oid[], OUT func_oid oid, OUT line_number bigint, OUT source textReturn the source code of a number of functions specified by an input array of Oids.
pl_profiler_functions_overflowboolean Return the flag functions_overflow from the shared state.
pl_profiler_get_collect_intervalboolean Report pid profiling state.
pl_profiler_get_enabled_globalboolean Report global profiling state.
pl_profiler_get_enabled_localboolean Report local profiling state.
pl_profiler_get_enabled_pidboolean Report pid profiling state.
pl_profiler_get_stacktext[]stack oid[]Converts a stack in Oid[] format into a text[].
pl_profiler_lines_overflowboolean Return the flag lines_overflow from the shared state.
pl_profiler_linestats_localSETOF recordOUT func_oid oid, OUT line_number bigint, OUT exec_count bigint, OUT total_time bigint, OUT longest_time bigintReturns the content of the local line stats hash table as a set of rows.
pl_profiler_linestats_sharedSETOF recordOUT func_oid oid, OUT line_number bigint, OUT exec_count bigint, OUT total_time bigint, OUT longest_time bigintReturns the content of the shared line stats hash table as a set of rows.
pl_profiler_reset_localvoid Drop all data collected in the local hash tables.
pl_profiler_reset_sharedvoid Drop all data collected in the shared hash tables and the shared state.
pl_profiler_set_collect_intervalbooleanseconds integerTurn pid profiling on or off.
pl_profiler_set_enabled_globalbooleanenabled booleanTurn global profiling on or off.
pl_profiler_set_enabled_localbooleanenabled booleanTurn local profiling on or off.
pl_profiler_set_enabled_pidbooleanpid integerTurn pid profiling on or off.
pl_profiler_versioninteger Get int version.
pl_profiler_versionstrtext Get text version.