开发者学堂课程【PostgreSQL 快速入门：23 PostgreSQL 监控4 动态内核跟踪 stap 篇】学习笔记，与课程紧密联系，让用户快速学习知识。
课程地址：https://developer.aliyun.com/learning/course/16/detail/82
23 PostgreSQL 监控4 动态内核跟踪 stap 篇
内容介绍：
一． 如何做实时跟踪
二． postgre 自定义探针
三． 清除统计信息
四． Read 和 write
五． Postgre 进程级别探针
六． 创建表
七． 加载自定义包
八． 网络层传输
一． 如何做实时跟踪
接下来介绍一下 Postgregre 数据库的实时活动的跟踪。需要打开 postgregre 的 Dtrace 以及它的 debug 的一个选项，也就是在编译 postgregre 软件时需要打开这个选项。
比如使用 pg_config 可以看到当时编译的一些参数，将 enable dtrace 打开，就可以跟踪 Postgregre 自定义的,就在原来自定义里面的一些探针。如果把 enable debug 也打开，那么就允许调试 Postgregre 所有的代码。比如要调试任何一个 posgre 代码里的一些函数，都是可以去调试的。如果只打开了这个 dtrace，就只能去调试那些自定义的探针或者是可以自己定义一些探针。也可以拿来做调试，但如果要自定义探针，相当于又要重新编译，打开 enable debug 就不需要重新编译，随时都可以对里面的函数做一些跟踪。
那么这里以两个例子来介绍一下如何来做这个实时的跟踪。第一个例子是跟踪每一个 sql 产生的 IO 以及整个会话产生的 IO，比如它读了多少个 sql 语句，它读了多少个对每一个设备包括区分设备或者不区分设备，读了多少个数据块，多少个字节，每秒的请求数有多少个，每秒平均的吞吐量是多少。如果是网络层就可以去跟踪一个sql语句，它在网络层传输的数据包有多少，它平均每秒传输多少个数据包，总共传输了多少的数据量，这些都可以拿来做跟踪。
其他的像下面的事务查询，以及检查点，buffer，对象读写，锁 xlog，排序，等探针用法，这些都是 Postgregre 里面自定义了一些探针，可以去直接使用。上面这些也是利用一些 sql 探针去做检测，以及超层面的一些系统调用。对这些系统调用的次数，以及它的返回值做一些统计，这样能达到统计每一条产生的一些 IO，还有网络存储量这样一个目的。
二．Postgre自定义探针
首先简单的来介绍一下 postgregre 它自定义的一些探针，可以去手册里面找到，打开这个9.3的手册，来看一下它的dtrace。这里面就有它自定义的 probes 这个探针，那么就可以直接拿来使用。要注意的是，如果使用 steper 去做，并且就在Linux环境里面，这个探针名后的减号要替换成两个下划线，具体为什么这样做，可以在代码里看到，因为它定义探针时它就是以两个下划线来定义的。
自定义探针的方式可以去看之前写过的一些 blog 里面有介绍如何自定义这个探针，包括去年全国大会时，分享的postgregre 的动态跟踪的话题，有兴趣也可以去看一下对应的 ppt， ppt 可以在首页里面 blog 的首页里面找到。
接下来就直接进入主题。比如要跟踪每一条 sql 的 IO，跟踪的方式为打开对应的 blog，打开这一篇文章。这篇文章里面，这是已经写好的 stp 使用 systemtap 的一个脚本。把这个脚本拷贝到这里，并简单的来介绍一下，如何写脚本。首先这里定义了一些全局变量，这些全局变量分别用来存储，比如非 cache 读写字节数，这个是指单 sql 的，就是一个 sql 语句产生了多少个非 cache 类的读写，非 cache 指的是超智系统层面的 cache，这里应该叫非os cache。
也就是在读一个快速类时，在超智系统层面 cache 里面已经命中了，那么非 cache 表示没有命中，那么 cache 就表示在超智系统层面已经命中了，区分的方式就是区分一个系统调用，它的 devname。devname 如果等于 N/A，这个就表示在 cache 里面命中，因为没有设备名。如果是 devname 不等于 N/A，它就是一个设备名。设备名指的就是非os cache 读写的这个设备名，所以用这个来区分什么是非 cache 的，什么是 cache 的。
那么 io_stat1和 io_stat11，一个用来存储读写的字节数，这个读写字节数就是从这个系统调用的返回值里面。return它就是一个字节数，也就是产生了一个这样的系统调用，它会返回这次读到了多少个字节，这就是它的返回值，那么这是一个系统调用。
另外还可以统计它，因为使用的是 return 这种探针，那么就可以统计这次系统调用盘消耗的时间，这个时间可以通过获得当前的时间，减去 vfs.read 这个函数的路口的时间，也就是@entry gettime of day，这样就能够获得 vfs.read 这个函数，进入的时候以及它返回的时候，这样一个时间差，也就是这次系统调用所消耗的时间。
下面的这个 io_ stat2以及 io_ stat22是用来统计这个 cache 类的，就是在 os 缓存里面已经命中的这些数据块的读写，那么 io_stat3和4分别是用于存储总的，也就是整个会话它对设备所产生的一些读和写，也是区分非 cache 和cache 的一个读和写。
三．清除统计信息
那么前面的一和二就是指单个的 sql，那么单个 sql 这里就需要记录下它的 Pid execname，还有设备名。并且在每次统计完 sql 之后，就要把这些统计信息清掉。清理的方式就是，首先每收到一个在内核里面放的这样的一个模块，就是在使用 steper时，实际上它会生成一个动态的模块放在这个内核里面。
那么这个模块就可以去跟内核交互，去获取内核里面的一些值，比如内核里面，它发生了一个 vfs。read 的这样一个系统调用，那么下面写的就是它的一个 hand，外面是一个探针，这个 hand 里面就表示，如果这个反馈值大于零，也就是读到数据了，如果它小于等于零，就说明有问题，错误或者是这一次系统调用就没有产生任何的读。
四．Read和write
这个 V_us 这个变量，是一个本地变量，是用来存储这一次系统调用所耗费的时间。那么下面一个判断，如果这个设备不等于 na，表示它不是在 cache 里面命中的，并且 execname 是 postgregres，假如这个系统调用是 postgregres 进程产生的一个系统调用，那么如果满足这个条件，这就是一次非 cache 的读的一个字节数，因为它是read，所以它是读，如果是 write 就是写。
先统计读的，那么就往这个数组里面存储一个值，这个数组是一个统计类型，所以使用这个三个小于号呢，就把return 的这个值填补到统计类型里面去，在 steper 里面是可以使用这个来存储一个统计类型的，后面会说出这个统计类型它的一些值。比如可以输出它的柱状图，可以输出这个统计类型面总共存储了多少值，存储这个统计类型里面它的 return 的和是多少，它可以计算 main max avg Some 还有 count，这些都可以计算。
下面是用于时间，也就是每一次发生这个调用的时候，就把这一次调用的时间填补到统计类型里面去，这样后面也可以来计算，比如平均的时间是什么，总共多少次。那么下面3和4就是总的统计，也就是整个会话层面的统计，所以说每次结束之后，不需要去清楚它，因为是到这次统计完成之后，再去把它的值打印出来。
下面这个2和4是一个 Cache 类的，也就是如果 device name 是这个 na，就比如其实这次是在 cache 里面命中的，那么同样也把它的值统计出来，也是使用前面的方法存储它的 Pid execname。
R 就表示存储的字符串，字符串 R 表示这里面存储的是一个读的数据，那么也是把它存储在这里面。第二个探针是VFS.read.return 要注意这里写错了，应该是VFS.Write return，这里是有一个 bug 写错了的，将它改过来。要看这个探针也可以使用这个命令去看，比如step-1 ‘vfs.** ‘，这样就可以把所有的 VFS 下面的一些探针打印出来。比如这里用到的 VFS.write. return，这里因为有一个bug先把它调整过来，编辑一下。
VFS 因为这里是 write 的，就要把它改成 write，那么这样就算改好了，再保存一下。这里是没有错的，就是后面出现了一个这样的小 bug。那么继续来看，write 跟 read 是一样的，如果这个系统调用它的返回值大于零，就表示这次系统调用已经写了，确实已经写了数据到这个快设备里面。如果是小于零，就说明它可能是反馈那些错误，那么等于零就表示这次写没有写任何东西。
同样它也是有这个设备名，这个设备名如果是空的，表示它是一个写在 os cache 里面的，如果不是空，是一个设备名，就比如这次写是直接写在物理设备里面，通过这个来区分一个是 cache 的写一个是非 cache 的写，这些都是超系统层面的，跟 postgregre 本身没有任何关系，postgregre 它自己有自己学的 buff。
五．Postgre 进程级别探针
那么接下来，前面这两个探针是针对，如果发生了这种系统调用去做这种统计的，那么下面的探针是跟 postgre 有关系，这是一个进程级别的探针，那 mark 表示这是一个预知探针，是一个前面提到的 postgre probe，它里面已经定义好了 query-start，这个 query-start 可以在它提供的一个手册里面可以看到。
这里应该叫 query-start，这个探针是当这个 planning of a query is started 查询，进入 pran 时所触发的触发器，所触发的一个事件叫做 Query start，那么它可以从里面取到一个返回值，这个返回值是这个 query string，也就是这个 sql 语句可以从这里面取到。
当这个查询开始时，就触发这下面的一系列动作，这个系列动作是用来清除前一个 sql 产生的一些统计变量存储的一些信息，因为在触发之后每一次系统调用，都会去写这些变量。那么 sql 执行结束之后就得把它清掉，这样下一个 Sql 开始的时候才能够取它的跟 sql 本身有关的一些，也就是前面所提到的，一和二是用来取单 sql，存储单个 sql 的这个全局变量。
那么三和四是用于存储整个会话的，所以一和二在这个sql开始的时候就得把它清掉。那么清掉就用到了第三个全局变量叫 del，用来存储这个 stat1和 stat2的索引，因为不能直接在这里面去清除这个索引，systemtep 在设计时就不允许在 foreach 里面去修改这个数组的元素，因为 systemtep 在设计时，就考虑到在做这个跟踪时，不能对系统或者是对这个进程产生太大的负面影响，否则就会影响比较大。
所以它是不允许在里面修改的，做了一层性能的保护。如果要清楚这个数据，就用到 DEL 这个数组用来存储这个索引，把这个 abcd 索引存储到这个 del 里面，先去便利它，然后存储到 del，再去便利 del，删除 iO_stat1和io_stat2，一个是 cache 类的，一个是非 cache 类，单 sql 类的统计，那么也就是在 sql 开始时，先把上一次的统计信息清掉，在查询结束时输出这个统计信息，比如查询结束时先输出它的 query，这个 query 来自于 $arg1，就是query_done 这个探针它的参数。
使用 user_string 这个函数把它转换成一个字符串，先打印非 cache 类的一个输出类，非 cache 类输出的打印要根据这个 Sum 来排序，倒序来输出它的设备的读写情况。那么 Var1就是@count，就比如这个 var3总共请求了多少次，读的系统调用总共请求了多少次，那么@sum 除以1024就是所有的 sql 语句，总共请求了多少个字节，请求的时间是io_stat11，这是非 cache 的一个输出。它也是包含了读和写的，所以这里区分开读和写。如下图：
在这里使用完之后就得把它清掉，因为下一个 Sql 语句，还要用到这个 io_stat1和io_stat1这样一个全局变量。接下来就是把这个本地变量清掉，因为下面还要输出 Cache 类，也要用到这些变量，方便后面的计算。那么这就是单个sql 的一个输出。
后面的 probe end 就比如整个探针结束时，输出一下整个会话的这个统计信息，整个会话统计信息这边只包含两个部分，一个是读或者写，另外一个 D 是设备名。也就是整个会话对哪一些设备有读写的请求，同样也是区分读和写。最后就删除一些本地变量，还有结束后清除所有的全局变量。如图所示：
先将这个脚本写到这个系统里面去。比如这里输入 vi io.stp，删掉打开一个，这样就把它写上去了，再输入 stap—vp11111./io.stp，就可以输出了。现在这里面还在解析，到第五步时就开始运行。它先会把它转换成一个C代码，转换时它会生成一个模块，这个模块会把它 C 到这个 ko 文件，C 到这个内核里去， 再 start running 了一下。
来到这个用户下面就可以去做这个操作了，这里需要注意一下，这里要用到的这个 postgre 这个程序的进程 home/pg93/pgsq10.3.1/bin/postgres ，一定要写对，这里是9.3.3的，所以刚才这要改一下，改好之后再重新来写一遍。那这里来修改一下，把它改到这里面，这样就可以了，还有这个 Query done 也要改。这里改掉之后，重新再来把它打开。连到数据库里面做一些查询，比如创建一个表，先看一下有哪个表，那么这里就有输出了，这个 done start。
六．创建表
比如创建一个表叫做t1<id serial primary key,info text ,crt_time timestamp>; 这里创建一个 Primary，那么创建这个表，statsinfo.sample 是之前每分钟采样一次的输出。创建表时它也有一个输出，创建表时这里就有读和写，比如写请求是一次，那么因为时间很短暂的关系，它计算出来的请求是每秒可以有上万次的请求。
这些都是这个 statsinfo 它所产生的一些sql，包括上面这些。如下图所示：
为了能够看清楚一点测试的这个语句，这样输出就可以。来 insert 一个 sql，输入 insert into t1 <info,crt__time> select md5<random<>::text>,now<> from generate_series<1,100000>；，插入十万条记录，这个语句执行完之就能够看到非 cache 类的写，是写在这个 SDE1这个快设备上面。写请求是300多次。它写了大概有11兆的数据，读了有一兆多一点的数据。如下图：
看一下这个写了11兆的数据，写了些什么值。t1这个表有七兆多，它有一个 pkey，这个 pkey 的大小是这两个值加起来，差不多也就是那个值。因为它还有一些其他的数据要写，那么就相当于是统计每个 sql 语句，它所产生的一些Cache 类的以及非 Cache 类的 io 的统计情况。包括速率，请求的请求数，请求的字节数，还有每秒的请求数以及每秒请求的字节数。
使用ctrl C退出的时候就会触发这个 probe end 这个探针，也就是在这里的这个探针，如果要输出，输出的就是io_stat3和4的值。那么可以看到这个非 Cache 类的读写，它包括了 sda sdb sdd sdc 的一些快设备读写的情况。如图所示：
如果要按照会话来输出，那么 sda3和 ada4就要加上 Pid，这里相当于没有加 pid，没有加 pid 相当于是记录了所有的 postgre 进程的读写的情况。如果加了 pid 就可以按照 pid 来输出，每一个会话它的读写的情况都可以输出。那么这是 io 的一个统计探针的脚本。
接下来看一下如果要统计网络层面，比每秒发了多少个包，每个 sql 语句发了多少个包，发了多少个字节数或者收了多少个字节数，那要做这个探针，可以去看这个 blog，bolg 也是在 pdf 里面，ppt 面都有，直接点进去看就可以。那么这里用到了几个探针，一个是超系层面 tcp 的 recvmsg这样一个探针，它其实是在内核里面的 tcp recvmsg 的这个函数。如下图：
还有一个函数是一个 send message 的，要注意 recvmsg return 里面就有这个来源ip以及端口，还有这个目的 ip 以及端口，但是在 send message 这个探针里会发现它里面只定义了两个东西，一个是探针名，还有一个是 size 就是返回值。
所以在发送包时，在网络层发送包时，要去统计它的来源 ip 和目的 ip还有端口，就不能使用它自带的，必须要使用内核层面的一些变量，其实就可以直接使用 foemat_ipaddr(_ip_sock_saddr($sk),_ip_sock_family($sk))这几个函数，这几个函数直接连到它的代码里面去看。比如 sendmsg 它到底对应的是哪个代码，可以粘过去，就能够输出。
比如输出对应的是这部分代码里面的第902行，打开它输入 debug/kernel-2.6.32-358.e16/linux-2.6.32-358.e16.x86_64/ net ipv4/tcp.c冒号902，就能够对应到这个探针，其实它所对应的这个函数就是 sandmsg，那么要输出它的来源 ip，目的 ip，就要用到里面的这一些变量，还有对应的这些，比如 format ipaddr，还有ip_sock_saddr，把这个 sock 对应的 SK 通过这个变量,$sock 表示要去取这个变量里面的这个值。
所以在写 send message 时，这一部分就得自己写，那么在写 receive message 时，ip 就直接使用它已经定义好的这个别名就行，就是这个探针它定义的别名。那么来看这个探针，首先这个 S tap 是后面安装的，来到这个 system tap 这个目录里面，里面有个 share 目录，还有一个 tapset。这里面就是 systemtap 它自带的探针，可以认为它是一个库。
七．加载自定义包
接着来 group 一下，group 这个 receive message，要加一个减号。能够看到它其实就是在.stp 这里面所定义的，它定义在这个地方，它会告诉这里面有哪些变量是能用的，比如 dport daddr sadd 这些是能用的，它是通过这里面定义的几个函数来取的，所以在使用这个探针时，其实这一些函数都是可以拿来使用的。因为 systemtap 在加载时，它就会去读这里面已经定义好的一些包，把它加载进来。
来看一下探针怎么写的，就是这个 system tap 怎么写。首先这个 var1 和 var11是用来记录每一个 sql 在网络传输的流量。这个11是一个时间的统计，将时间和这个流量分开了，因为时间是通过另外一个变量获取到的，是这个gettimeofday_us 以减去这个函数的入口时间戳，那就得到了这一次函数调用所耗费的时间，那么 return 是一个返回值，return 就相当于是填补到 var1这个变量里面去了，这个 v_us相当于填补到这个 var11里面去了。Var2就是记录整个会话它的一个开销。所以2里面记录的是这个 saddr,sport,daddr.dport，就是没有记录 Pid 和 execname。
接下来看一下整个的后面，同样也使用到了第三个 Del 这样一个中间变量，也是一个全局变量，就是上面在讲这个 io的获取时，用到了这个变量去删除一些每个 sql 语句所产生的一些统计信息的值，因为这个数组在 foreach 里面是不能去变更它的元素值的，就是对于本数组的 foreach 是不能去变更它的元素值。
所以要借助另外一个变量来存储它的一个索引，再便利这个变量，再把这个索引作为一个另外要清除的那些变量的索引，去清除那些元素的值。那么这里首先第一个探针是 tcp.send message，第二个探针是 tcp.receive message。
前面提到了 sendmsg 里面，因为没有定义的这些东西，所以直接就写这个地方，写在这个探针里面去，定义成它这个本地变量，再来使用它。那么 return 如果是大于零，就比如这一次这个系统调用 tcp.send message，这次系统调用表示有发送包出去了，那么 return 是一个字节数，gettimeofday 是一个时间，就是这次系统调用的一个时间，是通过这个 get time of day 向 us 减去这个路口时间得到的。
Saddr sport daddr dpor 是通过在这个 recviemsg 探针别名定义里面所查到的这一些，获取它的这个就是把 ip 地址格式化成可读的这种数据。Var1和 var11是用来存储，一个是存储字节数，一个是存储时间。那么 S 就表示 send，这里面记录了这个原 ip 端口，目的 ip 端口。PID 以及 execname 就是 postgres。var2和 var22就是用于存储整个的这个 Postgre 的数据库集群，它所产生的 send 发包的统计，也是包括了时间和这个字节数的一个统计。
那么 recvmsg 跟上面是一样的，那么这个地方也要稍微改一下。因在实际的环境当中是 pgsql 里面的，同样也是在sq 语句开始时就是 query_start，将这个821的数据做一次便利，将它存到这个 del 这个数组里面，给它随便设置一个值。再去便利这个del数组，再去删掉这个var1 和 var11这样一个值，就因为每一个 sql 语句是通过这两个变量来记的，所以每次 sql 开始时，就把这个值清掉，再 delete 这个 del 这样一个变量。
这个 query_done 也就是这个查询结束时，触发了一个这样的探针，先把它改过来，这里面就是一个输出。将这个$age1前面提到 sql 语句输出，输出同时去便利 var1这样一个数组，然后按照它的统计值的总和，@Sum 去做一个倒序输出，看哪个发送的包最多。如果这个g等于S，就比如 send 发送的包，那就把这个发送的包信息打出来，从哪里到哪里，它的这个统计值是什么样的。
要注意这里用了一个 sum 操作符。这里跟前面的也是一样的，如果这个v3，发送时间不等于零，那取前面这个词，如果等于零，也就是发送就没有时间的情况下就直接将这个 spv1返回一个零，这里就不去做这个除法了，因为除以零的话就会报错，就会报一个除以零的错误。
那包括下面这个 R，跟它不一样的就是G等于R， R就表示 recive 接收到的包也有这样的统计。那么在整个的探针结束时，就把这个前面提到的 var2的以及 var22的信息，把它输出出来，这个就是整个的 postgre 集群。它在网络上的一些传输的统计，将它写到这里面来。取了个名字叫做 Net.stp，接下来就执行它就好了，step.11。
Net 输出了，那么它就会把每一个 sql 语句，就是在 C trl c 之前它都是根据每个 sql 语句来打印的，只有你退出这个step 时，它才会打印整个集群的网络层传输的统计信息。那同样它也会去把这个模块数字化，输入 lsmod!grep stap，可以看到 Stp 的这样一个模块，这是刚刚加载的这个模块。如下图：
这里面是查询，后面没有直输出，没有直输出就表示这个 sql 语句还没有结束，来看一下是不是 sql 语句 begin 的时候有输出这个 sql 语句。query down，这里面根本就没有没有网络层的传输的一个模块。
八．网络层传输
那么接下来，用一个网络层传输来试一下，比如3.33连过来，连过来去做一个查询，输入 psql-h 172.16.3.150-p 1921-U postgres digal-c’’copy t1 to stdout’’>/dev/null 看一下刚刚是在哪个库里面的，刚刚是在 digoal 里面，那么 copyt1 to stdout，这样网络层就会产生一些传输，那把它输入到 dev/null 中。这里就能够看到这个有输出，它有从本机33.150：11921端口发送到3.33的这个端口总共发送了八百多个包，发送了大概六兆左右的数据，这个跟上面7584这个数据是差不多的。
因为这里没有数据块的格式化的一些东西，所以网络上传输的数据比实际上存储的数据要稍微小一点。那么这个就统计到了，相当于是每一个 sql 语句，它网络层所开销的一些数据包。如果 ctrl c 退出，就会把整个的打印出来。比如从3.105到3.33，3.33到3.150它发送多少包，这里面是根据端口把它区分开来，这就是网络层的一个统计。
那么其他的一些统计可以去看这里写的一些 blog，比如可以对一次排序做一个统计，结合这个超系统的一些系统调用，比如这次排序耗费了多少的 io，有多少是内存中完成的，有多少不是在内存里面完成的，包括这个跟踪，锁，buffer，检查点，它们都完成了多少 io 等等。
这就是系统探针的使用，那么就先讲到这里。
