一、奇怪的慢查询
我们先来看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)
以上。。。