tcpdump分析慢sql实战

AntTech_LUTVQZ · 2023 年9 月 6 日 20:43

环境准备:

1.新建一个 oracle 租户 1C2GB
obclient -uroot@sys -h127.0.0.1 -P2881
新建资源规格：
create resource unit u1_ora max_cpu=1,min_cpu=1,max_memory=‘2G’,min_memory=‘2G’,max_iops=128,max_disk_size=‘10G’,max_session_num=100;
新建资源池：
create resource pool pool_ora unit=‘u1_ora’,unit_num=1,zone_list=(‘zone1’,‘zone2’,‘zone3’);
新建租户：
CREATE TENANT IF NOT EXISTS ob_pay charset=‘utf8mb4’, replica_num=1, zone_list=(‘zone1’,‘zone2’,‘zone3’), resource_pool_list=(‘pool_ora’) SET ob_tcp_invited_nodes=’%’, ob_compatibility_mode=‘oracle’;

obclient -h172.16.1.221 -P2883 -uSYS@ob_pay#obce_test

2.新建 tpcc 用户，授予 dba 权限：
create user tpcc identified by obce_test;
grant dba to tpcc;

3.登陆 oracle 租户下的 tpcc 用户，创建 3 张表，模拟交易的场景，第 1 张表和第 2 张表的结构一致，第 3 张表为不同结构
obclient -utpcc@ob_pay#obce_test -h172.16.1.221 -P2883 -p

create table tab1 (c1 int primary key, c2 int, c3 varchar(10)) partition by hash(c1) partitions 10;
create table tab2 (c1 int primary key, c2 int, c3 varchar(10)) partition by hash(c1) partitions 10;
create table tab3 (d1 int primary key, d2 int) partition by list (d1)
(partition p0 values(1,2,3,4,5),
partition p1 values(6,7,8,9,10),
partition p2 values (11,12,13,14,15));

向表中插入测试数据
insert into tab1 select level, mod(level,10),‘003’ from dual connect by level<=150;
insert into tab2 select level, mod(level,5),‘004’ from dual connect by level<=150;
insert into tab3 select level, mod(level,3) from dual connect by level<=15;
commit;

show proxyconfig like ‘%query_digest_time_threshold%’;

ob_proxy_readonly_transaction_routing_policy 的默认值，修改query_digest_time_threshold=100us

obclient -h172.16.1.221 -P2883 -uroot@sys -p -Doceanbase
SQL>show parameters like ‘ob_proxy_readonly_transaction_routing_policy’; --默认值为true，无需修改
SQL> show proxyconfig like ‘query_digest_time_threshold’; --默认值为 100ms,
SQL>alter proxyconfig set query_digest_time_threshold=‘100us’;

打开一个新的 OS 命令行窗口，运行以下命令，监测网络的数据流量
netstat -anltp|grep obclient|grep 2883 –此命令查看第一步 obclient 的 session 端口号，记录第一个 IP 地址后面的端口号，这里为 30652; 注意显示结果中 observer 的 ip 地址相同。
[root@ocp ~]# netstat -anltp|grep obclient|grep 2883
tcp 0 0 172.16.1.221:46562 172.16.1.221:2883 ESTABLISHED 10126/obclient

tcp 0 0 127.0.0.1:16010 127.0.0.1:2883 ESTABLISHED 5378/obclient

tcpdump -i lo port 16010 -w /tmp/tcpdump.raw –-此命令将 tcpdump 获取的网络包写入一个临时文件

返回第一个步骤的 obclient 窗口，在 TPCC 用户下模拟运行一些查询和 update 语句
select c1,c2 from tab1 where c1=10;
select c1,c2 from tab2 where c1=10;
update tab3 set d2=2 where d1=10;
commit;
select c1,c2 from tab1 where c1=11;
select c1,c2 from tab2 where c1=11;
update tab3 set d2=3 where d1=11;
commit;
在 ssh 终端 tcpdump 命令窗口，使用 ctrl+c 终止命令

10 使用以下命令将 tcpdump.raw 文件转换为文本格式，便于使用文本编辑器查看

tcpdump -X -r /tmp/tcpdump.raw > /tmp/tcpdump.txt
more /tmp/tcpdump.txt

11 查看 tcpdump.txt 的内容, 参考以下信息解析 tcpdump 文件的内容
l 第一列：时分秒毫秒 21:26:49.013621
l 第二列：网络协议 IP
l 第三列：发送方的 ip 地址+端口号，其中 ob003 是主机名或者 ip，30652 是端口号
l 第四列：箭头 >，表示数据流向
l 第五列：接收方的 ip 地址+端口号，
l 第六列：冒号
l 第七列：数据包内容，包括 Flags 标识符，seq 号，ack 号，win 窗口，数据长度 length

12 登陆 sys 用户，执行以下命令查询 SQL 语句的执行情况
obclient -h127.0.0.1 -P2883 -uroot@sys -p -Doceanbase
select svr_ip,query_sql,sql_id,plan_id, trace_id,rpc_count,plan_type,is_hit_plan,elapsed_time,execute_time,get_plan_time from gv$sql_audit
where query_sql like ‘%TAB1%’ or query_sql like ‘%TAB2%’ or query_sql like ‘%TAB3%’ and tenant_id=1001
and user_name=‘tpcc’ order by request_time\G

*************************** 1. row ***************************
svr_ip: 172.16.1.221
query_sql: create table tab1 (c1 int primary key, c2 int, c3 varchar(10)) partition by hash(c1) partitions 10
sql_id: 26F460A2C1500C8C952103041689803F
plan_id: 0
trace_id: YB42AC1001DD-0005F90936C455DB-0-0
rpc_count: 1
plan_type: 0
is_hit_plan: 0
elapsed_time: 237434
execute_time: 236732
get_plan_time: 669
*************************** 2. row ***************************
svr_ip: 172.16.1.221
query_sql: create table tab2 (c1 int primary key, c2 int, c3 varchar(10)) partition by hash(c1) partitions 10
sql_id: F7BB7799058C1A18D70EB46932B77EF0
plan_id: 0
trace_id: YB42AC1001DD-0005F90936C455DC-0-0
rpc_count: 1
plan_type: 0
is_hit_plan: 0
elapsed_time: 137845
execute_time: 137392
get_plan_time: 420
*************************** 3. row ***************************
svr_ip: 172.16.1.221
query_sql: create table tab3 (d1 int primary key, d2 int) partition by list (d1)
(partition p0 values(1,2,3,4,5),
partition p1 values(6,7,8,9,10),
partition p2 values (11,12,13,14,15))
sql_id: F5888F9CB8A3C29E6355C0BCA0FFB456
plan_id: 0
trace_id: YB42AC1001DD-0005F90936C455DD-0-0
rpc_count: 1
plan_type: 0
is_hit_plan: 0
elapsed_time: 117867
execute_time: 117114
get_plan_time: 709
*************************** 4. row ***************************
svr_ip: 172.16.1.220
query_sql: insert into tab1 select level, mod(level,10),‘003’ from dual connect by level<=150
sql_id: E84B3E0A969ED47C2B31BA78A90D0D7E
plan_id: 845
trace_id: YB42AC1001DC-0005F909347639E3-0-0
rpc_count: 7
plan_type: 1
is_hit_plan: 0
elapsed_time: 18603
execute_time: 7782
get_plan_time: 10809
*************************** 5. row ***************************
svr_ip: 172.16.1.220
query_sql: insert into tab2 select level, mod(level,5),‘004’ from dual connect by level<=150
sql_id: 469E707CFBBAD378141B108D1958D2AF
plan_id: 847
trace_id: YB42AC1001DC-0005F909347639E4-0-0
rpc_count: 7
plan_type: 1
is_hit_plan: 0
elapsed_time: 14972
execute_time: 6342
get_plan_time: 8611
*************************** 6. row ***************************
svr_ip: 172.16.1.220
query_sql: insert into tab3 select level, mod(level,3) from dual connect by level<=15
sql_id: 9D07C3F680DD264B4959675B537FA073
plan_id: 848
trace_id: YB42AC1001DC-0005F909347639E5-0-0
rpc_count: 2
plan_type: 1
is_hit_plan: 0
elapsed_time: 6840
execute_time: 2038
get_plan_time: 4775
*************************** 7. row ***************************
svr_ip: 172.16.1.219
query_sql: select c1,c2 from tab1 where c1=10
sql_id: 4700CA3BD133AF6835C3DB95FF161077
plan_id: 9
trace_id: YB42AC1001DB-0005F90933087903-0-0
rpc_count: 2
plan_type: 1
is_hit_plan: 0
elapsed_time: 9048
execute_time: 119
get_plan_time: 8915
*************************** 8. row ***************************
svr_ip: 172.16.1.219
query_sql: select c1,c2 from tab2 where c1=10
sql_id: AF8B801A780497DD7F9D99C958A70B8F
plan_id: 12
trace_id: YB42AC1001DB-0005F90933087904-0-0
rpc_count: 4
plan_type: 2
is_hit_plan: 0
elapsed_time: 13721
execute_time: 9049
get_plan_time: 4648
*************************** 9. row ***************************
svr_ip: 172.16.1.219
query_sql: update tab3 set d2=2 where d1=10
sql_id: 0FC0EA8A8AC1577CE675D74174C60AFE
plan_id: 14
trace_id: YB42AC1001DB-0005F90933087905-0-0
rpc_count: 4
plan_type: 2
is_hit_plan: 0
elapsed_time: 8169
execute_time: 4578
get_plan_time: 3566
*************************** 10. row ***************************
svr_ip: 172.16.1.220
query_sql: select c1,c2 from tab1 where c1=11
sql_id: 4700CA3BD133AF6835C3DB95FF161077
plan_id: 857
trace_id: YB42AC1001DC-0005F909343639F1-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 0
elapsed_time: 2858
execute_time: 70
get_plan_time: 2774
*************************** 11. row ***************************
svr_ip: 172.16.1.220
query_sql: select c1,c2 from tab2 where c1=11
sql_id: AF8B801A780497DD7F9D99C958A70B8F
plan_id: 859
trace_id: YB42AC1001DC-0005F909343639F2-0-0
rpc_count: 1
plan_type: 2
is_hit_plan: 0
elapsed_time: 5322
execute_time: 4009
get_plan_time: 1299
*************************** 12. row ***************************
svr_ip: 172.16.1.220
query_sql: update tab3 set d2=3 where d1=11
sql_id: 0FC0EA8A8AC1577CE675D74174C60AFE
plan_id: 860
trace_id: YB42AC1001DC-0005F909343639F3-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 0
elapsed_time: 1558
execute_time: 179
get_plan_time: 1360
12 rows in set (0.060 sec)s

观察 rpc_count,plan_type, elapsed_time 等字段获取 SQL 语句执行时间执行计划等详情。

13 使用以下命令查看 obproxy_digest.log 中 SQL 语句的耗时情况
tail -100 /opt/taobao/install/obproxy/log/obproxy_digest.log

14 在第一步的 tpcc 窗口，创建一个表组，将表 tab1 和 tab2 放入此表组中
create tablegroup tab_group partition by hash partitions 10;
alter table tab1 tablegroup tab_group;
alter table tab2 tablegroup tab_group;

15 重复执行第 4 步 tcpdump -i lo port 46562 -w /tmp/tcpdump.raw 命令之后的步骤，比较表
组与没有表组的场景下，执行情况的不同

16 登陆 sys 用户，执行以下命令查询 SQL 语句的执行情况
obclient -h127.0.0.1 -P2883 -uroot@sys -p -Doceanbase
select svr_ip,query_sql,sql_id,plan_id, trace_id,rpc_count,plan_type,is_hit_plan,elapsed_time,execute_time,get_plan_time from gv$sql_audit
where query_sql like ‘%TAB1%’ or query_sql like ‘%TAB2%’ or query_sql like ‘%TAB3%’ and tenant_id=1001
and user_name=‘tpcc’ order by request_time\G

*************************** 13. row ***************************
svr_ip: 172.16.1.229
query_sql: alter table tab1 tablegroup tab_group
sql_id: 0FF35DE77EFFA8C6811958105F7A4521
plan_id: 0
trace_id: YB42AC1001E5-0005ED7C8D0F92E7-0-0
rpc_count: 1
plan_type: 0
is_hit_plan: 0
elapsed_time: 86433
execute_time: 86112
get_plan_time: 285
*************************** 14. row ***************************
svr_ip: 172.16.1.229
query_sql: alter table tab2 tablegroup tab_group
sql_id: 0B85B7893CB7A1C885C437166E9526D0
plan_id: 0
trace_id: YB42AC1001E5-0005ED7C8D0F92E8-0-0
rpc_count: 1
plan_type: 0
is_hit_plan: 0
elapsed_time: 35788
execute_time: 35561
get_plan_time: 198
*************************** 15. row ***************************
svr_ip: 172.16.1.230
query_sql: select c1,c2 from tab1 where c1=10
sql_id: 4700CA3BD133AF6835C3DB95FF161077
plan_id: 10
trace_id: YB42AC1001E6-0005ED7C8A517F5D-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 0
elapsed_time: 1507
execute_time: 83
get_plan_time: 1411
*************************** 16. row ***************************
svr_ip: 172.16.1.230
query_sql: select c1,c2 from tab2 where c1=10
sql_id: AF8B801A780497DD7F9D99C958A70B8F
plan_id: 11
trace_id: YB42AC1001E6-0005ED7C8A517F5E-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 0
elapsed_time: 992
execute_time: 57
get_plan_time: 919
*************************** 17. row ***************************
svr_ip: 172.16.1.230
query_sql: update tab3 set d2=2 where d1=10
sql_id: 0FC0EA8A8AC1577CE675D74174C60AFE
plan_id: 8
trace_id: YB42AC1001E6-0005ED7C8A517F5F-0-0
rpc_count: 2
plan_type: 2
is_hit_plan: 1
elapsed_time: 1442
execute_time: 1345
get_plan_time: 82
*************************** 18. row ***************************
svr_ip: 172.16.1.229
query_sql: select c1,c2 from tab1 where c1=11
sql_id: 4700CA3BD133AF6835C3DB95FF161077
plan_id: 882
trace_id: YB42AC1001E5-0005ED7C8D0F92E9-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 0
elapsed_time: 1758
execute_time: 90
get_plan_time: 1632
*************************** 19. row ***************************
svr_ip: 172.16.1.229
query_sql: select c1,c2 from tab2 where c1=11
sql_id: AF8B801A780497DD7F9D99C958A70B8F
plan_id: 883
trace_id: YB42AC1001E5-0005ED7C8D0F92EA-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 0
elapsed_time: 1117
execute_time: 62
get_plan_time: 1028
*************************** 20. row ***************************
svr_ip: 172.16.1.229
query_sql: update tab3 set d2=3 where d1=11
sql_id: 0FC0EA8A8AC1577CE675D74174C60AFE
plan_id: 862
trace_id: YB42AC1001E5-0005ED7C8D0F92EB-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 1
elapsed_time: 354
execute_time: 271
get_plan_time: 65
20 rows in set (0.025 sec)

17 修改参数 ob_proxy_readonly_transaction_routing_policy=False
alter system set ob_proxy_readonly_transaction_routing_policy=false tenant=all;

18 重复执行第 4 步 tcpdump -i lo port 30652 -w /tmp/tcpdump.raw 命令之后的步骤，比较表
组与没有表组的场景下，执行情况的不同，以下为部分样例，具体学员根据前序步骤尝试

19 重复 SQL 命令，获取执行时间等信息，比较 ob_proxy_readonly_transaction_routing_policy 在启用和禁用两种场景下，执行情况的不同
select c1,c2 from tab1 where c1=10;
select c1,c2 from tab2 where c1=10;
update tab3 set d2=2 where d1=10;
commit;
select c1,c2 from tab1 where c1=11;
select c1,c2 from tab2 where c1=11;
update tab3 set d2=3 where d1=11;
commit;

select svr_ip,query_sql,sql_id,plan_id, trace_id,rpc_count,plan_type,is_hit_plan,elapsed_time,execute_time,get_plan_time from gv$sql_audit where query_sql like ‘%TAB1%’ or query_sql like ‘%TAB2%’ or query_sql like ‘%TAB3%’ and tenant_id=1001
and user_name=‘tpcc’ order by request_time\G

*************************** 27. row ***************************
svr_ip: 172.16.1.219
query_sql: select c1,c2 from tab1 where c1=10
sql_id: 4700CA3BD133AF6835C3DB95FF161077
plan_id: 16
trace_id: YB42AC1001DB-0005F90933087910-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 1
elapsed_time: 174
execute_time: 91
get_plan_time: 57
*************************** 28. row ***************************
svr_ip: 172.16.1.219
query_sql: select c1,c2 from tab2 where c1=10
sql_id: AF8B801A780497DD7F9D99C958A70B8F
plan_id: 17
trace_id: YB42AC1001DB-0005F90933087911-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 1
elapsed_time: 114
execute_time: 54
get_plan_time: 35
*************************** 29. row ***************************
svr_ip: 172.16.1.221
query_sql: update tab3 set d2=2 where d1=10
sql_id: 0FC0EA8A8AC1577CE675D74174C60AFE
plan_id: 21
trace_id: YB42AC1001DD-0005F90936C455E2-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 0
elapsed_time: 1528
execute_time: 203
get_plan_time: 1311
*************************** 30. row ***************************
svr_ip: 172.16.1.220
query_sql: select c1,c2 from tab1 where c1=11
sql_id: 4700CA3BD133AF6835C3DB95FF161077
plan_id: 879
trace_id: YB42AC1001DC-0005F90934363A00-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 1
elapsed_time: 145
execute_time: 67
get_plan_time: 58
*************************** 31. row ***************************
svr_ip: 172.16.1.220
query_sql: select c1,c2 from tab2 where c1=11
sql_id: AF8B801A780497DD7F9D99C958A70B8F
plan_id: 880
trace_id: YB42AC1001DC-0005F90934363A01-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 1
elapsed_time: 91
execute_time: 48
get_plan_time: 28
*************************** 32. row ***************************
svr_ip: 172.16.1.220
query_sql: update tab3 set d2=3 where d1=11
sql_id: 0FC0EA8A8AC1577CE675D74174C60AFE
plan_id: 860
trace_id: YB42AC1001DC-0005F90934363A02-0-0
rpc_count: 0
plan_type: 1
is_hit_plan: 1
elapsed_time: 257
execute_time: 186
get_plan_time: 49
32 rows in set (0.027 sec)

结论：比较在 3 个场景执行一个事务（包含查询和 update 语句），根据整个 SQL 执行链路（obproxy，网络，observer），第三个场景下
（ob_proxy_readonly_transaction_routing_policy=False 结合表组），执行速度最快，第二个场景（ob_proxy_readonly_transaction_routing_policy=true 结合表组）
执行速度次之，最慢的是第一个场景（ob_proxy_readonly_transaction_routing_policy=true 无表组）

AntTech_LUTVQZ · 2023 年9 月 7 日 07:31

TCPDump是一个根据使用者的定义对网络上的数据包进行截获的包分析的工具

示例：使用TCPDump分析一个Java应用与数据库之间的网络耗时

l 在应用服务器tcpdump抓包步骤

找到应用线程连接OceanBase数据库(OBProxy)的端口：

netstat -anltp|grep java|grep 2883

使用TCPDump命令对Java线程与数据库连接的网络端口，并把报文存储在raw文件：

tcpdump -i eth0 and port ‘(xx or xx)’ -w /tmp/tcpdump.raw

xx：步骤1中查到的Java应用连接端口号

把搜集到的报文翻译成可读的txt文本：

tcpdump -X -r /tmp/tcpdump.raw > /tmp/tcpdump.txt

-X : 对报文进行翻译

-r：读取指定的tcpdump抓包文件

应用与数据库的三次通信握手

应用发送SQL到OceanBase数据库
OceanBase把执行结果返回给应用，可以有多个报文，数量与结果集的大小有关
应用发送应答给OceanBase确认数据已经接收完成

n 从应用角度看，SQL的执行时间就是步骤3减去步骤1的时间，包含了数据库执行和网络传输的时间

甫瑜 · 2023 年9 月 7 日 09:29

mark