【调试】Linux查看程序卡死位置|GDB|分析进程调用pstack和starce|分析耗时函数
目录
查找进程卡死原因的工具
starce
1、 strace -p [进程号]
strace -p 1002297
strace: Process 1002297 attached
futex(0x7fcbb95f3f84, FUTEX_WAIT_PRIVATE, 1, NULL
可以看到死在了futex(0x7fcbb95f3f84, FUTEX_WAIT_PRIVATE, 1, NULL
用strace查找进程卡死原因实例
最近遇到进程卡死的情况,但是自己调试的过程中并不一定能复现,都是需要运行一段时间某些条件下才会触发,对于这种运行着不能破坏现场的情况,我们可以使用gdb -p和strace -p来跟踪。
首先我们用ps auxf查看我们的进程执行到了哪一步:
可以看到执行到了docker exec -i 178.20.1.229_0115034556 ls然后就卡死了
然后我们进一步通过strace查看执行这个操作死在哪个系统回调了:
这里可以看到死在了系统回调read这里,描述符19的具体意义我们可以进入/proc/pid/fd再查看一下:
我们可以发现,19代表的是pipe,我们这里是死在了读pipe上面。
/********************************************************************************************************************************/
分割线,后面再次出现这个问题
我们先用ps auxf查看进程号和进程执行到了哪一步,可以看到进程号是27678,卡在docker exec
root 27678 0.3 0.4 512172 16500 Sl python /wns/cloud/app/com_host/main.pyc
root 25011 0.0 0.0 4332 652 S \_ /bin/sh -c docker exec -i mongo_docker_master ls
root 25014 0.0 0.2 136592 10600 Sl \_ docker exec -i mongo_docker_master ls
继续用strace -p 27678跟踪,发现卡在read,文件描述符是14
root@localhost:/# strace -p 27678
Process 27678 attached
read(14,
接着我们cd /proc/27678/,在这里我们可以查看进程状态
root@localhost:/proc/27678# cat status
Name: python
State: S (sleeping)
Tgid: 27678
Ngid: 0
Pid: 27678
PPid: 27677
查看进程的内核堆栈的调试信息,wchan表示导致进程睡眠或者等待的函数
root@localhost:/proc/27678# cat stack
[<ffffffff811a91ab>] pipe_wait+0x6b/0x90
[<ffffffff811a9c04>] pipe_read+0x344/0x4f0
[<ffffffff811a00bf>] do_sync_read+0x7f/0xb0
[<ffffffff811a0681>] vfs_read+0xb1/0x130
[<ffffffff811a1110>] SyS_read+0x80/0xe0
[<ffffffff818d4c49>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff
root@localhost:/proc/27678# cat wchan
pipe_wait
现在我们查看一下进程打开的文件描述符14代表什么,pipe文件
root@localhost:/proc/27678# ls -l ./fd
total 0
lr-x------ 1 root root 64 Mar 26 17:19 0 -> pipe:[30690124]
l-wx------ 1 root root 64 Mar 26 17:19 1 -> pipe:[30690125]
lrwx------ 1 root root 64 Mar 26 17:19 10 -> socket:[30691732]
lr-x------ 1 root root 64 Mar 26 17:19 11 -> /dev/urandom
lrwx------ 1 root root 64 Mar 26 17:19 12 -> socket:[30719611]
lrwx------ 1 root root 64 Mar 26 17:19 13 -> socket:[30719610]
lr-x------ 1 root root 64 Mar 26 17:19 14 -> pipe:[38483750]
我们已经可以确定main创建子进程执行shell命令docker exec -i mongo_docker_master ls,同时通过pipe和子进程通信,结果卡在了read pipe上。
其实在这里我们也可以使用lsof来定位,可以看到进程27678打开的FD 14是pipe,这里u代表可读可写,r代表可读
sangfor ~ # lsof -d 14
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
mongod 1907 root 14u REG 251,0 36864 130683 /wns/data/mongodb/db/collection-7--588642557116981989.wt
syslog-ng 3446 root 14u unix 0xffff88012227d800 0t0 40557736 /dev/log
dockerd 4025 root 14u unix 0xffff8800b8d5d800 0t0 13941 /run/docker/libnetwork/a73bd949b5fbb89c2b8bec3b4ac6af0a948a944958c8b037d9e6c9b324b44331.sock
docker-co 9382 root 14u 0000 0,9 0 9553 anon_inode
docker-co 21204 root 14u 0000 0,9 0 9553 anon_inode
python 27678 root 14r FIFO 0,8 0t0 38483750 pipe
也可以直接查看进程27678打开的,可以看到14是pipe
sangfor ~ # lsof -p 27678
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
python 27678 root 0r FIFO 0,8 0t0 30690124 pipe
python 27678 root 1w FIFO 0,8 0t0 30690125 pipe
python 27678 root 2w FIFO 0,8 0t0 30690126 pipe
python 27678 root 3u 0000 0,9 0 9553 anon_inode
python 27678 root 4u 0000 0,9 0 9553 anon_inode
python 27678 root 5u pack 30691718 0t0 unknown type=SOCK_RAW
python 27678 root 6w REG 251,0 76106652 130565 /wns/data/com_host/etc/config/err.log
python 27678 root 7u IPv4 30691716 0t0 TCP Sangfor:53102->Sangfor:42457 (ESTABLISHED)
python 27678 root 8u IPv4 30691717 0t0 TCP Sangfor:42457->Sangfor:53102 (ESTABLISHED)
python 27678 root 9u IPv4 30691731 0t0 TCP db.sdwan:54072->sdwan.io:27017 (ESTABLISHED)
python 27678 root 10u IPv4 30691732 0t0 TCP db.sdwan:54074->sdwan.io:27017 (ESTABLISHED)
python 27678 root 11r CHR 1,9 0t0 30690329 /dev/urandom
python 27678 root 12u IPv4 30719611 0t0 TCP db.sdwan:51404->db.sdwan:37017 (ESTABLISHED)
python 27678 root 13u IPv4 30719610 0t0 TCP db.sdwan:47124->db.sdwan:27017 (ESTABLISHED)
python 27678 root 14r FIFO 0,8 0t0 38483750 pipe
————————————————
原文链接:https://blog.csdn.net/peng314899581/article/details/79064616
pstack
(更多强大功能:linux命令-- pstack命令(跟踪进程栈) - milkty - 博客园)
pstack用来跟踪进程栈,这个命令在排查进程问题时非常有用,比如我们发现一个服务一直处于work状态(如假死状态,好似死循环),使用这个命令就能轻松定位问题所在;可以在一段时间内,多执行几次pstack,若发现代码栈总是停在同一个位置,那个位置就需要重点关注,很可能就是出问题的地方;
示例:查看bash程序进程栈:
/opt/app/tdev1$ps -fe| grep bash
tdev1 7013 7012 0 19:42 pts/1 00:00:00 -bash
tdev1 11402 11401 0 20:31 pts/2 00:00:00 -bash
tdev1 11474 11402 0 20:32 pts/2 00:00:00 grep bash
/opt/app/tdev1$pstack 7013
#0 0x00000039958c5620 in __read_nocancel () from /lib64/libc.so.6
#1 0x000000000047dafe in rl_getc ()
#2 0x000000000047def6 in rl_read_key ()
#3 0x000000000046d0f5 in readline_internal_char ()
#4 0x000000000046d4e5 in readline ()
#5 0x00000000004213cf in ?? ()
#6 0x000000000041d685 in ?? ()
#7 0x000000000041e89e in ?? ()
#8 0x00000000004218dc in yyparse ()
#9 0x000000000041b507 in parse_command ()
#10 0x000000000041b5c6 in read_command ()
#11 0x000000000041b74e in reader_loop ()
#12 0x000000000041b2aa in main ()
strace
strace常用来跟踪进程执行时的系统调用和所接收的信号。 在Linux世界,进程不能直接访问硬件设备,当进程需要访问硬件设备(比如读取磁盘文件,接收网络数据等等)时,必须由用户态模式切换至内核态模式,通过系统调用访问硬件设备。strace可以跟踪到一个进程产生的系统调用,包括参数,返回值,执行消耗的时间。
示例:
$strace cat /dev/null
execve("/bin/cat", ["cat", "/dev/null"], [/* 22 vars */]) = 0
brk(0) = 0xab1000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f29379a7000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
...
每一行都是一条系统调用,等号左边是系统调用的函数名及其参数,右边是该调用的返回值。 strace 显示这些调用的参数并返回符号形式的值。strace 从内核接收信息,而且不需要以任何特殊的方式来构建内核。
跟踪可执行程序
strace -f -F -o ~/straceout.txt myserver
-f -F选项告诉strace同时跟踪fork和vfork出来的进程,-o选项把所有strace输出写到~/straceout.txt里 面,myserver是要启动和调试的程序。
跟踪服务程序
strace -o output.txt -T -tt -e trace=all -p 28979
跟踪28979进程的所有系统调用(-e trace=all),并统计系统调用的花费时间,以及开始时间(并以可视化的时分秒格式显示),最后将记录结果存在output.txt文件里面。
链接:https://www.jianshu.com/p/d6686cb72f68
利用pstack 和 strace分析程序在哪里耗时?
目前测试了nws服务器代码中的while(!stop){...}死循环,发现while循环一次有的线程需要100ms左右,这个时间就有点长了。于是利用如下linux的ps、pstack和strace对程序进行了分析。
ps 查找进程的pid
pstack 打印进程或者线程的栈信息
strace 统计每一步系统调用花费的时间
实例分析
1. ps -aux | grep nws
可以看出nws的pid为171211
2. pstack 171211
打印出nws进程下所有的线程栈信息。可以看出程序好几个线程都卡在pwrite这一步。
3. strace -o output.txt -T -tt -e trace=all -p 171264
nws进程中的171264线程进行系统调用跟踪, 将输出的信息保存在output.txt中
可以发现pwrite调用一次需要这么长的时间,这里就可以优化一下。我用的是SATA盘,考虑用SSD固态硬盘,这时间就可以缩短为十几微妙。
如果还有什么好的办法,欢迎大家的意见。
本段摘自:https://blog.csdn.net/lotluck/article/details/77943152