项目中需要统计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事务的时延水平