Systemtap EXP: trace PostgreSQL instruction or block of instructions per sql or per session

背景

执行一个SQL需要多少条单步指令或指令块?

这个问题可以通过Instruction probes来得到.

参考以前写的一篇blog :

http://blog.163.com/digoal@126/blog/static/163877040201383042846295/

同时也测试一下使用普通全局变量和统计类型看看在没有锁争抢的情况下, 哪个效率更高一点, 从结果来看没有锁争抢的情况下普通的全局变量自增效率略高.  
下面是统计一个SQL以及整个会话耗费的单步指令数的 :   
查找当前连接的pid  
digoal=# select pg_backend_pid();  
 pg_backend_pid   
----------------  
          31531  
(1 row)  
一定要使用target process模式, 因为insn太庞大了 .  
stap -e '  
global var1%[60000], var2%[60000]  
  
probe process("/home/pg93/pgsql9.3.1/bin/postgres").insn {   
    var1[pid()]++  
    var2[pid()]++  
}   
  
probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("query__start") {  
  delete var1[pid()]  
}  
  
probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("query__done") {  
  printf("query:%s, insn:%d\n", user_string($arg1), var1[pid()])  
  delete var1[pid()]  
}  
  
probe end {  
  foreach(x in var2-)   
    printf("pid:%d, insn:%d\n", x, var2[x])  
  delete var1  
  delete var2  
}  
' -x 31531  
执行以下SQL :   
digoal=# select count(*) from pg_class;  
 count   
-------  
   296  
(1 row)  
  
Time: 1177.310 ms  
digoal=# select count(*) from pg_class;  
 count   
-------  
   296  
(1 row)  
  
Time: 1175.815 ms  
digoal=# select count(*) from pg_class;  
 count   
-------  
   296  
(1 row)  
  
Time: 1173.867 ms  
输出, 以上sql每条消耗了48万多次单步指令 :   
query:select count(*) from pg_class;, insn:488264  
query:select count(*) from pg_class;, insn:488252  
query:select count(*) from pg_class;, insn:488252  
一下为使用统计类型的测试结果, 速率上略慢 :   
stap -e '  
global var1%[60000], var2%[60000]  
  
probe process("/home/pg93/pgsql9.3.1/bin/postgres").insn {   
    var1[pid()] <<< 0  
    var2[pid()] <<< 0  
}   
  
probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("query__start") {  
  delete var1[pid()]  
}  
  
probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("query__done") {  
  printf("query:%s, insn:%d\n", user_string($arg1), @count(var1[pid()]))  
  delete var1[pid()]  
}  
  
probe end {  
  foreach(x in var2-)   
    printf("pid:%d, insn:%d\n", x, @count(var2[x]))  
  delete var1  
  delete var2  
}  
' -x 31531  
  
digoal=# select count(*) from pg_class;  
 count   
-------  
   296  
(1 row)  
  
Time: 1225.236 ms  
digoal=# select count(*) from pg_class;  
 count   
-------  
   296  
(1 row)  
  
Time: 1223.868 ms  
digoal=# select count(*) from pg_class;  
 count   
-------  
   296  
(1 row)  
  
Time: 1222.593 ms  
  
query:select count(*) from pg_class;, insn:488252  
query:select count(*) from pg_class;, insn:488252  
query:select count(*) from pg_class;, insn:488252  
  
以下为指令块的测试 :   
指令块约为单步指令的1/8  
[root@db-172-16-3-150 ~]# stap -e '  
global var1%[60000], var2%[60000]  
  
probe process("/home/pg93/pgsql9.3.1/bin/postgres").insn.block {   
    var1[pid()] <<< 0  
    var2[pid()] <<< 0  
}   
  
probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("query__start") {  
  delete var1[pid()]  
}  
  
probe process("/home/pg93/pgsql9.3.1/bin/postgres").mark("query__done") {  
  printf("query:%s, insn:%d\n", user_string($arg1), @count(var1[pid()]))  
  delete var1[pid()]  
}  
  
probe end {  
  foreach(x in var2-)   
    printf("pid:%d, insn:%d\n", x, @count(var2[x]))  
  delete var1  
  delete var2  
}  
' -x 31531  
  
digoal=# select count(*) from pg_class;  
 count   
-------  
   296  
(1 row)  
  
Time: 159.659 ms  
digoal=# select count(*) from pg_class;  
 count   
-------  
   296  
(1 row)  
  
Time: 159.453 ms  
digoal=# select count(*) from pg_class;  
 count   
-------  
   296  
(1 row)  
  
Time: 159.501 ms  
  
  
query:select count(*) from pg_class;, insn:60330  
query:select count(*) from pg_class;, insn:60342  
query:select count(*) from pg_class;, insn:60342  

参考

1. http://blog.163.com/digoal@126/blog/static/163877040201383042846295/

digoal’s 大量PostgreSQL文章入口