Linux System Tools for PHP Debugging

Berlin PHP Usergroup - https://www.bephpug.de - August 2023

Transcript

1. Linux Systems Tools For PHP Debugging and Performance Improvement Volker "Edorian" Dusch BePhpUg August 2023
2. Hi
3. Our story for today
4. Our story for today Your APM tool of choice (or sshing into a server) found a problem.
5. Our story for today Your APM tool of choice (or sshing into a server) found a problem. One of your workers is sometimes running into some sort of busy loop
6. Our story for today Your APM tool of choice (or sshing into a server) found a problem. One of your workers is sometimes running into some sort of busy loop 100% CPU usage, unresponsive PHP process
7. Our story for today Your APM tool of choice (or sshing into a server) found a problem. One of your workers is sometimes running into some sort of busy loop 100% CPU usage, unresponsive PHP process What now?
8. Our story for today Your APM tool of choice (or sshing into a server) found a problem. One of your workers is sometimes running into some sort of busy loop 100% CPU usage, unresponsive PHP process What now? In this process we'll explore tools that can help you along the way.
9. About me
10. About me Nearly 20 years of PHP
11. About me Nearly 20 years of PHP I work on web applications with long life cycles
12. About me Nearly 20 years of PHP I work on web applications with long life cycles Happyly working at @Tideways - But that's not what the talk is about
13. About me Nearly 20 years of PHP I work on web applications with long life cycles Happyly working at @Tideways - But that's not what the talk is about Manager and "Full Stack" Engineer
14. "Full Stack" Nothing is someone elses problem I might not know how it works But I'm sure we can fix it
15. ALERT!
16. Queue entries are not getting processed Let's investigate! ssh toil@one-of-the-servers.example.org kubectl exec -it <pod-name> -- /bin/bash
17. Looking around
18. top top - 21:48:05 up 50 days, 20:32, 1 user, load avg: 3,88, 3,69, 3,60 # ^^ time since last kernel patch - misleading legacy numbers ^^ Tasks: 57 total, 9 running, 48 sleeping, 0 stopped, 0 zombie %Cpu(s): 65,7us, 29,7sy, 0,0ni, 4,5id, 0,0wa, 0,0hi, 0,0si, 0,0st MiB Mem : 4096,0 total, 55,2 free, 1574,9 used, 2465,9 buff/cache MiB Swap: 0,0 total, 0,0 free, 0,0 used. 2508,4 avail Mem # Best case: There is no swap Actually free memory ^^ # Second best case: It's not used PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ CMD 3503292 app 20 0 447144 282988 15948 R 100,0 6,7 938:34.57 php 4103592 app 20 0 199508 129840 30488 R 25,9 3,1 0:53.07 php 4104473 app 20 0 205192 135332 30492 R 20,6 3,2 0:29.13 php 4097714 app 20 0 246388 176176 30400 R 18,3 4,2 3:04.75 php [...] 42 edo 20 0 12764 3516 2900 R 0.0 0.0 0:00.00 top
19. ps ProcesS We see a worker process fully occuping one core. ps faxwu USER PID %CPU %MEM VSZ RSS STAT START TIME COMMAND worker 3503292 87.1 6.7 447144 282988 R 02:15 938:39 \_php [..] // ^^ Process ID 15.6 hours of CPU usage ^^ f full-format a All users x Also processes without a tty w Wide output - See the full command u User-oriented format ("Useful")
20. ss - The new netstat Socket Statistics Our process is in CLOSE-WAIT ?! ss -tnap State Recv-Q Send-Q Local Addr:Port Peer Addr:Port Process ESTAB 0 0 10.4.2.42:47864 10.4.2.38:3306 users:(("p ESTAB 0 0 10.4.2.42:49598 10.4.2.38:3306 users:(("p ESTAB 0 0 10.4.2.42:54508 10.4.2.44:9200 users:(("p ESTAB 0 79 10.4.2.42:43018 10.4.2.45:6379 users:(("p CLOSE-WAIT 1 0 10.4.2.42:33622 10.4.2.35:80 users:(("p -t --tcp -a --all Also show listening sockets -n --numeric Don't resolve host names! -p --proccess Show the process using the socket
21. TCP
23. Diving deeper
24. lsof LiSt Open Files sudo lsof -Pnp 3503292 | grep -v ".so" COMMAND PID FD TYPE NAME php 3503292 cwd DIR / php 3503292 rtd DIR / php 3503292 txt REG /usr/bin/php8.1 php 3503292 mem REG /usr/lib/locale/locale-archive php 3503292 mem REG /usr/lib/locale/C.UTF-8/LC_CTYPE php 3503292 mem REG /usr/lib/x86_64-linux-gnu/gconv/gconv-modules php 3503292 4u unix type=STREAM php 3503292 5u unix type=STREAM php 3503292 9u IPv4 10.4.2.42:33622->10.4.2.35:80 (CLOSE_WAIT) php 3503292 16u unix type=DGRAM -n No hostname resolution -P Print port numbers instead of mappings from `/etc/services` -p Process Id
25. We found something! Why is this http connection waiting to be closed? Rerunning lsof doesn't seem to change anything. Let's see what's going on with strace. lsof -Pnp 3503292 | grep CLOSE_WAIT 10.4.2.42:33622->10.4.2.35:80 (CLOSE_WAIT) lsof -p 3503292 | grep CLOSE_WAIT worker.example.org:33622->service.example.org:http (CLOSE_WAIT)
26. Intro to strace
27. Basic usage strace -fttp Strace lists syscalls, like ltrace lists libraries, and mtrace lists memory -f --follow-forks - Usually doesn't happen in PHP, but just in case -tt --absolute-timestamps=precision:us Readable high precision time -p --attach=pid - Process Id strace php simple-reproduce.php
28. stderred It can be hard to figure out what's strace output and what's programm output. https://github.com/sickill/stderred cat stderred.php
29. Strace by example strace php strace-demo.php
30. Continue investigating It keeps looping the next three lines Let's see what's going on with gdb sudo strace -fttp 3503292 11:25:04.663911 rt_sigaction(SIGPIPE, NULL, {sa_handler=SIG_IGN, sa_m 11:25:04.663974 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[P 11:25:04.664026 rt_sigaction(SIGPIPE, {sa_handler=SIG_IGN, sa_mask=[P
31. Intro to gdb Gnu DeBugger Attack to a running process Demo gdb -p $pid gdb php simple-reproduce.php r run s step bt backtrace
32. Our example process sudo gdb -p 3503292 bt (gdb) bt #0 0x00007f763229e166 in ?? () from /lib/x86_64-linux-gnu/libc.so.6 #1 0x00007f762fc01ea5 in ?? () from /usr/lib/x86_64-linux-gnu/libcur #2 0x00007f762fc02a42 in ?? () from /usr/lib/x86_64-linux-gnu/libcur #3 0x00007f762fbeda5e in curl_share_cleanup () from /usr/lib/x86_64- #4 0x00007f762fc5d1f1 in ?? () from /usr/lib/php/20210902/curl.so #5 0x00005639ac7da6d3 in zend_objects_store_free_object_storage () #6 0x00005639ac7399ca in zend_shutdown_executor_values () #7 0x00005639ac739e43 in ?? () #8 0x00005639ac749d63 in zend_deactivate () #9 0x00005639ac6e5bf6 in php_request_shutdown () #10 0x00005639ac831bb0 in ?? () #11 0x00005639ac588f48 in ?? () #12 0x00007f763227f083 in __libc_start_main () from /lib/x86_64-linux #13 0x00005639ac58971e in _start ()
33. ?? Symbols Symbols tell your debugger which memory address has which name Debian With Ondřej:ppa apt install php8.2-phpdbg deb https://ppa.launchpadcontent.net/ondrej/php/ubuntu/ jammy main # just append "main/debug" apt update apt install php8.2-cli-dbgsym
34. Once again with symbols (gdb) bt #0 0x00007fbfef531166 in __GI___libc_sigaction (sig=sig@entry=13, ac #1 0x00007fbfef531299 in __GI___sigaction (sig=sig@entry=13, act=act #2 0x00007fbfece84f2a in sigpipe_ignore (ig=ig@entry=0x7ffd98161340, #3 0x00007fbfece85a42 in sigpipe_ignore (ig=0x7ffd98161340, data=<op #4 Curl_conncache_close_all_connections (connc=connc@entry=0x55863df #5 0x00007fbfece70a5e in curl_share_cleanup (share=0x55863df2b730) a #6 0x00007fbfed42e1f1 in curl_share_free_obj (object=0x7fbfe91c5ba8) #7 0x000055863c548833 in zend_objects_store_free_object_storage (obj #8 0x000055863c4a7b1a in zend_shutdown_executor_values (fast_shutdow #9 0x000055863c4a7f93 in shutdown_executor () at ./Zend/zend_execute #10 0x000055863c4b7eb3 in zend_deactivate () at ./Zend/zend.c:1271 #11 0x000055863c453c56 in php_request_shutdown (dummy=<optimized out> #12 0x000055863c59fd80 in do_cli (argc=10, argv=0x55863db55150) at ./ #13 0x000055863c2f6f68 in main (argc=10, argv=0x55863db55150) at ./sa
35. A couple searches later Let's try updating curl! https://github.com/curl/curl/commit/c06902713998d6 daf91468c288f8c97776ec9805e160a8a3bcb52e000110 https://github.com/curl/curl/issues/4915 https://github.com/googleapis/google-cloud-cpp/pull
36. Building curl wget https://github.com/curl/curl/releases/download/curl-7_87_0/curl- tar -zxf curl-7_87_0.tar.gz cd curl-7.87.0/ ./buildconf ./configure --with-openssl make # make install ?
37. LD_* We might not want to install a lib system wide LD_LIBRARY_PATH="/home/edo/curl-7.87.0/lib/.libs/" php -r \ 'var_dump(curl_version()["version"]);' string(10) "7.87.0-DEV"
38. Thank you!