Writing into text file performance problem

tprwrsg10

I'm having a performance problem appending text to a text file on a server. I have 2 scripts, which almost identical, like this:

<?php
$logfile = "D:/tmp/problem.log";
echo $logfile."\n";
$data = "#########@###############";
echo date("Y-m-d H:i:s")."\n";
for($i=0; $i<=1000; $i++)
{
	if($i%100==0) echo "$i ";
	error_log("$recipient\n", 3, $logfile);
}
echo "\n".date("Y-m-d H:i:s")."\n";
?>

Problem.log is a pre-existing 2 MB text file, of about 70K lines. I tried to run that script and it took 4:47 minutes to finish. Which is, too slow considering the hardware spec.

While the other script writes into a new, previously non-existing file. And that took just 9 seconds to finish.

This does not make sense to me, because I thought appending of text into text file shouldn't be affected by the size of the file being appended.

Some other facts:

I tried to write on another 10MB file, and it took just a few seconds longer than writing into non-existing file.
This does not happen to other 2MB file
Tried to run the script to append that problem.log on another computer, which is only a Pentium 4, SATA (no RAID), and took just less than 2 seconds to finish.

I've tried to use fopen, fwrite, and fclose instead of error_log, where the fopen and fclose are outside of the "for" loop, and it actually solves the performance problem. But I'm more interested in knowing what is wrong about the performance of writing that particular 2 MB file.

Anybody can give answer or opinion ?

If you need any other information, let me know and I can find out.

Thank you!

tprwrsg10

FYI, this is the spec of the server which is having the performance issue:

Windows Server 2003 Standard Edition SP 2
Intel Xeon E5540 (2.5 Ghz)
4GB of RAM

SCSI/RAID (Smart Array P410i Controller)
HP LOGICAL VOLUME SCSI Disk Device

IIS 7.0
PHP 5.2

tprwrsg10

So sorry there is a typo... the error_log command should be:

error_log("$data\n", 3, $logfile);

It should be $data and not $recipient.

NogDog

My guess is that you would get better performance by using the fopen() and fwrite(), as I suspect the error_log() call has to open a new file handle each time it's called.

<?php
$logfile = "D:/tmp/problem.log";
echo $logfile . "\n";
$data = "#########@###############";
echo date("Y-m-d H:i:s") . "\n";
$fh = fopen($logfile, 'a') or die("Unable to open '$logfile'");
for ($i = 0; $i <= 1000; $i++) {
   if ($i%100 == 0) echo "$i ";
   fwrite($fh, "$data\n");
}
fclose($fh);
echo "\n" . date("Y-m-d H:i:s") . "\n";
?>

bradgrafelman

You could use something like Process Monitor from the Sysinternals toolkit and compare the use of error_log versus fopen/fwrite/fclose; my suspicions are that NogDog is correct in that error_log does not maintain open file handles until the script has finished (which, to me, sounds wrong... though there must be a reason the PHP developers chose to do it that way).

Weedpacket

I agree that it looks like error_log() would need to go through an entire open-seek-write-close cycle for every line logged; clearly it's the culprit that needs a :glare: if avoiding it and appending to the log manually is quicker.

Two possibilities for altering it occur to me: they're independent and either or both could be implemented.

First is to allow the passing of an array of messages; then the open-seek-close only needs to happen once for the entire group.

Second would be to hold the open file handle in a static variable within the error log; it would probably be necessary to provide a way to pass an instruction to close the logfile to this function, and depending on what locking measures are in place it could get in the way of others.

But both of these approaches do seem a bit redundant: like bradgrafelman says, there must be a reason why the developers chose to do it that way. My guess is that they didn't anticipate someone writing something that deliberately generated a thousand and one error messages.

tprwrsg10

Hi everyone:

Yes I agree error_log is not the best solution. I have tried using fopen and fwrite, where the fopen is outside of the for loop and the result is much faster.

However, in case I have not made myself clear, the mystery is why the issue does not happen to other log files, which is 5x bigger, and also in another computer which is supposed to be much slower. Knowing where the issue lies is quite important to me because based on the real cause, I have to make sure that the issue does not affect other portion of my application.

Is the size of existing log file even relevant ?

Or is it because the problem.log contains too much line break ?

Or is this issue related to the RAID or other hardware ?

NogDog

Purely speculation, but maybe the existing large file with the poor performance is quite fragmented, which might impact the seek time when opening it and then seeking the end of it so that appending can be performed. I'm not sure how to test that, though, other than defragging the disk, if that's possible.

tprwrsg10

NogDog;10948178 wrote:
Purely speculation, but maybe the existing large file with the poor performance is quite fragmented, which might impact the seek time when opening it and then seeking the end of it so that appending can be performed. I'm not sure how to test that, though, other than defragging the disk, if that's possible.

That's a good suggestion. I will try that. Thanks..