乐趣区

关于oceanbase:技术分享-OB-慢查询排查思

本文汇总了我的项目实际中前辈的教训和笔者的了解,旨在帮忙初学 OceanBase(以下简称 OB)的工程师,疾速解决 SQL 执行迟缓等性能问题。当遇到性能问题时,很多工程师可能会感到无从下手,本文将依据要害日志提供多种剖析方向,以减速问题排查。

背景

利用连贯 OB 的生产架构,个别有两种:

  1. 应⽤ -> OBProxy -> OBServer
  2. 应⽤ -> OBProxy-Sharding -> OBServer

前者是大多数客户使⽤场景,后者是多数客户使⽤的单元化架构场景,后文将 OBProxy 和 OBProxy-Sharding 统称为 ODP(OceanBase Database Proxy)。

当咱们发现某条语句耗时较长时,咱们须要排查的点有:应⽤到 ODP 的⽹络工夫、ODP 的执行工夫、ODP 到 OBServer 的⽹络工夫、OBServer 的执行工夫。

从哪些信息动手?

要诊断哪局部工夫耗费长,以及起因是什么,大多数状况会从如下几个组件获取信息。

ODP 组件

  • obproxy_digest.log:审计⽇志,记录执⾏失败的 SQL 语句、执行工夫大于参数 query_digest_time_threshold 阈值(默认是 2ms)申请。
  • obproxy_slow.log:慢 SQL 申请日志,记录执⾏工夫大于参数 slow_query_time_threshold 阈值(默认是 500ms)的申请。
  • obproxy.log:ODP 总日志。

obproxy_digest.logobproxy_slow.log 中,第 15、16、17、18 列(即 8353us,179us,0us,5785us)别离示意:ODP 解决总工夫、ODP 预处理工夫、ODP 获取连接时间、OBServer 执⾏工夫。示例如下:

2023-05-04
16:46:03.513268,test_obproxy,,,,test:ob_mysql:sbtest,OB_MYSQL,sbtest1,sbtest1,COM_QUERY
,SELECT,failed,1064,select t1.*%2Ct2.* from sbtest1 t1%2Csbtest2 t2 where t1.id = t2.id
where id <10000,8353us,179us,0us,5785us,Y0-7FA25BB4A2E0,YB420ABA3FAC-0005FA2415BE0F81-
0-0,,,0,10.186.63.172:2881
  • ODP 解决总工夫的终点:ODP 接管到客户端申请的工夫;
  • ODP 解决总工夫的起点:ODP 把所有的数据都写回给客户端;
  • ODP 预处理工夫:蕴含去 oceanbase.__all_virtual_proxy_schema 查问 Leader 的工夫;
  • ODP 获取连接时间:目前不做记录,看到的都是 0;
  • OBServer 执行工夫:终点是 ODP 发送申请给 OBServer,起点是收到 OBServer 返回第一条记录。

从下面的原理能够看出,后三项工夫相加并不等于第一项工夫,比方 ODP 解决总工夫比拟长,然而预处理工夫和 OBServer 执行工夫都很短,有可能工夫耗费在 OBServer 将第一条记录返回给 ODPServer 和 ODPServer 把所有数据写回给客户端之间,这在后果集较大的 SQL 语句中⽐较常⻅。

OBserver 组件

  • gv$audit_sql:该视图⽤于展现所有 OBServer 上每⼀次 SQL 申请的起源、执⾏状态等统计信息。

该视图是依照租户拆分的,除了零碎租户,其余租户不能跨租户查问。⼀般常⽤的字段有:request_timesql_id,`
plan_idplan_typetrace_idsvr_ipclient_ipuser_client_ipuser_namedb_nameelapsed_timequeue_timeget_plan_timeexecute_timeretry_cnttable_scanret_codequery_sql`……

# 大抵的归类如下
标识信息:tenant_id,sql_id,trace_id,plan_id,sid,transaction_hash,......
来自哪⾥:user_name,user_client_ip,client_ip(OBProxy),......
在哪执行:svr_ip,db_name,plan_type,......
开始工夫:request_time
执行耗时:elapsed_time,get_plan_time,execute_time,......
期待耗时:total_wait_time_micro,queue_time,net_time,user_io_wait_time,......
数据扫描:table_scan(全表扫描),disk_reads,memstore_read_row_count,sstable_read_row_count,......
并行执行:expected_worker_count,used_worker_count,qc_id,sqc_id,worker_id,......
申请类型:request_type,......
强弱读:consistency_level
数据量:affected_rows,return_rows,partition_cnt,......
返回码:ret_code
  • observer.log:OBServer 运行的次要⽇志,这外面的信息十分全面,内部用户不易解读,很多状况下会依据 trace_id 去搜寻,例如通过 OCP 的 SQL 诊断性能获取到 TraceID,再进⾏查问。

常见 OB 慢查问剖析思路

1. ODP 给利用回写数据耗时长

当 SQL 的后果集很大,ODP 就须要较长时间将数据返回给利用,这时候会发现 OBServer 执行工夫和 ODP 预处理工夫相加,比 ODP 执行总工夫要小,以上面的 obproxy.log 记录为例:

[2023-04-19 19:12:31.662602] WARN [PROXY.SM] update_cmd_stats (ob_mysql_sm.cpp:8633)
[5628][Y0-7F820F6C7960] [lt=38] [dc=0] Slow Query: ((client_ip={x.x.x.x:51555},
server_ip={x.x.x.x:2881}, obproxy_client_port={x.x.x.x:33584},
server_trace_id=YB420A97B009-0005F6EF28FSFS11-0-0, route_type=ROUTE_TYPE_LEADER,
user_name=depo, tenant_name=su, cluster_name=cmcluster, logic_database_name=,
logic_tenant_name=, ob_proxy_protocol=0, cs_id=1077902,
proxy_sessid=1513983664671181892, ss_id=611834, server_sessid=3221841415, sm_id=260155,
cmd_size_stats={client_request_bytes:87, server_request_bytes:122,
server_response_bytes:0, client_response_bytes:185002181}, cmd_time_stats=
{client_transaction_idle_time_us=0, client_request_read_time_us=11,
client_request_analyze_time_us=10, cluster_resource_create_time_us=0,
pl_lookup_time_us=4, pl_process_time_us=4, congestion_control_time_us=1,
congestion_process_time_us=0, do_observer_open_time_us=2, server_connect_time_us=0,
server_sync_session_variable_time_us=0, server_send_saved_login_time_us=0,
server_send_use_database_time_us=0, server_send_session_variable_time_us=0,
server_send_all_session_variable_time_us=0, server_send_last_insert_id_time_us=0,
server_send_start_trans_time_us=0, build_server_request_time_us=2,
plugin_compress_request_time_us=0, prepare_send_request_to_server_time_us=65,
server_request_write_time_us=20, server_process_request_time_us=337792,
server_response_read_time_us=2353609, plugin_decompress_response_time_us=1299449,
server_response_analyze_time_us=17505, ok_packet_trim_time_us=0,
client_response_write_time_us=1130104, request_total_time_us=5309727}, sql=SELECT x,x,x
FROM sbtest.sbtest1 where id =1)
  • client_response_bytes:185002181
  • client_response_write_time_us=1130104

该示例中,ODP 回写给利用的数据为 185MB,耗时 1.1s,能够通过该信息观测下是否是 SQL 的后果集较大。

2. ODP 获取 location cache 慢

ODP 要把 SQL 路由到精确的 OBServer 上,只须要晓得每个 Table 的 Partition 的 Leader 所在位置,获取地位的过程叫做 “get location cache”。通常这个过程很快,并且获取后会缓存在本地,多数状况下,这个工夫耗费会慢,以上面为例:

[2023-05-07 00:01:04.506809] WARN [PROXY.SM] update_cmd_stats (ob_mysql_sm.cpp:8607)
[363][Y0-7F4521AA21A0] [lt=28] [dc=0] Slow Query: ((client_ip={x.x.x.x:36246},
server_ip={x.x.x.x:2881}, obproxy_client_port={21.2.1
92.29:40556}, server_trace_id=, route_type=ROUTE_TYPE_LEADER, user_name=mY14OyQ1tF,
tenant_name=bu06, cluster_name=cscluster2, logic_database_name=budb,
logic_tenant_name=odp-h170kfw30w7l, ob_proxy_protocol=2, cs_id=2993079,
proxy_sessid=1513983656080750373, ss_id=53737247, server_sessid=3223571471,
sm_id=44290320, cmd_size_stats={client_request_bytes:342, server_request_bytes:385,
server_response_bytes:66, client_response_bytes:66}, cmd_time_stats=
{client_transaction_idle_time_us=0, client_request_read_time_us=25,
client_request_analyze_time_us=25, cluster_resource_create_time_us=0,
pl_lookup_time_us=4998993, pl_process_time_us=126, congestion_control_time_us=2,
congestion_process_time_us=0, do_observer_open_time_us=5, server_connect_time_us=0,
server_sync_session_variable_time_us=0, server_send_saved_login_time_us=0,
server_send_use_database_time_us=0, server_send_session_variable_time_us=0,
server_send_all_session_variable_time_us=0, xxxxxxxx
  • pl_lookup_time_us=4998993

耗时 4s 显著有异样,获取到该日志后能够疾速和 OB 研发放大问题排查范畴。

3. 表的路由抉择

在 OceanBase 数据库中,有 Local 打算、Remote 打算和 Distributed 打算三种表路由。Local 打算、Remote 打算均为单分区的路由。ODP 的作⽤就是尽量打消 Remote 打算,将路由尽可能的变为 Local 打算。

如果表路由类型为 Remote 打算的 SQL 过多,则示意该 SQL 性能可能不是最优,通常的起因有 ODP 路由问题、无奈计算表分区 ID、应用了全局索引、须要开启二次路由等等。

通过 gv$sql_auditPLAN_TYPE 字段能够判断 SQL 的执行打算类型:

  • 1:Local
  • 2:Remote
  • 3:Distributed

4. OBServer 写入限速

当 memstore 已使⽤的内存达到 writing_throttling_trigger_percentage 时(默认 100),触发写入限速。当该配置项的值为 100 时,示意敞开写入限速机制。在触发写入限速后,残余 memstore 内存必须保障在
writing_throttling_maximum_duration(默认 1h)内不会调配完,也就是写入速度下限为 `memstore * (1-
writing_throttling_trigger_percentage) / writing_throttling_maximum_duration`。

通过监控 gv$memstore 能够晓得 memstore 应用的百分比。当产生了写入限速,observer.log 中会看到如下记录:

[2023-04-10 10:52:09.076066] INFO [COMMON] ob_fifo_arena.cpp:301 [68425][1739]
[YB420A830ADF-00058B41370AAF4F] [lt=85] [dc=0] report write throttle
info(cur_mem_hold=162644623360, throttle_info_={decay_factor_:"0.000000005732",
alloc_duration_:2400000000, trigger_percentage_:70, memstore_threshold_:231928233960,
period_throttled_count_:140, period_throttled_time_:137915965,
total_throttled_count_:23584, total_throttled_time_:27901629728})

关键字:report,write,throttle,info

还有⼀种场景就是发现 QPS 异样下降时(尤其是蕴含⼤量写⼊,能够通过查问零碎表的⽅式确认是否是因为写⼊限速导致。

select * from v$session_event where EVENT='memstore memory page alloc wait' \G;
*************************** 94. row ***************************
 CON_ID: 1
 SVR_IP: x.x.x.x
 SVR_PORT: 22882
 SID: 3221487713
 EVENT: memstore memory page alloc wait
 TOTAL_WAITS: 182673
 TOTAL_TIMEOUTS: 0
 TIME_WAITED: 1004.4099
 AVERAGE_WAIT: 0.005498403704981032
 MAX_WAIT: 12.3022
 TIME_WAITED_MICRO: 10044099
 CPU: NULL
 EVENT_ID: 11015
 WAIT_CLASS_ID: 109
 WAIT_CLASS#: 9
 WAIT_CLASS: SYSTEM_IO

关键字:memstore,memory,page,alloc,wait

5. 拜访执行打算

拜访打算也是影响 SQL 耗时的⼀个因素,没有命中 plan cache、拜访打算产生了预期外的变动都会造成 SQL 执行变慢。

没有命中 plan cache 能够在 gv$sql_audit 中看到 IS_HIT_PLAN=0

要查看 SQL 具体的执行打算有两种⽅式:一是执行 explain extended <query_sql>,但这只能看到以后环境下,该语句的执行打算,可能并不是现场迟缓 SQL 的执行打算,须要查看迟缓 SQL 正在应用的拜访打算,须要首先记录下 gv$sql_audit 中的四个值:SVR_IPSVR_PORTTENANT_IDPLAN_ID。并在 gv$plan_cache_plan_explain 中进行查问:

select SVR_IP, SVR_PORT, TENANT_ID, PLAN_ID from gv$sql_audit where query_sql ...
select * from gv$plan_cache_plan_explain where ip=<SVR_IP> and port=<SVR_PORT> and
tenant_id=<TENANT_ID> and plan_id=<PLAN_ID>

6. OBServer 锁期待

OceanBase 抉择 MVCC 来实现事务并发性和一致性,反对读写不互斥。因而事务间的锁期待个别产生在写申请上(lock_for_write),极少状况下也会产生在读申请(lock_for_shared)。

当产生了锁期待,SQL 执⾏耗时也会变长,通常的体现是:在 gv$sql_audit 中看到 elapsed_time 较大,execute_time 较小,retry_cnt 较大(>0),随同 observer.log 能够察看到如下日志:

[2023-03-29 12:00:26.310172] WARN [STORAGE.TRANS] on_wlock_retry
(ob_memtable_context.cpp:393) [135700][2338][Y1312AC1C4140-0005EFC759EADC21] [lt=10]
[dc=0] lock_for_write conflict(*this=alloc_type=0 ctx_descriptor=700817166
trans_start_time=1680062426310071 min_table_version=1679627152331552
max_table_version=1679627152331552 is_safe_read=false has_read_relocated_row=false
read_snapshot=1680062426310007 start_version=-1 trans_version=9223372036854775807
commit_version=0 stmt_start_time=1680062426310074 abs_expired_time=1680062436209982
stmt_timeout=9899908 abs_lock_wait_timeout=1680062436209982 row_purge_version=0
lock_wait_start_ts=0 trx_lock_timeout=-1 end_code=0 is_readonly=false ref=2 pkey=
{tid:1116004302242691, partition_id:0, part_cnt:0} trans_id={hash:4021727895899886621,
inc:669379877, addr:"172.28.65.64:4882", t:1680062426310046} data_relocated=0
relocate_cnt=0 truncate_cnt=0 trans_mem_total_size=0 callback_alloc_count=0
callback_free_count=0 callback_mem_used=0 checksum_log_ts=0,
key=table_id=1116004302242691 rowkey_object=[{"BIGINT":2024021}] ,
conflict_ctx="alloc_type=0 ctx_descriptor=700817301 trans_start_time=1680062426309892
xx
  • 关键字:lock_for_write,conflict

7. SQL 语句有问题

个别 SQL 语句查问慢排除上述问题后,大部分跟本身无关,例如 SQL 语句没有走到索引、写法有问题等。这种状况就须要:

  1. 通过 gv$sql_audit 表或 ODP 日志拿到具体的 SQL 文本。
# 查问以某个租户⼀段范畴内执⾏耗时的 SQL 语句进⾏排序
SELECT usec_to_time(request_time) as request_time,
sql_id, plan_id, plan_type, trace_id,
svr_ip, client_ip, user_client_ip, user_name, db_name elapsed_time, queue_time,
get_plan_time, execute_time, retry_cnt, table_scan,
ret_code,
query_sql
FROM gv$sql_audit
WHERE tenant_id=1001
AND request_time BETWEEN time_to_usec('2023_05_12 13:00:00')
AND time_to_usec('2023_05_13 13:10:00') AND is_executor_rpc = 0
ORDER BY elapsed_time DESC limit 10;
  1. 拿到 SQL 文本后,再通过 Explain 查问打算进⾏剖析(例如对下文语句进⾏ Explain 剖析,比方 name 中只有表名不蕴含索引列的话,则该 SQL 语句可能应用的主键或全表扫描)。
obclient [sbtest]> explain select * from sbtest1 where k like '%111181823%' \G
*************************** 1. row ***************************
Query Plan: ========================================
|ID|OPERATOR |NAME |EST. ROWS|COST |
----------------------------------------
|0 |TABLE SCAN|sbtest1|283098 |333648|
========================================
Outputs & filters:
-------------------------------------
0 - output([sbtest1.id], [sbtest1.k], [sbtest1.c], [sbtest1.pad]),
filter([(T_OP_LIKE, cast(sbtest1.k, VARCHAR(1048576)), '%111181823%', '\\')]),
 access([sbtest1.k], [sbtest1.id], [sbtest1.c], [sbtest1.pad]), partitions(p0)
1 row in set (0.004 sec)
  1. 排查 SQL 老本和执行打算中拜访程序是否有问题,就不具体开展了。

以上就是导致 OB 慢查问常见的起因及剖析思路,心愿对读者有所帮忙。

退出移动版