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) = 8 4510 read(3, "\0\1\0\0\0\0\0\0", 8) = 8 4510 read(3, "\1\4\0\1\0035\3\0", 8) = 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) = 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}, 8) = 0 4510 rt_sigprocmask(SIG_UNBLOCK, [PROF], NULL, 8) = 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 ) = 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
當你發現某個http請求造成CPU占用效驟然升高,你可以通過strace跟蹤查找問題的根源。同時,你也可以通過strace -c統計監控你的優化是否生效
//-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 ", 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 ... (這裡省去了一些)