【Greenplum常见问题】 “我的SQL卡住了怎么办？”

​大家好，我是Pivotal Greenplum团队的一名售后工程师。平时会帮助我们的全球的商业用户解决数据库的相关的问题。在实际工作中，我们经常会被数据库管理员问及：“我的SQL跑了很长时间没有结果，我该怎么样排查?” “数据库某一条SQL卡住了怎么办？” 今天，我们将就这个内容做一些分析和总结。

一般来说，SQL卡住或者运行时间长这类常见问题的原因如下：

• SQL因为死锁原因，并没有执行
• SQL因为Resource Queue或者Resource Group没有资源而等待
• SQL因为在某一个segment或者某个机器的问题而卡住

针对问题1 和 问题2，在Greenplum中，我们可以通过查询pg_locks表和gp_toolkit/GPCC中资源队列/组的状态来排查。
而问题3，往往是非常棘手又不得不解决的.下面我们将详细介绍在排除了死锁和资源组/队列问题后，SQL仍然长时间没有返回结果的排查方法。
首先，我们需要通过如下语句确定SQL的 Session ID也叫Connection ID。比如我们数据库中有一个truncate 语句长时间没有返回结果，我们可以通过下面语句确定SessionID

gpadmin=# SELECT * from pg_stat_activity where upper(current_query) like '%TRUNCATE%'; datid | datname | procpid | sess_id | usesysid | usename |                              current_query | waiting |        query_start | backend_start | client_addr | client_port | application_name |        xact_start | waiting_reason | rsgid | rsgname | rsgqueueduration
-------+---------+---------+---------+----------+---------+------------------------------------------------------------------------------+---------+-------------------------------+-------------------------------+-------------+-------------+------------------+-------------------------------+----------------+-------+---------+------------------ 
16384 | gpadmin |   15103 | 310 |     10 | gpadmin | TRUNCATE aoco;                                                             | t | 2019-11-12 00:24:56.017908-05 | 2019-11-12 00:24:47.147582-05 | |     -1 | psql | 2019-11-12 00:24:56.017908-05 | lock | 0 | unknown | 16384 | gpadmin |   15218 | 91014 |   10 | gpadmin | SELECT * from pg_stat_activity where upper(current_query) like '%TRUNCATE%'; | f     | 2019-11-12 00:28:06.973462-05 | 2019-11-12 00:24:58.490902-05 | | -1 | psql       | 2019-11-12 00:28:06.973462-05 | | 0 | unknown 
|(2 rows)

上面输出显示的sess_id是310。紧接着, 我们要通过gpssh 工具来检查每个segment的进程执行状况：
$ gpssh -f <hostfile> 'ps -ef | grep con<sess_id> | grep -v idle' 
注：这里的con<sess_id> 就是对应sessionID 310 就是con310
这里我们排除了idle的进程，因为idle进程是处理完自己Slice当时分配任务的进程，我们无需关心。通过上面gpssh命令的输出，我们就对所有这个SQL的对应进程在greenplum上的执行状况有个大致的了解。

• 比如说SQL只在一个segment进程上有非idle的情况，那么我们只要着重查看这个segment状况即可。可能引起这样状况的原因最常见的状况就是data Skew；就是这个SQL对应表可能有分布不均的情况，也有可能是我们的SQL join的键值原因导致的SQL处理过程中的分布不均。
• 假如说这个SQL的对应进程只在一个机器上有非idle的状况，那么我们可以着重关注一下这台机器对应的硬件是否有问题。最常见的就是磁盘的问题。是否磁盘的读写率一直很高在100%？是否其他SQL在这台机器上也有卡住的状况？
• 如果我们在所有的机器上看到这个SQL的进程都是分布很均匀的，那么很有可能这个SQL本身处理的数据量发生了变化，所以时间变长。还有一种最不好的可能性，就是因为我们这个SQL不能被Greenplum的优化器很好的识别，所以很慢。

不管针对上面的任何的情况，strace和pstack这两个工具都可以帮助我们理解在进程级别这些SQL都做了什么动作。所以，我们建议所有的机器都要装这两个工具。（另外，针对情况2的磁盘问题，我们建议iotop工具来甄别那个进程用的磁盘资源较多）
Strace是一个动态追踪进程系统调用的工具（进程跟操作系统内核的交互)，我们可以直接使用strace -p 这个命令直接查看，也可以用如下命令：
strace -T -f -ff -y -yy -p
根据我们的经验，这个strace的参数组合的可以更好的输出可读性更好的结果。Strace 是一个在顺着时间动态追踪的工具，而pstack可以纵向打印出来某个确定时间点上进程的Call Stack 信息。Call Stack 可以让我们知道进程在某个具体时间点某个进程究竟在做什么事情。比如：

[root@bdlgpscprd07 gpadmin]# pstack 6495
Thread 2 (Thread 0x7f442920e700 (LWP 6504)):
#0 0x00007f4424e2d043 in poll () from /lib64/libc.so.6
#1 0x0000000000bc1ac4 in rxThreadFunc ()
#2 0x00007f442588f9d1 in start_thread () from /lib64/libpthread.so.0
#3 0x00007f4424e3686d in clone () from /lib64/libc.so.6
Thread 1 (Thread 0x7f44293d2720 (LWP 6495)):
#0 0x00007f4424e2f2e3 in select () from /lib64/libc.so.6
#1 0x00000000008e1cfa in sendSequenceRequest ()
#2 0x00000000006ee69d in nextval_oid ()
#3 0x0000000000759606 in ExecMakeFunctionResultNoSets ()
#4 0x000000000075e662 in ExecProject ()
#5 0x0000000000784727 in ExecHashJoin ()
#6 0x0000000000757d64 in ExecProcNode ()
#7 0x000000000078f249 in SubqueryNext ()
#8 0x0000000000762d5b in ExecScan ()
#9 0x0000000000757c09 in ExecProcNode ()
#10 0x0000000000798b0a in ExecMotion ()
#11 0x0000000000757b66 in ExecProcNode ()
#12 0x000000000074d5bc in ExecutePlan ()
#13 0x000000000074dd76 in ExecutorRun ()
#14 0x000000000099d634 in ProcessQuery ()
#15 0x00000000009a0050 in PortalRun ()
#16 0x0000000000995dc0 in exec_mpp_query ()
#17 0x0000000000999c95 in PostgresMain ()
#18 0x00000000008f6e3e in ServerLoop ()
#19 0x00000000008f9ae0 in PostmasterMain ()
#20 0x00000000007fb13f in main ()

从上面这个callstack中我们可以看到这个进程在执行一个Hashjoin.所以如果看到所有的进程都是这个地方比较慢，我们可以尝试考虑对应的hashjoin是否有问题。（更加具体的分析可能需要结合代码）

针对pstack，我们可以用一个简单的shell脚本没20秒钟打印出一次，去更好的理解进程的工作状况，每20秒的工作状况。
$ while true; do date; pstack <pid>; sleep 20; done;
在运用了strace和pstack之后我们会对问题有个大致的判断。比如磁盘操作比较慢，比如大部分进程是在等待网络上的数据，等等。但是如果pstack和stace后，我们仍然无法对问题有一个深入的了解，对于商业用户，可以通过联络Pivotal技术支持获取帮助。（注：如果问题可以在您的环境重现问题，那么将极大的帮助Pivotal 技术支持定位问题）。那么，我们怎么样帮助Pivotal 技术支持收集相关信息呢？
Pivotal 技术支持已经开发了gpmt analyze_session tool来帮助商业用户收集SQL卡住的对应信息：
GPMT是一个非常好的收集日志的工具，也非常建议大家在环境中安装。另外，如果问题可以连续复现，我们建议您使用mini-repro来收集对应SQL的DDL和统计信息。这个我们在之前的文章也有过分享过收集日志的步骤，详情请查看链接。

今天的分享就到这里，非常感谢大家的关注，请大家继续关注我们的文章系列。如果有任何问题，可以给我们留言，商业用户可以通过Pivotal 技术支持与我们保持联络！

---

关于作者：

姜天旭（Alex Jiang）, Pivotal 技术支持中心售后支持专家。作者曾就职于EMC、埃森哲、爱立信等知名公司。有多年的数据库相关经验，熟悉Greenplum、PostgreSQL。