Speeding up the PHP log in your web project

We’ve recently been working on a framework developed by the Emagister team and, as you’d expect, although it shares quite a few features with our own framework, Creamture, there are other things that work differently and where we weren’t getting optimal performance.

One of these is error logging, which is done using a database table. Writing a log to a database is pretty slow compared with writing straight to a file on disk, although it does keep some of the expected advantages, such as being able to build a log viewer on top of SQL queries: you can read only the entries you need, sorted by date and paginated, without having to dump the whole log file, which could be huge. And even though writing to a database is much slower than writing to a file, the impact isn’t that big because only errors or exceptions end up in the log.

CodeIgniter, and Creamture, create one plain-text log file per day, which keeps files from growing too much. But since we use the log not only to dump serious errors but also as a journal for any kind of information we developers want to see, we can end up with daily files of several megabytes.

I recently improved the log viewer we had in Creamture, which can display log files from CI 1.7 up to CI 2.2 (Creamture). It has a mode to watch the current log in real time by doing partial reads of the file on disk. You can download it from this GIST.

The thing is, while thinking about how to improve it, this afternoon I set out to run a small test using a base CodeIgniter 1.7 install. It occurred to me that it might be more practical to use a storage system that’s better organised than a file, but still faster than a database.

The impact of normal logging on a controller

We enable only error logging, not debug or info, to minimise the impact (CodeIgniter writes debug log entries when going through almost any library), and we create a controller with a very, very simple method:

function index()
{
    echo 'OK';
}

To test the normal behaviour of our system we’ll use a small Node.js program called webstress-tool, which lets us fire concurrent requests and get their average. We’ll generate 10 batches of 50 concurrent requests each, with 1 second between batches.

$ webstress GET http://www.ci17.com 10 50
about to send 500 GET requests to url http://www.ci17.com over 10 seconds
done, took total over: 12034, avg response time: 240.68
done, took total over: 8849, avg response time: 176.98
done, took total over: 7800, avg response time: 156
done, took total over: 7804, avg response time: 156.08
done, took total over: 7686, avg response time: 153.72
done, took total over: 7636, avg response time: 152.72
done, took total over: 7701, avg response time: 154.02
done, took total over: 7713, avg response time: 154.26
done, took total over: 7171, avg response time: 143.42
done, took total over: 7073, avg response time: 141.46

Then I modified our little method to add a call to log_message: log_message('ERROR', 'Hola mundo!');. Testing again, we can see how logging affects the average response time:

$ webstress GET http://www.ci17.com 10 50
about to send 500 GET requests to url http://www.ci17.com over 10 seconds
done, took total over: 15360, avg response time: 307.2
done, took total over: 10872, avg response time: 217.44
done, took total over: 11044, avg response time: 220.88
done, took total over: 11931, avg response time: 238.62
done, took total over: 11037, avg response time: 220.74
done, took total over: 10955, avg response time: 219.1
done, took total over: 11189, avg response time: 223.78
done, took total over: 12869, avg response time: 257.38
done, took total over: 11121, avg response time: 222.42
done, took total over: 11744, avg response time: 234.88

We can see that a single log call has a significant impact, even though the call itself is simple. So we can’t ignore the fact that, even with plain-text files, the impact is considerable.

Trying SQLite

The idea is to create one SQLite file per day and store the same information as the log files. To do that we write an alternative log_message method that opens an SQLite database named after the current date. We always try to insert first; if it fails, we create the table, since the error will be because the table doesn’t exist yet. That’s faster than checking whether the table exists every time.

The result is discouraging:

$ webstress GET http://www.ci17.com 10 50
about to send 500 GET requests to url http://www.ci17.com over 10 seconds
done, took total over: 30964, avg response time: 619.28
done, took total over: 27871, avg response time: 557.42
done, took total over: 30341, avg response time: 606.82
done, took total over: 28935, avg response time: 578.7
done, took total over: 24958, avg response time: 499.16
done, took total over: 27928, avg response time: 558.56
done, took total over: 21769, avg response time: 435.38
done, took total over: 23220, avg response time: 464.4
done, took total over: 26227, avg response time: 524.54
done, took total over: 25003, avg response time: 500.06

It would indeed be possible to read the log with a viewer using SQL queries, but the penalty for inserting a single entry is far too high.

Using Redis to store the log

Having read about how fast NoSQL key-value stores are, we tried Redis, which is very, very simple to use, and there’s a well-tested library for PHP.

So we downloaded a build of Redis for Windows (there are versions for any Unix and OS X, plus a Windows build that takes up a little under 2 MB).

The new method we wrote is very simple:

function log_message2($level = 'error', $message, $php_error = FALSE)
{
    $redis = new Redis();
    $redis->connect('127.0.0.1', 6379);
    $redis->lpush('ci17-'.(date('Y-M-d')), (date('Y-M-d H:i:s')).' - '.$level.' --> '.$message);
}

The result is so good that the impact compared with the no-log version is minimal, and on top of that we can quickly retrieve the entries sorted by date, with pagination. We can see that Redis really is very useful if we want to keep a journal for high-traffic web projects.

$ webstress GET http://www.ci17.com 10 50
about to send 500 GET requests to url http://www.ci17.com over 10 seconds
done, took total over: 10579, avg response time: 211.58
done, took total over: 8524, avg response time: 170.48
done, took total over: 8419, avg response time: 168.38
done, took total over: 8616, avg response time: 172.32
done, took total over: 8254, avg response time: 165.08
done, took total over: 8351, avg response time: 167.02
done, took total over: 8383, avg response time: 167.66
done, took total over: 8320, avg response time: 166.4
done, took total over: 8017, avg response time: 160.34
done, took total over: 7932, avg response time: 158.64

Next up: updating our framework and the log viewer to use Redis, with a fallback to files if no running Redis server is detected.