lvm[12446]: Another thread is handling an event. Waiting

在检查一Linux服务器时，发现日志里面有大量“lvm[12446]: Another thread is handling an event. Waiting...”

Jul  4 00:01:42 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:09:36 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:13:42 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:13:43 localhost lvm[12446]: Extension of snapshot VolGroup05/LogVol00-PS-user-snapshot finished successfully.

Jul  4 00:13:43 localhost lvm[12446]: dm_task_run failed, errno = 9, Bad file descriptor

Jul  4 00:14:42 localhost lvm[12446]: Extension of snapshot VolGroup05/LogVol00-PS-user-snapshot finished successfully.

Jul  4 00:15:52 localhost lvm[12446]: Extension of snapshot VolGroup05/LogVol00-PS-user-snapshot finished successfully.

Jul  4 00:17:02 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:17:02 localhost lvm[12446]: Extension of snapshot VolGroup05/LogVol00-PS-user-snapshot finished successfully.

Jul  4 00:17:46 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:18:52 localhost lvm[12446]: Extension of snapshot VolGroup05/LogVol00-PS-user-snapshot finished successfully.

Jul  4 00:19:42 localhost lvm[12446]: Extension of snapshot VolGroup05/LogVol00-PS-user-snapshot finished successfully.

Jul  4 00:20:32 localhost lvm[12446]: Snapshot VolGroup05-LogVol00--PS--user--snapshot is now 80% full. 

Jul  4 00:20:32 localhost lvm[12446]: Extension of snapshot VolGroup05/LogVol00-PS-user-snapshot finished successfully.

Jul  4 00:23:12 localhost lvm[12446]: Snapshot VolGroup05-LogVol00--PS--user--snapshot is now 85% full. 

Jul  4 00:23:12 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:23:12 localhost lvm[12446]: Extension of snapshot VolGroup05/LogVol00-PS-user-snapshot finished successfully.

Jul  4 00:23:12 localhost lvm[12446]: dm_task_run failed, errno = 9, Bad file descriptor

Jul  4 00:26:09 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:26:52 localhost last message repeated 2 times

Jul  4 00:26:52 localhost lvm[12446]: Snapshot VolGroup05-LogVol00--PS--user--snapshot is now 90% full. 

Jul  4 00:26:52 localhost lvm[12446]: Extension of snapshot VolGroup05/LogVol00-PS-user-snapshot finished successfully.

Jul  4 00:28:52 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:28:52 localhost lvm[12446]: Snapshot VolGroup05-LogVol00--PS--user--snapshot is now 95% full. 

Jul  4 00:28:52 localhost lvm[12446]: Extension of snapshot VolGroup05/LogVol00-PS-user-snapshot finished successfully.

Jul  4 00:28:52 localhost lvm[12446]: dm_task_run failed, errno = 9, Bad file descriptor

Jul  4 00:31:07 localhost kernel: device-mapper: snapshots: Invalidating snapshot: Unable to allocate exception.

Jul  4 00:34:59 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:35:42 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:42:29 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:44:16 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:45:49 localhost lvm[12446]: Another thread is handling an event. Waiting...

Jul  4 00:46:59 localhost last message repeated 3 times

Jul  4 00:48:49 localhost last message repeated 2 times

在Redhat官网有看到相关资料介绍”"What does "lvm: Another thread is handling an event. Waiting..." log messages mean on Red Hat Enterprise Linux 6?" 如下所示:

问题

• lvm event log messages
• Continuous messages filling /var/log/messages
  

  lvm: Another thread is handling an event, Waiting...
  lvm: Another thread is handling an event, Waiting...
  

决议

• These messages can safely be ignored at this stage.  They are verbose messages that do not indicate any error has occurred.
• Red Hat are planning to remove these messages from the lvm2 package in a future release of Red Hat Enterprise Linux 6.

根源

• dmeventd daemon montors for events that need to occur on device-mapper devices.
  • There are segments of code that can only be entered by one thread at a time.
  • If a second thread tries to enter the code section, it will be forced to wait until the first thread has exited. This message is printed when a process is forced to wait.
• There is currently no evidence that there is any problem with locking access to critical code in dmeventd.

诊断步骤

If the following symptoms are present on your system, then this article may apply to your issue:

• Your lvm2 package is 2.02.87-6.el6 or earlier.
• You have more than 1 LVM snapshots on the system.

• Periodically, the following messages appear in /var/log/messages:

  Raw

      lvm: Another thread is handling an event. Waiting...
      lvm: Another thread is handling an event. Waiting...

根据官方文档资料，这个消息可以忽略，这中现象出现在你的系统中，当你系统满足下面条件：

当你的lvm2包版本是2.02.87-6.el6 或之前的版本。

当你的系统有超过一个LVM快照

对比、参考本机操作系统版本，发现lvm2的版本确实比2.02.87-6.el6 低。另外，这个系统也确实有多个LVM快照。唯一有点差别的是Linux版本Red Hat Enterprise Linux Server release 5.7 ，并不是Red Hat Enterprise Linux (RHEL) 6

[root@localhost ~]# rpm -qa | grep lvm

lvm2-2.02.84-6.0.1.el5

system-config-lvm-1.1.5-9.el5

[root@localhost ~]# cat /etc/redhat-release 

Red Hat Enterprise Linux Server release 5.7 (Tikanga)

另外，查看进程12446，也确实是/sbin/dmeventd

[root@localhost ~]# ps -ef | grep  12446 

root     12446     1  0 Jul02 ?        00:07:51 /sbin/dmeventd

root     26043 23106  0 11:06 pts/6    00:00:00 grep 12446

这个错误信息一直不停的出现在系统日志当中，很奇怪的时候，我同样环境的其它服务器又没有出现这个问题。应该是某些问题引起的。在做VG扫描时，发现有这样/dev/VolGroup03/LogVol00-PS-user-snapshot: read failed after 0 of 4096 at 0: Input/output error一些错误信息，怀疑这个导致引起的，但是生产环境还不能乱动，需要在测试环境测试、验证后，方能在生产环境处理。目前没有权限和资源处理，需要系统管理员帮忙解决。