基于Pacemaker+Corosync的PostgreSQL HA故障两例

前几天Pacemaker+Corosync的PostgreSQL HA集群发生了两次故障，再次提醒了HA的部署要谨慎，维护要细致。

故障1：高负载下自动切换

系统是基于Pacemaker+Corosync的PostgreSQL 1主2从 HA集群。在数据库上执行一个delete.从500w的表里删除13w条记录，发现Master挂了。然后自动起来，再执行这个SQL，再次挂。究竟怎么回事呢？

后来查了Pacemaker的日志，发现是expgsql RA的monitor发生超时，导致expgsql RA重启PostgreSQL。（迁移阈值是3，可以重启3次，超过3次就会发生主从切换。）

/var/log/messages

Nov 18 13:22:05 node1 expgsql(pgsql)[7774]: INFO: Stopping PostgreSQL on demote.
Nov 18 13:22:05 node1 expgsql(pgsql)[7774]: INFO: server shutting down
Nov 18 13:22:11 node1 expgsql(pgsql)[7774]: INFO: PostgreSQL is down
Nov 18 13:22:11 node1 expgsql(pgsql)[7774]: INFO: Changing pgsql-status on node1 : PRI->STOP.
Nov 18 13:22:11 node1 expgsql(pgsql)[8609]: INFO: PostgreSQL is already stopped.
Nov 18 13:22:12 node1 expgsql(pgsql)[8714]: INFO: Set all nodes into async mode.
Nov 18 13:22:12 node1 expgsql(pgsql)[8714]: INFO: server starting
Nov 18 13:22:12 node1 expgsql(pgsql)[8714]: INFO: PostgreSQL start command sent.
Nov 18 13:22:12 node1 expgsql(pgsql)[8714]: INFO: PostgreSQL is down
Nov 18 13:22:13 node1 expgsql(pgsql)[8714]: INFO: PostgreSQL is started.

corosync.log中发现在发生超时前，系统负载很高。

/var/log/cluster/corosync.log

Nov 18 13:20:55 [2353] node1       crmd:     info: throttle_handle_load:    Moderate CPU load detected: 12.060000
Nov 18 13:20:55 [2353] node1       crmd:     info: throttle_send_command:   New throttle mode: 0010 (was 0001)
Nov 18 13:21:25 [2353] node1       crmd:   notice: throttle_handle_load:    High CPU load detected: 16.379999
Nov 18 13:21:25 [2353] node1       crmd:     info: throttle_send_command:   New throttle mode: 0100 (was 0010)
Nov 18 13:21:44 [2350] node1       lrmd:  warning: child_timeout_callback:  pgsql_monitor_3000 process (PID 4822) timed out
Nov 18 13:21:44 [2350] node1       lrmd:  warning: operation_finished:  pgsql_monitor_3000:4822 - timed out after 60000ms
Nov 18 13:21:44 [2353] node1       crmd:    error: process_lrm_event:   Operation pgsql_monitor_3000: Timed Out (node=node1, call=837, timeout=60000ms)
Nov 18 13:21:44 [2348] node1        cib:     info: cib_process_request: Forwarding cib_modify operation for section status to master (origin=local/crmd/462)

系统是4核机，上面的输出表明系统已经超载，进入限流模式。后面甚至有负载达到49的记录。

Nov 18 13:24:55 [2353] node1       crmd:   notice: throttle_handle_load:    High CPU load detected: 48.320000
Nov 18 13:25:25 [2353] node1       crmd:   notice: throttle_handle_load:    High CPU load detected: 49.750000
Nov 18 13:25:39 [2350] node1       lrmd:  warning: child_timeout_callback:  pgsql_demote_0 process (PID 16604) timed out
Nov 18 13:25:55 [2353] node1       crmd:   notice: throttle_handle_load:    High CPU load detected: 48.860001
Nov 18 13:26:03 [2350] node1       lrmd:  warning: operation_finished:  pgsql_demote_0:16604 - timed out after 60000ms

throttle mode是什么鬼？

限流模式是Pacemaker的一种保护措施，进入限流模式后Pacemaker会减少自身可以并发执行的job数。在High CPU load下，限流模式会限制同时只能有1个job在跑。正常情况下，允许同时运行的最大job数是CPU核数的2倍。

https://github.com/ClusterLabs/pacemaker/blob/master/crmd/throttle.c

int
throttle_get_job_limit(const char *node)
{
...switch(r->mode) {case throttle_extreme:case throttle_high:jobs = 1; /* At least one job must always be allowed */break;case throttle_med:jobs = QB_MAX(1, r->max / 4);break;case throttle_low:jobs = QB_MAX(1, r->max / 2);break;case throttle_none:jobs = QB_MAX(1, r->max);break;default:crm_err("Unknown throttle mode %.4x on %s", r->mode, node);break;}
...
}

如何获取CPU LOAD和负载阈值

获取CPU LOAD的方式为取/proc/loadavg中第一行的1分钟负载。

至于负载阈值，有3个负载级别，不同阈值有不同的因子(throttle_load_target)

#define THROTTLE_FACTOR_LOW    1.2
#define THROTTLE_FACTOR_MEDIUM 1.6
#define THROTTLE_FACTOR_HIGH   2.0

对应的阈值分别为 load-threshold * throttle_load_target

load-threshold为集群参数，默认值为80%

判断是否超过阈值的方法是用调整后的CPU负载(上面的CPU LOAD除以核心数)和阈值比较

IO负载

除了CUP负载，Pacemaker还有IO负载的比较，但是相关函数存在多处错误，实际上无效。无效也好，如果下面这个问题解决了后面会有相反的bug导致会误判高IO负载。

static bool throttle_io_load(float *load, unsigned int *blocked)
{
if(fgets(buffer, sizeof(buffer), stream)) {...long long divo2 = 0;...long long diow =0;...long long Div = 0;*load = (diow + divo2) / Div; //结果始终为0...return TRUE; //只读了第一行就返回导致不会给blocked赋值
}
}

限流和本次故障有什么关系

不能肯定限流和这次故障是否有必然的联系。但是在限流下，Pacemaker执行job的能力弱了，系统负载又高，会增大monitor相关job得不到及时的CPU调度进而发生超时的概率。实际的罪魁祸首还应该是高负载及超时判断方法。

类似问题

搜索后发现有人遇到过类似问题，处理办法就是增大monitor的超时时间。

https://bugs.launchpad.net/fuel/+bug/1464131
https://review.openstack.org/#/c/191715/1/deployment/puppet/pacemaker_wrappers/manifests/rabbitmq.pp

解决办法

一方面修改增大monitor的超时时间。在线修改的方法如下：

pcs resource update pgsql op monitor interval=4s timeout=300s on-fail=restart
pcs resource update pgsql op monitor role=Master timeout=300s on-fail=restart interval=3s

另一方面，发现系统负载过重，经常跑到100%的CPU，即使没有HA这档子事也是个不稳定因素。通过修改应用，迁移大部分的读负载到SLave上，有效减轻了Master的压力。

其它案例

GitHub遇到过类似的故障，由于迁移到Master负载过高，进而Percona Replication Manager的健康检查失败进行了切换，切换后新主的缓存是冷的，负载同样过高，又切回去。（幸运的是我们的方案有3次迁移阈值的保护，不会立刻切。）GitHub权衡后的对策居然是放弃自动切换，只能由人工发起。

参考: GitHub 的两次故障分析

另，Pacemkaer的论坛有几件高负载导致corosync token超时的问题，同样由于相关job不能及时得到OS调度所致，该问题虚机上容易发生，特别是有超分的情况下，解决办法是加大token超时时间。

故障2：同步复制变成了异步复制

系统配置的同步复制，正常情况下2个Slave应该一个是sync，另一个是async。但是，某个时间发现2个Slave都是async，这对应用系统暂无影响，但是万一这时Master挂了会影响HA切换。查看Master上的rep_mode.conf配置文件，发现synchronous_standby_names是空。

vi /var/lib/pgsql/tmp/rep_mode.conf

synchronous_standby_names = ''

于是，手工修改为node2，再reload一下就OK了。

vi /var/lib/pgsql/tmp/rep_mode.conf

synchronous_standby_names = 'node2'

至于什么原因导致的，又仔细查看了一下RA脚本，未发现疑点，而现场已经不在，无从查起，只能等下次遇到再说。