从redo日志分析数据库的profile

 

标签

PostgreSQL , pg_xlogdump , 数据库profile

---

背景

在PostgreSQL中查看TOP SQL是比较方便的，如下：

《PostgreSQL 如何查找TOP SQL (例如IO消耗最高的SQL)》

而从另一个角度，比如REDO文件，我们也能分析出每个时间段数据库的操作类型，分析数据库资源消耗，以及提出优化建议。

redo日志长什么样

pg_xlogdump

要查看redo日志，不得不提pg_xlogdump，原理和介绍详见如下

《PostgreSQL xlog dump - pg_xlogdump 源码讲解》

我们简单的看看某个REDO文件的内容：

pg_xlogdump 000000050000159E00000095 000000050000159E00000099|less  
  
rmgr: Btree       len (rec/tot):     42/    74, tx:  891772656, lsn: 159E/95000CA0, prev 159E/94FFEC78, bkp: 0000, desc: insert: rel 1663/56867/10216768; tid 19180/150  
rmgr: Btree       len (rec/tot):     34/    66, tx:  891772656, lsn: 159E/95000CF0, prev 159E/95000CA0, bkp: 0000, desc: insert: rel 1663/56867/10906168; tid 150019/337  
rmgr: Transaction len (rec/tot):     12/    44, tx:  891772656, lsn: 159E/95000D38, prev 159E/95000CF0, bkp: 0000, desc: commit: 2017-05-04 13:15:50.262106 CST  
rmgr: Heap2       len (rec/tot):     26/    58, tx:          0, lsn: 159E/95000D68, prev 159E/95000D38, bkp: 0000, desc: clean: rel 1663/56867/10216762; blk 402406 remxid 891772032  
rmgr: Heap        len (rec/tot):     25/  8065, tx:  891772657, lsn: 159E/95000DA8, prev 159E/95000D68, bkp: 1000, desc: lock 891772657: rel 1663/56867/10216770; tid 39310/2 LOCK_ONLY EXCL_LOCK   
rmgr: Heap        len (rec/tot):     36/  8116, tx:  891772657, lsn: 159E/95002D48, prev 159E/95000DA8, bkp: 0100, desc: update: rel 1663/56867/10216770; tid 39310/2 xmax 891772657 ; new tid 122748/1 xmax 0  
rmgr: Btree       len (rec/tot):     18/  5238, tx:  891772657, lsn: 159E/95004D18, prev 159E/95002D48, bkp: 1000, desc: insert: rel 1663/56867/10216776; tid 15681/11  
rmgr: Transaction len (rec/tot):     12/    44, tx:  891772657, lsn: 159E/950061A8, prev 159E/95004D18, bkp: 0000, desc: commit: 2017-05-04 13:15:50.320538 CST  

rmgr是指这笔REDO RECORD的类别，后面是长度等信息。

通过以下命令，可以统计每个资源有多少笔redo记录，描述是什么？

pg_xlogdump 000000050000159E00000095 000000050000159E00000099|grep -v " lock "| awk '{print $2" "$16" "$17}'|sort |uniq -c|sort -n -r  
  
 178464 Gin Insert item,  
  39060 Gin Vacuum page,  
  30980 Heap2 clean: rel  
  23855 Gin Vacuum data  
  22240 Btree insert: rel  
  18068 Heap insert: rel  
  15650 Heap2 visible: rel  
   8516 Heap delete: rel  
   4057 Transaction commit: 2017-05-04  
   3727 XLOG full-page image:  
   3331 Gin Insert new  
   3026 Heap update: rel  
   1196 Transaction abort: 2017-05-04  
   1191 Gin Update metapage,  
    765 Btree vacuum: rel  
    755 Heap hot_update: rel  
    243 Gin Delete list  
     55 Btree insert_upper: rel  
     50 Btree split_r: rel  
     32 Btree unlink_page: rel  
     32 Btree mark_page_halfdead: rel  
     29 Btree reuse_page: rel  
     28 Heap2 freeze_page: rel  
     27 Standby running xacts:  
     27 Heap insert(init): rel  
     20 Heap inplace: rel  
     11 Btree delete: index  
      9 Heap2 cleanup info:  
      5 Standby AccessExclusive locks:  
      5 Btree split_l: rel  
      4 Gin Page split,  
      2 XLOG checkpoint: redo  
      2 Gin Create posting  
      1 Heap update(init): rel  

这个日志可以看出什么问题呢？

比如我们可以看到Gin的REDO非常多，说明用户使用了GIN索引，同时这个索引的写入，更新非常频繁。

对于这种情况，用户可以设置GIN索引的fastupdate特性，同时调大vacuum naptime，以及调大表的vacuum阈值，尽量的减少GIN的合并频率，（但是fastupdate会降低检索性能）。

其他，

如果你看到VACUUM非常多，说明这些REDO中包含大量的垃圾回收信息，用户可能产生了较多垃圾，正在被回收。

如果是VACUUM FREEZE较多，说明冻结较多，用户可以修改一下冻结周期，减少这种REDO。

参考

《PostgreSQL 使用pg_xlogdump找到误操作事务号》

《PostgreSQL xlog dump - pg_xlogdump 源码讲解》

《PostgreSQL 如何查找TOP SQL (例如IO消耗最高的SQL)》

本文为云栖社区原创内容，未经允许不得转载，如需转载请发送邮件至[e-mail]