當前位置:才華齋>設計>網頁設計>

PHP執行跟蹤工具phptrace介紹2017

網頁設計 閱讀(1.44W)

phptrace 是一個追蹤(trace)PHP執行流程的工具,你如果用過strace的話,則可能很容易想到phptrace到底實現了什麼樣的功能。其實,phptrace是類strace的一個實現,不同的是,strace用來追蹤系統呼叫,而phptrace用來追蹤PHP函式呼叫。無論是開發測試還是線上追查問題,程式碼執行流程往往會提供許多有用的資訊;

PHP執行跟蹤工具phptrace介紹2017

對於系統函式,我們可以用strace來觀察其呼叫資訊,然而PHP卻長久以來缺少這麼一個行之有效的工具,因此我們開發了phptrace。

  phptrace 目前包括兩部分功能:

1. 列印當前PHP呼叫棧。

2. 實時追蹤PHP呼叫。

地址:

  列印當前PHP程序呼叫棧

C程式的呼叫棧,我們通過pstack或gdb可以很容易獲取到。PHP作為一種非編譯型的語言,實際執行在C編寫的PHP虛擬機器之上。當我們用pstack 或 gdb來列印PHP的呼叫棧時,實際是列印的虛擬機器的執行資訊。

比如:

$ pstack 3130

#0 0x00000035ee6accc0 in __nanosleep_nocancel () from /lib64/.6

#1 0x00000035ee6acb50 in sleep () from /lib64/.6

#2 0x0000000000714f23 in zif_sleep ()

#3 0x00000000008e36cd in execute_internal ()

#4 0x00007f27b38b2b77 in phptrace_execute_core () from /home/renyongquan/opt/php5.4.35/lib/php/extensions/debug-non-zts-20100525/

#5 0x00007f27b38b2c04 in phptrace_execute_internal () from /home/renyongquan/opt/php5.4.35/lib/php/extensions/debug-non-zts-20100525/

#6 0x00000000008e44bc in zend_do_fcall_common_helper_SPEC ()

3130 為php-fpm的程序ID,通過pstack我們看到了PHP虛擬機器呼叫棧,然而對於一個PHP開發者來說,更感興趣的是PHP的呼叫棧,你可以通過phptrace獲取:

$ ./phptrace -p 3130 -s

phptrace 0.1 demo, published by infra webcore team

process id = 3130

script_filename = /home/renyongquan/opt/nginx//webapp/

[0x7f27b9a99dc8] sleep /home/renyongquan/opt/nginx/webapp/:6

[0x7f27b9a99d08] say /home/renyongquan/opt/nginx/webapp/:3

[0x7f27b9a99c50] run /home/renyongquan/opt/nginx/webapp/

-p 引數指定程序pid, -s表示我們需要獲取stack資訊; -p引數是必需的`,並且只能是PHP相關程序(php,php-cli,php-fpm)的pid,這很好理解,因為我們獲取的是PHP的呼叫資訊。-s 如果省略,則phptrace不會列印呼叫棧,而是實時獲取PHP函式執行流程,即phptrace的第二個功能,也是其主要功能。現在我們仍然回到stack上來。

程式輸出的第一行,是版本資訊,第二行顯示了其程序PID,第三行是當前執行的PHP指令碼,從第四行開始就是呼叫棧資訊,從列印的資訊可以看出,最外層run函式呼叫了say函式,最終呼叫了sleep函式。這時我們curl訪問以下這個php指令碼,顯然會被堵塞住:

curl http://localhost:8804/

我們知道,在sleep,但是我們卻不知道其到底要sleep多長時間,如果能獲取到sleep的引數,問題便迎刃而解了,這時,就需要用到我們的第二個功能:實施追蹤PHP呼叫。

  實時追蹤PHP呼叫(trace)

trace功能依賴於我們實現的PHP模組,模組作為後端實時獲取PHP呼叫資訊,前端程式phptrace則解析並列印呼叫資訊,因此,在使用這個功能之前需要先安裝phptrace擴充套件。安裝擴充套件後,重啟fpm,並開啟trace。

$ phptrace -p 3130

curl http://localhost:8804/ #重新訪問

phptrace 列印:

1417486170.247324 run(<Null>)

1417486170.247336 say($msg = "hello world")

1417486170.247356 sleep($seconds = "3600")

可以看到-p執行PID後,預設執行的就是trace功能,輸出的第一列為函式呼叫的時間,後面則是呼叫資訊,phptrace按照PHP呼叫順序,依此打出run, say, sleep;此時,我們可以看到sleep的引數為3600s,因此curl請求要在1小時後才能返回。

實際上phptrace還可以列印函式返回值及呼叫耗時,,由於run,say,sleep函式都沒有返回,在上面的例子中無法看到這個效果,我們改一下程式碼,使其sleep 1s :

$ ./phptrace -p 2459

1417506346.727223 run(<Null>)

1417506346.727232 say($msg = "hello world")

1417506346.727241 sleep($seconds = "1")

1417506347.727341 sleep => 0 1.000100

1417506347.727354 say => hello world 1.000122

1417506347.727358 run => nil 1.000135

輸出的前三行跟上面的例子相同,仍然是PHP函式的呼叫資訊,後三行則表明了對應函式的返回值以及呼叫耗時:sleep 返回0 ,耗時1.000100s, say 返回 "hello world",耗時1.000122s,之所以這麼長時間,是因為其呼叫了sleep函式,同樣run 返回nil,及沒有返回值,耗時1.000135s。