作者：Maxwell Li
日期：2017/01/20
未经作者允许，禁止转载本文任何内容。如需转载请留言。

问题发现

近段时间 Compass4NFV 物理部署 OpenStack Newton Ubuntu 极其不稳定，各种常见的不常见的概率性问题频发，提高代码稳定性与部署成功率刻不容缓。

1月20日，发现 aodh 在进行数据库同步时失败，而且仅仅出现在 huawei-pod2 和 intel-pod8 上，huawei-pod1 上的物理部署一切顺利。另外，在慕尼黑的 huawei-pod5 部署 OpenStack Newton CentOS 也没有出现过这个问题。
JIRA单请见：COMPASS-521

问题定位

Step1 查看 ERROR log

进入控制节点，手动初始化 aodh 数据库，ERROR 如下：

root@host1:~# su -s /bin/sh -c "aodh-dbsync" aodh
2017-01-19 22:07:57.990 4179 DEBUG aodh.storage [-] looking for 'mysql' driver in 'aodh.storage' get_connection_from_config /usr/lib/python2.7/dist-packages/aodh/storage/__init__.py:68
2017-01-19 22:07:58.078 4179 DEBUG oslo_db.sqlalchemy.engines [-] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION _check_effective_sql_mode /usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:261
2017-01-19 22:07:58.081 4179 INFO alembic.runtime.migration [-] Context impl MySQLImpl.
2017-01-19 22:07:58.082 4179 INFO alembic.runtime.migration [-] Will assume non-transactional DDL.
CRITI [aodh] DBError: (pymysql.err.InternalError) (1135, u'Can\'t create a new thread (errno 11 "Resource temporarily unavailable"); if you are not out of available memory, you can consult the manual for a possible OS-dependent bug')
Traceback (most recent call last):
  File "/usr/bin/aodh-dbsync", line 10, in <module>
    sys.exit(dbsync())
  File "/usr/lib/python2.7/dist-packages/aodh/cmd/storage.py", line 29, in dbsync
    storage.get_connection_from_config(conf).upgrade()
  File "/usr/lib/python2.7/dist-packages/aodh/storage/impl_sqlalchemy.py", line 108, in upgrade
    command.upgrade(cfg, "head")
  File "/usr/lib/python2.7/dist-packages/alembic/command.py", line 174, in upgrade
    script.run_env()
  File "/usr/lib/python2.7/dist-packages/alembic/script/base.py", line 407, in run_env
    util.load_python_file(self.dir, 'env.py')
  File "/usr/lib/python2.7/dist-packages/alembic/util/pyfiles.py", line 93, in load_python_file
    module = load_module_py(module_id, path)
  File "/usr/lib/python2.7/dist-packages/alembic/util/compat.py", line 79, in load_module_py
    mod = imp.load_source(module_id, path, fp)
  File "/usr/lib/python2.7/dist-packages/aodh/storage/sqlalchemy/alembic/env.py", line 92, in <module>
    run_migrations_online()
  File "/usr/lib/python2.7/dist-packages/aodh/storage/sqlalchemy/alembic/env.py", line 75, in run_migrations_online
    with connectable.connect() as connection:
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2018, in connect
    return self._connection_cls(self, **kwargs)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 72, in __init__
    if connection is not None else engine.raw_connection()
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2104, in raw_connection
    self.pool.unique_connection, _connection)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2078, in _wrap_pool_connect
    e, dialect, self)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1401, in _handle_dbapi_exception_noconnection
    util.raise_from_cause(newraise, exc_info)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 2074, in _wrap_pool_connect
    return fn()
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 318, in unique_connection
    return _ConnectionFairy._checkout(self)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 713, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 480, in checkout
    rec = pool._do_get()
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 1060, in _do_get
    self._dec_overflow()
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
    compat.reraise(exc_type, exc_value, exc_tb)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 1057, in _do_get
    return self._create_connection()
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 323, in _create_connection
    return _ConnectionRecord(self)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 449, in __init__
    self.connection = self.__connect()
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/pool.py", line 607, in __connect
    connection = self.__pool._invoke_creator(self)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/strategies.py", line 97, in connect
    return dialect.connect(*cargs, **cparams)
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 385, in connect
    return self.dbapi.connect(*cargs, **cparams)
  File "/usr/lib/python2.7/dist-packages/pymysql/__init__.py", line 88, in Connect
    return Connection(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 679, in __init__
    self.connect()
  File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 890, in connect
    self._get_server_information()
  File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 1190, in _get_server_information
    packet = self._read_packet()
  File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet
    packet.check_error()
  File "/usr/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error
    err.raise_mysql_exception(self._data)
  File "/usr/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception
    _check_mysql_exception(errinfo)
  File "/usr/lib/python2.7/dist-packages/pymysql/err.py", line 115, in _check_mysql_exception
    raise InternalError(errno, errorvalue)
DBError: (pymysql.err.InternalError) (1135, u'Can\'t create a new thread (errno 11 "Resource temporarily unavailable"); if you are not out of available memory, you can consult the manual for a possible OS-dependent bug')

使用 root 用户直接执行 aodh-dbsync 脚本，发现问题依然存在，初步排除数据库权限问题。

在 ERROR log 中发现 “Resource temporarily unavailable”，怀疑这是引起 aodh 数据库初始化失败的主要原因。在 /var/log/nova，/var/log/cinder，/var/log/heat 等目录下搜索 “Resource temporarily unavailable”，均在对应的 api.log 中发现。

Step2 验证 heat 服务

进入 /var/log/heat，发现在 heat-api.log 和 heat-engine.log 文件下都存在 “Resource temporarily unavailable” ERROR，但是 heat-api 和 heat-engine 服务均正常。
尝试直接登入 heat 数据库：

root@host3:/var/log/heat# mysql -u heat -pheat_db_secret -D heat
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 825749
Server version: 10.0.26-MariaDB-1~xenial-wsrep mariadb.org binary distribution, wsrep_25.13.raf7f02e

Copyright (c) 2000, 2016, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [heat]> exit
Bye

发现能够进入。
尝试验证 heat 服务：

root@host3:/var/log/heat# . /opt/admin-openrc.sh 
root@host3:/var/log/heat# openstack orchestration service list
WARNING: openstackclient.common.utils is deprecated and will be removed after Jun 2017. Please use osc_lib.utils
+----------+-------------+------------------------+-------+--------+------------------------+--------+
| hostname | binary      | engine_id              | host  | topic  | updated_at             | status |
+----------+-------------+------------------------+-------+--------+------------------------+--------+
| host1    | heat-engine | 6c20d3ab-b733-413c-b50 | host1 | engine | 2017-01-20T07:23:56.00 | down   |
|          |             | 9-210170055236         |       |        | 0000                   |        |
| host3    | heat-engine | 7708e359-83b8-4087     | host3 | engine | 2017-01-20T07:32:23.00 | up     |
|          |             | -973f-3f396734f5ce     |       |        | 0000                   |        |
| host3    | heat-engine | a355d8cb-b1a4-4afb-    | host3 | engine | 2017-01-20T07:32:45.00 | up     |
|          |             | 99e8-35dbadd75241      |       |        | 0000                   |        |
| host1    | heat-engine | 8902b38d-3267-46b8     | host1 | engine | 2017-01-20T07:32:22.00 | up     |
|          |             | -908f-d21f4ed5e0ee     |       |        | 0000                   |        |
......

heat 服务正常。说明 “Resource temporarily unavailable” ERROR 应该是间断性地，或者对手动输入的命令没有影响。由此猜测该问题与数据库性能相关。

Step3 查看进程

root@host3:~# netstat -natp | grep mysql | wc -l
411

发现有 411 个进程在访问数据库，有可能正是因为大量的访问进程才导致 “Resource temporarily unavailable”。
查看各服务进程：

root@host3:/var/log/heat# ps aux | grep heat-engine | wc -l
74
root@host3:/var/log/heat# ps aux | grep heat-api | wc -l
75
root@host3:/var/log/heat# ps aux | grep nova-api | wc -l
146
root@host3:/var/log/heat# ps aux | grep cinder-api | wc -l
74

Step4 查找进程数量参数

查看 heat-engine 进程，找到代码入口。

root@host3:/var/log/heat# ps aux | grep heat-engine
root       1584  0.0  0.0  12948  1088 pts/1    S+   23:41   0:00 grep --color=auto heat-en
heat     141782  1.5  0.2 382712 139640 ?       Ss   23:16   0:23 /usr/bin/python /usr/bin/heat-engine --config-file=/etc/heat/heat.conf --log-file=/var/log/heat/heat-engine.log
heat     141801  0.0  0.1 386808 129572 ?       S    23:16   0:01 /usr/bin/python /usr/bin/heat-engine --config-file=/etc/heat/heat.conf --log-file=/var/log/heat/heat-engine.log
heat     141802  0.0  0.1 386808 129620 ?       S    23:16   0:01 /usr/bin/python /usr/bin/heat-engine --config-file=/etc/heat/heat.conf --log-file=/var/log/heat/heat-engine.log

查看 /usr/bin/heat-engine 文件

#!/usr/bin/python
# PBR Generated from u'console_scripts'

import sys

from heat.cmd.engine import main


if __name__ == "__main__":
    sys.exit(main())

进入 heat/cmd 目录

root@host3:/var/log/heat# cd /usr/lib/python2.7/dist-packages/heat/cmd/
root@host3:/usr/lib/python2.7/dist-packages/heat/cmd# ll
total 68
drwxr-xr-x  2 root root 4096 Jan 19 23:45 ./
drwxr-xr-x 16 root root 4096 Jan 19 03:07 ../
-rw-r--r--  1 root root 2245 Oct  6 06:13 api_cfn.py
-rw-r--r--  1 root root 2224 Jan 19 03:07 api_cfn.pyc
-rw-r--r--  1 root root 2336 Oct  6 06:13 api_cloudwatch.py
-rw-r--r--  1 root root 2267 Jan 19 03:07 api_cloudwatch.pyc
-rw-r--r--  1 root root 2024 Oct  6 06:13 api.py
-rw-r--r--  1 root root 2032 Jan 19 03:07 api.pyc
-rw-r--r--  1 root root 2556 Oct  6 06:13 engine.py
-rw-r--r--  1 root root 2505 Jan 19 03:07 engine.pyc
-rw-r--r--  1 root root    0 Oct  6 06:13 __init__.py
-rw-r--r--  1 root root  140 Jan 19 03:07 __init__.pyc
-rw-r--r--  1 root root 8894 Oct  6 06:13 manage.py
-rw-r--r--  1 root root 8407 Jan 19 03:07 manage.pyc

查看 engine.py 文件

def main():
    logging.register_options(cfg.CONF)
    cfg.CONF(project='heat', prog='heat-engine',
             version=version.version_info.version_string())
    logging.setup(cfg.CONF, 'heat-engine')
    logging.set_defaults()
    messaging.setup()

    config.startup_sanity_check()

    mgr = None
    try:
        mgr = template._get_template_extension_manager()
    except template.TemplatePluginNotRegistered as ex:
        LOG.critical(_LC("%s"), ex)
    if not mgr or not mgr.names():
        sys.exit("ERROR: No template format plugins registered")

    from heat.engine import service as engine  # noqa

    profiler.setup('heat-engine', cfg.CONF.host)
    gmr.TextGuruMeditation.setup_autorun(version)
    srv = engine.EngineService(cfg.CONF.host, rpc_api.ENGINE_TOPIC)
    workers = cfg.CONF.num_engine_workers
    if not workers:
        workers = max(4, processutils.get_worker_count())

    launcher = service.launch(cfg.CONF, srv, workers=workers)
    if cfg.CONF.enable_cloud_watch_lite:
        # We create the periodic tasks here, which mean they are created
        # only in the parent process when num_engine_workers>1 is specified
        srv.create_periodic_tasks()
    launcher.wait()

走读代码，发现 workers 这个变量。基本断定这个变量控制了 heat-engine 的进程数量，并且设置了最小值为 4，并且猜测 get_worker_count() 函数功能是服务器的 CPU 核数计算最佳性能的进程数量。
在 /etc/heat 目录下搜索 num_engine_workers：

root@host3:/etc/heat# grep -rn "num_engine_workers" -C 5
heat.conf.55490.2017-01-19@03:08:10~-204-# Maximum depth allowed when using nested stacks. (integer value)
heat.conf.55490.2017-01-19@03:08:10~-205-#max_nested_stack_depth = 5
heat.conf.55490.2017-01-19@03:08:10~-206-
heat.conf.55490.2017-01-19@03:08:10~-207-# Number of heat-engine processes to fork and run. Will default to either to 4
heat.conf.55490.2017-01-19@03:08:10~-208-# or number of CPUs on the host, whichever is greater. (integer value)
heat.conf.55490.2017-01-19@03:08:10~:209:#num_engine_workers = <None>
heat.conf.55490.2017-01-19@03:08:10~-210-
heat.conf.55490.2017-01-19@03:08:10~-211-#
heat.conf.55490.2017-01-19@03:08:10~-212-# From heat.common.crypt
heat.conf.55490.2017-01-19@03:08:10~-213-#
heat.conf.55490.2017-01-19@03:08:10~-214-

Number of heat-engine processes to fork and run. Will default to either to 4 or number of CPUs on the host, whichever is greater. (integer value)

Step5 本地测试

在 /etc/heat/heat.conf 文件中加入 num_engine_workers = 10。

root@host3:/etc/heat# ps aux | grep heat-engine | wc -l
74
root@host3:/etc/heat# vim heat.conf
root@host3:/etc/heat# service heat-engine restart
root@host3:/etc/heat# ps aux | grep heat-engine | wc -l
12

可见加入这个配置项之后，heat-engine 的进程数量显著减少。

Step6 提交 Patch，修复 Bug

diff --git a/deploy/adapters/ansible/openstack/templates/nova.conf b/deploy/adapters/ansible/openstack
index 4a7bb0a..99071d7 100644
--- a/deploy/adapters/ansible/openstack/templates/nova.conf
+++ b/deploy/adapters/ansible/openstack/templates/nova.conf
@@ -39,6 +39,10 @@ notification_driver = nova.openstack.common.notifier.rpc_notifier
 notification_driver = ceilometer.compute.nova_notifier
 memcached_servers = {{ memcached_servers }}
 
+{% if ansible_processor_vcpus > 30 %}
+osapi_compute_workers = 30
+{% endif %}
+
 [database]
 # The SQLAlchemy connection string used to connect to the database
 connection = mysql://nova:{{ NOVA_DBPASS }}@{{ db_host }}/nova
diff --git a/deploy/adapters/ansible/roles/cinder-controller/templates/cinder.conf b/deploy/adapters/a
index d428a07..05a1c8f 100644
--- a/deploy/adapters/ansible/roles/cinder-controller/templates/cinder.conf
+++ b/deploy/adapters/ansible/roles/cinder-controller/templates/cinder.conf
@@ -35,6 +35,9 @@ quota_driver = cinder.quota.DbQuotaDriver
 
 osapi_volume_listen = {{ storage_controller_host }}
 osapi_volume_listen_port = 8776
+{% if ansible_processor_vcpus > 30 %}
+osapi_volume_workers = 30
+{% endif %}
 
 db_backend = sqlalchemy
 volume_name_template = volume-%s

由于 nova-api，cinder-api，heat-api，heat-engine 的进程数量较大，对它们加入了最大值限制。
Patch 地址：FIX access database failed

Bug 引入原因

由于数据库的性能瓶颈，导致各个服务利用 CPU 核心数计算出来的最佳性能进程数量压垮了 MySQL。这也从侧面反映了 Compass4NFV 在本地进行虚拟部署时非常稳定，但是一旦进行物理部署，就会出现各种问题。服务器性能越好，CPU 核心数越多，部署成功的概率反而越低。

问题反思

有些偶然性问题导致部署失败，虽然重新构建一把说不定就能够过去，但是这颗炸弹会一直隐藏在代码中。所以面对 CI 上那些低概率的问题，应该更加重视，及时优化代码。