标签
PostgreSQL , pg_terminate_backend , pg_cancel_backend , hang , pstack , strace
背景
当PostgreSQL进程无法被cancel, terminate时，进程处于什么状态？为什么无法退出？
例子
1、无法被kill的进程
Type "help" for help.
postgres=# select pg_cancel_backend(60827);
pg_cancel_backend
-------------------
t
(1 row)
postgres=# select pg_terminate_backend(60827);
pg_terminate_backend
----------------------
t
(1 row)
postgres=# select pg_terminate_backend(60827);
pg_terminate_backend
----------------------
t
(1 row)
2、查看进程当时的STACK，卡在__epoll_wait_nocancel
$pstack 60827
#0 0x00007f4bced78f13 in __epoll_wait_nocancel () from /lib64/libc.so.6
#1 0x0000000000753c35 in WaitEventSetWait ()
#2 0x000000000076d103 in ConditionVariableSleep ()
#3 0x00000000004cc4e1 in _bt_parallel_seize ()
#4 0x00000000004ce433 in ?? ()
#5 0x00000000004ce72e in ?? ()
#6 0x00000000004cf071 in _bt_first ()
#7 0x00000000004ccc2d in btgettuple ()
#8 0x00000000004c617a in index_getnext_tid ()
#9 0x0000000000650f87 in ?? ()
#10 0x000000000063efa1 in ExecScan ()
#11 0x000000000063d7c7 in ?? ()
#12 0x000000000064719e in ?? ()
#13 0x000000000064903c in ?? ()
#14 0x000000000063d7c7 in ?? ()
#15 0x000000000064c0c1 in ?? ()
#16 0x000000000063d7c7 in ?? ()
#17 0x000000000064719e in ?? ()
#18 0x000000000064903c in ?? ()
#19 0x000000000063d7c7 in ?? ()
#20 0x000000000063c4f0 in standard_ExecutorRun ()
#21 0x00007f4bc4cd7288 in ?? () from pg_stat_statements.so
#22 0x00007f4bc48cf87f in ?? () from auto_explain.so
#23 0x000000000077ed0b in ?? ()
#24 0x00000000007800d0 in PortalRun ()
#25 0x000000000077dc88 in PostgresMain ()
#26 0x000000000070782c in PostmasterMain ()
#27 0x000000000067d060 in main ()
3、查看进程的strace
$strace -e trace=all -T -tt -p 60827
Process 60827 attached - interrupt to quit
19:21:14.881369 epoll_wait(270,
^C <unfinished ...>
Process 60827 detached
4、查看这个系统调用的描述，等待某个FD的IO
$man epoll_wait
EPOLL_WAIT(2) Linux Programmer’s Manual EPOLL_WAIT(2)
NAME
epoll_wait, epoll_pwait - wait for an I/O event on an epoll file descriptor
SYNOPSIS
#include <sys/epoll.h>
int epoll_wait(int epfd, struct epoll_event *events,
int maxevents, int timeout);
int epoll_pwait(int epfd, struct epoll_event *events,
int maxevents, int timeout,
const sigset_t *sigmask);
5、查看epoll_wait(270, 这个270 FD对应的是什么
#cd /proc/60827/fd
#ll 270
lrwx------ 1 xxxxxx xxxxxxxxxxx 64 Jul 19 15:01 270 -> anon_inode:[eventpoll]
6、引起epoch_wait的PG调用WaitEventSetWait
src/backend/storage/ipc/latch.c
/*
* Wait for events added to the set to happen, or until the timeout is
* reached. At most nevents occurred events are returned.
*
* If timeout = -1, block until an event occurs; if 0, check sockets for
* readiness, but don't block; if > 0, block for at most timeout milliseconds.
*
* Returns the number of events occurred, or 0 if the timeout was reached.
*
* Returned events will have the fd, pos, user_data fields set to the
* values associated with the registered event.
*/
int
WaitEventSetWait(WaitEventSet *set, long timeout,
WaitEvent *occurred_events, int nevents,
uint32 wait_event_info)
{
int returned_events = 0;
instr_time start_time;
instr_time cur_time;
long cur_timeout = -1;
Assert(nevents > 0);
/*
* Initialize timeout if requested. We must record the current time so
* that we can determine the remaining timeout if interrupted.
*/
if (timeout >= 0)
{
INSTR_TIME_SET_CURRENT(start_time);
Assert(timeout >= 0 && timeout <= INT_MAX);
cur_timeout = timeout;
}
pgstat_report_wait_start(wait_event_info);
#ifndef WIN32
waiting = true;
#else
/* Ensure that signals are serviced even if latch is already set */
pgwin32_dispatch_queued_signals();
#endif
while (returned_events == 0)
{
int rc;
/*
* Check if the latch is set already. If so, leave the loop
* immediately, avoid blocking again. We don't attempt to report any
* other events that might also be satisfied.
*
* If someone sets the latch between this and the
* WaitEventSetWaitBlock() below, the setter will write a byte to the
* pipe (or signal us and the signal handler will do that), and the
* readiness routine will return immediately.
*
* On unix, If there's a pending byte in the self pipe, we'll notice
* whenever blocking. Only clearing the pipe in that case avoids
* having to drain it every time WaitLatchOrSocket() is used. Should
* the pipe-buffer fill up we're still ok, because the pipe is in
* nonblocking mode. It's unlikely for that to happen, because the
* self pipe isn't filled unless we're blocking (waiting = true), or
* from inside a signal handler in latch_sigusr1_handler().
*
* On windows, we'll also notice if there's a pending event for the
* latch when blocking, but there's no danger of anything filling up,
* as "Setting an event that is already set has no effect.".
*
* Note: we assume that the kernel calls involved in latch management
* will provide adequate synchronization on machines with weak memory
* ordering, so that we cannot miss seeing is_set if a notification
* has already been queued.
*/
if (set->latch && set->latch->is_set)
{
occurred_events->fd = PGINVALID_SOCKET;
occurred_events->pos = set->latch_pos;
occurred_events->user_data =
set->events[set->latch_pos].user_data;
occurred_events->events = WL_LATCH_SET;
occurred_events++;
returned_events++;
break;
}
/*
* Wait for events using the readiness primitive chosen at the top of
* this file. If -1 is returned, a timeout has occurred, if 0 we have
* to retry, everything >= 1 is the number of returned events.
*/
rc = WaitEventSetWaitBlock(set, cur_timeout,
occurred_events, nevents);
if (rc == -1)
break; /* timeout occurred */
else
returned_events = rc;
/* If we're not done, update cur_timeout for next iteration */
if (returned_events == 0 && timeout >= 0)
{
INSTR_TIME_SET_CURRENT(cur_time);
INSTR_TIME_SUBTRACT(cur_time, start_time);
cur_timeout = timeout - (long) INSTR_TIME_GET_MILLISEC(cur_time);
if (cur_timeout <= 0)
break;
}
}
#ifndef WIN32
waiting = false;
#endif
pgstat_report_wait_end();
return returned_events;
}
strace, pstack的使用教程（转载）
如何使用strace+pstack利器分析程序性能
http://www.cnblogs.com/bangerlee/archive/2012/04/30/2476190.html
http://www.cnblogs.com/bangerlee/archive/2012/02/20/2356818.html
引言
有时我们需要对程序进行优化、减少程序响应时间。除了一段段地对代码进行时间复杂度分析，我们还有更便捷的方法吗？
若能直接找到影响程序运行时间的函数调用，再有针对地对相关函数进行代码分析和优化，那相比漫无目的地看代码，效率就高多了。
将strace和pstack工具结合起来使用，就可以达到以上目的。strace跟踪程序使用的底层系统调用，可输出系统调用被执行的时间点以及各个调用耗时；pstack工具对指定PID的进程输出函数调用栈。
下面我们通过一个简单的消息收发程序，说明使用strace、pstack进行程序分析的具体方法。
程序说明
该程序是一个简单的socket程序，由server/client组成。server端监听某端口，等待client的连接，client连接server后定时向server发送消息，server每接收一条消息后向client发送响应消息。程序server与client交互如下图示：
在程序运行起来之后，发现server接收到client的submit消息之后，需要较长时间才发出resp响应。通过tcpdump抓包发现，time2与time1的时间间隔在1s左右：
由上初步分析可知，消息响应慢是server端程序问题。下面我们来看如何使用strace和pstack分析server端程序响应慢的原因。
strace查看系统调用
首先我们拉起server/client程序，并使用strace对server进程进行跟踪：
# ps -elf | grep server | grep -v grep
0 S root 16739 22642 0 76 0 - 634 1024 14:26 pts/2 00:00:00 ./server
# strace -o server.strace -Ttt -p 16739
Process 16739 attached - interrupt to quit
稍等一段时间之后，我们将strace停掉， server.strace文件中有以下输出：
14:46:39.741366 select(8, [3 4], NULL, NULL, {1, 0}) = 1 (in [4], left {0, 1648}) <0.998415>
14:46:40.739965 recvfrom(4, "hello", 6, 0, NULL, NULL) = 5 <0.000068>
14:46:40.740241 write(1, "hello\n", 6) = 6 <0.000066>
14:46:40.740414 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0 <0.000046>
14:46:40.740565 rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0 <0.000048>
14:46:40.740715 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 <0.000046>
14:46:40.740853 nanosleep({1, 0}, {1, 0}) = 0 <1.000276>
14:46:41.741284 sendto(4, "hello\0", 6, 0, NULL, 0) = 6 <0.000111>
可以看到server接收数据之后(对应recvfrom调用)，经过1s左右时间将消息发出(对应sendto调用)，从响应时间看，与抓包的结果吻合。又可以看出nanosleep系统调用耗费了1s时间。
因而可以断定响应延时由nanosleep对应的函数调用造成。
那具体是哪一个函数调用呢？在strace输出结果中并不能找到答案，因其输出显示都是系统调用，要显示程序中函数调用栈信息，就轮到pstack上场了。
pstack查看函数堆栈
pstack是一个脚本工具，其核心实现就是使用了gdb以及thread apply all bt命令，下面我们使用pstack查看server进程函数堆栈：
# sh pstack.sh 16739
#0 0x00002ba1f8152650 in __nanosleep_nocancel () from /lib64/libc.so.6
#1 0x00002ba1f8152489 in sleep () from /lib64/libc.so.6
#2 0x00000000004007bb in ha_ha ()
#3 0x0000000000400a53 in main ()
从以上信息可以看出，函数调用关系为：main->ha_ha->sleep，因而我们可以找到ha_ha函数进行分析和优化修改。
小结
本文通过一个server/client程序事例，说明了使用strace和pstack分析响应延时的方法。
由最初server端响应慢现象，到使用strace跟踪出具体耗时的系统调用，再到使用pstack查到程序中具体的耗时函数，一步步找到了影响程序运行时间的程序代码。
更多地了解底层，从操作系统层面着手，更有助于程序性能分析与优化。
本文中使用的server/client程序和pstack脚本可从这里下载。
strace 通用的完整用法 ：
strace -o output.txt -T -tt -e trace=all -p 10423
上面的含义是 跟踪28979进程的所有系统调用（-e trace=all），并统计系统调用的花费时间，以及开始时间（并以可视化的时分秒格式显示），最后将记录结果存在
output.txt文件里面。
限制strace只跟踪特定的系统调用 :
如果你已经知道你要找什么，你可以让strace只跟踪一些类型的系统调用。例如，在nginx执行程序时，你需要监视的系统调用epoll_wait。
让strace只记录epoll_wait的调用用这个命令：
strace -f -o epoll-strace.txt -e epoll_wait -p 10423
命令strace跟踪的是系统调用，对于nginx本身的函数调用关系无法给出更为明朗的信息，如果我们发现nginx当前运行不正常，想知道nginx当前内部到底在执行什么函数，
那么命令pstack就是一个非常方便实用的工具。pstack的使用也非常简单，后面跟进程id即可，比如在无客户端请求的情况下，nginx阻塞在epoll_wait系统调用处，此时
利用pstack查看到的nginx函数调用堆栈关系如下：
从main()函数到epoll_wait()函数的调用关系一目了然，和在gdb内看到的堆栈信息一样。我们可以利用此进行分析优化等。