大规模测试环境cinder-volume进程卡住定位

问题背景

最近底层这边搭了一个大规模集群测试环境，在测试的时候发现单个计算节点并发较大的情况下，cinder-volume进程会卡住，并发一大这种情况一定出现。进程卡住后看到的情况是：

• cinder-volume不打日志，卡住的节点上的cinder-volume服务最后一条日志都是一样的
• 查看cinder-volume对应的消息队列，有大量的unacked消息，但ready数为0
• 通过cinder service-list看到，cinder-volume的心跳还在，但通过cinder get-host-list看到其状态信息已经不上报了

这个问题困扰了比较久，这里主要总结一下在整个问题定位当中尝试的手段，后续再遇到类似进程卡住的情况时有排查思路可以参考。

定位过程

节点情况分析

第一个想到的是系统资源是不是不足了，因为是用虚拟机搭建的集群，虚拟机规格比较小，只有2G内存、4VCPU。但通过top、free等命令查看，发现系统剩余内存还很多，cinder-volume进程占用的资源也正常。

在后续的尝试过程中，我们发现当一个节点上管理的卷过多（2w+）时，cinder-volume进程在启动的时候会因为内存占用过多导致OOM进而进程被kill掉，因为cinder-volume在启动时候会从数据库把当前节点管理的卷信息都查询出来保存到内存中。

怀疑是否系统参数设置不对，limit和最大线程数等限制，因为是debian9系统并且nova在这方面也踩了不少坑。但是如果达到了系统的某项系统限制的话，日志里会有对应的异常抛出才对，而不是卡住。不过我们还是通过ulimit -a和cat /proc/$cinder-volume-pid/limit命令查看当前系统的limits，然后和自己开发用的虚拟机做对比，关键的open files参数没有问题，也进一步检查了pid_max、threads-max等参数，并尝试改大问题还是复现。后面也换了debian7的虚拟机也有同样的问题，基本可以判断不是系统及系统参数引起的问题。

尝试获取堆栈

执行sudo kill -USR1 $cinder-volume-pid，尝试打印出cinder-volume的执行堆栈，发现在/data/log/cinder目录并没有对应的输出。这个就比较尴尬了，后续也一直在找如何打印出cinder-volume的执行堆栈，在没有堆栈之前只能各种的猜测和尝试，花了不少时间。

代码分析

因为看到所有节点最后的一条日志都是

2018-01-17 21:17:55.436 24903 DEBUG cinder.openstack.common.periodic_task [-] Running periodic task NetEaseVolumeManager._publish_service_capabilities run_periodic_tasks /srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/periodic_task.py:176

所以怀疑这部分代码有什么问题，仔细看了这部分代码发现其逻辑比较简单，就是一个定时任务定时的把当前节点cinder-volume的状态（空间总量、剩余总量、后端名称等信息）通过RabbitMQ发送fanout消息，广播到每一个cinder-scheduler当中。能想到的一个问题是到RabbitMQ集群异常，导致客户端推消息的时候卡住，进而堵塞主进程。

但是通过检查RabbitMQ集群状态后发现集群正常，当前节点到RabbitMQ节点连通性也没有问题。按常理来说，RabbitMQ集群有异常的话，clinet这边会有错误日志打印出来，client这边有探活和重连机制，也不会出现直接卡死主进程的情况出现。所以后面我们在尝试着把这部分代码逻辑注释掉后，发现问题依旧。甚至尝试直接注释掉所有定时任务，也不行，问题肯定不是出现在定时任务上。

一个值得关注的现象是，在cinder-volume进程卡住的时候，其服务心跳还在，所谓服务心跳是一个定时任务（默认10s）去跟新一下数据库中对应的字段。尝试在这个定时任务中加一些日志后，发现心跳也不在了。

这说明其实进程其实是没有完全卡死的，首先心跳在，其次消息队列中消息均为acked而非ready。消息推送到队列当中后，显示为ready，当消息被消费者取出而未ack时消息显示acked。这说明cinder-volume还在从队列中取消息，只是一直没有处理而已。

从这点入手，注意到和RPC消息处理的两个参数，rpc_thread_pool_size和rpc_conn_pool_size。

rpc_thread_pool_size：cinder-volume在启动时，会初始化出rpc_thread_pool_size大小的绿色线程池，每次从MQ中取出消息后，从这个绿色线程池中分配出一个绿色线程去执行相关的命令。默认是64。

rpc_conn_pool_size：MQ连接池的大小，默认是30

有点怀疑是否是这两个值太小引起的问题，Google了下发现有人讨论建议增大rpc_thread_pool_size的默认值，参考附录链接1。因此试着把这两个值改大，发现问题不是必现了，进一步增大后，问题在当前并发规模下不再复现。

到这里问题已经有一个大致方向了，当绿色线程池分配不出线程时，它会一直在等待。那么问题的原因应该就是绿色线程池里的线程在处理的时候，都因为某种原因卡住了（死锁或者其他原因）。具体原因还是需要查看堆栈信息。

打印堆栈

通过sudo kill -USR1 $cinder-volume-pid没有结果，因此第一个想到的就是gdb，参考附录2中的内容尝试使用gdb和strace对进程进行了跟踪，因为是python的代码，而gdb打印出来的都是c的堆栈，在安装了libpython之后，发现打印出来的堆栈也没有意义，而strace跟踪到的系统调用都是epoll_wait，这是其实是正常的。

考虑到python当中使用eventlet这个库来实现并发，我们需要的是打印出eventlet绿色线程的堆栈，在查阅了资料后发现evenlet中有一个backdoor模块，这个模块提供了一种可以不阻塞应用正常操作的 Pyhon 交互解释器，从而极大地方便了调试、性能调优或仅仅是了解事情是怎么运转的，具体可以参考附录链接3，4。进一步发现OpenStack当中已经对这个有封装了，之前竟然一直没有发现，实现代码参见openstack/common/eventlet_backdoor.py，后续也可以对这部分代码做详细的分析，现在只要设置下backdoor_port指定一个端口号，进程起来后就可以telnet上去执行命令了。pgt()命令就可以打印出绿色线程的堆栈了，终于看到了堆栈，问题就明了了

问题确定

telnet上去执行pgt()命令后发现有非常多的堆栈，这显然不正常。同时发现大多数堆栈内容是类似的，拿其中的一个来看下：

46 <greenlet.greenlet object at 0x7faa8b79a7d0>
  File "/srv/stack/cinder/lib/python2.7/site-packages/eventlet/greenpool.py", line 82, in _spawn_n_impl
    func(*args, **kwargs)
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/amqp.py", line 468, in _process_data
    ctxt.reply(rval, None, connection_pool=self.connection_pool)
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/amqp.py", line 271, in reply  reply, failure, ending, log_failure)
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/amqp.py", line 249, in msg_reply
    conn.direct_send(msg_id, rpc_common.serialize_msg(msg))
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/amqp.py", line 152, in __exit__
    self._done()
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/amqp.py", line 141, in _done
    self.connection.reset()
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/impl_kombu.py", line 675, in reset
    self.channel.close()
  File "/srv/stack/cinder/lib/python2.7/site-packages/amqp/channel.py", line 181, in close
    (20, 41),  # Channel.close_ok
  File "/srv/stack/cinder/lib/python2.7/site-packages/amqp/abstract_channel.py", line 69, in wait
    return self.dispatch_method(method_sig, args, content)
  File "/srv/stack/cinder/lib/python2.7/site-packages/amqp/abstract_channel.py", line 87, in dispatch_method
    return amqp_method(self, args)
  File "/srv/stack/cinder/lib/python2.7/site-packages/amqp/channel.py", line 260, in _close_ok
    self._do_close()
  File "/srv/stack/cinder/lib/python2.7/site-packages/amqp/channel.py", line 106, in _do_close
    AMQP_LOGGER.debug('Closed channel #%d', self.channel_id)
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 1155, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 1286, in _log
    self.handle(record)
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 1296, in handle
    self.callHandlers(record)
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 1336, in callHandlers
    hdlr.handle(record)
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 757, in handle
    self.acquire()
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 708, in acquire
    self.lock.acquire()   <========= 注意这里是在拿文件锁
  File "/srv/stack/cinder/lib/python2.7/threading.py", line 174, in acquire
    rc = self.__block.acquire(blocking)
  File "/srv/stack/cinder/lib/python2.7/site-packages/eventlet/semaphore.py", line 113, in acquire
    hubs.get_hub().switch()
  File "/srv/stack/cinder/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch
    return self.greenlet.switch()
    

从堆栈当中可以看到一直在等待日志文件的锁，那么可以推测一定是有某个绿色线程拿着这个锁没有释放，继续找下堆栈，发现这条。

31 <greenlet.greenlet object at 0x7faa8a822870>
  File "/srv/stack/cinder/lib/python2.7/site-packages/eventlet/greenpool.py", line 82, in _spawn_n_impl
    func(*args, **kwargs)
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/amqp.py", line 481, in _process_data
    exc_info=exc_info)
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 1464, in error
    self.logger.error(msg, *args, **kwargs)
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 1193, in error
    self._log(ERROR, msg, args, **kwargs)
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 1286, in _log
    self.handle(record)
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 1296, in handle
    self.callHandlers(record)   <======== 这里拿到日志文件锁了
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 1336, in callHandlers
    hdlr.handle(record)
  File "/srv/stack/cinder/lib/python2.7/logging/__init__.py", line 759, in handle
    self.emit(record)
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/log_error_handler.py", line 65, in wrapper
    func(*args, **kwargs) File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/log_error_handler.py", line 122, in emit
    payload)
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/log_error_handler.py", line 104, in notify
    rpc_notifier.notify(context, msg)
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/notifier/rpc_notifier.py", line 43, in notify
    rpc.notify(context, topic, message)
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/__init__.py", line 224, in notify
    return _get_impl().notify(cfg.CONF, context, topic, msg, envelope)
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/impl_kombu.py", line 918, in notify
    envelope)
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/amqp.py", line 625, in notify
    with ConnectionContext(conf, connection_pool) as conn:
  File "/srv/stack/cinder/lib/python2.7/site-packages/cinder/openstack/common/rpc/amqp.py", line 122, in __init__
    self.connection = connection_pool.get()
  File "/srv/stack/cinder/lib/python2.7/site-packages/eventlet/pools.py", line 94, in get
    return self.channel.get()    <======= MQ连接池满了，一直在等待
  File "/srv/stack/cinder/lib/python2.7/site-packages/eventlet/queue.py", line 313, in get
    return waiter.wait()
  File "/srv/stack/cinder/lib/python2.7/site-packages/eventlet/queue.py", line 141, in wait
    return get_hub().switch()
  File "/srv/stack/cinder/lib/python2.7/site-packages/eventlet/hubs/hub.py", line 294, in switch
    return self.greenlet.switch()
   

上面这个绿色线程则是拿到了日志文件锁，但是此时MQ连接池满了，所以一直在等待MQ连接池中其他线程处理完消息，但此时其他绿色线程则一直在等待拿日志文件锁。这里有个疑问，为什么先拿日志文件锁，再去从MQ连接池中获取连接。看下log_error_handler.py里的代码，发现是对错误的日志做了一个trace，在打印错误日志的时，同时把这个错误日志推送到指定的队列当中。我们把这个功能通过配置项关闭，同时加大并发量测试，问题不再出现。

同时前面的一些奇怪的现象都可以解释了，在并发量不高的时候，它总是能从连接池中拿到连接，而当并发一高的时候，死锁就出现了。因为心跳代码不打日志，所以也不拿日志文件锁，只是更新下数据库中对应的记录，因此心跳可以正常上报，而后面给这个方法一加日志，就以为拿不到锁而卡住了。

参考资料

• Increase the rpc_thread_pool_size： https://bugzilla.redhat.com/show_bug.cgi?id=1155663#c3
• python进程调试：http://www.cnblogs.com/xybaby/p/8025435.html
• eventlet backdoor：http://www.cnblogs.com/Security-Darren/p/4172717.html
• Python interactive interpreter within a running process：http://eventlet.net/doc/modules/backdoor.html

本文来自网易实践者社区，经作者廖跃华授权发布。