MySQL: 奇怪的慢查询和其他问题

作者: 重庆八怪 | 来源:发表于2022-12-13 18:23 被阅读0次

Mysql 慢查询日志
关系型数据库my.cnf 配置文件参数0903
数据库性能优化-定位满查询
MySQL慢查询（一） - 开启慢查询
MySQL 慢查询分析实践
MySQL 索引及查询优化总结-2018-03-20
mysql慢查询日志
MySQL慢查询日志总结
Mysql-日志-慢查询日志
十、慢查询日志设置

一、奇怪的慢查询

我们先来看2个慢查询，版本8.0.23

# Time: 2022-12-14T17:40:45.941286+08:00
# User@Host: root[root] @ localhost []  Id:    18
# Query_time: 60.111780  Lock_time: 0.000493 Rows_sent: 0  Rows_examined: 0
SET timestamp=1671010785;
alter table testmy100 ALGORITHM=copy , add ill3333 int after id;
# Time: 2022-12-14T17:42:02.326428+08:00
# User@Host: root[root] @ localhost []  Id:    18
# Query_time: 60.007859  Lock_time: 0.000859 Rows_sent: 0  Rows_examined: 0
SET timestamp=1671010862;
alter table testmy100 ALGORITHM=inplace , add ill3333 int after id;

一般的理解如下（官方版本）：

Query_time：语句执行实际消耗时间。
Lock_time：包含MDL lock和InnoDB row lock和MyISAM表锁消耗时间的总和及锁等待消耗时间。
Rows_sent：发送给客户端的行数，通常为select，而对于DML来讲不需要有发送给客户端的行数，只需要返回OK PACKET将affect_rows返回给客户端即可。
Rows_examined：InnoDB引擎层扫描的行数,通常作于语句是否优化的重要评判标准。
SET timestamp：获取的服务器的当前的时间，每个慢查询语句都有。语句开始时间。
Time: 注意这个时间受到MySQLD参数log_timestamps的影响，有时区的概念在里面，如果同一时间记录多个慢查询，只会记录一次时间。语句结束时间。

这里我们发现2个DDL语句都大约在60秒左右记录到了慢查询（语句不管执行成功还是出错都会记录慢查询），而Lock_time的时间却很短，从理论上来讲，既然都在60秒左右记录到了慢查询那很可能是某种超时，引起DDL超时最可能就是MDL LOCK 超时，也就是参数lock_wait_timeout，查看这个参数确实设置是60。
但是如果是lock_wait_timeout超时，为什么Lock_time没有记录呢？且也不是0。这视乎有点奇怪。
实际上我们以前多次提到过对于MySQL层是否将时间加入到Lock_time，完全取决于是否执行了THD::set_time_after_lock函数，但是DDL的操作不管是copy还是inplace算法都并不是只会加一次MDL LOCK，而是会加很多次，到了DDL执行之前会升级为X锁，之前的MDL LOCK是能和select的MDL LOCK兼容的。

只有升级到X锁过后才会被select的SR锁堵塞，但是在之前已经多次跑了THD::set_time_after_lock函数，同时加MDL LOCK锁的表也会包含一些内部表，如下：

Breakpoint 18, MDL_context::acquire_lock (this=0x7ffeb0195310, mdl_request=0x7ffeb03d5f60, lock_wait_timeout=60) at /newdata/mysql-8.0.23/sql/mdl.cc:3351
3351      if (lock_wait_timeout == 0) {
(gdb)  p mdl_request->key.name()
$50 = 0x7ffeb03d5f8b "testmy100"
(gdb) p  mdl_request->type
$51 = MDL_SHARED_UPGRADABLE
(gdb) c
Continuing.

Breakpoint 18, MDL_context::acquire_lock (this=0x7ffeb0195310, mdl_request=0x7ffeb086ead8, lock_wait_timeout=31536000) at /newdata/mysql-8.0.23/sql/mdl.cc:3351
3351      if (lock_wait_timeout == 0) {
(gdb)  p mdl_request->key.name()
$52 = 0x7ffeb086eb05 "tablespace_files"
(gdb) c
Continuing.

Breakpoint 18, MDL_context::acquire_lock (this=0x7ffeb0195310, mdl_request=0x7ffeb03eb158, lock_wait_timeout=31536000) at /newdata/mysql-8.0.23/sql/mdl.cc:3351
3351      if (lock_wait_timeout == 0) {
(gdb)  p mdl_request->key.name()
$53 = 0x7ffeb03eb185 "tablespaces"
(gdb) c
Continuing.

Breakpoint 17, THD::set_time_after_lock (this=0x7ffeb0195280) at /newdata/mysql-8.0.23/sql/sql_class.cc:2826
2826      if (utime_after_lock != start_utime) return;

因此有少量的Lock_time是可以理解的。但是当我们真正出现MDL LOCK堵塞的时候实际上，并不会再次跑到THD::set_time_after_lock函数上，因此真正堵塞的时间不会被Lock_time记录。
接下来，Query_time - Lock_time > 慢查询设置的时间，就记录到了慢查询，当然前提是需要设置参数log_slow_admin_statements=ON，才会记录ALTER TABLE语句。
这样看来这个慢查询实际上也不是非常奇怪，我们将它归结为MDL LOCK超时就可以了。

二、information_schema.partitions表的CREATE_TIME

最近本来想用这个字段查一下分区建立的时间，结果发现没啥用，每次分区表操作过后，所有分区的时间都变化了，下面来大概看看。
实际上information_schema.partitions是一个视图，其定义比较长，其中CREATE_TIME来自mysql.tables的created字段，mysql.tables为一个内部表，非DEBUG版本访问不到，那么实际上这个属性是整个表的一个属性，因此所有分区显示一样也没什么问题，只是没啥用了。
另外对于普通表来讲就是information_schema.tables中的CREATE_TIME 同样来自tbl.created AS CREATE_TIME.并且每次建立索引/增加字段等 DDL操作都会导致这个时间变化（rename不会），因此大概看了一下更改的调用栈如下：

#0  dd::Abstract_table_impl::set_created (this=0x7ffeb00ff360, created=20221214073018) at /newdata/mysql-8.0.23/sql/dd/impl/types/abstract_table_impl.h:131
#1  0x0000000004d6ca3f in dd::Table_impl::set_created (this=0x7ffeb00ff360, created=20221214073018) at /newdata/mysql-8.0.23/sql/dd/impl/types/table_impl.h:453
#2  0x0000000004d6171d in dd::Schema_impl::create_table (this=0x7ffea8009c10, thd=0x7ffeb0195280) at /newdata/mysql-8.0.23/sql/dd/impl/types/schema_impl.cc:256
#3  0x0000000004b5488b in dd::create_dd_user_table (thd=0x7ffeb0195280, sch_obj=..., table_name="#sql-f98c_12", create_info=0x7ffeac138210, create_fields=..., keyinfo=0x7ffeb0969310, 
    keys=3, keys_onoff=Alter_info::LEAVE_AS_IS, fk_keyinfo=0x7ffeb09695b8, fk_keys=0, check_cons_spec=0x7ffeac138160, file=0x7ffeb0967c70) at /newdata/mysql-8.0.23/sql/dd/dd_table.cc:2351
#4  0x0000000004b54b90 in dd::create_table (thd=0x7ffeb0195280, sch_obj=..., table_name="#sql-f98c_12", create_info=0x7ffeac138210, create_fields=..., keyinfo=0x7ffeb0969310, keys=3, 
    keys_onoff=Alter_info::LEAVE_AS_IS, fk_keyinfo=0x7ffeb09695b8, fk_keys=0, check_cons_spec=0x7ffeac138160, file=0x7ffeb0967c70) at /newdata/mysql-8.0.23/sql/dd/dd_table.cc:2386
#5  0x00000000038a41cd in rea_create_base_table (thd=0x7ffeb0195280, path=0x7ffeac137014 "./t10/#sql-f98c_12", sch_obj=..., db=0x7ffeb0967158 "t10", 
    table_name=0x7ffeac136430 "#sql-f98c_12", create_info=0x7ffeac138210, create_fields=..., keys=3, key_info=0x7ffeb0969310, keys_onoff=Alter_info::LEAVE_AS_IS, fk_keys=0, 
    fk_key_info=0x7ffeb09695b8, check_cons_spec=0x7ffeac138160, file=0x7ffeb0967c70, no_ha_table=true, do_not_store_in_dd=true, part_info=0x0, binlog_to_trx_cache=0x0, 
    table_def_ptr=0x7ffeac135c88, post_ddl_ht=0x0) at /newdata/mysql-8.0.23/sql/sql_table.cc:1079
#6  0x00000000038b82f4 in create_table_impl (thd=0x7ffeb0195280, schema=..., db=0x7ffeb0967158 "t10", table_name=0x7ffeac136430 "#sql-f98c_12", error_table_name=0x7ffeb0966688 "testmy", 
    path=0x7ffeac137014 "./t10/#sql-f98c_12", create_info=0x7ffeac138210, alter_info=0x7ffeac1380a0, internal_tmp_table=true, select_field_count=0, find_parent_keys=true, 
    no_ha_table=true, do_not_store_in_dd=true, is_trans=0x0, key_info=0x7ffeac135e68, key_count=0x7ffeac135e64, keys_onoff=Alter_info::LEAVE_AS_IS, fk_key_info=0x7ffeac135e58, 
    fk_key_count=0x7ffeac135e54, existing_fk_info=0x7ffeb0967c48, existing_fk_count=0, existing_fk_table=0x7ffeb097cbd8, fk_max_generated_name_number=0, table_def=0x7ffeac135c88, 
    post_ddl_ht=0x0) at /newdata/mysql-8.0.23/sql/sql_table.cc:8739
#7  0x00000000038d01d0 in mysql_alter_table (thd=0x7ffeb0195280, new_db=0x7ffeb0967158 "t10", new_name=0x0, create_info=0x7ffeac138210, table_list=0x7ffeb0966b40, 
    alter_info=0x7ffeac1380a0) at /newdata/mysql-8.0.23/sql/sql_table.cc:16549

有兴趣的朋友可以研究下，至少说明这个字段不能表达为建表的时间，因为DDL也会造成其变化，如下：

mysql> select CREATE_TIME from information_schema.tables where TABLE_SCHEMA='t10' and table_name='testmy100' \G
*************************** 1. row ***************************
CREATE_TIME: 2022-12-14 18:17:53
1 row in set (0.00 sec)

 (增加字段)
mysql> select CREATE_TIME from information_schema.tables where TABLE_SCHEMA='t10' and table_name='testmy100' \G 
*************************** 1. row ***************************
CREATE_TIME: 2022-12-14 18:18:08
1 row in set (0.00 sec)

（增加索引）
mysql> select CREATE_TIME from information_schema.tables where TABLE_SCHEMA='t10' and table_name='testmy100' \G
*************************** 1. row ***************************
CREATE_TIME: 2022-12-14 18:18:23
1 row in set (0.00 sec)

以上。。。

Mysql 慢查询日志
Mysql 慢查询日志慢查询日志 MySQL的慢查询日志是MySQL提供的一种日志记录，它用来记录在MySQL中...
关系型数据库my.cnf 配置文件参数0903
oracle 慢查询 mysql慢查询
数据库性能优化-定位满查询
一、通过慢查询日志获取存在性能问题的SQL 开启mysql数据库慢查询日志和not using index的查询。...
MySQL慢查询（一） - 开启慢查询
MySQL慢查询（一） - 开启慢查询
MySQL 慢查询分析实践
mysql默认未开启慢查询记录功能；默认慢查询时间为10秒。一、mysql开启慢查询日志记录二、利用mysql...
MySQL 索引及查询优化总结-2018-03-20
MySQL 索引及查询优化总结文章《MySQL查询分析》讲述了使用MySQL慢查询和explain命令来定位my...
mysql慢查询日志
慢查询日志 MySQL 慢查询日志是排查问题 SQL 语句，以及检查当前 MySQL 性能的一个重要功能，执行时间...
MySQL慢查询日志总结
MySQL慢查询日志总结慢查询日志概念 MySQL的慢查询日志是MySQL提供的一种日志记录，它用来记录在MyS...
Mysql-日志-慢查询日志
本篇文章主要记述Mysql慢查询的学习过程，内容目录如下：慢查询日志是什么？慢查询日志开启和配置慢查询日志相关操作...
十、慢查询日志设置
如何发现有问题的sql；使用mysql慢查询日子对有效率问题sql进行监控是否开始慢查询日志； show var...