使用Linux Strace跟踪调试Oracle程序进程

所谓操作系统，是应用程序与服务器硬件进行沟通的中间层。应用程序的所有操作，都是和操作系统进行沟通交互。操作系统负责将所有交互转化为设备语言，进行硬件交互。我们在进行Oracle故障调试和内核原理工作的时候，经常需要了解后台运行的动作和细节。一些故障场景，如程序进程hang住、无法登陆等问题，就需要操作系统级别监控，检查定位问题。Oracle自身已经提供了很多这类型的工具，如oradebug、各种等待事件和跟踪方式。此外，各类型的操作系统提供出很多系统级别工具，帮助我们进行监控。本篇主要介绍Linux环境中的strace工具典型使用方法，留待需要朋友待查。1、环境介绍笔者使用红帽Red Hat 6.5进行测试。[root@XXX-Standby-Asm ~]# cat /etc/RedHat-releaseRed Hat Enterprise Linux Server release 6.5 （Santiago）[root@XXX-Standby-Asm ~]# uname -aLinux XXX-Standby-Asm 2.6.32-431.el6.x86_64 #1 SMP Sun Nov 10 22:19:54 EST 2013 x86_64 x86_64 x86_64 GNU/Linux对应使用Oracle版本为11.2.0.4。[oracle@XXX-Standby-Asm ~]$ sqlplus /nologSQL*Plus: Release 11.2.0.4.0 Production on Tue Jun 16 16:39:21 2015Copyright （c） 1982, 2013, Oracle. All rights reserved.SQL> conn / as sysdbaConnected.SQL> select * from v$version;BANNER--------------------------------------------------------------------------------Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit ProductionPL/SQL Release 11.2.0.4.0 - ProductionCORE 11.2.0.4.0 ProductionTNS for Linux: Version 11.2.0.4.0 - ProductionNLSRTL Version 11.2.0.4.0 – Production2、Strace命令信息使用-h参数，可以调用出strace命令的语法格式和各个使用参数。[oracle@XXX-Standby-Asm ~]$ strace -husage: strace [-dDffhiqrtttTvVxx] [-a column] [-e expr] ... [-o file] [-p pid] ... [-s strsize] [-u username] [-E var=val] ... [command [arg ...]] or: strace -c [-D] [-e expr] ... [-O overhead] [-S sortby] [-E var=val] ... [command [arg ...]]-c -- count time, calls, and errors for each syscall and report summary-f -- follow forks, -ff -- with output into separate files-F -- attempt to follow vforks, -h -- print help message-i -- print instruction pointer at time of syscall-q -- suppress messages about attaching, detaching, etc.-r -- print relative timestamp, -t -- absolute timestamp, -tt -- with usecs-T -- print time spent in each syscall, -V -- print version-v -- verbose mode: print unabbreviated argv, stat, termio[s], etc. args-x -- print non-ascii strings in hex, -xx -- print all strings in hex-a column -- alignment COLUMN for printing syscall results （default 40）-e expr -- a qualifying expression: option=[！]all or option=[！]val1[,val2]... options: trace, abbrev, verbose, raw, signal, read, or write-o file -- send trace output to FILE instead of stderr-O overhead -- set overhead for tracing syscalls to OVERHEAD usecs-p pid -- trace process with process id PID, may be repeated-D -- run tracer process as a detached grandchild, not as parent-s strsize -- limit length of print strings to STRSIZE chars （default 32）-S sortby -- sort syscall counts by: time, calls, name, nothing （default time）-u username -- run command as username handling setuid and/or setgid-E var=val -- put var=val in the environment for command-E var -- remove var from the environment for command在诸多参数中，比较常用的有如下几个：ü -t参数：可以显示调用操作系统过程的时间。这个在诊断中很重要，如果发现某一个执行过程时间消耗大，就可以定位到是什么问题；ü -p参数：strace除了可以从进程启动时候开始监控之外，还可以根据操作系统进程编号，进入一个运行中的进程进行debug；ü -o参数：输出结果如果需要以文件方式保存，就通过-o参数指定文件名称；ü -e参数：监控表达式。提供trace、signal、read和write等内容，反映监控方面项目。常用的参数是trace=file，集中在操作系统文件访问层面。下面，通过两个典型应用场景，来演示一下strace应用。3、启动程序监控strace监控研究的一个重要范例是sqlplus，很多前辈使用这个工具来测试跟踪sqlplus启动过程访问的文件形式。启动strace监控sqlplus，就是在strace命令后直接输入sqlplus命令即可。--启动命令[oracle@localhost ~]$ strace -t -e trace=file sqlplus /nolog14:21:14 execve（"/u01/app/oracle/bin/sqlplus", ["sqlplus", "/nolog"], [/* 31 vars */]） = 0 –启动命令14:21:14 access（"/etc/ld.so.preload", R_OK） = -1 ENOENT （No such file or directory）14:21:14 open（"/u01/app/oracle/lib/tls/x86_64/libsqlplus.so", O_RDONLY） = -1 ENOENT （No such file or directory）14:21:14 stat（"/u01/app/oracle/lib/tls/x86_64", 0x7fff3076da50） = -1 ENOENT （No such file or directory）14:21:14 open（"/u01/app/oracle/lib/tls/libsqlplus.so", O_RDONLY） = -1 ENOENT （No such file or directory）14:21:14 stat（"/u01/app/oracle/lib/tls", 0x7fff3076da50） = -1 ENOENT （No such file or directory）14:21:14 open（"/u01/app/oracle/lib/x86_64/libsqlplus.so", O_RDONLY） = -1 ENOENT （No such file or directory）14:21:14 stat（"/u01/app/oracle/lib/x86_64", 0x7fff3076da50） = -1 ENOENT （No such file or directory）14:21:14 open（"/u01/app/oracle/lib/libsqlplus.so", O_RDONLY） = 314:21:14 open（"/u01/app/oracle/lib/libclntsh.so.11.1", O_RDONLY） = 314:21:14 open（"/u01/app/oracle/lib/libnnz11.so", O_RDONLY） = 314:21:14 open（"/u01/app/oracle/lib/libdl.so.2", O_RDONLY） = -1 ENOENT （No such file or directory）（篇幅原因，有省略……）14:21:14 access（"/etc/tnsnav.ora", F_OK） = -1 ENOENT （No such file or directory）14:21:14 access（"/u01/app/oracle/network/admin/tnsnav.ora", F_OK） = -1 ENOENT （No such file or directory）14:21:14 open（"/u01/app/oracle/oracore/zoneinfo", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC） = 614:21:14 open（"/u01/app/oracle/oracore/zoneinfo/timezlrg_1.dat", O_RDONLY） = 714:21:14 open（"/u01/app/oracle/oracore/zoneinfo/timezlrg_2.dat", O_RDONLY） = 7（读取各种时区数据……）14:21:14 open（"/u01/app/oracle/oracore/zoneinfo/timezone_14.dat", O_RDONLY） = 714:21:14 open（"/u01/app/oracle/oracore/zoneinfo/timezlrg_14.dat", O_RDONLY） = 614:21:14 open（"/usr/lib64/libnuma.so", O_RDONLY） = -1 ENOENT （No such file or directory）14:21:14 open（"/usr/lib64/libnuma.so.1", O_RDONLY） = 614:21:14 open（"/proc/self/status", O_RDONLY） = 614:21:14 open（"/sys/devices/system/node", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC） = 614:21:14 open（"/sys/devices/system/node/node0/meminfo", O_RDONLY） = 714:21:14 open（"/sys/devices/system/cpu", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC） = 614:21:14 open（"/proc/self/status", O_RDONLY） = 614:21:14 open（"/proc/sys/kernel/shmmax", O_RDONLY） = 614:21:14 open（"/proc/meminfo", O_RDONLY） = 614:21:14 open（"/usr/lib64/libnuma.so", O_RDONLY） = -1 ENOENT （No such file or directory）14:21:14 open（"/etc/localtime", O_RDONLY） = 614:21:14 open（"/u01/app/oracle/rdbms/mesg/ocius.msb", O_RDONLY） = 6SQL*Plus: Release 11.2.0.4.0 Production on Fri Jun 12 14:21:14 2015Copyright （c） 1982, 2013, Oracle. All rights reserved.--启动之后，读取的文件。14:21:14 stat（"login.sql", 0x7fff3076c740） = -1 ENOENT （No such file or directory）14:21:14 stat（"/u01/app/oracle/sqlplus/admin/glogin.sql", {st_mode=S_IFREG|0644, st_size=368, ...}） = 014:21:14 access（"/u01/app/oracle/sqlplus/admin/glogin.sql", F_OK） = 014:21:14 statfs（"/u01/app/oracle/sqlplus/admin/glogin.sql", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=174170552, f_bfree=147038320, f_bavail=138190973, f_files=44236800, f_ffree=44019067, f_fsid={1821877354, 763674030}, f_namelen=255, f_frsize=4096}） = 014:21:14 open（"/u01/app/oracle/sqlplus/admin/glogin.sql", O_RDONLY） = 7如果在启动sqlplus过程中，直接进行登录。跟踪过程中还包括了登录动作。[oracle@localhost ~]$ strace -t -e trace=file sqlplus / as sysdba14:29:30 execve（"/u01/app/oracle/bin/sqlplus", ["sqlplus", "/", "as", "sysdba"], [/* 31 vars */]） = 0（相同篇幅内容，略……）SQL*Plus: Release 11.2.0.4.0 Production on Fri Jun 12 14:29:30 2015Copyright （c） 1982, 2013, Oracle. All rights reserved.--差异部分14:29:30 open（"/u01/app/oracle/dbs/cm_xxxdb.dat", O_RDONLY|O_DSYNC） = -1 ENOENT （No such file or directory）14:29:30 getcwd（"/home/oracle", 256） = 1314:29:30 open（"/proc/self/cmdline", O_RDONLY） = 714:29:30 open（"/etc/nsswitch.conf", O_RDONLY） = 714:29:30 open（"/u01/app/oracle/lib/libnss_files.so.2", O_RDONLY） = -1 ENOENT （No such file or directory）14:29:30 open（"/etc/ld.so.cache", O_RDONLY） = 714:29:30 open（"/lib64/libnss_files.so.2", O_RDONLY） = 714:29:30 open（"/etc/passwd", O_RDONLY|O_CLOEXEC） = 714:29:30 open（"/u01/app/oracle/lib/libnque11.so", O_RDONLY） = 714:29:30 getcwd（"/home/oracle", 256） = 1314:29:30 open（"/u01/app/oracle/nls/data/lx20369.nlb", O_RDONLY） = 714:29:30 open（"/u01/app/oracle/nls/data/lx207d0.nlb", O_RDONLY） = 714:29:30 readlink（"/proc/self/fd/0", "/dev/pts/0", 254） = 1014:29:30 open（"/etc/passwd", O_RDONLY|O_CLOEXEC） = 714:29:30 open（"/etc/host.conf", O_RDONLY） = 714:29:30 open（"/etc/resolv.conf", O_RDONLY） = 714:29:30 open（"/etc/hosts", O_RDONLY|O_CLOEXEC） = 714:29:30 open（"/etc/hostid", O_RDONLY） = -1 ENOENT （No such file or directory）14:29:30 open（"/etc/hosts", O_RDONLY|O_CLOEXEC） = 714:29:30 open（"/u01/app/oracle/rdbms/mesg/oraus.msb", O_RDONLY） = 7Connected to:Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit ProductionWith the Partitioning, OLAP, Data Mining and Real Application Testing options14:29:30 stat（"login.sql", 0x7fff0a822b10） = -1 ENOENT （No such file or directory）14:29:30 stat（"/u01/app/oracle/sqlplus/admin/glogin.sql", {st_mode=S_IFREG|0644, st_size=368, ...}） = 014:29:30 access（"/u01/app/oracle/sqlplus/admin/glogin.sql", F_OK） = 014:29:30 statfs（"/u01/app/oracle/sqlplus/admin/glogin.sql", {f_type="EXT2_SUPER_MAGIC", f_bsize=4096, f_blocks=174170552, f_bfree=147038317, f_bavail=138190970, f_files=44236800, f_ffree=44019066, f_fsid={1821877354, 763674030}, f_namelen=255, f_frsize=4096}） = 014:29:30 open（"/u01/app/oracle/sqlplus/admin/glogin.sql", O_RDONLY） = 74、跟踪执行进程方式除了上面介绍的方法外，strace还可以直接跟踪监控正在执行的系统进程。下面我们来观察一下strace对Oracle后台CKPT进程的监控。[oracle@XXX-Standby-Asm ~]$ ps -ef | grep ckptgrid 15950 1 0 Jun05 ？ 00:01:02 asm_ckpt_+ASMoracle 18608 17848 0 17:35 pts/0 00:00:00 grep ckptoracle 21395 1 0 Jun08 ？ 00:04:27 ora_ckpt_xxxstb从root角度，跟踪进程编号21395的后台进程。[root@XXX-Standby-Asm ~]# strace -t -p 21395Process 21395 attached - interrupt to quit17:36:42 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560827117:36:42 semtimedop（6062085, {{16, -1, 0}}, 1, {1, 840000000}） = -1 EAGAIN （Resource temporarily unavailable）17:36:44 getrusage（RUSAGE_SELF, {ru_utime={125, 122978}, ru_stime={142, 730301}, ...}） = 017:36:44 getrusage（RUSAGE_SELF, {ru_utime={125, 122978}, ru_stime={142, 730301}, ...}） = 017:36:44 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560845517:36:44 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560845517:36:44 read（16, "MSA210P20？P 200330266177177"..., 80） = 8017:36:44 read（16, "MSA210P20？P 200330266177177"..., 80） = 8017:36:44 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560845517:36:44 semtimedop（6062085, {{16, -1, 0}}, 1, {3, 0}） = -1 EAGAIN （Resource temporarily unavailable） –三秒差异17:36:47 getrusage（RUSAGE_SELF, {ru_utime={125, 123978}, ru_stime={142, 731301}, ...}） = 017:36:47 getrusage（RUSAGE_SELF, {ru_utime={125, 123978}, ru_stime={142, 731301}, ...}） = 017:36:47 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560875517:36:47 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560875517:36:47 read（16, "MSA210P20？P 200330266177177"..., 80） = 8017:36:47 read（16, "MSA210P20？P 200330266177177"..., 80） = 8017:36:47 read（16, "MSA210P20？P 200330266177177"..., 80） = 8017:36:47 read（16, "MSA210P20？P 200330266177177"..., 80） = 8017:36:47 read（16, "MSA210P20？P 200330266177177"..., 80） = 8017:36:47 read（16, "MSA210P20？P 200330266177177"..., 80） = 8017:36:47 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560875617:36:47 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560875617:36:47 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560875617:36:47 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560875617:36:47 times（{tms_utime=12512, tms_stime=14273, tms_cutime=0, tms_cstime=0}） = 64560875617:36:47 semtimedop（6062085, {{16, -1, 0}}, 1, {3, 0}^C Process 21395 detached从里面，我们可以看到ckpt的动作方式。5、结论Strace是Linux环境下的一个非常有用的工具。用好这个工具，可以让我们更加接近内核细节，丰富知识能力。更多Oracle相关信息见Oracle 专题页面 http://www.linuxidc.com/topicnews.aspx？tid=12本文永久更新链接地址