达梦数据库学习09：开启SQL跟踪日志

开启SQL跟踪日志

跟踪日志文件是一个纯文本文件，以 ‘dmsql_实例名_日期_时间命名’，默认生成在 DM 安装目录的 log 子目录下。跟踪日志内容包含系统各会话执行的 SQL 语句、参数信息、错误信息、执行时间等。跟踪日志主要用于分析错误和分析性能问题，基于跟踪日志可以对系统运行状态进行分析。跟踪日志配置方式如下：

配置 dm.ini 文件，设置 SVR_LOG = 1 以启用 sqllog.ini 配置，该参数为动态参数，可通过调用数据库函数直接修改。

SP_SET_PARA_VALUE(1,'SVR_LOG',1);

sqllog.ini 配置文件主要用于配置 sql 日志。如果需要开启 SQL 日志，则必须配置日志切换模式 SWITCH_MODE 和日志文件个数 FILE_NUM，防止日志无限增长导致磁盘撑爆，同步日志会严重影响系统效率，生产环境必须设置为异步日志。sqllog.ini 配置文件示例如下：

$ cat sqllog.ini 
BUF_TOTAL_SIZE  = 10240  #SQLs Log Buffer Total Size(K)(1024~1024000)
BUF_SIZE        = 1024   #SQLs Log Buffer Size(K)(50~409600)
BUF_KEEP_CNT    = 6      #SQLs Log buffer keeped count(1~100)

[SLOG_ALL]
    FILE_PATH       = ../log/tracesql
    PART_STOR       = 0
    SWITCH_MODE     = 2
    SWITCH_LIMIT    = 512
    ASYNC_FLUSH     = 1
    FILE_NUM        = 20
    ITEMS           = 0
    SQL_TRACE_MASK  = 1
    MIN_EXEC_TIME   = 0
    USER_MODE       = 0
    USERS           =

注意

为避免记录 SQL log 对服务器产生较大的影响，可以配置异步日志刷新（参数 ASYNC_FLUSH 设置为1）。

如果对 sqllog.ini 进行了修改，可通过调用以下函数即时生效，无需重启数据库。

SP_REFRESH_SVR_LOG_CONFIG();

sqllog.ini 文件配置成功后可在 dmsql 指定目录下生成 dmsql 开头的 log 日志文件。日志内容如下所示：

部分参数详解如下表所示：

参数	默认值	说明	属性
BUF_TOTAL_SIZE	10240	是 SQL 日志 BUFFER 占用空间的上限，单位为 KB，取值范围（1024~1024000）	动态，系统级
BUF_SIZE	1024	一块 SQL 日志 BUFFER 的空间大小，单位为 KB，取值范围（50~409600）。	动态，系统级
FILE_PATH	../log	SQL 日志文件所在的文件夹路径。	动态，系统级
SWITCH_MODE	2	表示 SQL 日志文件切换的模式:0：不切换；1：按文件中记录数量切换；2：按文件大小切换；3：按时间间隔切换	手动
SWITCH_LIMIT	128	同切换模式 SWITCH_MODE 下，意义不同： 1、按数量切换时，一个日志文件中的 SQL 记录条数达到多少条之后系统会自动将日志切换到另一个文件中。一个日志文件中的 SQL 记录条数达到多少条之后系统会自动将日志切换到另一个文件中。有效值范围（1000~ 10000000）； 2、按文件大小切换时，一个日志文件达到该大小后，系统自动将日志切换到另一个文件中，单位为 M。有效值范围（1~ 2000）； 3、按时间间隔切换时，每个指定的时间间隔，按文件新建时间进行文件切换，单位为分钟。有效值范围（1~ 30000）。	动态，系统级
ASYNC_FLUSH	1	是否打开异步 SQL 日志功能。0：表示关闭；1：表示打开。	动态，系统级
FILE_NUM	5	总共记录多少个日志文件，当日志文件达到这个设定值以后，再生成新的文件时，会删除最早的那个日志文件，日志文件的命令格式为 dmsql_实例名_日期_时间.log。当这个参数配置成 0 时，只会生成两个日志相互切换着记录。有效值范围（0~1024）。	动态，系统级

实例：

SQL> SP_SET_PARA_VALUE(1,'SVR_LOG',1);
DMSQL 过程已成功完成
已用时间: 10.136(毫秒). 执行号:600.
SQL> quit
[dmdba@DCA ~ 2023-08-23 22:06:46]
$ cd $DM_HOME/log
[dmdba@DCA /dm8/log 2023-08-23 22:06:52]
$ mkdir tracesql
[dmdba@DCA /dm8/data/PROD 2023-08-23 22:07:33]
$ vi sqllog.ini 
[dmdba@DCA /dm8/data/PROD 2023-08-23 22:24:31]
$ cat sqllog.ini 
BUF_TOTAL_SIZE          = 10240         #SQLs Log Buffer Total Size(K)(1024~1024000)
    BUF_SIZE                = 1024          #SQLs Log Buffer Size(K)(50~409600)
    BUF_KEEP_CNT            = 6             #SQLs Log buffer keeped count(1~100)

    [SLOG_ALL]
    FILE_PATH    = ../log/tracesql
    PART_STOR    = 0
    SWITCH_MODE  = 2
    SWITCH_LIMIT   = 512
    ASYNC_FLUSH   = 1
    FILE_NUM = 20
    ITEMS    = 0 
    SQL_TRACE_MASK  = 1 
    MIN_EXEC_TIME = 0 
    USER_MODE   = 0 
    USERS =
    
    [SLOG_ERROR]
    SQL_TRACE_MASK = 23
    FILE_PATH      = ../log/tracesql
    
    [SLOG_DDL]
    SQL_TRACE_MASK = 3
    
    [SLOG_LONG_SQL]
    SQL_TRACE_MASK = 25
    MIN_EXEC_TIME = 60000 

[dmdba@DCA /dm8/data/PROD 2023-08-23 22:09:02]

SQL> SP_REFRESH_SVR_LOG_CONFIG();
DMSQL 过程已成功完成
--制造慢sql
SQL> begin
2   sleep(10);
3   insert into T1 values(3,'c');
4   end;
5   /
[dmdba@DCA /dm8/data/PROD 2023-08-23 22:09:20]
$ cd $DM_HOME
[dmdba@DCA /dm8 2023-08-23 22:09:36]
$ cd log/tracesql/
[dmdba@DCA /dm8/log/tracesql 2023-08-23 22:09:42]
$ ll
总用量 4
-rw-r--r-- 1 dmdba dinstall 829  8月 23 22:09 dmsql_TEST_20230823_220916.log
[dmdba@DCA /dm8/log/tracesql 2023-08-23 22:09:43]

日志分析

[dmdba@DCA /dm8/log/tracesql 2023-08-23 22:57:19]
$ tail -f dmsql_TEST_20230823_220916.log 
2023-08-23 22:56:18.911 (EP[0] sess:0x7f98e0026868 thrd:2956 user:SYSDBA trxid:16130 stmt:NULL appname:disql) trx[16130] alloc pseg page[0, 383], page_lsn[48262], n_pages[1]
2023-08-23 22:56:18.911 (EP[0] sess:0x7f98e0026868 thrd:2956 user:SYSDBA trxid:16130 stmt:0x7f98e004a868 appname:disql ip:::1) [INS] insert into T1 values(1,'a'); EXECTIME: 0(ms) ROWCOUNT: 1(rows).
2023-08-23 22:56:58.597 (EP[0] sess:0x7f98e0026868 thrd:2956 user:SYSDBA trxid:16130 stmt:0x7f98e004a868 appname:disql ip:::1) [ORA]: begin
sleep(10);
insert into T1 values(2,'b');
end;
2023-08-23 22:57:09.292 (EP[0] sess:0x7f98e0026868 thrd:2956 user:SYSDBA trxid:16130 stmt:0x7f98e004a868 appname:disql ip:::1) [CAL] begin
sleep(10);
insert into T1 values(2,'b');
end; EXECTIME: 10695(ms).
2023-08-23 22:57:59.958 (EP[0] sess:0x7f98e0026868 thrd:2956 user:SYSDBA trxid:16130 stmt:NULL appname:disql) FREE SESSION
2023-08-23 22:57:59.959 (EP[0] sess:0x7f98e0026868 thrd:2956 user:SYSDBA trxid:16130 stmt:NULL appname:disql) TRX: ROLLBACK
2023-08-23 22:57:59.958 (EP[0] sess:0x7f98e0026868 thrd:2956 user:SYSDBA trxid:16130 stmt:NULL appname:disql) trx[16130]: pseg_reset_last_page free pseg page (0, 383)
2023-08-23 22:58:26.273 (EP[0] sess:0x7f9870034598 thrd:-1 user:NULL trxid:NULL stmt:NULL appname:) ALLOC SESSION
2023-08-23 22:58:26.287 (EP[0] sess:0x7f9870034598 thrd:3067 user:NULL trxid:0 stmt:NULL appname:) STARTUP
2023-08-23 22:58:26.288 (EP[0] sess:0x7f9870034598 thrd:3067 user:SYSDBA trxid:0 stmt:NULL appname:disql) LOGIN
2023-08-23 22:58:26.288 (EP[0] sess:0x7f9870034598 thrd:3067 user:SYSDBA trxid:0 stmt:NULL appname:disql) ALLOC STMT
2023-08-23 22:58:39.135 (EP[0] sess:0x7f9870034598 thrd:3067 user:SYSDBA trxid:0 stmt:NULL appname:disql) FREE SESSION
2023-08-23 22:58:40.453 (EP[0] sess:0x7f98e0026868 thrd:-1 user:NULL trxid:NULL stmt:NULL appname:) ALLOC SESSION
2023-08-23 22:58:40.466 (EP[0] sess:0x7f98e0026868 thrd:3070 user:NULL trxid:0 stmt:NULL appname:) STARTUP
2023-08-23 22:58:40.467 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:0 stmt:NULL appname:disql) LOGIN
2023-08-23 22:58:40.467 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:0 stmt:NULL appname:disql) ALLOC STMT
2023-08-23 22:59:14.540 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:0 stmt:0x7f98e004a868 appname:disql ip:::1) [ORA]: begin
sleep(10);
insert into T1 values(3,'c');
end;
2023-08-23 22:59:14.540 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:16131 stmt:NULL appname:disql) TRX: START
2023-08-23 22:59:14.541 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:16131 stmt:0x7f98e004a868 appname:disql ip:::1) [CAL] begin
sleep(10);
insert into T1 values(3,'c');
end;
2023-08-23 22:59:25.510 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:16131 stmt:NULL appname:disql) trx[16131] alloc pseg page[0, 399], page_lsn[48352], n_pages[1]
2023-08-23 22:59:25.510 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:16131 stmt:0x7f98e004a868 appname:disql ip:::1) [CAL] begin
sleep(10);
insert into T1 values(3,'c');
end; EXECTIME: 10968(ms).
2023-08-23 22:59:36.124 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:16131 stmt:0x7f98e004a868 appname:disql ip:::1) [ORA]: commit;
2023-08-23 22:59:36.124 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:16131 stmt:0x7f98e004a868 appname:disql ip:::1) [DML] commit;
2023-08-23 22:59:36.124 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:16131 stmt:NULL appname:disql) TRX: COMMIT
2023-08-23 22:59:36.124 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:16131 stmt:NULL appname:disql) trx[16131]: pseg_page_free_for_insert_only_trx free pseg page (0, 399), page_lsn = 48360
2023-08-23 22:59:36.125 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:0 stmt:NULL appname:disql) TRX: COMMIT LSN[48359]
2023-08-23 22:59:36.125 (EP[0] sess:0x7f98e0026868 thrd:3070 user:SYSDBA trxid:0 stmt:0x7f98e004a868 appname:disql ip:::1) [DML] commit; EXECTIME: 0(ms).
^C

#通过grep筛选出慢sql
[dmdba@DCA /dm8/log/tracesql 2023-08-23 22:59:49]
$ cat dmsql_TEST_20230823_220916.log |grep  -2 "[1-9][0-9][0-9][0-9][0-9](ms)"
end; EXECTIME: 10904(ms).
end; EXECTIME: 10695(ms).
end; EXECTIME: 10968(ms).

如需进行更为系统全面的分析，可使用DMLOG分析工具对SQL进行分类汇总
达梦数据库学习12：达梦 DM SQL 日志分析工具 DMLOG 使用说明

达梦社区技术https://eco.dameng.com

达梦数据库学习09：开启SQL跟踪日志

开启SQL跟踪日志

作者