数据库调用的追踪:慢查询怎么定位到调用链

  慢日志表里 start_time 相对客户端 db.query span 的偏移(用带注释的行精确对应后算出,中位数):相对 span 的结束时刻 -0.1 ms,相对 span 的开始时刻 +179.2 ms;因此没有注释时用 “慢日志时间 ≈ span 的结束时刻 ± 30 ms” 且规整后的 SQL 文本相同来找候选 span
  配置                  | 慢日志行数 | 唯一对应到一个 span | 有多个候选 span(对应不上) | 没有候选 | 平均候选 span 数 | 最多候选 span 数
  --------------------+-------+--------------+------------------+------+-------------+------------
  (a)带 traceparent 注释 | 120   | 120          | 0                | 0    | 1.0         | 1          
  (b)不带注释             | 120   | 14           | 106              | 0    | 3.0         | 5          
  有注释时,慢日志里的 SQL 文本带着 trace_id,直接对应到那一次调用;没有注释时只能靠 SQL 文本和时间推断,并发请求执行同一条 SQL(只有字面值不同)时,同一时刻有多个候选,分不出是哪一个请求

  30 次快查询里能按 trace_id 在 performance_schema 里找到的有 30 次;其中一条:digest_text = 'SELECT * FROM `orders` WHERE `id` = ?',TIMER_WAIT = 0.067 ms,SQL_TEXT 开头 "/*traceparent='00-3fe56ef50d43c718a408ebffac030568-798450faa80ce43d-03'*/ select";这些快查询不在慢日志里(慢日志表里现有 120 行,都是上一节的慢查询)
  慢日志只记录超过 long_query_time 的语句;performance_schema 的语句历史能记录所有语句(受表大小限制,会被覆盖),SQL 注释里的 trace_id 让两者都能和调用链对上

  写法         | 每个请求的 db span 个数 | 请求耗时 p50(ms) | p99(ms) | 每个请求 db span 耗时合计(ms)
  -----------+------------------+--------------+---------+----------------------
  (a)N+1     | 21.0             | 2.19         | 2.53    | 1.88                 
  (b)一次 JOIN | 1.0              | 0.79         | 0.88    | 0.77                 
  N+1 在 trace 里是一串等宽的短 db span 紧挨着排开,单个都不慢,所以慢日志抓不到;发现它靠看一个请求下 db span 的个数

  写法     | 不同的 db.statement 个数 | 含邮箱地址的 span 数 | db.statement 总字节数
  -------+---------------------+---------------+------------------
  (a)字面值 | 1000                | 1000          | 55890            
  (b)占位符 | 1                   | 0             | 37000            
  字面值把每个请求的参数都带进 span:不同语句的个数和请求数一样多,按语句聚合(比如统计各 SQL 的耗时)就没有意义,用户的邮箱也进了追踪后端;占位符形式的语句只有一种,聚合有意义也不含用户数据

  span           | 耗时中位数(ms) | 最小(ms) | 最大(ms)
  ---------------+-----------+--------+-------
  db.query.total | 507       | 202    | 814   
  pool.acquire   | 305       | 0      | 609   
  db.execute     | 203       | 200    | 206   
  只用一个 span 把“取连接 + 执行”包在一起时,看到的是“数据库慢”;其实一部分是排队等连接——拆成 pool.acquire 和 db.execute 才能看出数据库本身只用了约 200 ms,其余是等连接
ERRORS {}