库表变更、加锁没审计？PolarDB MySQL 新功能 SQL Detail

Author: 勉仁

PolarDB MySQL最新引入了库表变更、加锁操作的详细审计功能SQL Detail。

背景

在数据库使用过程中，库表的变更，例如删除、创建、增加列和索引等都是非常敏感的。对库表的加锁也会影响整个业务的使用。对应操作的审计日志对于数据库的运维人员就非常重要，需要能够知道操作的用户账号、客户端IP、操作时间、完成时间等详细信息。
以往的审计日志基本都是全局开关，对所有SQL语句都做审计。这样记录的SQL全面，但成本也会很高。同时很多时候需要额外的组件存储信息，维护和信息安全控制的成本也高。而对业务会造成重大影响的很多由库表操作引发，这部分的审计很多时候又不可或缺。
因此PolarDB MySQL内核开发了能够对库表变更、加锁操作的详细审计功能SQL Detail。同时该功能的审计记录存储在用户数据库实例中，用户可以配置审计记录的保存时间，审计记录过期后会自动删除。该功能审计的成本极低，以每条审计记录存储1KB，每天库表变更1024次，审计保存30天算，仅需要30M的存储空间。该功能在相关语句开始执行时就会捕获到，记录到相关系统表中，并会在执行结束时进一步更新相关状态。
下面会对该功能的使用做详细的介绍。

功能介绍

功能开关与相关变量

  • 功能开关

用户可以通过全局参数awr_sqldetail_enabled来开启SQL Detail功能（在阿里云PolarDB实例控制台上搜索参数loose_awr_sqldetail_enabled）。该参数的配置无需重启实例。

  • 审计SQL类型子开关

通过全局参数awr_sqldetail_switch可以控制库表变更或者库表加锁释放锁是否记录。作为一个switch变量，当前有两个子开关，ddl（是否记录DDL变更）和lock_db_table（是否记录库表加锁释放锁）。ddl和lock_db_table默认都是开启的，即默认值为’ddl=on,lock_db_table=on’。
DDL包括的语句类型如下：
create_table、alter_table、drop_table、rename_table、create_index、drop_index、create_db、drop_db、alter_db、create_view、drop_view、create_trigger、drop_trigger、create_event、alter_event、create_function、create_procedure、drop_procedure、drop_function、alter_procedure、alter_function、truncate、alter_tablespace、repair、optimize、install_plugin、uninstall_plugin、install_component、uninstall_component、alter_instance、import、create_spatial_reference_system、drop_spatial_reference_system。
LOCK_DB_TABLE包括的语句类型如下：
lock_tables、unlock_tables。

  • 审计保存时间定义

通过全局参数awr_sqldetail_retention可以配置SQL Detail审计记录的保存时间，其单位是秒。当审计记录保存超过该时候后，内核会通过后台线程自动淘汰该记录。该参数默认值是：2592000（30天）。

审计记录表

SQL Detail功能的记录存储在一张新的PolarDB系统表sys.hist_sqldetail中。该表的定义如下：

  1. CREATE TABLE `hist_sqldetail` (
  2.   `Id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  3.   `State` varchar(16) COLLATE utf8mb4_bin DEFAULT NULL,
  4.   `Thread_id` bigint(20) unsigned DEFAULT NULL,
  5.   `Host` varchar(60) COLLATE utf8mb4_bin NOT NULL DEFAULT '',
  6.   `User` varchar(32) COLLATE utf8mb4_bin NOT NULL DEFAULT '',
  7.   `Client_ip` varchar(60) COLLATE utf8mb4_bin DEFAULT NULL,
  8.   `Db` varchar(64) COLLATE utf8mb4_bin DEFAULT NULL,
  9.   `Sql_text` mediumtext COLLATE utf8mb4_bin NOT NULL,
  10.   `Server_command` varchar(32) COLLATE utf8mb4_bin DEFAULT NULL,
  11.   `Sql_command` varchar(64) COLLATE utf8mb4_bin DEFAULT NULL,
  12.   `Start_time` timestamp(6) NULL DEFAULT NULL,
  13.   `Exec_time` bigint(20) DEFAULT NULL,
  14.   `Wait_time` bigint(20) DEFAULT NULL,
  15.   `Error_code` int(11) DEFAULT NULL,
  16.   `Rows_sent` bigint(20) DEFAULT NULL,
  17.   `Rows_examined` bigint(20) DEFAULT NULL,
  18.   `Rows_affected` bigint(20) DEFAULT NULL,
  19.   `Logical_read` bigint(20) DEFAULT NULL,
  20.   `Phy_sync_read` bigint(20) DEFAULT NULL,
  21.   `Phy_async_read` bigint(20) DEFAULT NULL,
  22.   `Process_info` text COLLATE utf8mb4_bin,
  23.   `Extra` text COLLATE utf8mb4_bin,
  24.   `Create_time` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6),
  25.   `Update_time` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
  26.   PRIMARY KEY (`Id`),
  27.   KEY `i_start_time` (`Start_time`),
  28.   KEY `i_update_time` (`Update_time`)
  29. ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;

该表各个字段表示的意义如下。可以看到该表会详细的记录库表变更、锁操作。

字段描述
Idsys.hist_sqldetail表的自增ID。
State该操作被记录时所处的状态。
Thread_id执行该SQL会话的线程ID
Host执行该SQL会话的用户Host
User执行该SQL会话的用户名
Client_ip执行该SQL会话的客户端IP
Db该SQL执行时所在的DB
Sql_text具体SQL
Server_command执行该SQL的server命令
Sql_command命令类型
Start_time开始执行的时间
Exec_time执行时间，单位微秒
Wait_time等待时间，单位微秒
Error_code错误码
Rows_sent返回的数据行
Rows_examined扫描的数据行
Rows_affected影响的行数
Logical_read逻辑读次数
Phy_sync_read物理同步读次数
Phy_async_read物理异步读次数
Process_info扩展字段，处理过程信息。
Extra扩展字段，其他信息。
Create_time记录写入时间
Update_time记录更新时间

使用示例

配置awr_sqldetail_enabled为ON后，SQL Detail功能就会自动记录DDL，LOCK DB\TABLE操作，并自动管理这些记录。例如配置awr_sqldetail_enabled为ON后，我们在test库下做如下操作：

  1. mysql> create table t(c1 int);
  2. Query OK, 0 rows affected (0.02 sec)
  4. mysql> create table t(c1 int);
  5. ERROR 1050 (42S01): Table 't' already exists
  7. mysql>  alter table t add column c2 int;
  8. Query OK, 0 rows affected (0.02 sec)
  9. Records: 0  Duplicates: 0  Warnings: 0
  11. mysql> lock tables t read;
  12. Query OK, 0 rows affected (0.00 sec)
  14. mysql> unlock tables;
  15. Query OK, 0 rows affected (0.00 sec)
  17. mysql> insert into t values(1, 2);
  18. Query OK, 1 row affected (0.00 sec)

执行完后，我们可以通过sys.hist_sqldetail查看上述操作中DDL和LOCK DB\TABLE的信息，而DML语句不会被记录。

  1. mysql> select * from sys.hist_sqldetail\G
  2. *************************** 1. row ***************************
  3.             Id: 1
  4.          State: FINISH
  5.      Thread_id: 18
  6.           Host: localhost
  7.           User: root
  8.      Client_ip: 127.0.0.1
  9.             Db: test
  10.       Sql_text: create table t(c1 int)
  11. Server_command: Query
  12.    Sql_command: create_table
  13.     Start_time: 2023-01-13 16:18:21.840435
  14.      Exec_time: 17390
  15.      Wait_time: 318
  16.     Error_code: 0
  17.      Rows_sent: 0
  18.  Rows_examined: 0
  19.  Rows_affected: 0
  20.   Logical_read: 420
  21.  Phy_sync_read: 0
  22. Phy_async_read: 0
  23.   Process_info: NULL
  24.          Extra: NULL
  25.    Create_time: 2023-01-13 16:18:22.391407
  26.    Update_time: 2023-01-13 16:18:22.391407
  27. *************************** 2. row ***************************
  28.             Id: 2
  29.          State: FINISH
  30.      Thread_id: 18
  31.           Host: localhost
  32.           User: root
  33.      Client_ip: 127.0.0.1
  34.             Db: test
  35.       Sql_text: create table t(c1 int)
  36. Server_command: Query
  37.    Sql_command: create_table
  38.     Start_time: 2023-01-13 16:18:22.416321
  39.      Exec_time: 822
  40.      Wait_time: 229
  41.     Error_code: 1050
  42.      Rows_sent: 0
  43.  Rows_examined: 0
  44.  Rows_affected: 0
  45.   Logical_read: 55
  46.  Phy_sync_read: 0
  47. Phy_async_read: 0
  48.   Process_info: NULL
  49.          Extra: NULL
  50.    Create_time: 2023-01-13 16:18:23.393071
  51.    Update_time: 2023-01-13 16:18:23.393071
  52. *************************** 3. row ***************************
  53.             Id: 3
  54.          State: FINISH
  55.      Thread_id: 18
  56.           Host: localhost
  57.           User: root
  58.      Client_ip: 127.0.0.1
  59.             Db: test
  60.       Sql_text: alter table t add column c2 int
  61. Server_command: Query
  62.    Sql_command: alter_table
  63.     Start_time: 2023-01-13 16:18:34.123947
  64.      Exec_time: 16420
  65.      Wait_time: 245
  66.     Error_code: 0
  67.      Rows_sent: 0
  68.  Rows_examined: 0
  69.  Rows_affected: 0
  70.   Logical_read: 778
  71.  Phy_sync_read: 0
  72. Phy_async_read: 0
  73.   Process_info: NULL
  74.          Extra: NULL
  75.    Create_time: 2023-01-13 16:18:34.394067
  76.    Update_time: 2023-01-13 16:18:34.394067
  77. *************************** 4. row ***************************
  78.             Id: 4
  79.          State: FINISH
  80.      Thread_id: 18
  81.           Host: localhost
  82.           User: root
  83.      Client_ip: 127.0.0.1
  84.             Db: test
  85.       Sql_text: lock tables t read
  86. Server_command: Query
  87.    Sql_command: lock_tables
  88.     Start_time: 2023-01-13 16:19:49.891559
  89.      Exec_time: 145
  90.      Wait_time: 129
  91.     Error_code: 0
  92.      Rows_sent: 0
  93.  Rows_examined: 0
  94.  Rows_affected: 0
  95.   Logical_read: 0
  96.  Phy_sync_read: 0
  97. Phy_async_read: 0
  98.   Process_info: NULL
  99.          Extra: NULL
  100.    Create_time: 2023-01-13 16:19:50.399585
  101.    Update_time: 2023-01-13 16:19:50.399585
  102. *************************** 5. row ***************************
  103.             Id: 5
  104.          State: FINISH
  105.      Thread_id: 18
  106.           Host: localhost
  107.           User: root
  108.      Client_ip: 127.0.0.1
  109.             Db: test
  110.       Sql_text: unlock tables
  111. Server_command: Query
  112.    Sql_command: unlock_tables
  113.     Start_time: 2023-01-13 16:19:56.924648
  114.      Exec_time: 98
  115.      Wait_time: 0
  116.     Error_code: 0
  117.      Rows_sent: 0
  118.  Rows_examined: 0
  119.  Rows_affected: 0
  120.   Logical_read: 0
  121.  Phy_sync_read: 0
  122. Phy_async_read: 0
  123.   Process_info: NULL
  124.          Extra: NULL
  125.    Create_time: 2023-01-13 16:19:57.400294
  126.    Update_time: 2023-01-13 16:19:57.400294

SQL Detail在DDL开始执行时就会被捕获记录到系统表中。我们做如下操作

  1. create table t1 as select c1, sleep(10) from t;

在上述DDL执行时，我们用另一个session查看sys.hist_sqldetail，可以看到处理PROCESS状态的审计记录。当该语句执行完，相关状态会被自动更新。

  1. select * from sys.hist_sqldetail where state='PROCESS'\G
  2. *************************** 1. row ***************************
  3.             Id: xx
  4.          State: PROCESS
  5.      Thread_id: 36
  6.           Host: localhost
  7.           User: root
  8.      Client_ip: 127.0.0.1
  9.             Db: test
  10.       Sql_text: create table t1 as select c1, sleep(10) from t
  11. Server_command: Query
  12.    Sql_command: create_table
  13.     Start_time: 2023-01-19 17:34:42.293752
  14.      Exec_time: 0
  15.      Wait_time: 0
  16.     Error_code: 0
  17.      Rows_sent: 0
  18.  Rows_examined: 0
  19.  Rows_affected: 0
  20.   Logical_read: 0
  21.  Phy_sync_read: 0
  22. Phy_async_read: 0
  23.   Process_info: NULL
  24.          Extra: NULL
  25.    Create_time: 2023-01-19 17:34:42.641854
  26.    Update_time: 2023-01-19 17:34:42.641854

总结

PolarDB MySQL新功能SQL Detail可以详细记录用户的各类库表变更操作，并且可以自动淘汰过期记录，帮助用户以极低的成本对库表操作做审计工作。

原文：http://mysql.taobao.org/monthly/2023/01/03/