基于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脚本，未发现疑点，而现场已经不在，无从查起，只能等下次遇到再说。
