900字范文 > Linux 程序异常诊断工具（pstack与strace命令使用详解死锁）

Linux 程序异常诊断工具（pstack与strace命令使用详解死锁）

时间：2019-01-26 05:34:20

strace跟踪程序使用的底层系统调用，可输出系统调用被执行的时间点以及各个调用耗时；pstack工具对指定PID的进程输出函数调用栈。

一、strace

1.1 基本概念

strace是一个可用于诊断、调试和教学的Linux用户空间跟踪器。我们用它来监控用户空间进程和内核的交互，比如系统调用、信号传递、进程状态变更等。

strace常用来跟踪进程执行时的系统调用和所接收的信号。在Linux世界，进程不能直接访问硬件设备，当进程需要访问硬件设备(比如读取磁盘文件，接收网络数据等等)时，必须由用户态模式切换至内核态模式，通过系统调用访问硬件设备。strace可以跟踪到一个进程产生的系统调用,包括参数，返回值，执行消耗的时间。

1.2使用方法

strace -o output.txt -T -tt -e trace=all -p 28979

跟踪28979进程的所有系统调用（-e trace=all），并统计系统调用的花费时间，以及开始时间（并以可视化的时分秒格式显示），最后将记录结果存在output.txt文件里面。

参数：

-c 统计每一系统调用的所执行的时间,次数和出错的次数等.

-d 输出strace关于标准错误的调试信息.

-f 跟踪由fork调用所产生的子进程.

-ff 如果提供-o filename,则所有进程的跟踪结果输出到相应的filename.pid中,pid是各进程的进程号.

-F 尝试跟踪vfork调用.在-f时,vfork不被跟踪.

-h 输出简要的帮助信息.

-i 输出系统调用的入口指针.

-q 禁止输出关于脱离的消息.

-r 打印出相对时间关于,,每一个系统调用.

-t 在输出中的每一行前加上时间信息.

-tt 在输出中的每一行前加上时间信息,微秒级.

-ttt 微秒级输出,以秒了表示时间.

-T 显示每一调用所耗的时间.

-v 输出所有的系统调用.一些调用关于环境变量,状态,输入输出等调用由于使用频繁,默认不输出.

-V 输出strace的版本信息.

-x 以十六进制形式输出非标准字符串

-xx 所有字符串以十六进制形式输出.

-a column

设置返回值的输出位置.默认为40.

-e expr

指定一个表达式,用来控制如何跟踪.格式如下:

[qualifier=][!]value1[,value2]...

qualifier只能是 trace,abbrev,verbose,raw,signal,read,write其中之一.value是用来限定的符号或数字.默认的 qualifier是 trace.感叹号是否定符号.例如:

-eopen等价于 -e trace=open,表示只跟踪open调用.而-etrace!=open表示跟踪除了open以外的其他调用.有两个特殊的符号 all 和 none.

注意有些shell使用!来执行历史记录里的命令,所以要使用\\.

-e trace=set

只跟踪指定的系统调用.例如:-e trace=open,close,rean,write表示只跟踪这四个系统调用.默认的为set=all.

-e trace=file

只跟踪有关文件操作的系统调用.

-e trace=process

只跟踪有关进程控制的系统调用.

-e trace=network

跟踪与网络有关的所有系统调用.

-e strace=signal

跟踪所有与系统信号有关的系统调用

-e trace=ipc

跟踪所有与进程通讯有关的系统调用

-e abbrev=set

设定 strace输出的系统调用的结果集.-v 等与 abbrev=none.默认为abbrev=all.

-e raw=set

将指定的系统调用的参数以十六进制显示.

-e signal=set

指定跟踪的系统信号.默认为all.如 signal=!SIGIO(或者signal=!io),表示不跟踪SIGIO信号.

-e read=set

输出从指定文件中读出的数据.例如:

-e read=3,5

-e write=set

输出写入到指定文件中的数据.

-o filename

将strace的输出写入文件filename

-p pid

跟踪指定的进程pid.

-s strsize

指定输出的字符串的最大长度.默认为32.文件名一直全部输出.

-u username

以username 的UID和GID执行被跟踪的命令

1.3 应用举例

该部分应用参考参考文献【2】。

查看程序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

一段时间后，停止，查看servers.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>

由此知程序耗时在 nanosleep.

二、pstack

2.1 基本概念

pstack就是由gdb执行的shell脚本。用于打印正在运行的进程的栈跟踪信息。它能对潜在的死锁予以提示, 而pstack只提供了线索, 需要gdb进一步的确定。

2.2 使用方法

pstack是gdb的一部分。此命令允许使用的唯一选项是要检查的进程的 PID

ps auxf | grep <process_name>pstack $pid

pstack可以打印出该进程的所有线程的情况，那它自然就可以用来检测死锁。

该部分转载参考文献【1】，写得很详细：

（1）产生死锁的代码

#include <stdio.h>#include <pthread.h>#include <unistd.h>pthread_mutex_t mutex_1 = PTHREAD_MUTEX_INITIALIZER;pthread_mutex_t mutex_2 = PTHREAD_MUTEX_INITIALIZER;void *thread1_proc(void *data){pthread_mutex_lock(&mutex_1);sleep(1);pthread_mutex_lock(&mutex_2);pthread_mutex_unlock(&mutex_2);pthread_mutex_unlock(&mutex_1);return (void *)0;}void *thread2_proc(void *data){pthread_mutex_lock(&mutex_2);sleep(1);pthread_mutex_lock(&mutex_1);pthread_mutex_unlock(&mutex_1);pthread_mutex_unlock(&mutex_2);return (void *)0;}int main(){pthread_t tid1, tid2;pthread_create(&tid1, NULL, thread1_proc, NULL);pthread_create(&tid2, NULL, thread2_proc, NULL);pthread_join(tid1, NULL);pthread_join(tid2, NULL);return 0;}

（2）编译及运行程序：

# gcc -g -Wall -Werror dead_lock.c -pthread -o test

# ./test //则进程死锁一直卡住了

# pstack $pid

Thread 3 (Thread 0x7f0489d8e710 (LWP 3616)):#0 0x0000003c0f60e034 in __lll_lock_wait () from /lib64/libpthread.so.0#1 0x0000003c0f609345 in _L_lock_870 () from /lib64/libpthread.so.0#2 0x0000003c0f609217 in pthread_mutex_lock () from /lib64/libpthread.so.0#3 0x000000000040068e in thread1_proc ()#4 0x0000003c0f6077e1 in start_thread () from /lib64/libpthread.so.0#5 0x0000003c0f2e153d in clone () from /lib64/libc.so.6Thread 2 (Thread 0x7f048938d710 (LWP 3617)):#0 0x0000003c0f60e034 in __lll_lock_wait () from /lib64/libpthread.so.0#1 0x0000003c0f609345 in _L_lock_870 () from /lib64/libpthread.so.0#2 0x0000003c0f609217 in pthread_mutex_lock () from /lib64/libpthread.so.0#3 0x00000000004006d3 in thread2_proc ()#4 0x0000003c0f6077e1 in start_thread () from /lib64/libpthread.so.0#5 0x0000003c0f2e153d in clone () from /lib64/libc.so.6Thread 1 (Thread 0x7f0489d90700 (LWP 3615)):#0 0x0000003c0f60803d in pthread_join () from /lib64/libpthread.so.0#1 0x000000000040073d in main ()

Thread 2和Thread 3都在等待锁，就是等待别人释放自己想要锁的那把锁，但是并不能看出来是否是死锁，继续使用gdb分析。

（3）使用GDB分析

# gdb -p $pid

# info thread//打印所有的线程信息

3 Thread 0x7f645eb23710 (LWP 3687) 0x0000003c0f60e034 in __lll_lock_wait () from /lib64/libpthread.so.02 Thread 0x7f645e122710 (LWP 3688) 0x0000003c0f60e034 in __lll_lock_wait () from /lib64/libpthread.so.0* 1 Thread 0x7f645eb25700 (LWP 3686) 0x0000003c0f60803d in pthread_join () from /lib64/libpthread.so.0

*表示gdb锁定的线程，切换到第二个线程去查看

# thread 2//切换到第2个线程,可以看到线程id为 0x7f645e122710,而LWP指定的值是gdb用来唯一标示该进程中线程的，便于调试的时候追踪

[Switching to thread 2 (Thread 0x7f645e122710 (LWP 3688))]#0 0x0000003c0f60e034 in __lll_lock_wait ()

# bt // bt 可以打印函数堆栈，却无法看到函数参数，#0 0x0000003c0f60e034 in __lll_lock_wait () from /lib64/libpthread.so.0#1 0x0000003c0f609345 in _L_lock_870 () from /lib64/libpthread.so.0#2 0x0000003c0f609217 in pthread_mutex_lock () from /lib64/libpthread.so.0#3 0x00000000004006d3 in thread2_proc (data=0x0) at dead_lock.c:23#4 0x0000003c0f6077e1 in start_thread () from /lib64/libpthread.so.0#5 0x0000003c0f2e153d in clone () from /lib64/libc.so.6

# frame 3//打印第三帧信息(#3).每次函数调用都会有压栈的过程，而frame则记录栈中的帧信息

#3 0x00000000004006d3 in thread2_proc (data=0x0) at dead_lock.c:2323pthread_mutex_lock(&mutex_1);

# p mutext_1//打印mutex_1的值, __owner表示gdb中标示线程的值，即LWP

$1 = {__data = {__lock = 2, __count = 0, __owner = 3687, __nusers = 1, __kind = 0, __spins = 0, __list = {__prev = 0x0,

__next = 0x0}}, __size = "\002\000\000\000\000\000\000\000g\016\000\000\001", '\000' <repeats 26 times>, __align = 2}

分析另一个线程3

#thread 3

# frame 3

# p mutex_2

$2 = {__data = {__lock = 2, __count = 0,__owner = 3688, __nusers = 1, __kind = 0, __spins = 0, __list = {__prev = 0x0,

__next = 0x0}}, __size = "\002\000\000\000\000\000\000\000h\016\000\000\001", '\000' <repeats 26 times>, __align = 2}

LWP(3688)在等待LWP(3687)所拥有的mutex_1,而同时LWP(3687)又在等待LWP(3688)所拥有的mutex_2,死锁。