最新消息:

tcpdump分析MySQL事务的时延水平

mysql admin 4544浏览 1评论

项目中需要统计MySQL的事务响应时间,而前端没有打印SQL请求的时间戳,因此想到用tcpdump来抓取数据库和客户端的交互信息,以分析事务的时延水平。

初步分析了一段tcpdump的日志,发现客户端和数据库之间交互的事务主要分以下两种类型

编号 commit类型 SQL序列类型
1 自动提交 1.set autocommit=1

2.SQL请求

2 手动提交 1.set autocommit=0

2.insert/update/delete/select请求

3.commit

对于第一种类型的SQL,分析发现都只有set autocommit=1语句,客户端没有继续发送任何SQL。有可能是前端的编程框架发送的语句。分析中需要过滤掉。这种的请求的交互信息如下图所示

2738470048435856375

第二种类型,是手动开启一个事务然后手动提交,其TCP交互过程如下图所示:

3173067412559332353

我们需要得到一个事务的处理时间,该时间区间,应该是从client端发送set autocommit=0命令开始计时,到MySQL对commit命令发送响应截止。对tcpdump的数据需要做如下的处理

1.过滤掉set autocommit=1,以及在autocommit=1场景下的所有SQL

2.截取set autocommit=0的时间,截取MySQL对commit命令发送响应的时间

3.由于tcpdump出的数据混合了MySQL和所有客户端的交互信息,因此需要区分每一个客户端的请求交互。另外为了样本足够大,以及排除单个client的噪点(如跨网络,client性能不好),需要把所有client的每个事务的处理时间进行汇总处理。

由于tcpdump的结果是ip,tcp和mysql协议三层数据的组合。为了解决上面的问题,需要了解三个协议的格式

(1)IP协议

IP协议格式如下:

3159838088653944172

其各个字段的意义如下表解释:

协议版本(4bit) 头部长度(4bit)(需*多少32bits) 服务类型TOS(8bit) IP包总长度(16bits) 包唯一标识(16bits) 标识字段和片偏移,用于分片(16bits) TTL(8bits)存活时间 协议类型(8bits)对于tcp协议是06 表头校验(16bits) 源IP(4字节) 目的IP(4字节     )

(2)TCP协议

TCP协议格式如下图:

886364701761964731

其各个字段的内容如下表所示:

源端口(2字节) 目的端口(2字节) 包顺序号(4字节) 确认序号,在设置了ACK位事有效(4字节) TCP包头部长度(4bits)需乘以4 保留位(6bits) 标志位6bits(分别标志URG,ACK,PSH,RST,SYN,FIN) 窗口大小(2字节) 校验和(2字节) 紧急指针(2字节) 选项字段(这里一般为12字节)

(3)MySQL协议

MySQL和client之间所有的交互都封装为packet,所有packet 头部都带有4个字节的管理信息,分别是3字节长度,一个字节的顺序ID,每个语句的交互中sequence id都从0开始。

3bytes packet长度,不包括首部四字节。小字节优先,最大16M 1字节(squence id)

client->server 客户端发送到server端的请求。

client和server之间的交互分为两个阶段,分别是connection阶段和command阶段。前者是连接阶段的,后者是执行命令阶段发送的命令。我们主要关注command阶段交互协议。

(1)client->server请求

client到server的请求除了标准的4字节头部外,紧接着1个字节表示了请求的类型,其格式如下

3bytes packet长度,不包括首部四字节。小字节优先最大16M 1字节(squence id) 1 bytes 标志请求类型

请求类型的编码值及其意义如下表所示:

hex constant name
00 COM_SLEEP
01 COM_QUIT
02 COM_INIT_DB
03 COM_QUERY
04 COM_FIELD_LIST
05 COM_CREATE_DB
06 COM_DROP_DB
07 COM_REFRESH
08 COM_SHUTDOWN
09 COM_STATISTICS
0a COM_PROCESS_INFO
0b COM_CONNECT
0c COM_PROCESS_KILL
0d COM_DEBUG
0e COM_PING
0f COM_TIME
10 COM_DELAYED_INSERT
11 COM_CHANGE_USER
12 COM_BINLOG_DUMP
13 COM_TABLE_DUMP
14 COM_CONNECT_OUT
15 COM_REGISTER_SLAVE
16 COM_STMT_PREPARE
17 COM_STMT_EXECUTE
18 COM_STMT_SEND_LONG_DATA
19 COM_STMT_CLOSE
1a COM_STMT_RESET
1b COM_SET_OPTION
1c COM_STMT_FETCH
1d COM_DAEMON
1e COM_BINLOG_DUMP_GTID

(2)server->client的回复主要为三种类型。其类型也是由第四个字节表示,其编码和意义如下表所示

编号 16进制编码 意义
1 0X00 OK_packet 前一命令执行成功(insert/date/update成功)
2 0Xff ERR_packet 前一命令执行失败
3 0Xfe EOF_packet 返回了结果集(select)

三种类型的回复协议如下:

a. OK_Packet:正确信息其格式如下

3bytes packet长度 1字节(squence id) 1字节headder(ox00) 受影响行数(lenenc_int) laster_insert_id

(lenenc_id)

status_flags

(2字节)

warnings数目

(2字节)

用户可读的字符信息(string.EOF类型,即可以用总长度减去头部长度得到)

b.ERR_packet:错误信息

3bytes packet长度 1字节(squence id) 1字节headder(oxff) error_code错误码(2字节) sql_state_maker(1字节) sql_state(5字节 ) error_message(sting.EOF类型)

c. EOF_Packet:只在4.1以上存在。

3bytes packet长度 1字节(squence id) 1字节headder(oxfe) warning_count(2字节)错误数目 status_flag(2字节)

其中Status_flag标志各位的内容如下所示

HEX 枚举值 意义
0x0001 SERVER_STATUS_IN_TRANS 事务处在活跃状态中
0x0002 SERVER_STATUS_AUTOCOMMIT auto_commit打开,此语句已提交
0x0008 SERVER_MORE_RESULTS_EXISTS
0x0010 SERVER_STATUS_NO_GOOD_INDEX_USED
0x0020 SERVER_STATUS_NO_INDEX_USED
0x0040 SERVER_STATUS_CURSOR_EXISTS
0x0100 SERVER_STATUS_DB_DROPPED
0x0200 SERVER_STATUS_NO_BACKSLASH_ESCAPES
0x0400 SERVER_STATUS_METADATA_CHANGED
0x0800 SERVER_QUERY_WAS_SLOW
0x1000 SERVER_PS_OUT_PARAMS

因此判断事务是否提交是只需要看status_flags中是否包含了SERVER_STATUS_AUTOCOMMIT(0x0002) , 在网络中小字节优先

特别的,对于有结果集返回的请求,如Com_query类型请求,MySQL的返回值由大量的packet组成组成.例如对一个成功的select请求。主要组成分别如下

(1)列数目,

(2) 列定义,每一个列定义中都包含了db_name,table_name,colum_name

(3)EOF_PACKET,

(4)结果集内容,行格式存储

(5)EOF_Packet

可能的packet组成结构如下图所示,由于我们这里只需要获取事务的处理时间,不需要关注此种类型的响应。

6597541457146308919

有了上述的背景,再来分析tcpdump的数据。

对一个set autocommit=1的请求,交互过程如下:

 

 

 

16:16:00.116127 IP 10.46.17.51.18168 > 10.23.230.6.5858: tcp 21

0x0000: 4500 0049 d646 4000 3b06 5dea 0a2e 1133 E..I.F@.;.]….3

0x0010: 0a17 e606 46f8 16e2 b3e2 3eeb 09ca 3820 ….F…..>…8.

0x0020: 8018 00e3 fb23 0000 0101 080a 5ef3 5a5d …..#……^.Z]

0x0030: 0167 40dc 1100 0000 0353 4554 2061 7574 .g@……SET.aut

0x0040: 6f63 6f6d 6d69 743d 31 ocommit=1

16:16:00.116171 IP 10.23.230.6.5858 > 10.46.17.51.18168: tcp 11

 

 

0x0000: 4508 003f 27a9 4000 4006 078a 0a17 e606 E..?’.@.@…….

 

 

0x0010: 0a2e 1133 16e2 46f8 09ca 3820 b3e2 3f00 …3..F…8…?.

 

0x0020: 8018 3210 0bb0 0000 0101 080a 0167 40dd ..2……….g@.

0x0030: 5ef3 5a5d 0700 0001 0000 0002 0000 00 ^.Z]………..

 

 

 

上图中,红色部分是IP协议头部(18字节),绿色部分是TCP协议头部(32字节),剩余的部分是MySQL协议内容。我们需要过滤掉set autocommit=1及其响应包。

而对于set autocommit=0状态下的一个事务,交互如下:

(我们只需要得到第一个packet的时间和最后一个packet的时间,即可以计算出事务时间)

 

16:15:19.175053 IP 10.46.17.51.18168 > 10.23.230.6.5858: tcp 21

0x0000: 4500 0049 d582 4000 3b06 5eae 0a2e 1133 E..I..@.;.^….3

0x0010: 0a17 e606 46f8 16e2 b3e2 2c9c 09ca 329f ….F…..,…2.

0x0020: 8018 00e3 555a 0000 0101 080a 5ef2 ba6a ….UZ……^..j

0x0030: 0166 9f6a 1100 0000 0353 4554 2061 7574 .f.j…..SET.aut

0x0040: 6f63 6f6d 6d69 743d 30 ocommit=0

16:15:19.175099 IP 10.23.230.6.5858 > 10.46.17.51.18168: tcp 11

0x0000: 4508 003f 2747 4000 4006 07ec 0a17 e606 E..?’G@.@…….

0x0010: 0a2e 1133 16e2 46f8 09ca 329f b3e2 2cb1 …3..F…2…,.

0x0020: 8018 3210 0bb0 0000 0101 080a 0166 a0e9 ..2……….f..

0x0030: 5ef2 ba6a 0700 0001 0000 0000 0000 00 ^..j………..

16:15:19.176120 IP 10.46.17.51.18168 > 10.23.230.6.5858: tcp 0

0x0000: 4500 0034 d584 4000 3b06 5ec1 0a2e 1133 E..4..@.;.^….3

0x0010: 0a17 e606 46f8 16e2 b3e2 2cb1 09ca 32aa ….F…..,…2.

0x0020: 8010 00e3 33cc 0000 0101 080a 5ef2 ba6b ….3…….^..k

0x0030: 0166 a0e9 .f..

16:15:19.195241 IP 10.46.17.51.18168 > 10.23.230.6.5858: tcp 143

0x0000: 4500 00c3 d586 4000 3b06 5e30 0a2e 1133 E…..@.;.^0…3

0x0010: 0a17 e606 46f8 16e2 b3e2 2cb1 09ca 32aa ….F…..,…2.

0x0020: 8018 00e3 bc48 0000 0101 080a 5ef2 ba7e …..H……^..~

0x0030: 0166 a0e9 8b00 0000 0375 7064 6174 6520 .f…….update.

0x0040: 4643 5f57 6f72 642e 776f 7264 696e 666f FC_Word.wordinfo

0x0050: 3320 3.

16:15:19.195383 IP 10.23.230.6.5858 > 10.46.17.51.18168: tcp 52

0x0000: 4508 0068 2749 4000 4006 07c1 0a17 e606 E..h’I@.@…….

0x0010: 0a2e 1133 16e2 46f8 09ca 32aa b3e2 2d40 …3..F…2…-@

0x0020: 8018 3210 0bd9 0000 0101 080a 0166 a0fe ..2……….f..

0x0030: 5ef2 ba7e 3000 0001 0001 0001 0000 0028 ^..~0……….(

0x0040: 526f 7773 206d 6174 6368 6564 3a20 3120 Rows.matched:.1.

0x0050: 2043 .C

16:15:19.196351 IP 10.46.17.51.18168 > 10.23.230.6.5858: tcp 0

0x0000: 4500 0034 d588 4000 3b06 5ebd 0a2e 1133 E..4..@.;.^….3

0x0010: 0a17 e606 46f8 16e2 b3e2 2d40 09ca 32de ….F…..-@..2.

0x0020: 8010 00e3 32e0 0000 0101 080a 5ef2 ba7f ….2…….^…

0x0030: 0166 a0fe .f..

16:15:19.201148 IP 10.46.17.51.18168 > 10.23.230.6.5858: tcp 11

0x0000: 4500 003f d58a 4000 3b06 5eb0 0a2e 1133 E..?..@.;.^….3

0x0010: 0a17 e606 46f8 16e2 b3e2 2d40 09ca 32de ….F…..-@..2.

0x0020: 8018 00e3 d78d 0000 0101 080a 5ef2 ba84 …………^…

0x0030: 0166 a0fe 0700 0000 0363 6f6d 6d69 74 .f…….commit

16:15:19.201529 IP 10.23.230.6.5858 > 10.46.17.51.18168: tcp 11

0x0000: 4508 003f 274b 4000 4006 07e8 0a17 e606 E..?’K@.@…….

0x0010: 0a2e 1133 16e2 46f8 09ca 32de b3e2 2d4b …3..F…2…-K

0x0020: 8018 3210 0bb0 0000 0101 080a 0166 a104 ..2……….f..

0x0030: 5ef2 ba84 0700 0001 0000 0000 0000 00 ^…………..

由上面的数据set autocommit=1/0两个请求语句只有最后一个字节内容不同(一个1,一个0),我们需要一定的特征提取出来。为此使用了两个特征点

(1)set autocommit=0/1命令的长度为73字节,即此 IP packet的长度为73字节,表达式为ip[2:2] & 0Xffff ==73

(2)通过最后一个字节的不同过滤掉set autocommit=1,(为了特异性更强,取了两个字节)。判断表达式为 tcp[51:2] == 0X3d300。(tcp协议第51个字节开始的2个字节内容)

二者组合形成的tcpdump 过滤命令如下:

tcpdump -r tcp.log -x -q -n ‘ip[2:2] & 0Xffff ==73 and tcp[51:2] == 0X3d300′

这条语句可以得到所有的set autocommit=0类的请求。

得到set autocommit=0请求发出的时间之后,我们需要得到commit命令的响应包的时间戳。分析上面set autocommit=1和set autocommit=0的交互,发现commit语句的响应包不具有特异性。它和set autocommit=1及set autocommit=0的响应包类似。

上面两次交互中set autocommit=1的响应包如下

 

16:16:00.116171 IP 10.23.230.6.5858 > 10.46.17.51.18168: tcp 11

0x0000: 4508 003f 27a9 4000 4006 078a 0a17 e606 E..?’.@.@…….

0x0010: 0a2e 1133 16e2 46f8 09ca 3820 b3e2 3f00 …3..F…8…?.

0x0020: 8018 3210 0bb0 0000 0101 080a 0167 40dd ..2……….g@.

0x0030: 5ef3 5a5d 0700 0001 0000 0002 0000 00 ^.Z]………..

set autocommit=0的响应包如下

16:15:19.175099 IP 10.23.230.6.5858 > 10.46.17.51.18168: tcp 11

0x0000: 4508 003f 2747 4000 4006 07ec 0a17 e606 E..?’G@.@…….

0x0010: 0a2e 1133 16e2 46f8 09ca 329f b3e2 2cb1 …3..F…2…,.

0x0020: 8018 3210 0bb0 0000 0101 080a 0166 a0e9 ..2……….f..

0x0030: 5ef2 ba6a 0700 0001 0000 0000 0000 00 ^..j………..

commit的响应包如下:

16:15:19.201529 IP 10.23.230.6.5858 > 10.46.17.51.18168: tcp 11

0x0000: 4508 003f 274b 4000 4006 07e8 0a17 e606 E..?’K@.@…….

0x0010: 0a2e 1133 16e2 46f8 09ca 32de b3e2 2d4b …3..F…2…-K

0x0020: 8018 3210 0bb0 0000 0101 080a 0166 a104 ..2……….f..

0x0030: 5ef2 ba84 0700 0001 0000 0000 0000 00 ^…………..

根据前面MySQL协议格式,set autocommit=1的响应包的的status_flags字段包含了SERVER_STATUS_AUTOCOMMIT(特征编码0X0002)标志位,表示事务在autocommit状态下提交。而对于autocommit=0状态下的响应包,status_flags都是0X0000,因此下面的语句条件可以去除set autocommit=1的响应包:

tcp[39:2]== 0x0000

为了更具特异性,可以结合响应包的长度都为63字节条件组合过滤条件如下:

tcp[39:2]== 0x0000 and ip[2:2] & 0xffff ==63

和前面的过滤条件组合:

tcpdump -r tcp.log -x -q -n ‘(ip[2:2] & 0Xffff ==73 and tcp[51:2] == 0X3d300) or (tcp[39:2]== 0x0000 and ip[2:2] & 0xffff ==63)’

而对于set autcommit=0及commit语句的响应包,其内容相同,

编码都是:0700 0001 0000 0000 0000 00,这个可以通过管道传递给后续的shell命令过滤。

最终命令过滤出来tcp包只剩下如下序列。

(1)16:15:19.175053 IP 10.46.17.51.18168 > 10.23.230.6.5858: tcp 21

0x0000: 4500 0049 d582 4000 3b06 5eae 0a2e 1133 E..I..@.;.^….3

0x0010: 0a17 e606 46f8 16e2 b3e2 2c9c 09ca 329f ….F…..,…2.

0x0020: 8018 00e3 555a 0000 0101 080a 5ef2 ba6a ….UZ……^..j

0x0030: 0166 9f6a 1100 0000 0353 4554 2061 7574 .f.j…..SET.aut

0x0040: 6f63 6f6d 6d69 743d 30 ocommit=0

(2)16:15:19.175099 IP 10.23.230.6.5858 > 10.46.17.51.18168: tcp 11

0x0000: 4508 003f 2747 4000 4006 07ec 0a17 e606 E..?’G@.@…….

0x0010: 0a2e 1133 16e2 46f8 09ca 329f b3e2 2cb1 …3..F…2…,.

0x0020: 8018 3210 0bb0 0000 0101 080a 0166 a0e9 ..2……….f..

0x0030: 5ef2 ba6a 0700 0001 0000 0000 0000 00 ^..j………..

(3)16:15:19.201529 IP 10.23.230.6.5858 > 10.46.17.51.18168: tcp 11

0x0000: 4508 003f 274b 4000 4006 07e8 0a17 e606 E..?’K@.@…….

0x0010: 0a2e 1133 16e2 46f8 09ca 32de b3e2 2d4b …3..F…2…-K

0x0020: 8018 3210 0bb0 0000 0101 080a 0166 a104 ..2……….f..

0x0030: 5ef2 ba84 0700 0001 0000 0000 0000 00 ^…………..

上面的序列中,(1)是set autocommit=0命令,(2)是MySQL对(1)的响应。而(3)是MySQL对commit语句的响应包。因此(3)的时间戳减去(1)的就是该事务的响应时间。每一个事务交互都得到这样三个TCP包,通过shell进一步处理就可以得到时间序列。例如对IP为HOST,端口为PORT的client,如下的命令可以直接计算出该client所有事务的平均处理时间(us为单位):

tcpdump -r tcpdump.log -q -n  -tttt ‘host HOST and port PORT and ((ip[2:2] & 0xffff ==73 and tcp[51:2]==0x3d30) or (ip[2:2] & 0xffff ==63 and tcp[39:2]== 0x0000))’|awk ‘{print $2}’|sed ‘s/[:.]/ /g’|awk ‘{print ($1*3600+$2*60+$3)*1000000+$4}’|awk ‘BEGIN{ar[0]=0;num=0}{ar[num]=$1;num++}END{for(i=0;i<num;i=i+3){print ar[i+2]-ar[i]}}’|awk ‘BEGIN{sum=0;num=0}{sum+=$1;num++}END{printf(“%d %d %dn”,sum,num,sum/num)}’

而如果要得到MySQL处理的所有事务的时间,需要对每个Client进行分批次处理。这个可以通过先得到所有client的HOST:PORT组合,然后逐个分析来实现。也可以直接不区分IP和端口得到所有符合条件的包,然后写一个python或者shell脚本来处理,都非常方便。

 

转载请注明:爱开源 » tcpdump分析MySQL事务的时延水平

您必须 登录 才能发表评论!

网友最新评论 (1)