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)

以上。。。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 214,504评论 6 496
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 91,434评论 3 389
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 160,089评论 0 349
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 57,378评论 1 288
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 66,472评论 6 386
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 50,506评论 1 292
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 39,519评论 3 413
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,292评论 0 270
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 44,738评论 1 307
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,022评论 2 329
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,194评论 1 342
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 34,873评论 5 338
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,536评论 3 322
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,162评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,413评论 1 268
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,075评论 2 365
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,080评论 2 352

推荐阅读更多精彩内容