OceanBase诊断调优 】—— 如何快速定位SQL问题

作者简介:

花名:洪波,OceanBase 数据库解决方案架构师,目前负责 OceanBase 数据库在各大型互联网公司及企事业单位的落地与技术指导,曾就职于互联网大厂和金融科技公司,主导过多项数据库升级、迁移、国产化落地等工作。拥有丰富的数据库管理经验,曾负责研发数据库一体化管控平台。对数据库系统有较深理解,目前深耕分布式数据库技术的研究。

大家在使用数据库的过程中,经常遇到慢sql,或者执行错误的sql,有些sql是很容易判断出来错误,以及sql运行比较慢的原因,但是有些sql就很难判断出来,如果遇到这种情况,我们该怎么处理,怎么判断SQL出错原因,以及是SQL需要优化,数据库本身配置是否设置好等,接下来我就跟大家简单介绍下,如何快速定位SQL问题。在开始之前,我们先来了解下一条SQL,在进入OceanBase数据库中执行时都经历了哪些模块。

访问路径

首先我们从SQL的访问路径开始介绍,一条SQL从应用发出之后,一般会经过负载均衡(根据情况选择是否需要),然后到OBProxy,然后再到OBServer。大概流程如下图所示:

1702610573

OBProxy主要起到一个路由转发的作用,以及快速解析,根据OceanBase数据库中数据副本分布情况,直接将请求快速发送到对应的OBServer上。

SQL在进入OBServer之后,还会经历数据库内部很多模块,具体如下:

1702610587

SQL的在数据库内部的执行过程,这些模块具体的含义,可以参考官网文档:SQL 请求执行流程,在整个SQL执行过程中,会首先根据SQL的ip、port、自增序列号等信息生成一个全局唯一的trace_id,后续的sql跟踪,我们都使用这个trace_id来对sql进行定位追踪。

SQL错误

这种问题一般都比较好处理,大多都是sql写的格式不对,或者库、表、列名等不存在,或者OceanBase语法不支持等,一般情况,根据返回的错误信息,就大致可以判断出错误原因。

但也有一些很隐蔽的错误,一时很难判断出具体是哪里错了,这个时候就要借助错误日志来帮助我们进行判断了,这里就举一个例子,这是在一个用户那里实实在在遇到的问题,用户的场景比较复杂,拿OceanBase用来做数据的清洗,将多张表进行关联计算,然后将数据写入到结果表中,而在执行其中一条SQL过程中,收到了这样一个报错:

ERROR 1292 (22007): Incorrect value 

当时用户收到这个报错后很茫然,因为用户的SQL长达200多行,并且有多层嵌套子查询和多张表关联查询,所以一时间很难判断出来是哪里出现了错误,SQL大致如下(脱敏后):

REPLACE INTO abc.table1(m_id,st_id,con_id,`date`,t_ord,t_role,tag,con_pri,con_qu,con_in,update_time
)
SELECT tmp5.m_id,tmp5.st_id,tmp5.con_id,tmp5.`date`,tmp5.t_ord_96,tmp5.t_role,tmp5.tag,cast(sum(tmp5.con_pri) as decimal(20,6)) as con_pri,cast(sum(tmp5.con_qu) as decimal(20,6)) as con_qu,cast(sum(tmp5.con_in) as decimal(20,6)) as con_in,current_timestamp
FROM (SELECT tmp4.m_id,tmp4.st_id,tmp4.con_id,tmp4.`date`,tmp4.t_ord,dstl2.t_ord_96,tmp4.t_role,tmp4.tag,casewhen tmp4.t_ord = dstl2.t_ord_96 then con_prielse 0end as con_pri,casewhen tmp4.t_ord = dstl2.t_ord_96 then con_quelse 0end as con_qu,casewhen tmp4.t_ord = dstl2.t_ord_96 then con_inelse 0end as con_inFROM (SELECTtmp3.m_id,tmp3.st_id,tmp3.con_id,tmp3.`date`,tmp3.t_ord_96 as t_ord,tmp3.t_role,tmp3.tag,tmp3.con_pri,cast(tmp3.con_qu as decimal(20,6)) as con_qu,cast(tmp3.con_qu * tmp3.con_pri as decimal(20,6)) as con_inFROM(SELECT tmp2.m_id,tmp2.st_id,tmp2.con_id,tmp2.`date`,tmp2.t_ord_96,casewhen tmp2.con_name like '%xxx%' then 1when tmp2.con_name like '%x%' then 2when tmp2.con_name like '%xx%' then 3elsecasewhen tmp2.contract_type_name like '%xx%' then 4else 5endend as tag,case when tmp2.con_name like '%xxxxx%' then tmp2.vendee_priceelse tmp2.sale_priceend as con_pri,case when tmp2.con_name like '%xxxxx%' then tmp2.vendee_energyelse tmp2.sale_energyend as con_qu,tmp2.t_roleFROM(select tmp.m_id,tmp.st_id,tmp.st_name,tmp.member_id,tmp.con_id,tmp.con_name,dd.`date`,tmp.t_ord_96,tmp.sale_energy / (datediff(tmp.timepart_endtime, tmp.timepart_starttime) + 1) / tmp.re as sale_energy,tmp.sale_price,tmp.vendee_energy / (datediff(tmp.timepart_endtime, tmp.timepart_starttime) + 1) / tmp.re as vendee_energy,tmp.vendee_price,tmp.timepart_starttime,tmp.timepart_endtime,tmp.seller_member_name,tmp.contract_type_name,tmp.t_rolefrom(select tmp1.*,dstl.t_ord_96,count(1) over(PARTITION by member_id, con_id, time_division_range, timepart_endtime, timepart_starttime) as refrom (select distinct spcdp.m_id,ds.st_id,ds.st_name,spcdp.member_id, spcdp.con_id,dc.con_name,spcdp.sale_energy, spcdp.sale_price, spcdp.vendee_energy, spcdp.vendee_price, spcdp.time_division_code,spcdp.time_division_name,casewhen dc.con_name like '%xx%' then case when substr(date_add(cast(concat('2022-10-01 ', right(spcdp.time_division_range, 5), ':00') as datetime), interval 1 hour), 12, 5) = '00:00' then concat(left(spcdp.time_division_range, 6), '24:00')else concat(left(spcdp.time_division_range, 6), substr(date_add(cast(concat('2022-10-01 ', right(spcdp.time_division_range, 5), ':00') as datetime), interval 1 hour), 12, 5))endelse spcdp.time_division_rangeend as time_division_range, spcdp.timepart_endtime,spcdp.timepart_starttime,dc.seller_member_name,dc.contract_type_name,case when locate('x',dc.con_name) > 0 then 1when locate('x',dc.con_name) > 0 then 2else if(dc.con_qu>0,2,1)end as t_rolefrom (select distinct m_id, member_id, con_id, sale_energy, sale_price, vendee_energy, vendee_price, time_division_code, time_division_name, time_division_range, timepart_endtime, timepart_starttime from select DISTINCTif(spcdp.m_id is null,spcdpa.m_id,spcdp.m_id) as m_id,if(spcdp.member_id is null,spcdpa.member_id,spcdp.member_id) as member_id,if(spcdp.con_id is null,spcdpa.con_id,spcdp.con_id) as con_id,if(spcdp.sale_energy is null,spcdpa.sale_energy,spcdp.sale_energy) as sale_energy,if(spcdp.sale_price is null,spcdpa.sale_price,spcdp.sale_price) as sale_price,if(spcdp.vendee_energy is null,spcdpa.vendee_energy,spcdp.vendee_energy) as vendee_energy,	if(spcdp.vendee_price is null,spcdpa.vendee_price,spcdp.vendee_price) as vendee_price,if(spcdp.time_division_code is null,spcdpa.time_division_code,spcdp.time_division_code) as time_division_code,if(spcdp.time_division_name is null,spcdpa.time_division_name,spcdp.time_division_name) as time_division_name,if(spcdp.time_division_range is null,spcdpa.time_division_range,spcdp.time_division_range) as time_division_range,if(spcdp.timepart_endtime is null,spcdpa.timepart_endtime,spcdp.timepart_endtime) as timepart_endtime,if(spcdp.timepart_starttime is null,spcdpa.timepart_starttime,spcdp.timepart_starttime) as timepart_starttime,if(spcdp.creator is null,spcdpa.creator,spcdp.creator) as creator,if(spcdp.creation_time is null,spcdpa.creation_time,spcdp.creation_time) as creation_time,if(spcdp.modifier is null,spcdpa.modifier,spcdp.modifier) as modifier,if(spcdp.modification_time is null,spcdpa.modification_time,spcdp.modification_time) as modification_timefrom(select * from ods.table2 where modification_time >= date_format(date_sub(current_date, interval 1 day), '%Y-%m-%d %T')) spcdp  full join (select * from ods.table2_xxx where modification_time >= date_format(date_sub(current_date, interval 1 day), '%Y-%m-%d %T')) spcdpa  on spcdp.m_id = spcdpa.m_id and spcdp.member_id = spcdpa.member_id and spcdp.con_id = spcdpa.con_idand spcdp.time_division_code = spcdpa.time_division_code and spcdp.timepart_starttime = spcdpa.timepart_starttimeand spcdp.timepart_endtime = spcdpa.timepart_endtime)where m_id = 'PXBGS' and time_division_range <> '') spcdpinner join (select * from abc.table3 where service_provider_id = 1) ds on spcdp.member_id = ds.counterparty_codeinner join (select * from abc.table4 where is_deleted <> 1) dc on spcdp.con_id = dc.con_id and ds.st_id = dc.st_id and date(spcdp.timepart_starttime) between dc.contract_start_date and dc.contract_end_date) tmp1left join (selectt_ord_96,CASE when end_time_96 = '00:00:00' then '24:00'else left(end_time_96, 5)END as end_time_96from abc.dim_spot_time_list) dstl on dstl.end_time_96 > left(tmp1.time_division_range, 5) and dstl.end_time_96 <= right(tmp1.time_division_range, 5)) as tmpleft join abc.dim_date dd on dd.`date` BETWEEN date(tmp.timepart_starttime) and date(timepart_endtime)) as tmp2) as tmp3where tmp3.t_ord_96 is not null and tmp3.con_id <> 'xxxxxxxxxxxx' ) as tmp4left join abc.dim_spot_time_list dstl2 on 1 = 1) as tmp5group by tmp5.m_id, tmp5.st_id, tmp5.con_id, tmp5.`date`, tmp5.t_ord_96, tmp5.t_role, tmp5.tag;

从这个SQL文本来看,整体还是比较复杂,想快速找到问题根因还是比较困难,这个时候就需要我们根据SQL执行过程中的trace_id,来一步步追踪问题的根因。

这里先说结论,通过对日志过滤排查,我们发现是字段类型强转,导致转出来的日期字段是无效的,所以报除了这个错误,当时获取到的日志如下(部分截取):

[2023-07-19 14:24:27.757645] WARN [LIB.TIME] str_to_ob_time_with_date (ob_time_convert.cpp:1938) [7526][T1004_TNT_L0_G0][T1004][YB42AC116182-00060043C87B7F7D-0-0] [lt=16] datetime is invalid or out of range(ret=-4219, str=2022-10-01 24:00:00, ob_time={mode_:3, parts:[2022, 10, 1, 24, 0, 0, 0, 0, 0, 0, 0], tz_name:"", tzd_abbr:"", time_zone_id:-1, transition_type_id:-1, is_tz_name_valid:false}, date_sql_mode={allow_invalid_dates:0, no_zero_date:0}, lbt()=0xb553efb 0xb4b501f 0xb4a0a96 0xb4a0731 0x80360d3 0x807ed03 0x8098f84 0x61dc801 0x8098f84 0x804c103 0x8098f84 0x7e3b29f 0x8098f84 0x686dcc7 0x8098f84 0x6669ef4 0x8098f84 0x7373827 0x7373e77 0x74e80f3 0x755c04b 0x756110c 0x7563293 0x737face 0x6eb659d 0x6eb7931 0x6ebf317 0x737face 0x743726d 0x737face 0x69a057d 0x737face 0x69ed74b 0x699f2b4 0x69df421 0x39cbc45 0x7a5d60f 0x7a5cd06 0x7a5b37d 0x7a94139 0x7a48812 0x7a2b8cb 0x7a2a815 0x3bbaed5 0x392f401 0x4602029 0x39277e4 0x46025c7 0xb5380c7 0xb53303a 0x7f1759d17ea5 0x7f1759a40b0d)
[2023-07-19 14:24:27.757663] WARN [LIB.TIME] str_to_datetime (ob_time_convert.cpp:398) [7526][T1004_TNT_L0_G0][T1004][YB42AC116182-00060043C87B7F7D-0-0] [lt=18] failed to convert string to datetime(ret=-4219)
[2023-07-19 14:24:27.757667] WARN [SQL] common_string_datetime (ob_datum_cast.cpp:1104) [7526][T1004_TNT_L0_G0][T1004][YB42AC116182-00060043C87B7F7D-0-0] [lt=4] str_to_datetime failed(ret=-4219, in_str=2022-10-01 24:00:00)
[2023-07-19 14:24:27.757671] WARN [SQL] string_datetime (ob_datum_cast.cpp:2406) [7526][T1004_TNT_L0_G0][T1004][YB42AC116182-00060043C87B7F7D-0-0] [lt=3] fail to exec common_string_datetime(expr, ObString(child_res->len_, child_res->ptr_), ctx, res_datum)(ret=-4219)
[2023-07-19 14:24:27.757673] WARN [SQL] anytype_anytype_explicit (ob_datum_cast.cpp:6263) [7526][T1004_TNT_L0_G0][T1004][YB42AC116182-00060043C87B7F7D-0-0] [lt=3] inner cast failed(ret=-4219)
[2023-07-19 14:24:27.757676] WARN [SQL] eval_param_value (ob_expr.h:944) [7526][T1004_TNT_L0_G0][T1004][YB42AC116182-00060043C87B7F7D-0-0] [lt=2] evaluate parameter failed(ret=-4219, param_index=0)
[2023-07-19 14:24:27.757679] WARN [SQL.ENG] calc_date_adjust (ob_expr_date_add.cpp:144) [7526][T1004_TNT_L0_G0][T1004][YB42AC116182-00060043C87B7F7D-0-0] [lt=2] eval param value failed
[2023-07-19 14:24:27.757682] WARN [SQL] datetime_string (ob_datum_cast.cpp:3524) [7526][T1004_TNT_L0_G0][T1004][YB42AC116182-00060043C87B7F7D-0-0] [lt=2] eval arg failed(ret=-4219, ctx={batch_idx:8, batch_size:136, max_batch_size:256, frames_:0x7f12f57f0f90})
........

从日志的第一行,我们就可以看到datetime is invalid or out of range的报错,在这里就基本可以判断是datetime类型有问题,第二行的提示则更明显:failed to convert string to datetime,所以我们很快就可以定位到是在做string转datetime类型的时候,出现了错误,通过回看SQL可以找到,有两处使用cast函数来做字符串类型转时间类型的转换,然后根据用户提供的表数据,我们对问题进行复现,确信就是这里的错误。SQL中类型转换如下:

cast(concat('2022-10-01 ', right(spcdp.time_division_range, 5), ':00') as datetime)

那我们是怎么快速找到这条日志的呢,下面我把问题简化,重新复现报错现场,看下是怎么一步步找到关键日志,发现问题的。具体如下,简单创建两张表:

t1表:

CREATE TABLE `t1` (`a_id` int(11) DEFAULT NULL,`a_name` varchar(10) DEFAULT NULL,`a_time` varchar(10) DEFAULT NULL
)

t2表:

CREATE TABLE `t2` (`t_id` int(11) DEFAULT NULL,`t_name` varchar(10) DEFAULT NULL,`t_time` datetime DEFAULT NULL
)

其中t2表,是目标写入表,t1表是源数据表,t1表和t2表区别主要是第三个字段的类型不一样,一个是varchar,一个是datetime类型,源数据表t1中数据如下:

obclient [test]> select * from t1;
+------+--------+--------+
| a_id | a_name | a_time |
+------+--------+--------+
|    1 | test   | 24:00  |
+------+--------+--------+
1 row in set (0.011 sec)

模拟数据清洗并写入

obclient [test]> insert into t2 select a_id, a_name,cast(concat('2022-10-10 ', right(tb.a_time,5), ':00') as datetime) from t1 tb;
ERROR 1292 (22007): Incorrect value

可以看到出现了类似的报错,接下来我们就需要去日志里定位到这个报错,因为OceanBase的日志打印比较多,如果直接去找是很难快速定位到跟这条SQL相关的日志,这里就需要用到trace_id。前面我们说到每条SQL进入到数据库,都会产生一个唯一的trace_id,那这个trace_id是怎么获取呢,这里有几种方式:

方式一:

在SQL执行完成之后,通过select last_trace_id();获取

obclient [test]> select last_trace_id();
+-----------------------------------+
| last_trace_id()                   |
+-----------------------------------+
| YB42AC18FF11-0005FE3D398CC982-0-0 |
+-----------------------------------+
1 row in set (0.001 sec)

方式二:

通过查询 GV$OB_SQL_AUDIT 审计视图查询获取,根据query_sql字段过滤查询的关键字,获取对应的trace_id,关于审计视图的各字段含义,可参考官方文档:GV$OB_SQL_AUDIT

obclient [test]> select SVR_IP,SVR_PORT,TRACE_ID,,TENANT_NAME,SQL_ID,QUERY_SQL ->     from oceanbase.gv$ob_sql_audit->     where query_sql like "%right(tb.a_time,5)%"\G;
*************************** 1. row ***************************SVR_IP: 172.24.255.17SVR_PORT: 2882TRACE_ID: YB42AC18FF11-0005FE3D398CC982-0-0TENANT_NAME: obtestSQL_ID: D8F4A48653895C3AAACE903CA04EDD21QUERY_SQL: insert into t2 select a_id, a_name,cast(concat('2022-10-10 ', right(tb.a_time,5), ':00') as datetime) from t1 tb
1 rows in set (0.224 sec)

方式三:

开启enable_rich_error_msg参数,不过这个是集群级别的,需要在sys租户下开启

开启方式:

alter system set enable_rich_error_msg=true;

在开启之后,如果SQL执行报错,会自动返回trace_id和ip信息

obclient [test]> insert into t2 select a_id, a_name,cast(concat('2022-10-10 ', right(tb.a_time,5), ':00') as datetime) from t1 tb;
ERROR 1292 (22007): Incorrect value
[172.24.255.17:2882] [2023-08-03 20:42:36.361996] [YB42AC18FF11-0005FE3D398CC986-0-0]

以上三种方式,我们一般会采用第二种方式,方式一只能获取到trace_id,但是获取不到OBServer的IP信息,因为OceanBase为分布式数据库,一套集群一般会有多个OBServer节点,如果没有IP信息,我们很难得知这条SQL是在哪个OBServer节点上执行的。所以是需要这个IP信息方便我们拿着trace_id直接去机器上过滤日志。方式三需要开启集群级别的参数,有的租户并不一定需要这个,并且展示信息相对较少。

通过获取到的trace_id,以及SVR_IP信息,我们直接到172.24.255.17这台机器的/home/admin/oceanbase/log目录下,过滤observer.log,得到如下日志:

[root@ob1 log]# grep "YB42AC18FF11-0005FE3D398CC982-0-0" observer.log
[2023-08-03 20:36:01.943682] WDIAG [LIB.TIME] str_to_ob_time_with_date (ob_time_convert.cpp:1948) [24791][T1012_L0_G0][T1012][YB42AC18FF11-0005FE3D398CC982-0-0] [lt=14][errcode=-4219] datetime is invalid or out of range(ret=-4219, str=2022-10-10 24:00:00, ob_time={mode_:3, parts:[2022, 10, 10, 24, 0, 0, 0, 0, 0, 0, 0], tz_name:"", tzd_abbr:"", time_zone_id:-1, transition_type_id:-1, is_tz_name_valid:false}, date_sql_mode={allow_invalid_dates:0, no_zero_date:0}, lbt()=0xf0bba8c 0xec2b439 0xec175b5 0xec17245 0xb24a08c 0xb2c0cb8 0x41329cc 0xb23d520 0xb2d4359 0x3fbefb0 0xa55f81d 0x3fbe901 0x411b7eb 0x9f87f2e 0x411b290 0x3fb8c7d 0x3ffbe9a 0x7f29409 0x3fb334e 0x3fb0562 0x3fabed9 0x3fa9d9a 0x3fa6768 0x6a0ad14 0xf3666c7 0xf35faca 0x7fc02405fea5 0x7fc023d88b0d)
[2023-08-03 20:36:01.943700] WDIAG [LIB.TIME] str_to_datetime (ob_time_convert.cpp:397) [24791][T1012_L0_G0][T1012][YB42AC18FF11-0005FE3D398CC982-0-0] [lt=19][errcode=-4219] failed to convert string to datetime(ret=-4219)
[2023-08-03 20:36:01.943705] WDIAG [SQL] common_string_datetime (ob_datum_cast.cpp:1190) [24791][T1012_L0_G0][T1012][YB42AC18FF11-0005FE3D398CC982-0-0] [lt=4][errcode=-4219] str_to_datetime failed(ret=-4219, in_str=2022-10-10 24:00:00)
[2023-08-03 20:36:01.943709] WDIAG [SQL] string_datetime (ob_datum_cast.cpp:2838) [24791][T1012_L0_G0][T1012][YB42AC18FF11-0005FE3D398CC982-0-0] [lt=4][errcode=-4219] fail to exec common_string_datetime(expr, ObString(child_res->len_, child_res->ptr_), ctx, res_datum)(ret=-4219)
[2023-08-03 20:36:01.943712] WDIAG [SQL] anytype_anytype_explicit (ob_datum_cast.cpp:8389) [24791][T1012_L0_G0][T1012][YB42AC18FF11-0005FE3D398CC982-0-0] [lt=3][errcode=-4219] inner cast failed(ret=-4219)
[2023-08-03 20:36:01.943715] WDIAG [SQL] cast_eval_arg_batch (ob_datum_cast.cpp:2306) [24791][T1012_L0_G0][T1012][YB42AC18FF11-0005FE3D398CC982-0-0] [lt=3][errcode=-4219] fail to eval one row(ret=-4219, i=0)
.......

从日志的前两行中,可以看到这次的报错,和用户日志中过滤出来的报错是一样的,因此我们就可以判断是这里的cast转换出现了错误。

这里为什么这样转换是不行的呢,我们可以看到在t1表中,a_time字段是varchar类型,具体数值是 24:00 ,通过concat('2022-10-10 ', right(tb.a_time,5), ':00') 拼接之后,组成的字符串是 "2022-10-10 24:00:00" ,乍一看貌似没有什么问题,但为什么会转换失败?实际我们细心观察就会发现,2022-10-10 24:00:00 在计算机中是一个非法时间,2022-10-10 24:00:00 其实已经到 2022-10-11 00:00:00,所以这块我们建议用户对这个字符串做下修改,不要使用24:00:00。

修改之后我们再来看一下执行情况。

首先t1表内容

obclient [test]> select * from t1;
+------+--------+--------+
| a_id | a_name | a_time |
+------+--------+--------+
|    1 | test   | 00:00  |
+------+--------+--------+
1 row in set (0.001 sec)

再次执行写入

obclient [test]> insert into t2 select a_id, a_name,cast(concat('2022-10-11 ', right(tb.a_time,5), ':00') as datetime) from t1 tb;
Query OK, 1 row affected (0.003 sec)obclient [test]> select * from t2;
+------+--------+---------------------+
| t_id | t_name | t_time              |
+------+--------+---------------------+
|    1 | test   | 2022-10-11 00:00:00 |
+------+--------+---------------------+
1 row in set (0.001 sec)

可以看到执行写入成功,问题得以解决。

在实际生产过程中,我们还会遇到其他很多类型的错误,大多都是可以通过这种方式快速定位和解决问题。另外还有一种情况,就是我们遇到了慢SQL,导致整个数据库系统变卡,也影响到其他SQL的执行。下面就来看下如何快速定位慢SQL。

慢SQL

慢SQL对于DBA来说,一直是一个比较头疼的地方,当遇到慢SQL的时候,总是需要想各种办法去优化慢SQL,如果不快速优化,就会引发一系列问题,那么在OceanBase中我们如何判断是慢SQL,以及如何发现慢SQL呢。

OceanBase中有一个参数 trace_log_slow_query_watermark 用来设置慢SQL的阈值,当SQL的执行超过这个阈值,那么OceanBase就会认为这是一条慢SQL,然后被记录,这个值默认是 1 秒。

属性描述
参数类型时间类型
默认值1s
取值范围[1ms, +∞)
是否重启 OBServer 生效

那么,这些慢SQL信息具体记录在哪些地方呢,我们如何快速找到它呢?

方式一:

首先,我们前面提到所有的SQL的执行都会记录在observer.log的日志里,慢SQL也不例外,在observer.log日志里,我们可以过滤 slow query 关键字,就能获取到执行超过 1 秒的慢SQL,例如下面这条日志

[root@ob1 log]# grep "slow query" observer.log
[2023-08-04 11:05:36.254730] TRACE [TRACE] after_process (obmp_base.cpp:142) [14092][T1_L0_G0][T1][YB42AC18FF11-0005FE3E568CA6E9-0-0] [lt=14] [slow query](TRACE=begin_ts=1691118333740472 2023-08-04 03:05:33.740472|[process_begin] u=0 in_queue_time:15, receive_ts:1691118333740456, enqueue_ts:1691118333740457|[start_sql] u=0 addr:{ip:"127.0.0.1", port:23382}|[query_begin] u=1 trace_id:YB42AC18FF11-0005FE3E568CA6E9-0-0|[before_processor_run] u=3 |[session] u=2 sid:3221725883, tenant_id:1|[calc_partition_location_begin] u=48 |[plc_serialize_begin] u=4 |[plc_serialize_end] u=5 |[tl_calc_part_id_end] u=36 |[get_location_cache_begin] u=0 |[calc_partition_location_end] u=2 |[get_plan_type_end] u=1 |[pc_choose_plan] u=2 |[check_priv] u=4 |[plan_id] u=1 plan_id:18101|[do_open_plan_begin] u=2 plan_id:18101|[sql_start_stmt_begin] u=0 |[sql_start_stmt_end] u=0 |[exec_plan_begin] u=0 |[exec_plan_end] u=4 |[do_open_plan_end] u=0 |[get_row] u=1672 |[close_plan_begin] u=2512423 |[start_end_stmt] u=14 |[end_stmt] u=0 |[close_plan_end] u=0 |[affected_rows] u=1 affected_rows:-1|[store_found_rows] u=0 found_rows:0, return_rows:296|[auto_end_plan_begin] u=0 |[auto_end_plan_end] u=2 |[query_end] u=19 |[process_end] u=10 run_ts:1691118333740476|total_timeu=2514256)

这条日志其实记录了很多信息,包括SQL的trace_id,以及执行总时间total_time和各个模块的执行时间。

方式二:

在OBProxy的日志目录里,专门有一个 obproxy_slow.log 的日志,这个日志也会记录所有的慢SQL信息,我们可以直接查看这个日志,发现执行慢的SQL

2023-08-01 17:44:51.779606,odp,,,,obcluster:obtest:oceanbase,OB_MYSQL,,,OB_MYSQL_COM_QUERY,SELECT,success,,select /*+ ob_querytimeout(10000000000) */ sleep(5),5000864us,120us,0us,5000571us,Y0-00007FCC9D7BC3A0,YB42AC18FF13-0005FE3D2CBF2C76-0-0,,,0,172.24.255.19:2881
2023-08-03 14:30:47.370874,odp,,,,obcluster:obtest:test,OB_MYSQL,,,OB_MYSQL_COM_QUERY,SELECT,success,,select sleep(1),1011179us,86us,0us,1010966us,Y0-00007FCC9DBBD320,YB42AC18FF13-0005FE3D2CBF2CE3-0-0,,,0,172.24.255.19:2881
2023-08-03 16:41:08.255751,odp,,,,obcluster:obtest:test,OB_MYSQL,,,OB_MYSQL_COM_QUERY,DROP,success,,drop table chat_req_records,620960us,113us,0us,620687us,Y0-00007FCC9D7BD3E0,,,,0,172.24.255.19:2881

obproxy的慢SQL日志中总共有24个字段,根据这些字段,我们也可以获取到一些信息,有些字段为暂时留空,这些字段依次是

日志打印时间2023-08-01 17:44:51.779606,
当前应用名odp
TraceIdYB42AC18FF13-0005FE3D2CBF2C76-0-0
RpcId
逻辑数据源名称
物理库信息(cluster:tenant:database)
数据库类型(OB/RDS)obcluster:obtest:oceanbase
逻辑表名OB_MYSQL
物理表名
SQL 命令(COM_QUERY、COM_STMT_PREPARE等)
SQL 类型(CRUD)SELECT
执行结果(success/failed)success
错误码(succ时为空)
SQLselect /*+ ob_querytimeout(10000000000) */ sleep(5)
执行总耗时(ms,包括内部 SQL 执行耗时)5000864us
预执行时间120us
链接建立时间0us
数据库执行时间5000571us
当前线程名(odp的内部线程ID)Y0-00007FCC9D7BC3A0
系统穿透数据(系统灾备信息等)YB42AC18FF13-0005FE3D2CBF2C76-0-0
穿透数据
DBKey 名称
是否使用 BeyondTrust(version>= 2.0.20 1 是,0 否)0
后端 Server IP172.24.255.19:2881

方式三:

如果系统当前时段就很慢,可以查询正在执行的比较慢的SQL,通过视图 __all_virtual_processlist 根据 time 字段排序,获取当前系统中,正在执行的慢SQL。

查询SQL如下

SELECT USER,tenant,sql_id,concat(time, 's') as time,info,svr_ip,svr_port,trace_id
FROM __all_virtual_processlist
WHERE STATE = 'ACTIVE'
ORDER BY time DESC LIMIT 1

现在模拟一个慢SQL, select /*+ query_timeout(100000000) */ sleep(100); 查询结果如下

+------+--------+----------------------------------+------+---------------------------------------------------+---------------+----------+-----------------------------------+
| USER | tenant | sql_id                           | time | info                                              | svr_ip        | svr_port | trace_id                          |
+------+--------+----------------------------------+------+---------------------------------------------------+---------------+----------+-----------------------------------+
| root | obtest | DE47F6BC20D6E36C14AA4D90BDE3B083 | 2s   | select /*+ query_timeout(100000000) */ sleep(100) | 172.24.255.19 |     2882 | YB42AC18FF13-0005FE3D2CBF2D57-0-0 |
+------+--------+----------------------------------+------+---------------------------------------------------+---------------+----------+-----------------------------------+
1 row in set (0.003 sec)

方式四:

如果有OCP的话,也是可以在OCP上直接查看慢SQL,进到具体的租户下面,然后进到SQL诊断中,有慢SQL页面,这里的SQL文本,都是有相同SQL_ID的SQL

1702610623

这里再解释下SQL_ID,SQL_ID是每条SQL进入数据库之后,会根据SQL字符串生成一个md5值,所以执行相同的SQL 会有相同的SQL_ID,但是trace_id是不一样的。

想要查看某条SQL具体是哪次执行慢了,可以点击SQL文本进到下一个页面,拿到执行慢的那一次的 SQL 的trace_id。

1702610639

通过这几种方式,我们就可以很快获取到系统中执行的慢SQL,不过前两种方式和第四种方式只能获取到trace_id,而第三种方式可以直接获取到执行的SQL,以及SQL_ID。对于前两种方式,想要看具体的内容,还需要再进一步查询。这里又用到我们的 GV$OB_SQL_AUDIT 视图,可以根据视图中的trace_id直接定位到对应的SQL内容:

obclient [oceanbase]> select SVR_IP,SVR_PORT,TRACE_ID,TENANT_NAME,SQL_ID,QUERY_SQL,PLAN_ID->     from gv$ob_sql_audit ->     where trace_id = "YB42AC18FF13-0005FE3D2CBF2D57-0-0"\G;
*************************** 1. row ***************************SVR_IP: 172.24.255.19SVR_PORT: 2882TRACE_ID: YB42AC18FF13-0005FE3D2CBF2D57-0-0TENANT_NAME: obtestSQL_ID: DE47F6BC20D6E36C14AA4D90BDE3B083QUERY_SQL: select /*+ query_timeout(100000000) */ sleep(100)PLAN_ID: 2518
1 row in set (0.146 sec)

通过这个查询,我们就知道了具体是哪条SQL执行慢了,并且获取到了SQL执行计划的PLAN_ID,接着就可以根据PLAN_ID去查找这条SQL的执行计划,根据执行计划再进一步排查

获取执行计划相关信息

obclient [oceanbase]> SELECT tenant_id,->    svr_ip,->    svr_port,->    sql_id,->    plan_id,->    last_active_time,->    first_load_time,->    outline_data-> FROM GV$OB_PLAN_CACHE_PLAN_STAT-> WHERE TENANT_ID = 1012-> AND SQL_ID = 'DE47F6BC20D6E36C14AA4D90BDE3B083'-> AND SVR_IP = '172.24.255.19'-> AND SVR_PORT = 2882;
*************************** 1. row ***************************tenant_id: 1012svr_ip: 172.24.255.19svr_port: 2882sql_id: DE47F6BC20D6E36C14AA4D90BDE3B083plan_id: 2518
last_active_time: 2023-08-04 11:42:47.834366first_load_time: 2023-08-04 11:42:47.834366outline_data: /*+BEGIN_OUTLINE_DATA QUERY_TIMEOUT(100000000) OPTIMIZER_FEATURES_ENABLE('4.0.0.0') END_OUTLINE_DATA*/
1 row in set (0.019 sec)

得到这个查询的执行计划的编号(plan_id),这个执行计划第一次生成的时间(first_load_time)以及最后一次被使用的时间(last_active_time)

接着,就可以根据plan_id来获取这条SQL的物理执行计划

obclient [oceanbase]> SELECT OPERATOR, NAME, ROWS, COST FROM GV$OB_PLAN_CACHE_PLAN_EXPLAIN->     WHERE TENANT_ID = 1012 AND->     SVR_IP = '172.24.255.19' AND->     SVR_PORT = 2882 AND->     PLAN_ID = 2518;
+-----------------+------+------+------+
| OPERATOR        | NAME | ROWS | COST |
+-----------------+------+------+------+
| PHY_EXPR_VALUES | NULL |    1 |    0 |
+-----------------+------+------+------+
1 row in set (0.001 sec)

如果想要获取SQL的逻辑执行计划,可以直接使用 explain SQL 获取

obclient [test]> explain select /*+ query_timeout(100000000) */ sleep(100);
+--------------------------------------------------------------+
| Query Plan                                                   |
+--------------------------------------------------------------+
| ==========================================                   |
| |ID|OPERATOR  |NAME|EST.ROWS|EST.TIME(us)|                   |
| ------------------------------------------                   |
| |0 |EXPRESSION|    |1       |1           |                   |
| ==========================================                   |
| Outputs & filters:                                           |
| -------------------------------------                        |
|   0 - output([sleep(cast(100, DECIMAL(3, 0)))]), filter(nil) |
|       values({sleep(cast(100, DECIMAL(3, 0)))})              |
+--------------------------------------------------------------+
9 rows in set (0.007 sec)

接着就可以根据执行计划,来判断问题的原因。执行计划解读,可参考官网文档:执行计划,定位到问题之后,我们也有很多优化的方式,这些后续我们再展开来将,其中包括 hint, outline绑定等。

另外,在OceanBase 4.0版本之后,我们也推出了全链路追踪的功能,依靠全链路追踪,可以更快速的定位到一条SQL具体是哪里执行慢。相关全链路追踪文档,可以参考这里:OceanBase 4.0 解读:全链路追踪要解决什么问题?从一条慢SQL说起

本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。如若转载,请注明出处:http://www.mzph.cn/diannao/2531.shtml

如若内容造成侵权/违法违规/事实不符,请联系多彩编程网进行投诉反馈email:809451989@qq.com,一经查实,立即删除!

相关文章

Qt配置CMake出错

一个项目需要在mingw环境下编译Opencv源码&#xff0c;当我用Qt配置opencv的CMakeLists.txt时&#xff0c;出现了以下配置错误&#xff1a; 首先我根据下述博文介绍&#xff0c;手动配置了CMake&#xff0c;但仍不能解决问题。 Qt(MinGW版本)安装 - 夕西行 - 博客园 (cnblogs.…

计算机网络相关知识总结

一、概述 计算机网络可以极大扩展计算机系统的功能机器应用范围&#xff0c;提高可靠性&#xff0c;在为用户提供放方便的同时&#xff0c;减少了整体系统费用&#xff0c;提高性价比。 计算机网络的功能主要有&#xff1a;1. 数据共享&#xff1b;2. 资源共享&#xff1b;3. 管…

用html画一个四叶草

<!DOCTYPE html> <html lang"en" > <head> <meta charset"UTF-8"> <title>四叶草</title> <link href"" rel"stylesheet"> <link rel"stylesheet" href"css/style.css&q…

数字逻辑电路基础-有限状态机

文章目录 一、有限状态机基本结构二、verilog写一个基础有限状态机(moore型状态机)三、完整代码一、有限状态机基本结构 本文主要介绍使用verilog编写有限状态机FSM(finite state machine),它主要由三部分组成,下一状态逻辑电路,当前状态时序逻辑电路和输出逻辑电路。 有…

更易使用,OceanBase开发者工具 ODC 4.2.4 版本升级

亲爱的朋友们&#xff0c;大家好&#xff01;我们的ODC&#xff08;OceanBase Developer Center &#xff09;再次迎来了重要的升级V 4.2.4&#xff0c;这次我们诚意满满&#xff0c;从五个方面为大家精心打造了一个更加易用、贴心&#xff0c;且功能更强的新版本&#xff0c;相…

SAP Fiori开发中的JavaScript基础知识15 - 原型,object,constructor,class,继承

1. 前言 本文将介绍JavaScript中的核心概念 - 原型&#xff0c;并会介绍基于原型的应用场景object&#xff0c;constructor&#xff0c;class&#xff0c;继承。 本文会将这几个核心概念汇总在一篇博客中&#xff0c;因为这些概念是触类旁通的&#xff0c;希望对你有帮助。 …

RTU遥测终端为城市排水安全保驾护航!

近年来&#xff0c;全球气候变迁与城市化进程不断加速&#xff0c;导致强降雨事件频发&#xff0c;道路低洼地带、下穿式立交桥和隧道等区域在暴雨中常易积水&#xff0c;严重阻碍了人民的出行&#xff0c;甚至危及生命与财产安全。而传统的排水管网管理方式已难以适应现代城市…

STM32 学习13 低功耗模式与唤醒

STM32 学习13 低功耗模式与唤醒 一、介绍1. STM32低功耗模式功能介绍2. 常见的低功耗模式&#xff08;1&#xff09;**睡眠模式 (Sleep Mode)**:&#xff08;2&#xff09;**停止模式 (Stop Mode)**:&#xff08;3&#xff09;**待机模式 (Standby Mode)**: 二、睡眠模式1. 进入…

BBS前后端混合项目--01

总路由 # urls.py """BBS1 URL ConfigurationThe urlpatterns list routes URLs to views. For more information please see:https://docs.djangoproject.com/en/3.2/topics/http/urls/ Examples: Function views1. Add an import: from my_app import views2…

related_name和related_query_name属性

在Django模型继承中&#xff0c;假如在外键或多对多字段中使用了related_name属性或related_query_name属性&#xff0c;则必须为该字段提供一个独一无二的反向名字和查询名字。但是&#xff0c;这样在抽象基类中一般会引发问题&#xff0c;因为基类中的字段都被子类继承并且保…

初见-响应式编程-002

&#x1f917; ApiHug {Postman|Swagger|Api...} 快↑ 准√ 省↓ GitHub - apihug/apihug.com: All abou the Apihug apihug.com: 有爱&#xff0c;有温度&#xff0c;有质量&#xff0c;有信任ApiHug - API design Copilot - IntelliJ IDEs Plugin | Marketplace #Reacti…

BERT-CRF 微调中文 NER 模型

文章目录 数据集模型定义数据集预处理BIO 标签转换自定义Dataset拆分训练、测试集 训练验证、测试指标计算推理其它相关参数CRF 模块 数据集 CLUE-NER数据集&#xff1a;https://github.com/CLUEbenchmark/CLUENER2020/blob/master/pytorch_version/README.md 模型定义 imp…

【iOS开发】(五)react Native路由和导航20240421-22

【iOS开发】(五)react Native 路由和导航Navigation 20240421 在&#xff08;一&#xff09;&#xff08;二&#xff09;中我们 Reactnative搭建了开发环境、学习了 基础语法、状态管理&#xff0c;JSX、组件、状态和生命周期以及样式布局等。 在&#xff08;三&#xff09;&a…

MATLAB 数据类型

MATLAB 数据类型 MATLAB 不需要任何类型声明或维度语句。每当 MATLAB 遇到一个新的变量名&#xff0c;它就创建变量并分配适当的内存空间。 如果变量已经存在&#xff0c;那么MATLAB将用新内容替换原始内容&#xff0c;并在必要时分配新的存储空间。 例如&#xff0c; Tota…

Vue3中使用无缝滚动插件vue3-seamless-scroll

官网&#xff1a;https://www.npmjs.com/package/vue-seamless-scroll 1、实现效果文字描述&#xff1a; 表格中的列数据进行横向无缝滚动&#xff0c;某一列进行筛选的时候&#xff0c;重新请求后端的数据&#xff0c;进行刷新 2、安装&#xff1a;npm i vue3-seamless-scrol…

小程序 rich-text 解析富文本 图片过大时如何自适应?

在微信小程序中&#xff0c;用rich-text 解析后端返回的数据&#xff0c;当图片尺寸太大时&#xff0c;会溢出屏幕&#xff0c;导致横向出现滚动 查看富文本代码 图片是用 <img 标签&#xff0c;所以写个正则匹配一下图片标签&#xff0c;手动加上样式即可 // content 为后…

Python 面向对象——5.多态

本章学习链接如下&#xff1a; Python 面向对象——1.基本概念 Python 面向对象——2.类与对象实例属性补充解释&#xff0c;self的作用等 Python 面向对象——3.实例方法&#xff0c;类方法与静态方法 Python 面向对象——4.继承 1.基本概念 多态是面向对象编程&#x…

贪吃蛇(C语言版)

在我们学习完C语言 和单链表知识点后 我们开始写个贪吃蛇的代码 目标&#xff1a;使用C语言在Windows环境的控制台模拟实现经典小游戏贪吃蛇 贪吃蛇代码实现的基本功能&#xff1a; 地图的绘制 蛇、食物的创建 蛇的状态&#xff08;正常 撞墙 撞到自己 正常退出&#xf…

Python蜘蛛侠

目录 写在前面 蜘蛛侠 编写代码 代码分析 更多精彩 写在后面 写在前面 本期小编给大家推荐一个酷酷的Python蜘蛛侠&#xff0c;一起来看看叭~ 蜘蛛侠 蜘蛛侠&#xff08;Spider-Man&#xff09;是美国漫威漫画宇宙中的一位标志性人物&#xff0c;由传奇创作者斯坦李与艺…

探索ChatGPT在提高人脸识别与软性生物识准确性的表现与可解释性

概述 从GPT-1到GPT-3&#xff0c;OpenAI的模型不断进步&#xff0c;推动了自然语言处理技术的发展。这些模型在处理语言任务方面展现出了强大的能力&#xff0c;包括文本生成、翻译、问答等。 然而&#xff0c;当涉及到面部识别和生物特征估计等任务时&#xff0c;这些基于文…