[20190314]使用strace注意的问题.txt

--//使用strace跟踪进程,我发现我自己忽略一个问题.一般看函数调用花费时间一般使用如下参数:

-r    Print a relative timestamp upon entry to each system call.  This records the time difference between the beginning

      of successive system calls.

-t    Prefix each line of the trace with the time of day.

-tt   If given twice, the time printed will include the microseconds.

-ttt  If given thrice, the time printed will include the microseconds and the leading portion will be printed as the

      number of seconds since the epoch.

-T    Show the time spent in system calls. This records the time difference between the beginning and the end of each

      system call.

--//注意-T,-r参数的区别.-T显示的system calls的时间,显示在最后.

--//-r 显示相对时间,显示在前面.

--//通过例子说明:

$ export TNS_ADMIN=/tmp

--//在tmp目录下建立如下文件:

$ cat tnsnames.ora

CLIENT_CON =

 (DESCRIPTION =

  (LOAD_BALANCE=OFF)

   (TRANSPORT_CONNECT_TIMEOUT=1)

   (ADDRESS = (PROTOCOL = TCP)(HOST =10.10.10.10)(PORT = 1522))

   (ADDRESS = (PROTOCOL = TCP)(HOST =11.11.11.11)(PORT = 1522))

   (ADDRESS = (PROTOCOL = TCP)(HOST =12.12.12.12)(PORT = 1522))

   (ADDRESS = (PROTOCOL = TCP)(HOST =13.13.13.13)(PORT = 1522))

   (ADDRESS = (PROTOCOL = TCP)(HOST =14.14.14.14)(PORT = 1522))

   (ADDRESS = (PROTOCOL = TCP)(HOST =15.15.15.15)(PORT = 1522))

  (CONNECT_DATA =

     (SERVER = DEDICATED)

     (SERVICE_NAME = orclgg)

   ))

$ strace -r -tT -f tnsping client_con 2>&1 | grep -C1  -E 'poll'

     0.000084 mmap(NULL, 528384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0c2342a000 <0.000023>

     0.000078 poll([{fd=4, events=POLLOUT}], 1, 1000) = 0 (Timeout) <1.001095>

     1.001171 close(4)                  = 0 <0.000076>

--

     0.000122 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 10709770534 <0.000027>

     0.000085 poll([{fd=4, events=POLLOUT}], 1, 1000) = 0 (Timeout) <1.001072>

     1.001181 close(4)                  = 0 <0.000111>

--

     0.000128 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 10709770634 <0.000026>

     0.000084 poll([{fd=4, events=POLLOUT}], 1, 1000) = 0 (Timeout) <1.001086>

     1.001340 close(4)                  = 0 <0.000055>

--

     0.000126 times({tms_utime=0, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 10709770735 <0.000056>

     0.000116 poll([{fd=4, events=POLLOUT}], 1, 1000) = 0 (Timeout) <1.001093>

     1.001261 close(4)                  = 0 <0.000080>

--

     0.000125 times({tms_utime=1, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 10709770835 <0.000027>

     0.000084 poll([{fd=4, events=POLLOUT}], 1, 1000) = 0 (Timeout) <1.001079>

     1.001265 close(4)                  = 0 <0.000082>

--

     0.000120 times({tms_utime=1, tms_stime=0, tms_cutime=0, tms_cstime=0}) = 10709770935 <0.000027>

     0.000085 poll([{fd=4, events=POLLOUT}], 1, 1000) = 0 (Timeout) <1.001085>

     1.001255 close(4)                  = 0 <0.000055>

--//说明-C1,显示匹配poll前后1行.

--//另外可以发现-t显示时间的参数如下,在使用-r参数时.

--//-r显示的时间在前面,不可能close花费1秒,实际上poll调用后,调用close前的时间.

--//-T显示的时间在后面,这个是system call花费的时间.

--//注意这些区别对于诊断问题帮助很大.遇到不熟悉的函数可以使用man查看,比如:

$ man poll

POLL(2)                    Linux Programmer's Manual                   POLL(2)

NAME

       poll, ppoll - wait for some event on a file descriptor

SYNOPSIS

       #include <poll.h>

       int poll(struct pollfd *fds, nfds_t nfds, int timeout);

       #define _GNU_SOURCE

       #include <poll.h>

       int ppoll(struct pollfd *fds, nfds_t nfds,

               const struct timespec *timeout, const sigset_t *sigmask);

DESCRIPTION

       poll() performs a similar task to select(2): it waits for one of a set of file descriptors to become ready to perform I/O.

  The set of file descriptors to be monitored is specified in the fds argument, which is an array of nfds

  structures of the following form:

           struct pollfd {

               int   fd;         /* file descriptor */

               short events;     /* requested events */

               short revents;    /* returned events */

           };

       The field fd contains a file descriptor for an open file.