基于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倍。

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的超时时间。

解决办法

一方面修改增大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权衡后的对策居然是放弃自动切换，只能由人工发起。

参考: 

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