SQL跟踪日志文件

文档目的

1、了解SQL跟踪日志文件的基本概念。
2、学习SQL跟踪日志的使用方法。

适用人员

从事达梦数据库管理系统的运维、开发、测试人员

1、SQL跟踪日志文件的概念

达梦数据库管理系统使用了磁盘上大量的物理存储结构来保存和管理用户的数据，这些文件统称为数据库文件。SQL跟踪日志文件为其中之一，主要用于存放数据库管理系统中执行的SQL语句。
生产环境中，分析SQL跟踪日志文件是我们处理问题的一个常用技术手段，SQL跟踪日志的内容主要包含了以下三类：
1、 系统中各个会话执行的 SQL 语句。
2、 参数信息。
3、 错误信息。
通过SQL日志文件我们可以对系统的运行状态有一个分析，达到以下目的：
1、 分析系统或SQL的错误。
2、 分析性能问题。比如：挑出系统现在执行速度较慢的SQL语句，进而对其进行优化。
3、 侧面反应数据库系统的规模。
4、 数据库重演。
5、 应用系统测试。
SQL跟踪日志使用时的注意点：
打开SQL日志会对系统的性能会有较大影响，常见使用场景为查错和调优。达梦数据库管理系统安装完毕后，默认是关闭SQL跟踪日志。大多数情况下，生产环境不需要开启SQL跟踪日志，需要根据客观情况进行评估，评估的主要参考点为应用系统的稳定性。
若需要跟踪日志但对日志的实时性没有严格的要求，又希望系统有较高的效率，可以设置配置文件sqllog.ini中的参数SQL_TRACE_MASK和 MIN_EXEC_TIME 去记录关注的相关记录，这样可以减少日志总量，减轻相应负担。也可以设置配置文件sqllog.ini中的参数 ASYNC_FLUSH 打开SQL跟踪日志的异步刷盘功能，以提高系统性能。

2、SQL跟踪日志的使用方法

SQL日志文件是一个纯文本文件。根据配置文件sqllog.ini中的参数PART_STOR取值不同而命名格式不同。
PART_STOR为0时，SQL跟踪日志以dmsql_实例名_日期_时间的格式命名。
PART_STOR为1时，SQL跟踪日志以dmsql_实例名_用户名_日期_时间的格式命名。
SQL跟踪日志缺省生成在达梦安装目录的log子目录下面，该生成目录可以调整，管理员根据实际情况调整sqllog.ini中的参数FILE_PATH设置即可。
调整配置文件dm.ini中的SVR_LOG参数后就可以打开或关闭SQL跟踪日志。
关于参数SVR_LOG的介绍如下：
SVR_LOG为动态系统级参数，取值范围为0，1，2，3。
0：不开启SQL跟踪日志。
1：打开，使用sqllog.ini中的配置记录日志。
2：打开，按文件中记录数量切换日志文件，日志记录为详细模式。
3：打开，不切换日志文件，日志记录为简单模式，只记录时间和原始语句。
调整SVR_LOG值的常见方式有两种。一是静态修改dm.ini中该参数的值。二是调用存储过程SP_SET_PARA_VALUE动态修改该参数的值。
如：SP_SET_PARA_VALUE(1,’SVR_LOG’,2);

2.1 SVR_LOG为2

实际的生产环境中，如果SVR_LOG配置为2，我们还需要设置一些其他参数，具体内容如下：
设置SQL跟踪日志中记录的内容，可参考2.2中该参数解释：
SP_SET_PARA_STRING_VALUE(1,’SQL_TRACE_MASK’,’2:3:29’);
设置SQL跟踪日志记录的个数：
SP_SET_PARA_VALUE(1,’SVR_LOG_FILE_NUM’,30);
设置SQL跟踪日志每个文件中记录SQL的行数。
SP_SET_PARA_VALUE(1,’SVR_LOG_SWITCH_COUNT’,100000);
注：不建议初学者使用该方式配置SQL跟踪日志。

2.2 SVR_LOG为1

生产环境中，建议设置SVR_LOG为1，结合配置文件sqllog.ini来配置SQL跟踪日志。配置文件sqllog.ini中包含多个参数，均为SQL跟踪日志服务。
在数据库服务运行过程中，如果修改了sqllog.ini，需要通过调用存储过程SP_REFRESH_SVR_LOG_CONFIG()使其生效。
Sqllog.ini中常用的参数以及解释如下：
1、SQL_TRACE_MASK。
该参数可以设置日志中记录哪些类型的内容。需要注意该参数的值是字符串，而非常见的整型。格式是x: x: x。
1：全部记录（22-30），2：全部DML语句。3：全部DDL语句。4：update类型语句。5：delete类型语句。6：insert类型语句。7：select类型语句。8：commit类型语句。9：rollback类型语句。10：call类型语句。11：backup类型语句。12：restore类型语句。13：创建对象操作（create ddl）。14：修改对象操作（alter ddl）。15：删除对象操作（drop ddl）。16：授权操作（grant ddl）17：回收操作（revoke ddl）。22：记录绑定参数。23：记录存在错误的语句。24：记录执行语句。25：打印执行语句和语句执行的时间，以及语句影响的行数。26：记录执行语句的时间和语句影响的行数。27：记录原始语句。28：记录参数信息，包含参数的序号、数据类型和值。29：记录事务相关事件，包含所类型、锁等待时间等。30：记录xa事务。
举例：如果需要记录原始语句、创建、修改对象的操作，则SQL_TRACE_MASK设置为13:14:27
2、FILE_NUM
该参数表示总共记录多少个日志文件，当日志文件达到这个设定值以后，再生成新的文件时，会删除最早的那个日志文件，日志文件的命令格式为 dmsql_实例名_日期_时间.log。当这个参数配置成 0 时，只会生成两个日志相互切换着记录。有效值范围（0~1024）。
举例：FILE_NUM=0，实例名为dxc时，根据当时的日期时间，生成的日志为：dmsql_dxc_20230816_163101.log、dmsql_dxc_20230816_163102.log。
3、SWITCH_MODE
该参数表示的是SQL跟踪日志的切换模式，不同的值对应不用模式。共有四种类型。0：不切换。1：按照文件中记录数量切换。2：按照文件大小切换。3：按时间间隔切换。
4、SWITCH_LIMIT
该参数需要结合SWITCH_MODE来使用，在不同切换模式的SWITCH_MODE 下，SWITCH_LIMIT所代表的意义不同。详细说明如下：
1、SWITCH_MODE=1,即按文件中记录数量切换。一个日志文件中的 SQL 记录条数达到多少条之后系统会自动将日志切换到另一个文件中。此时取值范围为1000-10000000。
2、SWITCH_MODE=2，即按日志文件大小切换。一个日志文件达到该大小后，系统自动将日志切换到另一个文件中，单位为 M。此时取值范围为1-2000。
3、SWITCH_MODE=3，即按时间间隔切换。每个指定的时间间隔，按文件新建时间进行文件切换，单位为分钟。此时取值范围为1-30000。
5、ASYNC_FLUSH
该参数表示是否开启异步日志功能。0：不开启。1：开启。
6、MIN_EXEC_TIME
该参数表示记录多少执行时间之上的语句。若SQL语句的执行时间小于该参数设置的时间，则不被记录在文件中。单位为毫秒，取值范围为0- 4294967294。
7、FILE_PATH
该参数表示日志文件存放的位置。默认值为安装目录下的log目录。
8、BUF_TOTAL_SIZE
该参数表示SQL日志BUFFER占用空间的上限，单位为KB，取值范围为1024-1024000。
9、BUF_SIZE
该参数表示一块SQL日志BUFFER的空间大小，单位为 KB，取值范围为50-409600。
10、BUF_KEEP_CNT
该参数表示系统保留的SQL日志缓存的个数，取值范围为1-100。
11、PART_STOR
该参数表示SQL日志分区存储的划分条件。0：表示不划分。1：根据不同用户分布存储。
12、USER_MODE
该参数表示SQL日志按用户过滤时的过滤模式。0：关闭用户过滤 1：白名单模式，只记录列出的用户操作的SQL日志 2：黑名单模式，列出的用户不记录 SQL 日志。
13、USERS
该参数结合USER_MODE参数使用，表示指定的用户列表。格式为：用户名：用户名：用户名

3、SQL跟踪日志使用实操

3.1确认是否开启SQL跟踪日志

结论：文件和内存中SVR_LOG均为0，系统未开启SQL跟踪日志。同时获取了SVR_LOG_NAME为SLOG_ALL。

3.2开启SQL跟踪日志

结论：通过调用参数设置存储过程，已开启SQL跟踪日志功能。

3.3设置sqllog.ini

结论：sqllog.ini配置生效。

3.4就sql跟踪日志的内容做简单分析

分析前提：
设置SQL_TRACE_MASK为1，代表SQL跟踪日志包含绑定参数、错误语句、执行的语句、执行语句以及时间等参数值为22到30对应的内容。
首先简单看一下跟踪日志中是什么内容，分别建立两个会话执行相同的SQL语句。SQL跟踪日志中得到下图的结果。

从左到右的项目依次是执行时间、服务器站点号、操作的sess地址、操作的用户、对应的事务id、语句的地址、操作客户端名称、操作客户端ip、操作类型、操作内容、执行结果。

3.4.1 创建会话对应的日志内容

在终端使用disql登录服务端。在跟踪日志中对应四条记录。如下图：

对于这四条记录，我们从上向下依次标记为1-4。
记录1：服务端对于登录服务器的请求分配session，这时我们可以看到sess地址已经存在了，但是线程号、用户信息、事务id、语句地址等均未显示。同时线程号为-1，此时还未分配线程。
记录2：有了会话地址后，开始分配线程，给出初始事务号。此时线程号已经具备，同时事务号为0。
记录3：用户登录阶段，可以看到客户端名称、用户信息已经记录。
记录4：分配语句地址阶段，但并没有实质性的语句执行，所以stmt的值还为null。

3.4.2 查询语句对应的内容

在3.4.1中建立的会话上执行查询语句select * from t3。

跟踪日志中新增四条记录。同样，从上向下依次标记为1-4。
记录1：服务端接收原始语句阶段，ORA标识代表该条记录为原始语句记录。该阶段因为已经有了语句，所以分配到了语句地址。同时，客户端的IP地址也有所展示。此时事务id为0，代表事务外的一些记录。如果没有事务终止的标记，则后续多条语句的事务id保持同一个值。直到事务终止的标记出现。
记录2：事务开始标志。
记录3：执行语句的内容，对应SQL_TRACE_MASK参数值24。同时，标识SEL代表该语句为查询语句。同时INS、DEL、UPD、CAL分别为增、删、改、调用的标识，同时其他的操作也会有各自的标识。
记录4：记录执行语句的内容、时间、影响行数。注意到记录3和记录4都有记录了执行语句，原因为为SQL_TRACE_MASK为1时包含了值为23、24的内容。
注意：生产环境中，语句执行频率高，SQL跟踪日志中的内容多，分析时，可以通过sess、thrd、trxid、stmt四个项目锁定是否是一条SQL语句的记录。如下图：

上图表示的是同一会话，执行两条相同的SQL语句select * from t3。
若同一会话中执行不同的语句，一般sess地址、线程号不会发生变化。在3.4.3中可以进行验证。不同会话执行相同语句可以通过区分sess地址、线程号、语句地址、事务号进行会话区分。

3.4.3 增、改、删语句对应的内容

按照顺序对表进行插入、修改、删除操作后，SQL跟踪日志中出现下图中的内容。

结论：
1、同一会话中，出现事务结束标志时，会出现事务id为0的阶段。同时该会话中如果有下条语句或需要开始下个事务的情况下，事务id发生变化。
2、同一会话中，执行不同语句时，sess地址、线程号会发生变化。
接下来分析一下增、改、删分别对应的记录，这三类操作对应的日志内容大体相近。
阶段1：接收原始语句阶段。
阶段2：执行语句内容。INS、UPD、DEL、DML表示插入、修改、删除、事务结束操作。
阶段3：回滚段分配、逻辑日志号分配阶段。
阶段4：记录插入语句的执行时间、影响行数、
事务结束阶段：记录事务结束标志commit经历的过程，分别是收到原始语句、记录语句内容、事务内容、记录在线日志、记录逻辑日志号、记录执行时间。最后时刻事务结束，语句地址被收回。

3.4.4 错误语句对应的内容

我们测试的前提是SQL_TRACE_MASK为1的情况，包含了记录错误的语句，在这种情况下，执行一条错误语句，看看日志中的内容。

从上图可以发现，不同错误的语句可以进入的阶段不同，这是根据SQL语句的错误类型决定的。
在生产环境中，如果频繁出现错误语句，会对数据库造成冲击。一方面是资源的无谓消耗，另一方面是数据库性能的影响。
针对错误语句的情况，解决问题需要找到问题的源头，这时SQL跟踪日志中的IP、客户端名称可以起到作用。但需要注意的是客户端名称不一定存在，需要应用程序做对应的配置才可以。
抓取SQL跟踪日志中的错误记录可以通过 grep的方式进行，如：

3.4.5慢语句对应的内容

在生产环境中，找到运行效率差的SQL是一个周期性工作。在没有外部工具协助的情况下，利用动态性能视图和分析SQL跟踪日志是两种常见的方式。动态性能视图由于具备即时性的特点，适合在单一时间点开展分析工作，对于全面分析的需求来说，匹配度较差。
因为SQL_TRACE_MASK参数的值为1，包含了记录语句的执行时间。可以通过grep的方式从SQL跟踪日志中找到符合一定执行条件的语句，方便后续开展优化工作。
比如找到执行时间超过1秒的语句可以使用下图中的方法：

找到执行时间超过10秒的语句可以使用下图中的方法：

如果筛选出的慢SQL较多，可以定向到文件中方便查看。如下图：

除了grep的方式以外，出于SQL日志量过大不易分析的考虑，达梦的SQL跟踪日志可以在sqllog.ini中设置MIN_EXEC_TIME参数记录对应内容。
如：需要记录执行时间超过1秒的SQL语句可以按照以下步骤进行：
1、 编辑sqllog.ini，调整MIN_EXEC_TIME=1000。
2、 调用sp_refresh_svr_log()，使sqllog.ini的配置生效。

3.4.6 常见情况分析

在上面的例子中我们可以发现，在SQL_TRACE_MASK为1的情况下，一条SQL语句执行的开始和结束会有ORA和执行语句两类记录。
如果一条语句没有执行完是不是只有一类记录呢？我们试一个阻塞的案例。
A会话执行：update t3 set id=1 不提交。
B会话执行：delete from t3;
SQL跟踪日志的内容如下：

A会话的SQL日志内容包含了更新类SQL的正常阶段，由于A会话的中的事务对B会话中的事务造成了阻塞，对于数据库来说，只能接收到B会话中的原始语句，并且证明事务已经开始，但由于阻塞的原因B会话中的事务无法向下进行。也证明了B会话事务对应的SQL没有执行完毕。
生产环境中经常遇到阻塞的问题，这时可以通过记录中的客户端名称和客户端IP，即APPNAME、IP项目反推出是哪个客体造成的阻塞。同时请注意，这里指的是历史阻塞问题的排查，对于实时阻塞，分析系统动态视图是优选的排查手段。
比如上述例子，delete语句的执行时间可以侧面反映问题，那例子中delete语句的执行时间究竟是多久呢？我们对A、B会话的事务均附上事务终止标记，看看SQL跟踪日志中的内容。

可以发现，delete语句的执行时间来到了521457ms，显然这不是一个正常的耗时。排除该语句本身慢的情况下，非正常耗时的原因有可能是被阻塞造成的。
另外，生产环境如果使用较旧的数据库版本，RDC功能不够健壮的情况下，SQL跟踪日志也可以作为一个角度去分析数据库进程内存转储的原因。
假设数据库进程内存转储的原因是由于SQL触发BUG导致，则该SQL应该是无法执行完毕的，在上述内容中，未执行完毕的SQL只有原始语句的记录，而无执行时间和影响行数的记录。
由数据库进程内存转储的时刻向远进行SQL跟踪日志分析，找到未执行完毕的SQL或SQL群。另外，本着稳定运行的环境中，80%的问题都是由于人为操作造成的，也可以优先对SQL跟踪日志进行客户端名称过滤，如过滤‘DTS’、‘MANAGER’等人为的数据库交互工具，可以缩小范围，提升效率。