慢日志位置
CN节点的操作系统用户家目录的log下，本文以zxdbproxy1为例
su - zxdbproxy1
ll ~/log/slow_query*
-rw-r-----. 1 zxdbproxy1 goldendb 0 5月 5 00:00 slow_query.log
-rw-r-----. 1 zxdbproxy1 goldendb 0 5月 5 19:59 slow_query_log.info
慢日志启用
CN节点的操作系统用户家目录的etc目录下，本文以zxdbproxy1为例
su - zxdbproxy1vim ~?etc/proxy.ini
slow_query_log = 1 #开启慢日志
long_query_time = 1000 #慢日志打印阀值 单位ms#保存退出
dbtool -p -lc #动态生效参数
注意：慢日志的参数只有在分布式场景下配置才会生效，集中式场景CN节点为透传模式，慢日志参数配置不生效，CN节点不记录慢日志
慢日志格式
具体的慢日志格式如下：
[2022-02-27 20:10:09:610]|DEBUG||311-5-102-1645963809605777||176608|177238|dbp_proxytool.cc:3167||#EXECUTE:Port[8885]Session[102]TransSerial[]LinkIP[10.229.31.132]LinkPort[44121]UserName[dbproxy]ProxyName[CN5]ClusterName[cluster1]Database[zhuyu]TotalExecTime[9734us]BeginTs[20:10:09:605721]EndTs[20:10:09:615455]SQL[update range_test4 set col3=5]
MsgToExecTime[0us,BeginTs:20:10:09:605721]ParserSQLTime[105us,BeginTs:20:10:09:605816]PlanTreeCreateTime[435us,BeginTs:20:10:09:605923]GetGTIDTime[875us,BeginTs:20:10:09:606382]GetAutoIncValueTime[0us,BeginTs:08:00:00:000000]FreeGtidTime[805us,BeginTs:20:10:09:614619]PlanTreeExecTime[7323us,BeginTs:20:10:09:607276]
SubSQL[1]:TaskID[1]ExecTime[2199us]BeginTs[20:10:09:607282]FinishTime[32us]QueryGTID[180us]GroupTime[
g1 num:2, duration:1069us
sqltoRoute num:2,duration:92us,beginTs:20:10:09:607885
getTask num:2,duration:90us
SyncConn num:2,duration:0us
TaskWait num:2,duration:18us
runSql num:2,duration:40us
addEpoll num:3,duration:10us
DB connection_id:406296,duration:383us,beginTs:20:10:09:608001
handleEpoll num:3,duration:0us
workerdelay num:3,duration:40us
worker num:4,duration:283us
restoExec num:2,duration:67us
g2 num:2, duration:2547us
sqltoRoute num:2,duration:196us,beginTs:20:10:09:607939
getTask num:2,duration:42us
SyncConn num:2,duration:1574us
TaskWait num:2,duration:10us
runSql num:2,duration:22us
addEpoll num:3,duration:4us
DB connection_id:1128483,duration:340us,beginTs:20:10:09:608858
handleEpoll num:3,duration:0us
workerdelay num:3,duration:33us
worker num:4,duration:233us
restoExec num:2,duration:60us]SQL[SELECT `range_test4`.`col1`,`zhuyu`.`range_test4`.`gtid` as `gtid1` FROM `zhuyu`.`range_test4` FOR UPDATE]
SubSQL[2]:TaskID[2]ExecTime[2426us]BeginTs[20:10:09:609489]FinishTime[16us]QueryGTID[0us]GroupTime[
g1 num:1, duration:1566us
sqltoRoute num:1,duration:28us,beginTs:20:10:09:610318
getTask num:1,duration:36us
SyncConn num:1,duration:0us
TaskWait num:1,duration:13us
runSql num:1,duration:12us
addEpoll num:1,duration:2us
DB connection_id:406296,duration:1355us,beginTs:20:10:09:610406
handleEpoll num:1,duration:0us
workerdelay num:1,duration:7us
worker num:1,duration:29us
restoExec num:1,duration:43us
g2 num:1, duration:978us
sqltoRoute num:1,duration:72us,beginTs:20:10:09:610359
getTask num:1,duration:11us
SyncConn num:1,duration:0us
TaskWait num:1,duration:5us
runSql num:1,duration:11us
addEpoll num:1,duration:1us
DB connection_id:1128483,duration:751us,beginTs:20:10:09:610453
handleEpoll num:1,duration:0us
workerdelay num:1,duration:8us
worker num:1,duration:41us
restoExec num:1,duration:43us]SQL[UPDATE zhuyu.range_test4 SET
range_test4.GTID=258120785,`col3`=5 WHERE (`col1`=1 OR `col1`=2 OR `col1`=3 OR `col1`=4 OR `col1`=146 OR `col1`=147 OR `col1`=148)]
SubSQL[3]:autocommit time:2662us
慢日志解读分析
慢日志上半部分-执行概况
Port[xxxx]： #CN的连接实例端口
Session[xxx]： #CN为当前客户端分配的dialogid
TransSerial[xxxx]： #通过set @transaction_serial_number语句为事务设置的流水号
LinkIP[xxxx]： #前端客户端的IP
LinkPort[xxxx]： #前端客户端的端口
UserName[xxxx]： #CN的连接实例用户
ProxyName[xxxx]： #CN的名称，与OMM页面一致
ClusterName[xxxx]： #连接实例绑定的集群名称，与OMM页面一致
DataBase[xxxx]： #这条链路上面的默认database，如果后面的语句不带库名，就用这个库
TotalExecTime[xxxx]： #语句执行的总时间，以执行线程线程收到OS转发的语句消息为开始，以执行线程最终给客户端回响应时为结束（如果是错误慢查询日志中错误码为10834的语句，则该时间表示语句执行开始时间到链路断开时间的时间差）
BeginTs[xxxx]： #语句开始执行的时间，以执行线程线程收到OS转发的语句消息为开始
EndTs[xxxx]： #语句执行结束的时间，以执行线程最终给客户端回响应时为结束（如果是错误慢查询日志中错误码为10834，则代表断链时间）
SQL[xxxx]： #客户端下发的原始语句
MsgToExecTime[xxxx]： #客户端语句从OS转发到执行线程的时间，执行线程消息积压在其中会有体现,如果这个时间为0us。很有可能是因为执行积压，客户端发了kill，uMsgToExecBegin记的是kill的时间，比uSQLBegin大。相减是负值，所以记0
ParserSQLTime[xxxx]： #CN做语法解析占用的时间
PlanTreeCreateTime[xxxx]： #CN创建计划树占用的时间
GetGTIDTime[xxxx]： #CN申请GTID占用的时间，开始和结束统计的时间均在执行线程
GetAutoIncValueTime[xxxx]: #CN申请自增列值占用的时间。
FreeGtidTime[xxxx]： #CN释放GTID占用的时间，开始和结束统计的时间均在gtmproxy代理线程，释放GTID可能存在重试，但该时间只记录最后一次释放GTID的时间
PlanTreeExecTime[xxxx]： #执行计划树的总时间，以创建计划树结束为开始，计划树执行结束为结束，包含第二部分的全部时间
慢日志上半部分-CN具体执行情况
SubSQL[xxxx]： #执行计划中子语句的编号
ExecTime[xxxx]： #执行计划中子语句的执行总耗时，开始和结束的时间统计均在执行线程，执行线程消息积压、路由线程消息积压、worker线程忙无法及时处理epoll事件以及查询活跃gitd重试耗时均会有体现
BeginTs[xxxx]： #执行计划中子语句的开始执行的时间
FinishTime[xxxx]： #子语句执行结束，执行线程调用sqlnode的finish方法的耗时（这部分的耗时如果比较长，说明结果集在执行线程处理的时间长，排序，去重，join等）
QueryGTID[xxxx]： #查询活跃GTID的耗时，开始与结束时间在gtmproxy代理线程设置。如果存在查询活跃，该值记录最后一次查询活跃GTID的耗时。如果存在查询活跃，对应于子语句会多次执行，这会在每个group统计数据中的num及duration中有所体现，这些统计会做累加
GroupTime[xxxx]： #子语句在具体每个group上的执行耗时分析
g1 num:xxxx, duration:xxxxus： #子语句在具体每个group上的执行耗时，以语句准备从执行线程发往路由线程为开始，以执行收到该group的响应为结束。如果该值与DN统计项的duration相差较大，可能由于执行线程消息积压、路由线程消息积压、worker线程忙无法及时处理epoll事件导致
sqltoRoute num:xxxx,duration:xxxxus： #语句从执行线程下发到路由线程，路由线程最终收到请求并处理的耗时。开始时间统计在执行线程，结束时间统计在路由线程，路由线程消息积压会在该统计项中体现。#这部分时间超过100us，说明路由线程有积压，需要把路由线程数量调大
getTask num:xxxx,duration:xxxxus：#为SQL获取一个空闲task的时间，其中包括获取后端链路的时间：如果有空闲链路，则获取空闲链路；#如果没有空闲链路，则建链的时间以及链路属性设置的时间在下面的SyncConn中
SyncConn num:xxxx,duration:xxxxus： #getTask未获取到链路属性一致的链路。需要新建链路或者重置链路属性，建链成功后。发送set语句，收到DN响应后记录消耗的时间
TaskWait num:xxxx,duration:xxxxus：#语句加入到执行队列中到真正开始执行的等待时间（队列中还有其他语句，需要等待，如果是这部分时间长，是其他语句引起的，跟本子查询无关）
runSql num:xxxx,duration:xxxxus：#调用mysql_real_query_start接口将SQL下发给DN实例的耗时，注意该时间并非语句完全执行的时间，除非语句的执行结果能从接口函数的返回值全部返回，否则是异步过程。
addEpoll num:xxxx,duration:xxxxus：#mysql_real_query_start是异步接口，如果语句执行响应不能一次返回，则需要将端口加入epoll进行监听。该统计项则统计加入epoll事件的耗时。
DB connection_id:xxxx,duration:xxxxus,beginTs:xxxx：#connection_id是和DN之间MySQL链路的thread id，#duration是语句真正在DB的执行时间，这个时间比较大，说明语句确实在DN执行慢。#beginTs是路由下发语句到DN的开始时间(注意有一种场景这个时间会比DN上面的短：大结果集DN分包发送，CN收到第一个包就记录了DN执行结束时间，后续worker一边处理结果集，一边继续从DN收。#所以大结果集的情况，后端的耗时要把DB时间WorkerDelay时间Worker时间都算上) 还有一种场景，这个时间比语句的总时间长，DN记录的时间是多条语句的累积时间，#如果语句补发了start transaction，CN会收到两个响应，DN的时间就会记录两次，多出来的时间就是start transaction的执行时间。
handleEpoll num:xxxx,duration:xxxxus：#listener线程监听到epoll事件后，将发生事件的socket分离的时间。
workerdelay num:xxxx,duration:xxxxus：#listener将task放入队列，到worker开始执行的时间，为该响应在CN侧等待处理的时间#Workerdelay时间长说明有其他语句占用了worker线程，一般是大结果集，或者高并发的群发所有分片的语句，需要在附近的慢日志中找到这些语句，进行优化
worker num:xxxx,duration:xxxxus：#listener线程监听到epoll事件后，会将相应的task放入队列，并通过条件变量唤醒一个空闲worker线程，该统计项统计空闲worker线程被唤醒后，拿到task做后续处理的时间，一般是对语句执行结果做处理的时间#woker时间长，一般num数量也大，说明结果集大
restoExec num:xxxx,duration:xxxxus：#路由线程或worker线程将语句执行结果处理结束后，给执行线程发消息，通知执行线程向客户端回响应。这部分统计开始时间在路由或者worker线程，统计结束时间在执行线程，执行线程消息积压会在这部分里有体现。
SubSQL[3]:autocommit time:xxxxus: #自动提交场景，该语句的commit执行时间
