Mysql5.7 的错误日志中最常见的note级别日志解释

末蓝、 2022-07-13 13:39 127阅读 0赞

在使用mysql5.7的时候，发现了不少在mysql5.6上不曾见过的日志，级别为note, 作者梳理了一下，最常见的note日志以下三种，下面我们来逐个解释。

第一种，Aborted connection . 如上图，信息如下：

2016-03-17T14:44:24.102542Z 59 \[Note\] Aborted connection 59 to db: ‘unconnected’ user: ‘mha’ host: ‘197.xx.xx.xx’ (Got an error reading communication packets)

2016-03-17T14:44:31.273897Z 61 \[Note\] Aborted connection 61 to db: ‘unconnected’ user: ‘mha’ host: ‘197.xx.xx.xx(Got an error reading communication packets)

2016-03-17T14:44:31.273897Z 61 \[Note\] Aborted connection 61 to db: ‘unconnected’ user: ‘mha’ host: ‘197.xx.xx.xx(Got  timeout  reading communication packets)

上面两个是连接中断的错误信息，原因不一样，Got an error reading communication packets  的原因是因为网络等原因导致。 Got  timeout  reading communication packets 这个错误的原因是会话的idle时间达到了数据库指定的timeout时间。

第二种：SLAVE多线程同步的信息

如图，信息如下：

2016-03-14T15:48:26.432150Z 73 \[Note\]Multi-threaded slave statistics for channel ”: seconds elapsed = 121; eventsassigned = 100374529; worker queues filled over overrun level = 0; waited due aWorker queue full = 0; waited due the total size = 0; waited at clock conflicts= 1451875661700 waited (count) when Workers occupied = 3211993 waited whenWorkers occupied = 445032386000

2016-03-14T15:50:28.398745Z 73 \[Note\]Multi-threaded slave statistics for channel ”: seconds elapsed = 122; eventsassigned = 100500481; worker queues filled over overrun level = 0; waited due aWorker queue full = 0; waited due the total size = 0; waited at clock conflicts= 1452001865500 waited (count) when Workers occupied = 3211993 waited whenWorkers occupied = 445032386000

我们通过源代码，找到下面一段，该段实现了上述日志的输出。

if ((my\_now – rli\->mts\_last\_online\_stat)>=

mts\_online\_stat\_period)

sql\_print\_information(“Multi-threadedslave statistics%s: “

“seconds elapsed = %lu; “

“events assigned = %llu; “

“worker queues filled over overrun level = %lu;”

“waited due a Worker queue full = %lu; “

“waited due the total size = %lu; “

“waited at clock conflicts = %llu “

“waited(count) when Workers occupied = %lu “

“waited when Workers occupied = %llu”,

rli\->get\_for\_channel\_str(),

static\_cast<unsignedlong>

(my\_now – rli\->mts\_last\_online\_stat),

rli\->mts\_events\_assigned,

rli\->mts\_wq\_overrun\_cnt,

rli\->mts\_wq\_overfill\_cnt,

rli\->wq\_size\_waits\_cnt,

rli\->mts\_total\_wait\_overlap,

rli\->mts\_wq\_no\_underrun\_cnt,

rli\->mts\_total\_wait\_worker\_avail);

rli\->mts\_last\_online\_stat=my\_now;

通过这一句(my\_now – rli\->mts\_last\_online\_stat),  以及最后一句rli\->mts\_last\_online\_stat=my\_now;   可以得知， seconds elapsed 就是上一次统计跟这一次统计的时间间隔。

而mts\_online\_stat\_period =120秒，硬代码，因此就是几乎每隔120秒，就有上述日志的输出。 通过进一步查看原代码，初步了解上述日志信息的含义，如下：

events assigned：总共有多少个event被分配执行，计的是总数。

worker queues filled over overrun level：多线程同步中，worker 的私有队列长度超长的次数，计的是总数。

waited due a Worker queue full ：因为worker的队列超长而产生等待的次数，计的是总数。

waited due the total size ：超过最大size的次数，这个由参数slave\_pending\_jobs\_size\_max  指定。

waited at clock conflicts ：因为逻辑时间产生冲突的等待时间，单位是纳秒。

waited (count) when Workers occupied ：因为workder被占用而出现等待的次数。（总计值）。

waited when Workersoccupied ：因为workder被占用而出现等待的总时间，总计值，单位是纳秒。

第三种：page\_cleaner线程的输出日志

如图，信息如下：

2016-03-24T17:45:28.005117Z 0 \[Note\] InnoDB:page\_cleaner: 1000ms intended loop took 4750ms.The settings might not beoptimal. (flushed=1519 and evicted=0, during the time.)

查找源代码，发现是上面的日志由下面一段代码输出：

if (ret\_sleep == OS\_SYNC\_TIME\_EXCEEDED) \{

ulint   curr\_time = ut\_time\_ms();

if (curr\_time >next\_loop\_time + 3000) \{

if (warn\_count == 0) \{

ib::info() << “page\_cleaner: 1000ms”

” intended loop took “

<<1000 + curr\_time

– next\_loop\_time

<<“ms. The settings might not”

” be optimal. (flushed=”

<<n\_flushed\_last