PG数据库hang住了,慌个der

提示1:由于事发突然,第一时间恢复业务为主要任务(最要原因是想早点搞完去聚餐,谁TM愿意5.1休息时间搞问题);因此在紧急解决问题过程中很多截图没来得及截取(也不想去搞),后续复盘无法复现,因此有点蜻蜓点水的感觉。;当然这个问题归根结底还是基于异步/同步/半同步机制(参考MySQL半同步以及分布式Paxos/Raft协议机制);对于gdb源码也有一些小研究,见文章内容中间部分。

提示2:事情太多,写的比较匆忙


**一、 问题描述**

5月4号下午16:00左右接到紧急电话,一线业务操作提示业务系统无法使用,系统数据全部无法保存。


1)业务界面错误提示:

2)jdbc日志信息提示连接数过多

**二、 问题分析**

**1. 环境信息确认**

现网使用PAF搭建主从高可用环境,读写分离。

**2. 登录数据库主库**

登录主库执行pg_autoctl show state查看主从状态,提示”-bash: fork retry:no child process”。

Linux使用bash 使用fork()函数创建子进程。当无法使用bash fork()子进程,大多场景是因为ulimit限制或者资源耗尽导致。目前看来是因为Resource资源耗尽导致。


**3. 查看pg后端进程**

大量事务相关的COMMIT/Update waitig等待:

总共5037个进程:

**4. 查看操作系统资源使用情况**

1)内存free378MB(总共126GB),SWAP使用5.8GB,可用内存几乎耗尽。

2)资源使用超负载:

Max_connections=5000

Shared_buffers=60GB


3)资源估算以及紧急处理

最大内存估算:

Max memory usage:

                  shared_buffers (60GB)

                + max_connections * work_mem * average_work_mem_buffers_per_connection (5037 * 128 MB * 150%

=206 GB)

                + autovacuum_max_workers * maintenance_work_mem (8 * 2GB = 16GB)

                + track activity size (0.00 B)

                = 222 GB >>OS mem(126GB)


经过估算内存最大使用量远超过操作系统最大内存128GB,在极限内存使用场景下,内存资源不足。


**5. 紧急处理**


在这种情况下,很多人可能就会考虑重启数据库。在通常场景下,运维“三板斧”确实很管用,但是在这个情况就不行了(这是后话)。

--题外话:当数据库出现异常时,第一时间不是重启,而是在时间允许的情况下(争取故障恢复缓冲时间)保留故障现场,尽可能收集足够多的信息(例如mem/io/process以及各种不易保存的日志信息截图等),作为后续故障复盘或者故障定界(“谁的锅”)的重要“证据”。


使用脚本kill所有postgres waiting状态的进程,回收内存及进程资源资源:

ps -ef| grep postgres | grep “waiting”|grep -v grep |awk ‘{print $2}’|xargs kill -s 9


此时数据库处于“psql is in recover”状态,慢慢等待一小会就可以psql登录数据库。

`

``sql
当然也可以使用
ps aux --sort=rss|grep postgres | awk '{sum+=$6}END{print sum/1024/1024}'
ps aux --sort=rss|head -n 10 
pmap
gstack等工具分析内存
/proc/pid/status分析内存泄漏情况,OOM情况
java可以使用arthas分析内存gc等
为了赶时间就不一一不详述
```


**重点解释:**

**1)为什么要kiss -s 9,用户态(tx commited)的kill -s 9如果都能出现异常,那么pg的机制确实存在很大风险;如果有也是MVCC机制问题,最多就是事务恢复长短而已;如果涉及WAL被清空也没这么夸张,都有终极办法恢复的

2)在hang状态下,数据肯定是有部分丢失,谁有没有办法;但是考虑有备机在,有WAL日志在,即使主库因为kill -s 9脆皮宕机,也可以借助手段恢复(分布式半同步多副本机制自行研究补脑);还有数据库备份保障等其他特殊恢复手段兜底,因此不必大惊小怪;

3)本人曾在原厂和研发有深入交流,经常模拟coredump测试产品稳定性,这种情况早就司空见惯。对于目前这个情形,当前这个情况根本还没到coredump阶段,慌个der;

4)PG 主备原理与MySQL同步/半同步/异步机制大同小异,与Oracle ADG更没法比;所以不用担心这些因为kill -9就业务风险;Oracle随便你怎么kill用户态进程都没事(这是后话)

5)紧急情况,第一时间恢复业务是第一准则,内存OOM问题其实很简单,gdb打一个中断就好了(但问题是5000个会话占满连接池,后续还有源源不断的高并发进入,你gdb能一下把5000个进程包括后续进程持续不断地搞定?),参考PG内存管理:**


```sql
通过内存上下文gdb打印中断
例如常见的ExecResult函数可以追踪SQL执行结果;
ReadBuffer_common函数定义了本地缓冲区和共享缓冲区的通用读取方法
示例:
gdb -p 21469
(gdb) bt
#0  0x00007f7bf070ff23 in __epoll_wait_nocancel () at ../sysdeps/unix/syscall-template.S:81
#1  0x000000000078846a in WaitEventSetWaitBlock (nevents=1, occurred_events=0x7ffcd5c896a0, cur_timeout=-1, set=0x16dd718) at latch.c:1489
#2  WaitEventSetWait (set=0x16dd718, timeout=timeout@entry=-1, occurred_events=occurred_events@entry=0x7ffcd5c896a0, nevents=nevents@entry=1, wait_event_info=wait_event_info@entry=100663296) at latch.c:1435
#3  0x000000000068faae in secure_read (port=0x16d5010, ptr=0xdbe780 , len=8192) at be-secure.c:186
#4  0x0000000000695968 in pq_recvbuf () at pqcomm.c:957
#5  0x0000000000696545 in pq_getbyte () at pqcomm.c:1000
#6  0x00000000007ab308 in SocketBackend (inBuf=0x7ffcd5c89850) at postgres.c:351
#7  ReadCommand (inBuf=0x7ffcd5c89850) at postgres.c:474
#8  PostgresMain (dbname=, username=) at postgres.c:4525
#9  0x000000000048d5f4 in BackendRun (port=, port=) at postmaster.c:4511
#10 BackendStartup (port=0x16d5010) at postmaster.c:4239
#11 ServerLoop () at postmaster.c:1806
#12 0x000000000072d8a8 in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x16afc20) at postmaster.c:1478
#13 0x000000000048e426 in main (argc=3, argv=0x16afc20) at main.c:202
//Breakpoint ExecResult
//ExecResult 断点
(gdb) b ExecResult
Breakpoint 2 at 0x677970: file nodeResult.c, line 69.
//continue
(gdb) c
Continuing.
Breakpoint 2, ExecResult (pstate=0x1772180) at nodeResult.c:69
69      nodeResult.c: No such file or directory.
--seesion1 
select 1;
//New Breakpoint
(gdb) bt
#0  ExecResult (pstate=0x1772180) at nodeResult.c:69
#1  0x0000000000648082 in ExecProcNode (node=0x1772180) at ../../../src/include/executor/executor.h:259
#2  ExecutePlan (execute_once=, dest=0x17702c8, direction=, numberTuples=0, sendTuples=true, operation=CMD_SELECT, use_parallel_mode=, planstate=0x1772180,
    estate=0x1771f58) at execMain.c:1636
#3  standard_ExecutorRun (queryDesc=0x16d7398, direction=, count=0, execute_once=) at execMain.c:363
#4  0x00000000007ad86e in PortalRunSelect (portal=portal@entry=0x17238a8, forward=forward@entry=true, count=0, count@entry=9223372036854775807, dest=dest@entry=0x17702c8) at pquery.c:924
#5  0x00000000007aec80 in PortalRun (portal=portal@entry=0x17238a8, count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=true, run_once=run_once@entry=true, dest=dest@entry=0x17702c8,
    altdest=altdest@entry=0x17702c8, qc=qc@entry=0x7ffcd5c896b0) at pquery.c:768
#6  0x00000000007aab5e in exec_simple_query (query_string=query_string@entry=0x16b41b8 "select 1;") at postgres.c:1250
#7  0x00000000007ab187 in PostgresMain (dbname=, username=) at postgres.c:4593
#8  0x000000000048d5f4 in BackendRun (port=, port=) at postmaster.c:4511
#9  BackendStartup (port=0x16d5010) at postmaster.c:4239
#10 ServerLoop () at postmaster.c:1806
#11 0x000000000072d8a8 in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x16afc20) at postmaster.c:1478
#12 0x000000000048e426 in main (argc=3, argv=0x16afc20) at main.c:202


```


**6.故障分析**

1) 主备数据库状态看起来是正常的

实际上使用pg_autoctl show state信息是有延迟的,甚至可能不准确(这个场景也不准确)。显示的主备同步OK,但是复制链路早就断开了,从数据库日志及同步延迟查询均可以看到。

2) 查看复制链路,复制信息为空,链路中断


3) 尝试在主库创建表ddl以及insert数据处于阻塞等待,等待事件”SyncRep”,即等待备机响应。

```sql
SELECT
    s.procpid,
    s.start,
    now() - s.start AS elapsed_time,
    a.state,
    a.wait_event,
    s.current_query
FROM
    (SELECT
        backendid,
        pg_stat_get_backend_pid(S.backendid) AS procpid,
        pg_stat_get_backend_activity_start(S.backendid) AS start,
       pg_stat_get_backend_activity(S.backendid) AS current_query
    FROM
        (SELECT pg_stat_get_backend_idset() AS backendid) AS S
    ) AS s,
    pg_stat_activity  a
WHERE
   s.procpid=a.pid
AND
   s.current_query <> '' 
AND 
   a.state<>'idle'   
AND
--exclude current pid
   s.procpid <> pg_backend_pid()
AND 
   now() - s.start > interval '1 seconds'
ORDER BY
   now() - s.start DESC; 
\watch 2;
```


3)观测一段时间, 发现先进入的会话(DDL/DML)一直被阻塞,后续进入(DML/DDL)均处于阻塞状态,前端业务始终无法保存数据。这样会导致进程一直进入数据库而不能commit提交回收,资源堆积积压越来越严重。当到max_connections阈值以及内存使用满后,则业务端无法使用,业务异常。


4)使用手动创建表以及执行insert动作,均被阻塞。


**7 进一步分析**

1)pg_profile执行结果

Pg_profile使用crontab定时任务每半小时执行一次,而snap_id在234、235、236都出现了统计信息重置,初步怀疑数据库异常重启&切换;同时234、235、235快照执行时间过长(>30mins),可能原因是因为数据库负载过高,导致调用profile.snapshot() 生成快照失败。

2)查看日志文件,大量的insert写入慢日志(10s+)


三、 问题定位

1. 新的会话不断进入,数据库DDL/DML(大量insert并发写入)均被阻塞;

2. 尝试手动执行DDL创建表、DML更新数据均被阻塞(手动执行变更主要是测试数据库是否是全局都被阻塞或者局部数据被阻塞)

3. 尽管pg_autoctl show state显示有明显主备关系,实际上信息可能不准确(可自行测试)。考虑到主备复制链路异常(WAL日志GAP)以及因负载过高导致切换脑裂(日志记录),初步怀疑数据库事务是否被设置为read_only。实际检查结果为off(read write),排除这个可能性。


4. 结合第2步骤以及会话进入后一直处于SyncRep(COMMIT)等待落盘,推测主备同步机制是否出现异常,Async->sync。


5. 检查主备同步状态信息:

[postgres@monitor data]$ pg_autoctl get formation settings
  Context |    Name |                   Setting | Value
----------+---------+---------------------------+------
formation | default |      number_sync_standbys | 0
  primary |  node_1 | synchronous_standby_names | '*'
     node |  node_1 |        candidate priority | 50
     node |  node_2 |        candidate priority | 50
     node |  node_1 |        replication quorum | true
     node |  node_2 |        replication quorum | true



可以看到,主备为同步模式,这就可以解释为什么主库发起的所有DDL/DML都被阻塞了。


6. 问题复盘(**不想去分析原因,太累,跟着经验走就行**):

1) 大量insert以及高负载SQL进入pg数据库,将数据库资源吃满(内存/进程/磁盘)

2) 数据库压力过高,PAF触发切换;

3) PAF切换到备机后,备机负载很快拉满;

4) 业务出现故障,人为干预手动切换(WAL)(日志记录)等切换操作导致异常脑裂(WAL GAP)

5) 一线业务人员重建主备环境(出厂设置规范)恢复,模式设置为sync同步模式;

6) 在sync同步模式下,主库DDL/DML均等待备机ACK应答无法落盘,而此时主备复制链路中断导致备机无法响应主库的commit,请求,因此主库会话一直处于COMMIT “SyncRep”状态;

7) 资源耗尽,业务数据无法保存(write)。

四、 问题处理

问题定位清楚后,解决步骤:

1. 将同步模式改为异步模式:

pg_autoctl set node replication-quorum false


2. 查看状态更为异步模式

```sql

//更改前

[postgres@monitor data]$ pg_autoctl get formation settings
  Context |    Name |                   Setting | Value
----------+---------+---------------------------+------
formation | default |      number_sync_standbys | 0
  primary |  node_1 | synchronous_standby_names | '*'
     node |  node_1 |        candidate priority | 50
     node |  node_2 |        candidate priority | 50
     node |  node_1 |        replication quorum | true
     node |  node_2 |        replication quorum | true
//更为PAF为async异步模式后:
[postgres@monitor data]$  pg_autoctl get formation settings
  Context |    Name |                   Setting | Value
----------+---------+---------------------------+------
formation | default |      number_sync_standbys | 0
  primary |  node_1 | synchronous_standby_names | ''
     node |  node_1 |        candidate priority | 50
     node |  node_2 |        candidate priority | 50
     node |  node_1 |        replication quorum | false
     node |  node_2 |        replication quorum | false


```

3. 观察主库写入情况

主库写入DDL/DML均正常,会话负载未被阻塞积压,业务恢复正常。


结束语:

经过排查,diao毛人员设计安装器出厂把PAF复制默认为同步模式,天大的巨坑,真TM想骂娘!




请使用浏览器的分享功能分享到微信等