第2章 跟踪与调试
跟踪与调试,不仅是我们解决程序Bug的有力途径,也是帮助我们理解现有代码的有效方法。通过跟踪程序执行的过程,我们可以清楚地了解程序的内部逻辑,对于不明就里的实现细节,调试查看程序内部变量也能更好地帮助我们做出正确的理解。本章将介绍一些跟踪与调试程序的方法,除了最基本的gdb调试,我还将结合个人经验,介绍一些相对高级的应用技巧。
2.1 利用gdb调试
gdb是Linux下调试程序的常用工具,任何Linux开发工程师初学程序调试时第一个接触到的工具应该就是gdb。关于gdb本身的详细用法,我们不多详述,读者可以参考gdb官网手册,而在这里,我们将重点介绍一些与Nginx相关的注意点与调试技巧。
2.1.1 绑定Nginx到gdb
利用gdb调式Nginx,首先得在生成Nginx程序时把-g编译选项打开。当然,这并不是说不打开-g选项就无法用gdb调试它,只是会因为缺少相应的符号信息导致调试不便,而此时可能也将获得“No symbol table is loaded. Use the "file" command.”的提示。上一章已经介绍了如何编译Nginx,在执行./configure命令生成对应的objs/Makefile文件后,检查该文件里的CFLAGS变量是否已带上了-g选项,没有则加上即可。另一个值得关注的编译选项是-O0,如果在gdb内打印变量时提示“<value optimized out>”或gdb显示的当前正执行的代码行与源码匹配不上而让人感觉莫名其妙,那么,这多半是因为gcc的优化导致,我们可以加上-O0选项来强制禁用gcc的编译优化。除了可以通过编辑objs/Makefile文件,把这两个选项直接加在CFLAGS变量里以外,还有另外几种方法也可以达到同样的效果。
1. 在进行configure配置时,按如下方式执行。
[root@localhost nginx-1.2.0]# ./configure--with-cc-opt='-g -00'
上面是利用configure所提出的选项来做的,属于比较推荐的方法,但也可使用如下方法。
[root@localhost nginx-1.2.0]# CFLAGS="-g -O0" ./configure
2. 在执行make时,按如下方式执行。
[root@localhost nginx-1.2.0]# make CFLAGS="-g -O0"
直接修改objs/Makefile文件和上面提到的第2种方法是在我们已经执行configure之后进行的,如果之前已经执行过make,那么在进行第二次make时,需带上强制重新编译 2 选项-B或--aluays-make。也可以通过刷新所有源文件的时间戳,间接达到重新编译出一个新Nginx可执行程序的目的。
[root@localhost nginx-1.2.0]# find . -name "*.c" | xargs touch
不直接使用make clean是因为执行它会把objs整个目录都删除,当然这也包括我们修改过的objs/Makefile文件。获得正常编译后的Nginx二进制可执行程序后,我们可以利用gdb调试它,不过这首先需要把Nginx运行起来。在默认情况下,Nginx会有多个进程,所以需通过如下类似命令正确找到我们要调试的进程。
[root@localhost ~]# ps -efH | grep nginx root 397124701 0 12:20 pts/4 00:00:00 grep nginx[root@localhost nginx-1.2.0]#make-B root 3905 1 0 12:16 ? 00:00:00 nginx: master process ./nginx nobody 3906 3905 0 12:16 ? 00:00:00 nginx: worker process nobody 3907 3905 0 12:16 ? 00:00:00 nginx: worker process
源码实现已经给Nginx进程加上了title,所以根据标题很容易区分出哪个是监控进程,哪些个是工作进程。如要对如上所示的工作进程3906进行gdb调试,那么可以利用gdb的-p命令行参数。
[root@localhost ~]# gdb -p 3906
或者执行gdb命令进入gdb后执行。
(gdb) attach 3906
这两种方法都可以。
如果是要调试Nginx对客户端发过来请求的处理过程,那么要注意请求是否被交付给另外一个工作进程处理而导致绑定到gdb的这个工作进程实际没有动作。此时可以考虑开两个终端,运行两个gdb分别attach到两个工作进程上或干脆修改配置项worker_processes的值为1,从而使得Nginx只运行一个工作进程。
worker_processes 1;
通过上面这种方法只能调试Nginx运行起来之后的流程,对于启动过程中的逻辑,比如进程创建、配置解析等,因为已经执行完毕而无法调试,要调试这部分逻辑必须在Nginx启动的开始就把gdb绑定上,也就是在gdb里启动Nginx。这有几点需要注意,首先是Nginx默认以daemon形式运行,即它会调用fork()创建子进程并且把父进程直接exit(0)丢弃,因此在启动Nginx前,我们需设定
set follow-fork-mode child
也就是让gdb跟踪fork()之后的子进程,而gdb默认将跟踪fork()之后的父进程,不做此设定则将导致跟踪丢失。即便做了这样的设置,仍然比较麻烦,因为Nginx创建工作进程也用的是fork()函数,所以如果要调试监控进程则还需要做另外的灵活处理。我们可以修改Nginx配置文件。
daemon off;
这样Nginx就不再以daemon形象执行,利用gdb可以从Nginx的main()函数开始调试,默认情况下调试的当然就是监控进程的流程,如果要调试工作进程的流程需要在进入gdb后执行set follow-fork-mode child,在刚才已经提到了该条gdb命令的作用。另外更简单的方法就是直接设置:
master_process off;
将监控进程逻辑和工作进程逻辑全部合在一个进程里。不管怎样做,我们都必须让gdb attach到想要调试的对应进程上,比如如果必须要经过多次fork()后才能达到的代码位置(像函数ngx_cache_manager_process_cycle()),那么就要在多处恰当位置下断点,然后在执行到该断点时根据需要切换follow-fork-mode标记。这些变通设置对于调试像配置信息解析流程、文件缓存等这一类初始相关逻辑是非常重要的,因为Nginx的这些逻辑是在Nginx启动时进行的。如果你发现gdb跟丢了进程或当前调试的代码不是你预想的流程,那么请仔细做这些确认与检查工作。
最后,因为执行Nginx需指定配置文件路径,如何在gdb里带参数运行Nginx是必须知道的。这有很多种方法,比如在Shell里执行:
gdb --args ./objs/nginx -c /usr/local/nginx/conf/nginx.conf
进入到gdb后在执行r命令即可;或者在Shell里执行:
gdb ./objs/nginx
进入到gdb后执行r -c /usr/local/nginx/conf/nginx.conf或在gdb内先执行命令
set args -c /usr/local/nginx/conf/nginx.conf
再执行r命令。
2.1.2 gdb的watch指令
将Nginx特定进程绑定到gdb后,剩余的跟踪与调试操作无非就是gdb的使用,这可以参考官方手册。手册内容很多,因为gdb提供的功能非常丰富,但平常我们使用的功能却很少。其实gdb的某些功能是相当有利用价值的,像Break conditions、Watchpoints等。这里仅以Watchpoints(监视点)为例看看它的实际使用效果。Watchpoints可以帮助我们监视某个变量在什么时候被修改,这对于我们了解Nginx程序的执行逻辑非常有帮助。比如在理解Nginx的共享内存逻辑时,看到ngx_shared_memory_add()函数内初始化的shm_zone->init回调为空。
1256:代码片段2.1.2-1,文件名: ngx_cycle.c 1257:ngx_shm_zone_t * 1258:ngx_shared_memory_add(ngx_conf_t *cf, ngx_str_t *name, size_t size, void *tag) 1259: { 1260: … 1318: shm_zone->init = NULL;
而在ngx_init_cycle()函数里对该回调函数却是直接执行而并没有做前置判空处理。
41: 代码片段2.1.2-2,文件名: ngx_cycle.c 42: ngx_cycle_t * 43: ngx_init_cycle(ngx_cycle_t *old_cycle) 44: { 45: … 475: if (shm_zone[i].init(&shm_zone[i], NULL) != NGX_OK) { 476: goto failed; 477: }
这说明这个函数指针一定是在其他某处被再次赋值,但具体是在哪里呢?搜索Nginx全部源代码可能一下子没找到对应的代码行,那么,此时就可利用gdb的Watchpoints功能进行快速定位。
(gdb) b ngx_cycle.c:1318 Breakpoint 1 at 0x805d7ce: file src/core/ngx_cycle.c, line 1318. (gdb) r Starting program:/home/gqk/nginx-1.2.0/objs/nginx-c/usr/local/nginx/conf/nginx.conf. upstream.sharedmem [Thread debugging using libthread_db enabled] Breakpoint 1,ngx_shared_memory_add(cf=0xbffff39c,name=0xbfffeed8,size=134217728,tag=0x80dbd80) at src/core/ngx_cycle.c:1318 1318 shm_zone->init = NULL; Missing separate debuginfos,use:debuginfo-install glibc-2.12-1.47.el6.i686 nss-softokn-freebl-3.12.9-11.el6.i686 openssl-1.0.0-20.el6.i686 pcre-7.8-3.1.el6.i686 zlib-1.2.3-27.el6.i686 (gdb) p &shm_zone->init $1 = (ngx_shm_zone_init_pt *) 0x80eba68 (gdb) watch *(ngx_shm_zone_init_pt *) 0x80eba68 Hardware watchpoint 2: *(ngx_shm_zone_init_pt *) 0x80eba68 (gdb) c Continuing. Hardware watchpoint 2: *(ngx_shm_zone_init_pt *) 0x80eba68 Old value = (ngx_shm_zone_init_pt) 0 New value = (ngx_shm_zone_init_pt) 0x809d9c7 <ngx_http_file_cache_init> ngx_http_file_cache_set_slot(cf=0xbffff39c,cmd=0x80dc0d8,conf=0x0)at src/http/ngx_http_file_cache.c:1807 1807 cache->shm_zone->data = cache;
先在shm_zone->init = NULL;代码所对应的第1318行先下一个Breakpoint,执行Nginx后将在此处暂停程序,通过p指令打印获取shm_zone->init的地址值,然后直接给shm_zone->init对应的地址下个Watchpoint进行监视。这样即便是跑出shm_zone->init变量所在的作用域也没有关系,执行c命令继续执行Nginx,一旦shm_zone->init被修改,那么就停止在进行修改的代码的下一行,修改之前的值Old value和修改之后的值New value也将都被gdb抓取出来。如上示例中,可以看到修改逻辑在第1806行(我这里是以proxy_cache所用的共享内存作为实例,而在其他实例情况下,可能将与此不同)。
1084:代码片段2.1.3-1,文件名: ngx_http_file_cache.c 1085: … 1086: cache->shm_zone->init = ngx_http_file_cache_init; 1087: cache->shm_zone->data = cache;
从上面的简单示例里可以看到gdb watch命令的强大作用,除了利用该命令监控指定变量的写操作以外,还可以利用另外两个同类命令rwatch和awatch分别监控指定变量的读操作和读/写操作。当然,关于这方面的更多内容,在gdb手册上有详细介绍。
2.1.3 Nginx对gdb的支持
Nginx本身对于gdb也有相关辅助支持,这表现在配置指令debug_points上,对于该配置项的配置值可以是stop或abort。当Nginx遇到严重错误时,比如内存超限或其他不可预料的逻辑错误,就会调用ngx_debug_point()函数(这类似于assert()一样的断言函数,只是函数ngx_debug_point()本身不带判断),该函数根据debug_points配置指令的设置做出相应的处理。如果将debug_points设置为stop,那么ngx_debug_point()函数的调用将使得Nginx进程进入到暂停状态,以便我们可通过gdb接入到该进程查看相关上下文信息。
[root@localhost ~]# ps aux | grep nginx root 4614 0.0 0.0 24044 592 ? Ts 12:48 0:00 ./nginx root 4780 0.0 0.1103152 800 pts/4 S+ 13:00 0:00 grep nginx
注意上面的./nginx状态为Ts(s代表Nginx进程为一个会话首进程session leader),其中T就代表Nginx进程处在TASK_STOPPED状态,此时我们用gdb连上去即可查看问题所在(我这里只是一个测试,在main函数里主动调用ngx_debug_point()而已,所以下面看到的bt堆栈很简单,实际使用时,我们当然要把该函数放在需要观察的代码点,比如非正常逻辑点)。
[root@localhost ~]# gdb -q -p 4614 Attaching to process 4614 Reading symbols from /usr/local/nginx/sbin/nginx...done. ... openssl-1.0.0-4.el6.x86_64 pcre-7.8-3.1.el6.x86_64 zlib-1.2.3-25.el6.x86_64 (gdb) bt #0 0x0000003a9ea0f38b in raise () from /lib64/libpthread.so.0 #1 0x0000000000431a8a in ngx_debug_point () at src/os/unix/ngx_process.c:603 #2 0x00000000004035d9 in main (argc=1, argv=0x7fffbd0a0c08) at src/core/ nginx.c:406 (gdb) c Continuing. Program received signal SIGTERM, Terminated.
执行c命令,Nginx即自动退出。
如果将debug_points设置为abort,那么Nginx调用ngx_debug_point()函数时直接将程序abort崩溃掉,如果对操作系统做了恰当的设置,则将获得对应的core文件,这就大大方便我们进行事后的慢慢调试,延用上面的直接在main函数里主动调用ngx_debug_point()的例子。
[root@localhost nginx]# ulimit -c 0 [root@localhost nginx]# ulimit -c unlimited [root@localhost nginx]# ulimit -c unlimited [root@localhost nginx]# ./sbin/nginx [root@localhost nginx]# ls client_body_temp core.5242 html proxy_temp scgi_temp conf fastcgi_temp logs sbin uwsgi_temp
生成了名为core.5242的core文件,利用gdb调试该core文件。
[root@localhost nginx]# gdb sbin/nginx core.5242-q Reading symbols from /usr/local/nginx/sbin/nginx...done. [New Thread 5242] ... (gdb) bt #0 0x0000003a9de329a5 in raise () from /lib64/libc.so.6 #1 0x0000003a9de34185 in abort () from /lib64/libc.so.6 #2 0x0000000000431a92 in ngx_debug_point () at src/os/unix/ngx_process.c:607 #3 0x00000000004035d9 in main (argc=1, argv=0x7fffd5625f18) at src/core/ nginx.c:406 (gdb) up 3 #3 0x00000000004035d9 in main (argc=1, argv=0x7fffd5625f18) at src/core/nginx.c:406 406 ngx_debug_point(); (gdb) list 401 } 402 } 403 404 ngx_use_stderr = 0; 405 406 ngx_debug_point(); 407 408 if (ngx_process == NGX_PROCESS_SINGLE) { 409 ngx_single_process_cycle(cycle); 410
2.1.4 宏
Nginx里有大量的宏。如果不事先做一下处理,在gdb里将无法查看这些宏的定义以及展开形式,也就会获得如下提示信息。
(gdb) info macro NGX_OK The symbol 'NGX_OK' has no definition as a C/C++ preprocessor macro at <user-defined>:-1 (gdb) p NGX_OK No symbol "NGX_OK" in current context.
如果我们将编译选项-g改为-ggdb3,虽然这样编译得到的二进制文件会比较大,但是因为它包含了所有与宏相关的信息(当然也包含了很多其他信息),所以我们就可以在gdb里使用类似命令。
(gdb) info macro NGX_OK Defined at src/core/ngx_core.h:30 included at src/core/nginx.c:9 #define NGX_OK 0 (gdb) macro expand NGX_OK expands to: 0
来查看指定宏的定义与展开形式,而gdb命令里也可以直接使用这些宏,比如执行打印指令p。
(gdb) p NGX_OK $1 = 0
当然,这些操作需要在当前上下文里有对应的NGX_OK宏定义,否则同样无法查看。这很容易理解,毕竟宏也有对应的“作用域”,也就是说同一个宏名在不同的代码处可能有不同的展开,所以gdb是利用当前代码列表作为选择“作用域”的参考点。
如果当前应用程序在执行当中,比如在main()函数处下断点,然后执行r命令后被断了下来,那么当前代码列表就是以main函数里的第一行作为参考点,宏展开也就以当前执行行作为参考点。如果应用程序当前未处于执行状态,并且也没有使用list命令指定当前代码行,那么宏可能无法显示或显示不正确。比如我在Nginx的main()函数处查看EPOLLIN宏,结果如下。
(gdb) info macro EPOLLIN The symbol `EPOLLIN' has no definition as a C/C++ preprocessor macro at <user-defined>:-1
结果表明没有找到EPOLLIN宏,但如果我使用list命令列表,会使用到EPOLLIN宏的源文件,那么对应的情况如下。
(gdb) list ngx_epoll_module.c:0 1 2 /* 3 * Copyright (C) Igor Sysoev 4 * Copyright (C) Nginx, Inc. 5 */ 6 7 8 #include <ngx_config.h> 9 #include <ngx_core.h> 10 #include <ngx_event.h> (gdb) info macro EPOLLIN Defined at /usr/include/sys/epoll.h:47 included at src/os/unix/ngx_linux_config.h:86 included at src/core/ngx_config.h:26 included at src/event/modules/ngx_epoll_module.c:8 #define EPOLLIN EPOLLIN
可以看到第二次info macro就能正确找到并显示EPOLLIN宏了。关于这方面的更多实例,请参考这里。
2.1.5 cgdb
cgdb 是我想推荐给大家使用的一个封装gdb的开源调试工具。相比Windows下的Visual Studio等图形调试工具而言,它的可视化功能显得十分轻量级,但它的最大好处在于能在终端里运行并且原生具备gdb的强大调试功能。关于cgdb的详细使用可以参考官方手册或这里。
cgdb在远程ssh里执行的界面如图2-1所示,如果上面类vi窗口没有显示对应的源代码或下面gdb窗口提示No such file or directory.,那么需要利用directory命令把Nginx源代码增加到搜索路径。
图2-1 cgdb运行时界面
2.2 利用日志信息跟踪Nginx
优秀的程序都会带有自己的日志输出接口,并且一般还会给出不同等级的输出级别,以便于重次信息的过滤,比如Linux内核的日志输出标准接口为printk,并且给出了KERN_EMERG、KERN_ALERT、KERN_DEBUG等这样的输出等级。Nginx与此类似,下面具体来看。
为了获取最丰富的日志信息,我们在进行configure配置时,需要把--with-debug选项加上,这样能生成一个名为NGX_DEBUG的宏,而在Nginx源码内,该宏被用作控制开关,如果没有它,那么很多日志逻辑代码将在make编译时直接跳过。比如对单连接的debug_connection调试指令、分模块日志调试debug_http功能等。
00: 代码片段2.2-1,文件名: ngx_auto_config.h 01: #define NGX_CONFIGURE " --with-debug" 02: 03: #ifndef NGX_DEBUG 04: #define NGX_DEBUG 1 05: #endif 620: 代码片段2.2-2,文件名: nginx.c 621: #if (NGX_DEBUG) 622: { 623: char **e; 624: for (e = env; *e; e++) { 625: ngx_log_debug1(NGX_LOG_DEBUG_CORE, cycle->log, 0, "env: %s", *e); 626: } 627: } 628: #endif
有了上面这个编译前提条件之后,我们还需在配置文件里做恰当的设置。关于这点,Nginx提供的主要配置指令为error_log。该配置项的默认情况(默认值定义在objs/ngx_auto_config.h文件内)为
error_log logs/error.log error;
表示日志信息记录在logs/error.log(如果没改变Nginx的默认工作路径的话,那么其父目录为/usr/local/nginx/)文件内,而日志记录级别为error。
在实际进行配置时,可以修改日志信息记录文件路径(比如修改为/dev/null,此时所有日志信息将被输出到所谓的Linux黑洞设备,导致日志信息全部丢弃)或直接输出到标准终端(此时指定为stderr)。Nginx提供的日志记录级别一共有八级,等级从低到高分别为debug、info、notice、warn、error、crit、alert、emerg。如果设置为error,则表示Nginx内等级为error、crit、alert和emerg的四种级别的日志将被输出到日志文件或标准终端。另外的debug、info、notice和warn这四种日志将被直接过滤掉而不会输出。因此如果我们只关注特别严重的信息,只需将日志等级设置为error即可大大减少Nginx的日志输出量,这样就避免了在大量的日志信息里寻找重要信息的麻烦。
当我们利用日志跟踪Nginx时,需要获取最大量的日志信息,所以此时可以把日志等级设置为最低的debug级。在这种情况下,如果觉得调试日志太多,Nginx提供按模块控制的更细粒等级:debug_core、debug_alloc、debug_mutex、debug_event、debug_http、debug_imap。比如如果只想看http的调试日志,则需做如下设置。
error_log logs/error.log debug_http;
此时Nginx将输出从info到emerg所有等级的日志信息,而debug日志则将只输出与http模块相关的内容。
error_log配置指令可以放在配置文件的多个上下文内,比如main、http、server、location,但同一个上下文中只能设置一个error_log,否则Nginx将提示类似如下这样的错误。
nginx: [emerg] "error_log" directive is duplicate in /usr/local/nginx/conf/ nginx.conf:9
但在不同的配置文件上下文里可以设置各自的error_log配置指令,通过设置不同的日志文件,这是Nginx提供的又一种信息切割过滤手段。
00: 代码片段2.2-3,文件名: example.conf 01: ... 02: error_log logs/error.log error; 03: ... 04: http { 05: error_log logs/http.log debug; 06: ... 07: server { 08: ... 09: error_log logs/server.log debug; 10: ...
Nginx提供的另一种更有针对性的日志调试信息记录是针对特定连接的,这通过debug_connection配置指令来设置,比如如下设置调试日志仅针对IP地址192.168.1.1和IP段192.168.10.0/24:
11: 代码片段2.2-4,文件名: example.conf 12: events { 13: debug_connection 192.168.1.1; 14: debug_connection 192.168.10.0/24; 15: }
Nginx的日志功能仍在不断改进中,如能利用得好,对于我们跟踪Nginx还是非常有帮助的,至少我知道有不少朋友十分习惯于使用C库的printf()函数打印调试,相比之下,Nginx提供的ngx_log_xxx()系列函数要强大得多。
2.3 利用strace/pstack调试Nginx
Linux下有两个命令strace和ltrace可以分别用来查看一个应用程序在运行过程中所发起的系统函数调用和动态库函数调用,这对作为标准应用程序的Nginx自然同样可用。由于这两个命令大同小异,下面就仅以strace为例做简单介绍,大致了解一些它能帮助我们获取哪些有用的调试信息。关于strace/ltrace以及后面介绍的pstack更多的用法请参考对应的Man手册。
从strace的Man手册可以看到几个有用的选项。
● -p pid:通过进程号来指定被跟踪的进程。
● -o filename:将跟踪信息输出到指定文件。
● -f:跟踪其通过frok调用产生的子进程。
● -t:输出每一个系统调用的发起时间。
● -T:输出每一个系统调用消耗的时间。
首先利用ps命令查看到系统当前存在的Nginx进程,然后用strace命令的-p选项跟踪Nginx工作进程,如图2-2所示。
图2-2 查看Nginx进程
为了简化操作,我这里只设定了一个工作进程,该工作进程会停顿在epoll_wait系统调用上,这是合理的,因为在没有客户端请求时,Nginx就阻塞于此(除非是在争用accept_mutex锁),在另一终端执行wget命令向Nginx发出http请求后,再来看strace的输出,如图2-3所示。
图2-3 strace的输出
[root@localhost ~]# wget 127.0.0.1
通过strace的输出可以看到Nginx工作进程在处理一次客户端请求过程中发起的所有系统调用。我这里测试请求的HTML非常简单,没有附带css、js、jpg等文件,所以看到的输出也比较简单。strace输出的每一行记录一次系统调用,等号左边是系统调用名以及调用参数,等号右边是该系统调用的返回值。逐一说明如下所述。
1. epoll_wait返回值为1,表示有1个描述符存在可读/写事件,这里当然是可读事件。
2. accept4接受该请求,返回的数字3表示socket的文件描述符。
3. epoll_ctl把accept4建立的socket套接字(注意参数3)加入到事件监听机制里。
4. recv从发生可读事件的socket文件描述符内读取数据,读取的数据存在第二个参数内,读取了107个字节。
5. stat64判断客户端请求的html文件是否存在,返回值为0表示存在。
6. open/fstat64打开并获取文件状态信息。open文件返回的文件描述符为9,后面几个系统调用都用到这个值。
7. writev把响应头通过文件描述符3代表的socket套接字发给客户端。
8. sendfile64把文件描述符9代表的响应体通过文件描述符3代表的socket套接字发给客户端。
9. 再往文件描述符4代表的日志文件内write一条日志信息。
10. recv看客户端是否还发了其他待处理的请求/信息。
11. 最后关闭文件描述符3代表的socket套接字。
由于strace能够提供Nginx执行过程中的这些内部信息,所以在出现一些奇怪现象时,比如Nginx启动失败、响应的文件数据和预期不一致、莫名其妙的Segment ation Fault段错误、存在性能瓶颈(利用-T选项跟踪各个函数的消耗时间),利用strace也许能提供一些相关帮助。最后,要退出strace跟踪,按Ctrl+C即可。
命令strace跟踪的是系统调用,对于Nginx本身的函数调用关系无法给出更为明朗的信息,如果我们发现Nginx当前运行不正常,想知道Nginx当前内部到底在执行什么函数,那么命令pstack就是一个非常方便实用的工具。
pstack的使用也非常简单,后面跟进程ID即可。比如在无客户端请求的情况下,Nginx阻塞在epoll_wait系统调用处,此时利用pstack查看到的Nginx函数调用堆栈关系,如图2-4所示。
图2-4 Nginx函数调用堆栈关系
从main()函数到epoll_wait()函数的调用关系一目了然,和在gdb内看到的堆栈信息一模一样,其实命令pstack本身也就是一个利用gdb实现的Shell脚本,关于这点,感兴趣的读者可以自己看下pstack对应的脚本程序。
2.4 获得Nginx程序完整执行流程
利用strace命令能帮助我们获取到Nginx在运行过程中所发起的所有系统调用,但是不能看到Nginx内部各个函数的调用情况。利用gdb调试Nginx能让我们很清晰地获得Nginx每一步的执行流程,但是单步调试毕竟是非常麻烦的,有没有更为方便的方法一次性获得Nginx程序执行的整个流程呢?答案是肯定的,而且方法还非常多。虽然相比直接使用某些强大工具(如System Tap)而言,下面要介绍的方法比较笨,但它的确可行,而且从这个过程中也许能学到一些额外的知识。我们只需利用gcc的一个名为-finstrument- functions的编译选项,再加上一些我们自己的处理,就可以达到既定目的。关于gcc提供的这个-finstrument-functions选项,这里不做过多介绍,我们只需明白它提供的是一种函数调用记录追踪功能。关于这些,感兴趣的读者请直接参考gcc官网手册,下面来看获得Nginx程序完整执行流程的具体操作。
首先,我们准备两个文件,文件名和文件内容分别如下。
00: 代码片段2.4-1,文件名: my_debug.h 01: #ifndef MY_DEBUG_LENKY_H 02: #define MY_DEBUG_LENKY_H 03: #include <stdio.h> 04: 05: void enable_my_debug( void ) __attribute__((no_instrument_function)); 06: void disable_my_debug( void ) __attribute__((no_instrument_function)); 07: int get_my_debug_flag( void ) __attribute__((no_instrument_function)); 08: void set_my_debug_flag( int ) __attribute__((no_instrument_function)); 09: void main_constructor( void ) __attribute__((no_instrument_function, constructor)); 10: void main_destructor(void)__attribute__((no_instrument_function,destructor)); 11: void__cyg_profile_func_enter(void*,void*)__attribute__((no_instrument_function)); 12: void__cyg_profile_func_exit(void*,void*)__attribute__((no_instrument_function)); 13: 14: #ifndef MY_DEBUG_MAIN 15: extern FILE *my_debug_fd; 16: #else 17: FILE *my_debug_fd; 18: #endif 19: #endif 00: 代码片段2.4-2,文件名: my_debug.c 01: #include "my_debug.h" 02: #define MY_DEBUG_FILE_PATH "/usr/local/nginx/sbin/mydebug.log" 03: int _flag = 0; 04: 05: #define open_my_debug_file() \ 06: (my_debug_fd = fopen(MY_DEBUG_FILE_PATH, "a")) 07: 08: #define close_my_debug_file() \ 09: do { \ 10: if (NULL != my_debug_fd) { \ 11: fclose(my_debug_fd); \ 12: } \ 13: }while(0) 14: 15: #define my_debug_print(args, fmt...) \ 16: do{ \ 17: if (0 == _flag) { \ 18: break; \ 19: } \ 20: if (NULL == my_debug_fd && NULL == open_my_debug_file()) { \ 21: printf("Err: Can not open output file.\n"); \ 22: break; \ 23: } \ 24: fprintf(my_debug_fd, args, ##fmt); \ 25: fflush(my_debug_fd); \ 26: }while(0) 27: 28: void enable_my_debug( void ) 29: { 30: _flag = 1; 31: } 32: void disable_my_debug( void ) 33: { 34: _flag = 0; 35: } 36: int get_my_debug_flag( void ) 37: { 38: return _flag; 39: } 40: void set_my_debug_flag( int flag ) 41: { 42: _flag = flag; 43: } 44: void main_constructor( void ) 45: { 46: //Do Nothing 47: } 48: void main_destructor( void ) 49: { 50: close_my_debug_file(); 51: } 52: void __cyg_profile_func_enter( void *this, void *call ) 53: { 54: my_debug_print("Enter\n%p\n%p\n", call, this); 55: } 56: void __cyg_profile_func_exit( void *this, void *call ) 57: { 58: my_debug_print("Exit\n%p\n%p\n", call, this); 59: }
这两个文件是我2009年写的,比较乱,不过够用且测试无误,所以我这里也就直接先用它。将这两个文件放到/nginx-1.2.0/src/core/目录下,然后编辑/nginx-1.2.0/objs/Makefile文件,给CFLAGS选项增加-finstrument-functions选项。
02: 代码片段2.4-3,文件名: Makefile
03: CFLAGS = -pipe -O0-W -Wall -Wpointer-arith -Wno-unused-parameter -Wunused-function -Wunused-va riable -Wunused-value -Werror -g -finstrument-functions
接着,需要将my_debug.h和my_debug.c引入到Nginx源码里一起编译,所以继续修改/nginx-1.2.0/objs/Makefile文件,根据Nginx的Makefile文件特点,修改的地方主要有如下几处。
00: 代码片段2.4-4,文件名: Makefile 01: … 18: CORE_DEPS = src/core/nginx.h \ 19: src/core/my_debug.h \ 20: … 84: HTTP_DEPS = src/http/ngx_http.h \ 85: src/core/my_debug.h \ 86: … 102: objs/nginx: objs/src/core/nginx.o \ 103: objs/src/core/my_debug.o \ 104: … 211: $(LINK) -o objs/nginx \ 212: objs/src/core/my_debug.o \ 213: … 322: objs/src/core/my_debug.o: $(CORE_DEPS) \ 323: src/core/my_debug.c 324: $(CC) -c $(CFLAGS) $(CORE_INCS) \ 325: -o objs/src/core/my_debug.o \ 326: src/core/my_debug.c 327: …
为了在Nginx源码里引入my_debug,这需要在Nginx所有源文件都包含有头文件my_debug.h,当然没必要每个源文件都去添加对这个头文件的引入,我们只需要在头文件ngx_core.h内加入对my_debug.h文件的引入即可,这样其他Nginx的源文件就间接地引入了这个文件。
37: 代码片段2.4-5,文件名: ngx_core.h 38: #include "my_debug.h"
在源文件nginx.c的最前面加上对宏MY_DEBUG_MAIN的定义,以使得Nginx程序有且仅有一个my_debug_fd变量的定义。
06: 代码片段2.4-6,文件名: nginx.c 07: #define MY_DEBUG_MAIN 1 08: 09: #include <ngx_config.h> 10: #include <ngx_core.h> 11: #include <nginx.h>
最后就是根据我们想要截取的执行流程,在适当的位置调用函数enable_my_debug();和函数disable_my_debug();,这里仅作测试,直接在main函数入口处调用enable_my_debug();,而disable_my_debug();函数就不调用了。
200: 代码片段2.4-7,文件名: nginx.c 201: main(int argc, char *const *argv) 202: { 203: … 208: enable_my_debug();
至此,代码增补工作已经完成,重新编译Nginx,如果之前已编译过Nginx,那么需记得先把Nginx源文件的时间戳进行刷新。
以单进程模式运行Nginx,并且在配置文件里将日志功能的记录级别设置低一点,否则将有大量的日志函数调用堆栈信息,经过这样的设置后,我们才能获得更清晰的Nginx执行流程,即配置文件里做如下设置。
00: 代码片段2.4-8,文件名: nginx.c 01: master_process off; 02: error_log logs/error.log emerg;
正常运行后的Nginx将产生一个记录程序执行流程的文件,这个文件会随着Nginx的持续运行迅速增大,所以在恰当的地方调用disable_my_debug();函数是非常有必要的,不过我这里在获取到一定量的信息后就直接kill掉Nginx进程了。mydebug.log的内容如下所示。
[root@localhost sbin]# head -n 20 mydebug.log Enter 0x804a5fc 0x806e2b3 Exit 0x804a5fc 0x806e2b3 …
这记录的是Nginx执行函数调用关系,不过这里的函数还只是以对应的地址显示而已,利用另外一个工具addr2line可以将这些地址转换回可读的函数名。addr2line工具在大多数Linux发行版上默认有安装,如果没有那么在官网1下载即可,其具体用法也可以参考官网手册。这里我们直接使用,写个addr2line.sh脚本。
00: 代码片段2.4-9,文件名: addr2line.sh 01: #!/bin/sh 02: 03: if [ $# != 3 ]; then 04: echo 'Usage: addr2line.sh executefile addressfile functionfile' 05: exit 06: fi; 07: 08: cat $2 | while read line 09: do 10: if [ "$line" = 'Enter' ]; then 11: read line1 12: read line2 13: # echo $line >> $3 14: addr2line -e $1-f $line1-s >> $3 15: echo "--->" >> $3 16: addr2line -e $1-f $line2-s | sed 's/^/ /' >> $3 17: echo >> $3 18: elif [ "$line" = 'Exit' ]; then 19: read line1 20: read line2 21: addr2line -e $1-f $line2-s | sed 's/^/ /' >> $3 22: echo "<---" >> $3 23: addr2line -e $1-f $line1-s >> $3 24: # echo $line >> $3 25: echo >> $3 26: fi; 27: done
执行addr2line.sh进行地址与函数名的转换,这个过程挺慢的,因为从上面的Shell脚本可以看到对于每一个函数地址都调用addr2line进行转换,执行效率完全没有考虑,不过够用就好,如果非要追求高效率,直接写个C程序来做这个转换工作当然也是可以的。
[root@localhost sbin]# vi addr2line.sh [root@localhost sbin]# chmod a+x addr2line.sh [root@localhost sbin]# ./addr2line.sh nginx mydebug.log myfun.log [root@localhost sbin]# head -n 12 myfun.log main nginx.c:212 ---> ngx_strerror_init ngx_errno.c:47 ngx_strerror_init ngx_errno.c:47 <--- main nginx.c:212 …
关于如何获得Nginx程序执行流程的方法大体就是上面描述的这样,不过这里介绍得很粗略,写的代码也仅只是作为示范使用,关于gcc以及相关工具的更深入研究已不在本书的讨论范围之内,如感兴趣可查看上文中提供的相关链接。
2.5 加桩调试
如果我们对代码做过单元测试,那么肯定知道加桩的概念,简单点说就是为了让一个模块执行起来,额外添加的一些支撑代码。比如,我要简单测试一个实现某种排序算法的子函数的功能是否正常,那么我也许需要写一个main()函数,设置一个数组,提供一些乱序的数据,然后利用这些数据调用排序子函数(假设它提供的接口就是对数组的排序),然后printf打印排序后的结果,看是否排序正常,所有写的这些额外代码(main()函数、数组、printf打印)就是桩代码。
上面提到的这种用于单元测试的方法,同样也可以用来深度调试Nginx内部逻辑,而且Nginx很多的基础实现(比如slab机制、红黑树、chain链、array数组等)都比较独立,要调试它们只需提供少量的桩代码即可。
以Nginx的slab机制为例,我们通过下面所提供的这些桩代码即可调试该功能的具体实现。Nginx的slab机制用于对多进程共享内存的管理,不过单进程也是一样的执行逻辑,除了加/解锁直通以外(即加锁时必定成功),所以我们采取最简单的办法,直接在Nginx本身的main()函数内插入我们的桩代码。当然,必须根据具体情况把桩代码放在合适的调用位置,比如这里的slab机制就依赖一些全局变量(像ngx_pagesize等),所以需要把桩代码的调用位置放在这些全局变量的初始化之后。
197: 代码片段2.5-1,文件名: nginx.c 198: void ngx_slab_test() 199: { 200: ngx_shm_t shm; 201: ngx_slab_pool_t *sp; 202: u_char *file; 203: void *one_page; 204: void *two_page; 205: 206: ngx_memzero(&shm, sizeof(shm)); 207: shm.size = 4 * 1024 * 1024; 208: if (ngx_shm_alloc(&shm) != NGX_OK) { 209: goto failed; 210: } 211: 212: sp = (ngx_slab_pool_t *) shm.addr; 213: sp->end = shm.addr + shm.size; 214: sp->min_shift = 3; 215: sp->addr = shm.addr; 216: 217: #if (NGX_HAVE_ATOMIC_OPS) 218: file = NULL; 219: #else 220: #error must support NGX_HAVE_ATOMIC_OPS. 221: #endif 222: if (ngx_shmtx_create(&sp->mutex, &sp->lock, file) != NGX_OK) { 223: goto failed; 224: } 225: 226: ngx_slab_init(sp); 227: 228: one_page = ngx_slab_alloc(sp, ngx_pagesize); 229: two_page = ngx_slab_alloc(sp, 2 * ngx_pagesize); 230: 231: ngx_slab_free(sp, one_page); 232: ngx_slab_free(sp, two_page); 233: 234: ngx_shm_free(&shm); 235: 236: exit(0); 237: failed: 238: printf("failed.\n"); 239: exit(-1); 240: } 241: … 353: if (ngx_os_init(log) != NGX_OK) { 354: return 1; 355: } 356: 357: ngx_slab_test(); 358: …
上面是修改之后的nginx.c源文件,直接make后生成新的Nginx,不过这个可执行文件不再是一个Web服务器,而是一个简单的调试slab机制的辅助程序。可以看到,程序在进入main()函数后先做一些初始化工作,然后通过ngx_slab_test()函数调入到桩代码内执行调试逻辑,完成既定目标后便直接exit()退出整个程序。
正常运行时,Nginx本身对内存的申请与释放是不可控的,所以直接去调试Nginx内存管理的slab机制的相关代码逻辑非常困难,利用这种加桩的办法,ngx_slab_alloc()申请内存和ngx_slab_free()释放内存都能精确控制,对每一次内存的申请或释放后,slab机制的内部结构发生了怎样的变化都能准确地掌握,对其相关逻辑的理解也就没有那么困难了。
2.6 特殊应用逻辑的调试
前面所讲的调试方法都是针对Nginx本身很容易跑到的逻辑,而对于某些只有在特定情况下才会被执行到的代码,又该怎样去调试呢?举个例子,我们知道Nginx里有大量的超时处理,比如,如果读取客户端请求头部数据超时,Nginx就将执行对应的超时处理函数,假设我想通过单步执行的方式来了解这部分相关逻辑,无疑就得让Nginx的执行逻辑走到这条路径上来。由于此时影响Nginx行为的决定因素是客户端所发送的请求头部数据,我们就必须在客户端做动作来构造出这种场景。一般的浏览器,如IE、Firefox等发出请求的行为基本已经固定,而常用的命令行工具,比如curl、wget的源代码又略显复杂,定制它们的请求动作和改变环境来构造所需的场景相对较为麻烦,所以一种更便利的方法就是我们自己写个socket通信的客户端即可,而这并不需要多少代码。
下面给出一个测试示例用代码,为了简单,所以服务器IP和端口都是固定在代码里的,用于发送数据的函数write()调用也未做返回值判断等(后续还有其他类似测试代码也是如此,这点请注意)。
00: 代码片段2.6-1,文件名: request_timeout.c 01: /** 02: * gcc -Wall -g -o request_timeout request_timeout.c 03: */ 04: #include <sys/types.h> 05: #include <stdio.h> 06: #include <stdlib.h> 07: #include <string.h> 08: #include <errno.h> 09: #include <sys/socket.h> 10: #include <netinet/in.h> 11: #include <arpa/inet.h> 12: #include <unistd.h> 13: 14: //char req_header[]="GET/HTTP/1.1\r\nUser-Agent:curl/7.19.7\r\nHost:127.0.0.1\r\nAccept: */*\r\n\r\n"; 15: char req_header[] = "GET / HTTP/1.1\r\nUser-Agent: curl/7.19.7\r\n"; 16: 17: int main(int argc, char *const *argv) 18: { 19: int sockfd; 20: struct sockaddr_in server_addr; 21: 22: if ((sockfd = socket (AF_INET, SOCK_STREAM, 0)) == -1) { 23: fprintf (stderr, "Socket error,%s\r\n", strerror (errno)); 24: return -1; 25: } 26: 27: bzero (&server_addr, sizeof (server_addr)); 28: server_addr.sin_family = AF_INET; 29: server_addr.sin_port = htons (80); 30: 31: if(!inet_aton("192.168.1.1", &server_addr.sin_addr)) { 32: fprintf (stderr, "Bad address:%s\r\n", strerror (errno)); 33: close (sockfd); 34: return -1; 35: } 36: 37: if (connect (sockfd, (struct sockaddr *) (&server_addr), 38: sizeof (struct sockaddr)) == -1) { 39: fprintf (stderr, "Connect Error:%s\r\n", strerror (errno)); 40: close (sockfd); 41: return -1; 42: } 43: 44: write (sockfd, req_header, strlen(req_header)); 45: 46: close (sockfd); 47: return 0; 48: }
该程序的代码比较简单,变量req_header存储的是http请求头部数据,被注释掉的是正常的请求头,而我这里使用的请求头是不完整的(正常请求头可以用wget、curl或wireshark等工具获得,异常请求头必须根据自己所预期场景来进行构造,比如在这里,其他异常情况的请求头可能导致Nginx以其他错误方式返回而不是进行超时监控),所以这会使得Nginx在接收到该请求后,持续等待进一步的头部数据,直到超时。编译这个源代码得到应用程序request_timeout。
将接受http请求的Nginx工作进程绑定到gdb,然后在超时函数ngx_event_expire_timers()内的第149行下断点并按c继续。
75: 代码片段2.6-2,文件名: ngx_event_timer.c 76: void 77: ngx_event_expire_timers(void) 78: { 79: … 147: ev->timedout = 1; 148: 149: ev->handler(ev);
这个断点是Nginx已经捕获到超时事件,设置其超时旗标并调用对应的回调函数进行处理。在另一个gdb内执行request_timeout,当然,我们需要让它停止在第47行,避免程序退出,导致它与Nginx工作进程之间的连接断开。等待约60秒(Nginx读取请求头部数据的默认超时时间为60秒,可通过配置指令client_header_timeout修改)后,attach到Nginx工作进程的gdb就会断下来,按s跟进函数,再顺着执行路径而下就会发现此时Nginx将执行到这个逻辑里。
955: 代码片段2.6-3,文件名: ngx_event_timer.c 956: static void 957: ngx_http_process_request_headers(ngx_event_t *rev) 958: { 959: … 976: if (rev->timedout) { 977: ngx_log_error(NGX_LOG_INFO, c->log, NGX_ETIMEDOUT, "client timed out"); 978: c->timedout = 1; 979: ngx_http_close_request(r, NGX_HTTP_REQUEST_TIME_OUT); 980: return; 981: }
将执行到第976行的if判断内部,即连接超时,我们看到对于在读取请求头部数据超时的情况下,Nginx工作进程最后所做的几步主要工作,即日志记录、关闭请求并返回。通过这样一个实例,我们也就了解了如何去调试这样的特殊应用逻辑,不仅仅只是针对客户端,对于后端应用服务器也能如此进行模拟构造。
上面演示的环境构造步骤,虽然比较简单且能真实模拟,但毕竟需要我们了解它的细节,也就是需知道触发这种情况的前提条件,如果前提条件比较多,那么模拟起来可能还是比较麻烦,其实,如果我们只是了解一下Nginx如果这样执行会怎么样,那么完全可以通过利用gdb的p命令或set命令修改对应条件变量的值来达到目的。比如在前面的例子里,在一般情况下,rev->timedout为0,即不超时而无法执行第977-980行代码,但我又想看一下执行这几条语句的情况会怎么样,那么就可以像下面这样做。
Breakpoint 1, ngx_http_process_request_headers (rev=0x94a6bfc) at src/http/ ngx_http_request.c:976 976 if (rev->timedout) { (gdb) p rev->timedout $1 = 0 (gdb) p rev->timedout=1 $2 = 1 (gdb) n 977 ngx_log_error(NGX_LOG_INFO, c->log, NGX_ETIMEDOUT, "client timed out"); (gdb) set rev->timedout=0 (gdb) p rev->timedout $3 = 0 (gdb)
通过执行“p rev->timedout=1”把变量rev->timedout的值改为1,这样就执行到第977行了,当然,如上所示,set命令也可以改变Nginx执行变量的值。值得特别注意的是,这样做仅仅只是因为改变了条件判断的变量值而使得Nginx程序执行路径发生变化,但是其在新的路径上,可能由于使用的某些变量值不是原本所期望的情况而导致执行异常。