项目中需要统计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。有可能是前端的编程框架发送的语句。分析中需要过滤掉。这种的请求的交互信息如下图所示
第二种类型,是手动开启一个事务然后手动提交,其TCP交互过程如下图所示:
我们需要得到一个事务的处理时间,该时间区间,应该是从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协议格式如下:
其各个字段的意义如下表解释:
协议版本(4bit) | 头部长度(4bit)(需*多少32bits) | 服务类型TOS(8bit) | IP包总长度(16bits) | 包唯一标识(16bits) | 标识字段和片偏移,用于分片(16bits) | TTL(8bits)存活时间 | 协议类型(8bits)对于tcp协议是06 | 表头校验(16bits) | 源IP(4字节) | 目的IP(4字节 ) |
(2)TCP协议
TCP协议格式如下图:
其各个字段的内容如下表所示:
源端口(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组成结构如下图所示,由于我们这里只需要获取事务的处理时间,不需要关注此种类型的响应。
有了上述的背景,再来分析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
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事务的时延水平