This is not too easy. At Log4PHP we have exactly that problem right now. Somebody is using the FileAppender and figured out, that one Apache process was waiting looong time before it could write. Reason: the logger locked the Logfile for the whole time of the request. If you have lots of requests, you can think what it means. Performance is past, in the case.

Time for me to think about the different options to write to log files.

I figured out, that I have to compare the following options:

1) Not closing the file while the whole request is running. This is not an option in a live system, but will give me a good idea whats currently the case

$fp = fopen($file, 'a+');
while($count < $loop) {
   fwrite($fp, $text);
}
fclose($fp);

2) Closing the file directly after fwrite is called

while($count < $loop) {
   $fp = fopen($file, 'a+');
   fwrite($fp, $text);
   fclose($fp);
}

3) Use file_put_contents, which is known as an alias to fopen, fwrite and fclose

while($count < $loop) {
   file_put_contents($file, $text, FILE_APPEND);
}

4) Leave the file open while the whole request, but unlock it with flock and flock it again, when the next log event occurs

$fp = fopen($file, 'a+');
flock($fp, LOCK_UN);
while($count < $loop) {
   if (flock($fp, LOCK_EX)) {
      fwrite($fp, $text);
   }
   flock($fp, LOCK_UN);
}
fclose($fp);

5) Use a nonblocking stream for this and flock

$fp = fopen($file, 'a+');
stream_set_blocking($fp, 0);

while($count < $loop) {
   if (flock($fp, LOCK_EX)) {
       fwrite($fp, $text);
   }
   flock($fp, LOCK_UN);
}
fclose($fp);

6) Use the error_log method, which my friend Kevin Horst brought up

while($count < $loop) {
   error_log($text, 3, $file);
}

For each of this options I wrote a simple function which wrote 10000 times 100 characters in  a freshly created log file. I measured before opening and after closing. Additionally I tried out with 2 seperated threads if the write access is nonblocking. Good thing is, option 2 to 6 are actually nonblocking. And here are the timing results:

1) Execution with NOT closing the log file took 0.0668561458588 seconds
2) Execution with CLOSING the log after each write file took 30.1630220413 seconds
3) Execution with file_put_content took 30.153963089 seconds
4) Execution with leaving the file open, but LOCKING and UNLOCKING it took 0.148998975754 seconds
5) Execution with nonblocking stream took 0.149605989456 seconds
6) Execution with the error_log method took 30.069578886 seconds

Let’s see what it means.

Not closing the file until the 10000 fwrite calls are handled as actually the fastest. No surprise. It just took 0.0668 seconds but this one is not really an option, cause other threads have to wait until this request has been finished.

If you close the file after each fwrite and make it available to other threads and then reopen it, is hell. For 10000 calls of this kind I needed 30 seconds! It’s insane to have this in a productive system. The same goes with file_put_contents. Well, I allready knew (its in the php docs) that this method is nothing else then a wrapper for fopen, fwrite and fclose. Times are so similar that I say it’s exactly the same. Sometimes the one is some millis faster, sometimes the other.

If you open the file, unlock it with flock and flock it again it works very well. Just 0.14 ms for the 10000 fwrite calls. Thats the double amount of option 1, but yeah, here we do some more stuff. The interpreter cares about who is allowed to write, together with the OS. flock works that way, that a call to this function blocks until the requestor gets the actual lock. You can be sure that only one thread is actually writing.

Same goes to the nonblocking stream. This works with stream_set_blocking($fp, 0);. The file stream is nonblocking, means each thread could write at it the same time. That no mess happens, we need an flock here too. That brings us to the nearly same results as fopen, flock, fwrite, flock, fclose option above. But looking at the logfiles of this one and option 4, this one looks more nice to me. This is just subjective, but it looks like the lock is shared more nicely between both threads.

Last one is the error_log method. It didn’t had any idea what to expect, but… 30 seconds! This one behaviours like a wrapper for fopen, fwrite and fclose, like file_put_content. No guys, this is not really a method enabled for logging! If one would use this in a framework like Log4PHP, that would be hell to performance. I would think that this should better removed out. The name suggests a good logging method, but this is not the case.

Having that all said, Log4PHP will get the lock and unlock option number 4. I feel good with it, since it’s quite straightforward. I don’t have too much expierence with the non blocking stream and don’t want to have this in a framework like log4php is.

However, Logging must be used carefully at all. I thnk on a system with 10000 request a second. Enabling logging into one file could bring the system down. I think a live system should have the option to log exactly one request. Maybe triggered by an url param. Think carefully what you log and how you configure your live system.

The complete script can be found here.

Tags: Apache Log4PHP, PHP

This entry was posted on Friday, August 21st, 2009 at 6:21 pm and is filed under Apache Log4PHP, Open Source, Software Development. You can follow any responses to this entry through the RSS 2.0 feed. You can leave a response, or trackback from your own site.