)Linux利器 strace

簡介：這是(轉)Linux利器 strace的詳細頁面，介紹了和php,nginx, cgi, php, linux (轉)Linux利器 strace有關的知識、技巧、經驗，和一些php源碼等。

class='pingjiaF' frameborder='0' src='http://biancheng.dnbcw.info/pingjia.php?id=347704' scrolling='no'>
原文：http://www.perfgeeks.com/?p=501

今天才發現strace是個好東西呀

strace常用來跟蹤進程執行時的系統調用和所接收的訊號。 在Linux世界，進程不能直接存取硬體裝置，當進程需要訪問硬體裝置(比如讀取磁碟檔案，接收網路資料等等)時，必須由使用者態模式切換至核心態模式，通過系統調用訪問硬體裝置。strace可以跟蹤到一個進程產生的系統調用,包括參數，傳回值，執行消耗的時間。

strace使用參數

-p 跟蹤指定的進程

-f 跟蹤由fork子進程系統調用

-F 嘗試跟蹤vfork子進程系統調吸入，與-f同時出現時, vfork不被跟蹤

-o filename 預設strace將結果輸出到stdout。通過-o可以將輸出寫入到filename檔案中

-ff 常與-o選項一起使用，不同進程(子進程)產生的系統調用輸出到filename.PID檔案

-r 列印每一個系統調用的相對時間

-t 在輸出中的每一行前加上時間資訊。 -tt 時間確定到微秒級。還可以使用-ttt列印相對時間

-v 輸出所有系統調用。預設情況下，一些頻繁調用的系統調用不會輸出

-s 指定每一行輸出字串的長度,預設是32。檔案名稱一直全部輸出

-c 統計每種系統調用所執行的時間，調用次數，出錯次數。

-e expr 輸出過濾器，通過運算式，可以過濾出掉你不想要輸出

應用情境

#1.跟蹤你的web伺服器系統調用

系統調用最佳化，也是web效能最佳化的一個較為重要的方向，尤其是在I/O密集型web應用的情況。我們這裡的測試環境是CentOS5.4+Nginx+FastCGI。

<?php

//file:hello.php

define('DOCUMENT_ROOT', dirname(__FILE__));

include("hello.inc");

include("./hello.inc");

include(DOCUMENT_ROOT . "/hello.inc");

?>

#strace -f -F -o strace_nginx strace /wwwchroot/nginx/sbin/nginx -c /wwwchroot/nginx/nginx.conf

... (有部分不重要的資料影響排版，在這裡使用...代替)

//--接受來自用戶端的http請求

4165  recv(16, "GET /hello.php HTTP/1.1\r\nHost: f"..., 32768, 0) = 391

4165  epoll_ctl(9, EPOLL_CTL_MOD, 16, {EPOLLIN|EPOLLOUT|EPOLLET, {u32=3081162952, u64=698098541354471624}}) = 0

//--進行DNS尋找

4165  getsockname(16, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("222.73.211.214")}, [16]) = 0

//--建立一個socket，串連Fast-CGI,連接埠號碼為9000

4165  socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 17

4165  ioctl(17, FIONBIO, [1])           = 0

4165  epoll_ctl(9, EPOLL_CTL_ADD, 17, {EPOLLIN|EPOLLOUT|EPOLLET, {u32=3081163048, u64=697886249710965032}}) = 0

4165  connect(17, {sa_family=AF_INET, sin_port=htons(9000), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 )

4165  epoll_wait(9, {{EPOLLOUT, {u32=3081163048, u64=697886249710965032}}, {...}, 5\

12, 300000) = 2

4165  gettimeofday({1295420285, 130967}, NULL) = 0

4165  recv(16, 0xbfdd7d8b, 1, MSG_PEEK) = -1 EAGAIN (Resource temporarily unavailable)

4165  getsockopt(17, SOL_SOCKET, SO_ERROR, [0], [4]) = 0

//--將使用者http請求交給Fast-CGI

4165  writev(17, [{"\1\1\0\1\0\10\0\0\0\1\0\0\0\0\0\0\1\4\0\1\3\30\0\0\21\7GATEWA"..., 832}], 1) = 832

4165  epoll_wait(9, {{EPOLLIN|EPOLLOUT, {u32=3081163048, u64=697886249710965032}}}, 512, 300000) = 1

4165  gettimeofday({1295420285, 131559}, NULL) = 0

//--接收Fast-CGI響應

4165  recv(17, "\1\6\0\1\0V\2\0X-Powered-By: PHP/5.2.10"..., 65536, 0) = 112

4165  readv(17, [{"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 65424}], 1) = 0

4165  mmap2(NULL, 274432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7514000

4165  close(17)                         = 0

4165  munmap(0xb7514000, 274432)        = 0

//-- 響應用戶端http請求,即http響應

4165  writev(16, [{"HTTP/1.1 200 OK\r\nServer: nginx/0"..., 228}, {"22\r\n", 4}, ..., 5) = 273

4165  write(5, "116.66.34.82 - - [19/Jan/2011:14"..., 191) = 191

4165  setsockopt(16, SOL_TCP, TCP_NODELAY, [1], 4) = 0

4165  recv(16, 0x9b024e8, 32768, 0)     = -1 EAGAIN (Resource temporarily unavailable)

...

通過這些,我們只能夠大概地瞭解，Nginx這裡啟用了epoll。同時，還可以瞭解到Nginx和Fast-CGI底層是如何運作的。奇怪，hello.php檔案中有三個inclue，即載入了三次檔案，這裡沒有看到相應的i/o邏輯操作，是為什麼呢？這是因為，Nginx並沒解析處理PHP指令碼，而是交給Fast-CGI去做這部事情了。

#strace -f -F -o php-cgi-strace /wwwchroot/php/bin/php-cgi --fpm-config /wwwchroot/php/etc/php-fpm.conf

//--接收來自Nginx發出的請求

4510  <... accept resumed> {sa_family=AF_INET, sin_port=htons(35983), sin_addr=inet_addr("127.0.0.1")}, [16]) = 3

4510  clock_gettime(CLOCK_MONOTONIC, {22638545, 869965681}) = 0

4510  poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])

4510  read(3, "\1\1\0\1\0\10\0\0",
   = 8

4510  read(3, "\0\1\0\0\0\0\0\0",
    = 8

4510  read(3, "\1\4\0\1\0035\3\0",
   = 8

4510  read(3, "\21\7GATEWAY_INTERFACECGI/1.1\17\5SERV"..., 824) = 824

4510  read(3, "\1\4\0\1\0\0\0\0",
    = 8

4510  time(NULL)                        = 1295425149

//--載入請求資源檔hello.php

4510  lstat64("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0

4510  lstat64("/var/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0

4510  lstat64("/var/www/ep", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0

4510  lstat64("/var/www/ep/hello.php", {st_mode=S_IFREG|0644, st_size=119, ...}) = 0

4510  clock_gettime(CLOCK_MONOTONIC, {22638545, 870893872}) = 0

4510  setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={60, 0}}, NULL) = 0

4510  rt_sigaction(SIGPROF, {0x835c120, [PROF], SA_RESTART}, {SIG_DFL, [], 0},
= 0

4510  rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL,
= 0

4510  time(NULL)                        = 1295425149

4510  open("/var/www/ep/hello.php", O_RDONLY) = 4

4510  fstat64(4, {st_mode=S_IFREG|0644, st_size=119, ...}) = 0

4510  time(NULL)                        = 1295425149

4510  chdir("/var/www/ep")              = 0

4510  fstat64(4, {st_mode=S_IFREG|0644, st_size=119, ...}) = 0

4510  mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fe7000

4510  read(4, "\n", 8192) = 29

4510  read(4, "", 8192)                 = 0

4510  read(4, "", 8192)                 = 0

4510  close(4)                          = 0

//--  載入hello.inc, 對應php代碼include './hello.inc'

4510  getcwd("/var/www/ep"..., 4096)    = 12

4510  time(NULL)                        = 1295425149

4510  open("/var/www/ep/hello.inc", O_RDONLY) = 4

4510  fstat64(4, {st_mode=S_IFREG|0644, st_size=29, ...}) = 0

4510  read(4, "\n", 8192) = 29

4510  read(4, "", 8192)                 = 0

4510  read(4, "", 8192)                 = 0

4510  close(4)                          = 0

4510  time(NULL)                        = 1295425149

//-- 載入hello.inc, 對應php代碼include DOCUMENT_ROOT . '/hello.inc'

4510  lstat64("/var", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0

4510  lstat64("/var/www", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0

4510  lstat64("/var/www/ep", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0

4510  lstat64("/var/www/ep/hello.inc", {st_mode=S_IFREG|0644, st_size=29, ...}) = 0

4510  open("/var/www/ep/hello.inc", O_RDONLY) = 4

4510  fstat64(4, {st_mode=S_IFREG|0644, st_size=29, ...}) = 0

4510  read(4, "\n", 8192) = 29

4510  read(4, "", 8192)                 = 0

4510  read(4, "", 8192)                 = 0

4510  close(4)                          = 0

//-- 將響結果輸出給Nginx，並且關閉串連

4510  write(3, "\1\6\0\1\0V\2\0X-Powered-By: PHP/5.2.10"..., 96) = 96

4510  setitimer(ITIMER_PROF, {it_interval={0, 0}, it_value={0, 0}}, NULL) = 0

4510  write(3, "\1\3\0\1\0\10\0\0\0\0\0\0\0ere", 16) = 16

4510  shutdown(3, 1 /* send */)         = 0

4510  recv(3, "\1\5\0\1\0\0\0\0", 8, 0) = 8

4510  recv(3, "", 8, 0)                 = 0

4510  close(3)                          = 0

通過跟蹤php-cgi，我們可以知道，相較與其它二種方法include ‘./hello.inc’的效能是最高的。這裡看到strace輸出都被截斷了，如果你需要看到更多的輸出，可以通過-s選項，讓strace輸出更多內容。

當你發現某個http請求造成CPU佔用效驟然升高，你可以通過strace跟蹤尋找問題的根源。同時，你也可以通過strace -c統計監控你的最佳化是否生效

#2. MySQL執行語句列表

當發生個http請求的時候，很多時候希望得到這個http請求發生了多少次資料庫SELECT操作，是否在同一個mysql connection串連裡面完成。這裡以訪問本頁為例子，通過strace來跟蹤這些MySQL SELECT查詢語句。

//-9514是mysqld的進程號,為了看到整條SQL語句,我們通過-s 1024希望輸出更多內容

#strace -f -F -ff -o strace-mysqld -s 1024 -p 9514

#find . -name "strace-mysqld*" -type f -print |xargs grep -n "SELECT.*FROM wp_"

./strace-mysqld.19203:64:

read(19, "\3SELECT option_name, option_value FROM wp_options WHERE autoload = 'yes'", 72) = 72

./strace-mysqld.19203:165:

read(19, "\3SELECT * FROM wp_users WHERE user_login = 'admin'", 50) = 50

./strace-mysqld.19203:184:

read(19, "\3SELECT meta_key, meta_value FROM wp_usermeta WHERE user_id = 1", 63) = 63

./strace-mysqld.19203:295:

read(19, "\3SELECT option_value FROM wp_options WHERE option_name = 'rewrite_rules' LIMIT 1", 80) = 80

./strace-mysqld.19203:311:

read(19, "\3 SELECT   wp_posts.* FROM wp_posts  WHERE 1=1  AND wp_posts.ID = 501

     AND wp_posts.post_type = 'post'  ORDER BY wp_posts.post_date DESC ", 136) = 136

... (這裡省去了一些)

愛J2EE關注Java邁克爾傑克遜視頻站JSON線上工具

http://biancheng.dnbcw.info/php/347704.html pageNo:3