长话短说mysql slow log的query time

  1. 云栖社区>
  2. 博客>
  3. 正文

长话短说mysql slow log的query time

漫天花雨 2018-02-11 11:07:57 浏览855 评论0

摘要: 当时MySQL卡顿的时间只有62s,为什么这个时间却是427553s? 先看下慢日志: # Time: 160601 15:09:52 # User@Host: slave[slave] @ [10.

1
当时MySQL卡顿的时间只有62s,为什么这个时间却是427553s?

先看下慢日志:

# Time: 160601 15:09:52
# User@Host: slave[slave] @  [10.236.232.132]  Id: 5668740
# Query_time: 427536.674791  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1464764992;
# administrator command: Binlog Dump;

慢日志的源码在log.cc:

/*
  Log a query to the slow log table
 
  SYNOPSIS
    log_slow()
    thd               THD of the query
    current_time      current timestamp
    query_start_arg   command start timestamp
    user_host         the pointer to the string with user@host info
    user_host_len     length of the user_host string. this is computed once
                      and passed to all general log event handlers
    query_time        Amount of time the query took to execute (in microseconds)    ###查询语句花费的时间,单位:微秒
    lock_time         Amount of time the query was locked (in microseconds)
    is_command        The flag, which determines, whether the sql_text is a
                      query or an administrator command (these are treated
                      differently by the old logging routines)
    sql_text          the very text of the query or administrator command
                      processed
    sql_text_len      the length of sql_text string
 
  DESCRIPTION
 
   Log a query to the slow log table
 
  RETURN
    FALSE - OK
    TRUE - error occured
*/
....
if (thd->start_utime)
    {
      query_utime= (current_utime - thd->start_utime); #query_utime=当前时间-线程开始时间
      lock_utime=  (thd->utime_after_lock - thd->start_utime);
    }

所以这个时间就可以解释了,这个binlog dump一共执行了427536.674791s,是正常的,这次记录慢查询的时间是:Time: 160601 15:09:52,因为上一次binlog记入的时间是:# Time: 160527 16:22:34,时间上可以对的上.

【云栖快讯】一站式开发者服务,海量学习资源免费学  详情请点击

网友评论