How to : strace php process via apache

This little adventure started today when a customer was complaining of having a slow website (8 seconds plus to serve the home page without any additional resources) for the past 10 days or so. No file modification or change dates matched this timeframe. Also, a scan using clam and another proprietary scanner showed up nothing, so for the time being I continued under the assumption that there was a bug in the site somewhere.

It’s possible to attach strace to a php file directly by running it from the command line like this

Where username is the account that owns the php file, and HTTP_HOST is the virtual host’s fully qualified domain name, REQUEST_URI is the URI that would result in the php file being hit by apache.

So, I ran this, and it completed in well under a second, serving the correct page content. Accessing the site using curl from the command line, however, took 8 seconds.

So, without trying to figure out every last environment variable that the script would encounter while being accessed via apache, I figured the most accurate picture would be obtained by actually accessing the script via apache! This presents a particular problem in that we have no way of knowing the process ID of the apache thread that will handle the request ahead of making it.

The technique I used required two steps. Oh, and it requires PHP to be running under SuExec – meaning that PHP scripts are run under the account owner’s username, and not the anonymous apache account (usually nobody or httpd). It also helps if you can restrict access to the site to just your IP address, at least while you do this test, as it will take the guesswork out of which PHP processes were those initiated by your test requests.

Step 1 – Strace php process via apache to log files

It should be said that this will place quite an overhead on your CPU and I/O so keep an eye on things using top and/or iotop. Open a terminal window and run the command

This will show all of the apache processes. The parent process ID (PPID) of the main apache process will be the number that appears in the leftmost column for all of the httpd listeners – in the sample output below the apache PPID is 229443 – the last line shows the main apache process itself, whose own parent is PID 1 – init.

So, to start tracing apache’s processes, run this command

It will take a little time for strace to start attaching to new apache processes, so I usually wait until it’s filled my screen with output before initiating the next step. Each process strace attached to will be straced to a file called stracelog.[PID] and will be dumped into the current working directory. There will be a lot of them, but let them build up for now.

Step 2 – Record all PHP processes initiated for the user

Open a terminal window and run the command

This is just a rough and ready way to echo to screen the process IDs of any PHP files it detects running for the user. It might miss a PHP process that runs only very briefly, but it’s fine for catching anything that takes longer than a few hundred milliseconds. Just leave it filling up the screen.

Step 3 – Open that problem URL

Now open the problem URL using either curl from another terminal window, or using a web browser. Once the page has loaded, you can Ctrl-C out of the processes running in Step 1 and Step 2 above. Phew! Now we can look for clues.

Step 4 – Analysis

Look at the terminal screen from Step 2, and make a note of the process ID that was recorded WHEN you loaded the problem URL. In the directory where you ran the strace command from, you will find dozens or hundreds of strace log files named stracelog.[PID]. Just open the log file for the PID you logged in Step 2.

Understanding an strace log file is another matter entirely, but at least now you have the data to analyse. Each row (system call) is time stamped so you will very quickly be able to see where time was ticking by and not much was going on.

In my case, I found an unexpected socket connection to a Chinese IP address which led me to finding some injected code in the website’s WordPress theme.

Happy bug hunting!

, ,

No comments yet.

Leave a Reply

Time limit is exhausted. Please reload CAPTCHA.