Sunday, July 27, 2014

Unix Shell: Process Tracing

Process tracing could help identify all system calls the process made. This is very helpful for debugging a process if we don't have the source code base.

script_1:
 #! /bin/bash  
   
 echo "Hello world!"  

1. Trace all system calls script_1 has made:
terminal:
After running script_1 script, it outputs all system calls it has made.
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ strace ./script_1  
 execve("./script_1", ["./script_1"], [/* 64 vars */]) = 0  
 brk(0)                 = 0x9c64000  
 access("/etc/ld.so.nohwcap", F_OK)   = -1 ENOENT (No such file or directory)  
 mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb772e000  
 access("/etc/ld.so.preload", R_OK)   = -1 ENOENT (No such file or directory)  
 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3  

   ......

 read(255, "#! /bin/bash\n\necho \"Hello world!"..., 34) = 34
 write(1, "Hello world!\n", 13Hello world!
 )          = 13
 read(255, "", 34)                       = 0
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
 exit_group(0)                           = ?
 +++ exited with 0 +++

2. Trace only specified system calls script_1 has made:
terminal:
1) Only output the "write" system call script_1 has made
2) Output the "read" and "write" system call script_1 has made
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ strace -e write ./script_1  
 write(1, "Hello world!\n", 13Hello world!  
 )     = 13  
 +++ exited with 0 +++  
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ strace -e trace=open,write ./script_1  
 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3  
 open("/lib/i386-linux-gnu/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = 3  
 open("/lib/i386-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3  
 open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3  
 open("/dev/tty", O_RDWR|O_NONBLOCK|O_LARGEFILE) = 3  
 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3  
 open("/proc/meminfo", O_RDONLY|O_CLOEXEC) = 3  
 open("/usr/lib/i386-linux-gnu/gconv/gconv-modules.cache", O_RDONLY) = 3  
 open("./script_1", O_RDONLY|O_LARGEFILE) = 3  
 write(1, "Hello world!\n", 13Hello world!  
 )     = 13  
 +++ exited with 0 +++  

3. Output the tracing result to external file
terminal:
1) run strace command to output only "write" system call script_1 has made, output the tracing result to external file trace.txt
2) Print out the file content of trace.txt
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ strace -e write -o trace.txt ./script_1  
 Hello world!  
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ cat ./trace.txt  
 write(1, "Hello world!\n", 13)     = 13  
 +++ exited with 0 +++  

4. Trace the running process
script_2:
This is a simple process which is doing non-stop loop
 #! /bin/bash  
   
 a=1  
 while [ $a -ne 0 ]  
 do  
   ((a++))  
   sleep 5  
 done  

terminal:
1) Run ps command ,  script_2 is already launched
2) Use root user(we have to use root user in this case), to monitor the system call made by process with id 3519, which is script_2. Then it will keep outputting the system call list.
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ ps  
  PID TTY     TIME CMD  
  2833 pts/1  00:00:00 bash  
  2968 pts/1  00:00:17 emacs  
  3519 pts/1  00:00:00 script_2  
  3554 pts/1  00:00:00 sleep  
  3555 pts/1  00:00:00 ps  
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ sudo strace -p 3519  
 Process 3519 attached  
 waitpid(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 3557  
 rt_sigaction(SIGINT, {SIG_DFL, [], 0}, {0x8087c50, [], 0}, 8) = 0  
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0  
 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=3557, si_status=0, si_utime=0, si_stime=2} ---  
 waitpid(-1, 0xbfd244f8, WNOHANG)    = -1 ECHILD (No child processes)  
 sigreturn() (mask [])          = 0  
 rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0  
 rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0 
 ......
 

5. Trace the process with timestamp
terminal:
-t option will make strace output the command
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ strace -t -e trace=open,write ./script_1  
 11:29:40 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3  
 11:29:40 open("/lib/i386-linux-gnu/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = 3  
 11:29:40 open("/lib/i386-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3  
 11:29:40 open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3  
 11:29:40 open("/dev/tty", O_RDWR|O_NONBLOCK|O_LARGEFILE) = 3  
 11:29:40 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3  
 11:29:40 open("/proc/meminfo", O_RDONLY|O_CLOEXEC) = 3  
 11:29:40 open("/usr/lib/i386-linux-gnu/gconv/gconv-modules.cache", O_RDONLY) = 3  
 11:29:40 open("./script_1", O_RDONLY|O_LARGEFILE) = 3  
 11:29:40 write(1, "Hello world!\n", 13Hello world!  
 ) = 13  
 11:29:40 +++ exited with 0 +++  

6. Trace the process with relative execution time
terminal:
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ strace -r -e trace=open,write ./script_1  
    0.000000 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3  
    0.003371 open("/lib/i386-linux-gnu/libtinfo.so.5", O_RDONLY|O_CLOEXEC) = 3  
    0.015814 open("/lib/i386-linux-gnu/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3  
    0.001950 open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3  
    0.020927 open("/dev/tty", O_RDWR|O_NONBLOCK|O_LARGEFILE) = 3  
    0.001489 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3  
    0.011242 open("/proc/meminfo", O_RDONLY|O_CLOEXEC) = 3  
    0.009761 open("/usr/lib/i386-linux-gnu/gconv/gconv-modules.cache", O_RDONLY) = 3  
    0.021213 open("./script_1", O_RDONLY|O_LARGEFILE) = 3  
    0.005412 write(1, "Hello world!\n", 13Hello world!  
 ) = 13  
    0.008233 +++ exited with 0 +++  

7. Trace the process with system calls report
terminal:
-c option will make strace command to generate a statistics report for all system calls. In this case, it indicates that open has been launched 9 times, write has been launched 1 time.
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ strace -c -e trace=open,write ./script_1  
 Hello world!  
 % time   seconds usecs/call   calls  errors syscall  
 ------ ----------- ----------- --------- --------- ----------------  
 100.00  0.000319     35     9      open  
  0.00  0.000000      0     1      write  
 ------ ----------- ----------- --------- --------- ----------------  
 100.00  0.000319          10      total  

8. Process Accounting
Whenever we run a process, it would generate the accounting information at system files. We can output the these accounting information, to know what kind of processes have been launched from the very beginning.

terminal:
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ sa | head -n 10  
   1553   516.40re    1.17cp     0avio   1344k  
    65   101.18re    0.26cp     0avio   2446k  ***other*  
     2    0.44re    0.21cp     0avio   22785k  update-apt-xapi  
    908   81.84re    0.16cp     0avio   1055k  sleep  
     5    0.19re    0.09cp     0avio   5012k  command-not-fou  
     2    0.27re    0.08cp     0avio   1680k  apt-get  
     4   62.64re    0.06cp     0avio   35264k  unity-panel-ser  
     2    0.18re    0.06cp     0avio    994k  mandb  
    27    2.73re    0.04cp     0avio    603k  strace  
     2    0.39re    0.02cp     0avio   13126k  ubuntu-sso-logi  

9. /proc File system
Unix will save the process related information into files.
Location is /proc

terminal:
1) Run ps command to list current running process
2) List the folder /proc/5293, 5293 is the process id of script_2, that folder contains all process running information, which are organized as files.
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ ps  
  PID TTY     TIME CMD  
  2833 pts/1  00:00:02 bash  
  5293 pts/1  00:00:10 script_2  
  7907 pts/1  00:00:07 emacs  
  8532 pts/1  00:00:00 sleep  
  8533 pts/1  00:00:00 ps  
 aubinxia@aubinxia-fastdev:~/Desktop/xxdev$ ls /proc/5293  
 attr    comm       fd    loginuid  mountstats   pagemap   sessionid syscall  
 autogroup  coredump_filter fdinfo  map_files net      personality smaps   task  
 auxv    cpuset      gid_map maps    ns       projid_map  stack   timers  
 cgroup   cwd       io    mem    oom_adj    root     stat    uid_map  
 clear_refs environ     latency mountinfo oom_score   sched    statm   wchan  
 cmdline   exe       limits  mounts   oom_score_adj schedstat  status 

No comments:

Post a Comment