Using Strace to Identify Slow Website

There are quite a few times where troubleshooting slow page load times can well…be troublesome. Now this doesnt work every time and unless you are very well tuned to all the system calls of strace (If so, why are you reading this?), it may not even be useful. However, this command has completely solved my issue on a number of occasions:

strace -t -f -o strace.txt /usr/bin/php index.php

If you open strace .txt, on the left hand side you will see a time field. If you open strace.txt file using less or your favorite file editor, you will notice 3+ columns:

12521 13:59:33 open("/opt/curlssl//lib64/libstdc++.so.6", O_RDONLY) = -1 ENOENT (No such file or directory)

The first column is the PID of the actual PHP command, the second is the time at which it ran and the third and fourth are the system calls and potential errors such as a file not being found in this case. If you see page just spin and spin and spin, check the time and see if there is one command that is slowing down everything. I made a little test to demonstrate this. Take a look at the following PHP script:

<?php
$fp = fsockopen("www.example.com", 8080, $errno, $errstr, 30);
if (!$fp) {
    echo "$errstr ($errno)<br />\n";
} else {
    $out = "GET / HTTP/1.1\r\n";
    $out .= "Host: www.example.com\r\n";
    $out .= "Connection: Close\r\n\r\n";
    fwrite($fp, $out);
    while (!feof($fp)) {
        echo fgets($fp, 128);
    }
    fclose($fp);
}
?>

This script will try and hit http://example.com and make sure it can connect to port 8080. Now this port is closed so it will fail and timeout. The timeout is whats going to get us here. The script cant complete and move past this time unless the script times out or the remote server send us something. Lets take a look at the strace:

24281 16:05:50 fcntl(3, F_GETFL)        = 0x2 (flags O_RDWR)
24281 16:05:50 fcntl(3, F_SETFL, O_RDWR|O_NONBLOCK) = 0
24281 16:05:50 connect(3, {sa_family=AF_INET, sin_port=htons(8080), sin_addr=inet_addr("192.0.43.10")}, 16) = -1 EINPROGRESS (Operation now in progress)
24281 16:05:50 poll([{fd=3, events=POLLIN|POLLOUT|POLLERR|POLLHUP}], 1, 30000) = 0 (Timeout)
24281 16:06:20 fcntl(3, F_SETFL, O_RDWR) = 0
24281 16:06:20 close(3)                 = 0

If you look soley in thesecond column, you will see a big jump in time of 30 seconds for this one command. Taking a closer look at the commands themselves you can see sin_addr=inet_addr(“192.0.43.10”) and the port sin_port=htons(8080) seem to be the likely culprit. From there you can find out if the port is open in your firewall or theires and if all else fails using a clever hack to work around it!