Posts tagged ‘file_put_contents’

记录log,对于很多人而言是很简单或者低级的事情。但是,随着项目经验的增长,遇到生产环境中bug数的增多,至少对于我来说,日志的重要性日益增加。

这次,需要对项目中log类进行重构,主要希望实现4个目的:

  1. 建立日志监控机制,第一时间发现问题
  2. 协助定位问题,帮助快速解决问题
  3. 记录用户行为,协助解答客户疑问
  4. 记录用户行为,协助制定安全与个性化等策略

除了这些功能性的目的,由于log类在一次请求中的调用频率相对较高,且与基本业务无关,如果性能方面有问题的话,就太本末颠倒了,所以先从性能说起。

log一般记录在文件里,所以其本质上是写文件,使用php作为开发语言的话,主要考虑了3个方面:

  1. 选择fwrite还是file_put_contents?
  2. 是否使用debug_backtrace函数获取文件名和行号?
  3. 怎样保证并发写的原子性?

选择fwrite还是file_put_contents?

php有多种写文件的函数,fwrite需要先fopen获取到文件句柄,而file_put_contents直接使用文件名即可,且传入的data参数可以是字符串,也可以是数组,甚至stream,使用较简单。

zend框架的Zend_Log_Writer_Stream类,使用的是fwrite函数;而公司内部多个team的log封装都使用了file_put_contents函数。首先考虑,我们的log类,给谁用?内部使用,暂时没考虑开源。传入的参数,是否需要支持string,array or stream?记录log而已,支持string即可,而且log的基本样式是每次记录一行。所以,比较两者在写入多行数据之间的性能区别即可:

$str = "abc\n";
$n = 10000;
$filename = 'test_write.txt';

$start_time = mytime();
write_with_open($filename, $str, $n);
$used_time = mytime() - $start_time;
printf("%20s%s\n","fwrite","Time used: $used_time ");

$start_time = mytime();
write_without_open($filename, $str, $n);
$used_time = mytime() - $start_time;
printf("%20s%s\n","file_put_contents","Time used: $used_time ");

$start_time = mytime();
write_with_errorlog($filename, $str, $n);
$used_time = mytime() - $start_time;
printf("%20s%s\n","error_log","Time used: $used_time ");

function write_with_open($filename, $str, $n){
        $fp = fopen($filename, 'a') or die("can't open $filename for write");

        while($n--){
                fwrite($fp, $str);
        }

        fclose($fp);
}

function write_without_open($filename, $str, $n){
        while($n--){
                file_put_contents($filename, $str, FILE_APPEND);
        }
}

function write_with_errorlog($filename, $str, $n){
        while($n--){
                error_log($str, 3, $filename);
        }
}

执行该测试脚本的结果是:

fwriteTime used: 0.018175840377808
file_put_contentsTime used: 0.22816514968872
error_logTime used: 0.2338011264801

可见fwrite的性能要远远大于另外两者,直观上看,fwrite仅关注于写,而文件句柄的获取仅由fopen做一次,关闭操作也尽有一次。如果修改write_with_open函数,把fopen和fclose函数放置到while循环里,则3者的性能基本持平。

以上结论,也可以通过查看PHP源代码得知,fwrite和file_put_contents的源码都在php-5.3.10/ext/standard/file.c里,file_put_contents不但逻辑较为负载,还牵涉到open/锁/close操作,对于只做一次写操作的请求来说,file_put_contents可能较适合,因为其减少了函数调用,使用起来较为方便。而对于log操作来说,fwrite从性能角度来说,较为适合。

2012-06-22补充:

以上只是单纯从“速度”角度考虑,但是在web的生产环境里,如果并发数很高,导致系统的open files数目成为瓶颈的话,情况就不同了!fwrite胜在多次写操作只用打开一次文件,持有file handler的时间较长;而file_put_contents每次都在需要的时候打开文件,写完就立即关闭,持有file handler的时间较短。如果open files的值已无法调高,那么使用file_put_contents在这种情况下,就会是另外一种选择了。

是否使用debug_backtrace函数获取文件名和行号?

在gcc,标准php出错信息里,都会给出出错的文件名和行号,我们也希望在log里加上这两个信息,那么是否使用debug_backstrace函数呢?

class A1{
        public static $_use_debug=true;
        function run(){
                # without debug_backtrace
                if (!self::$_use_debug){
                        #echo "Quit\n";
                        return;
                }

                # with debug_backtrace
                $trace = debug_backtrace();
                $depth = count($trace) - 1;
                if ($depth > 1)
                        $depth = 1;
                $_file = $trace[$depth]['file'];
                $_line = $trace[$depth]['line'];

                #echo "file: $_file, line: $_line\n";
        }
}

class A2{
        function run(){
                $obj = new A1();
                $obj->run();
        }
}

class A3{
        function run(){
                $obj = new A2();
                $obj->run();
        }
}
class A4{
        function run(){
                $obj = new A3();
                $obj->run();
        }
}
class A5{
        function run(){
                $obj = new A4();
                $obj->run();
        }
}
class A6{
        function run(){
                $obj = new A5();
                $obj->run();
        }
}

$n = 1000;
$start_time = mytime();
A1::$_use_debug = true;
$obj = new A6();
while($n--){
        $obj->run();
}
$used_time = mytime() - $start_time;
printf("%30s:%s\n", "With Debug Time used", $used_time);

$n = 1000;
$start_time = mytime();
A1::$_use_debug = false;
$obj = new A6();
while($n--){
        $obj->run();
}
$used_time = mytime() - $start_time;
printf("%30s:%s\n", "Without Debug Time used", $used_time);

function mytime(){
        list($utime, $time) = explode(' ', microtime());
        return $time+$utime;
}

运行的结果是:

flykobe@desktop test $ php test_debug_trace.php
With Debug Time used:0.005681037902832
Without Debug Time used:0.0021991729736328

但是若多次运行,少数情况下,with debug版本甚至与快于without版本。综合考虑,还是决定不用debug_backtrace,而由调用者传入__FILE__和__LINE__值。

怎样保证并发写的原子性?

写文件时,大致有这3种情况:

  1. 一次写一行,中间被插入其他内容
  2. 一次写多行,行与行之间被插入其他内容
  3. 多次写多行,行与行之间被插入其他内容

对于web访问这种高并发的写日志而言,一条日志一般就是一行,中间绝不允许被截断,覆盖或插入其他数据。但行与行之间,是否被插入其他内容,并不care。既然之前是决定采用fwrite,php手册上说的很清楚:

If handle was fopen()ed in append mode, fwrite()s are atomic (unless the size of string exceeds the filesystem’s block size, on some platforms, and as long as the file is on a local filesystem). That is, there is no need to flock() a resource before callingfwrite(); all of the data will be written without interruption.

即当fwrite使用的handler是由fopen在append模式下打开时,其写操作是原子性的。不过也有例外,如果一次写操作的长度超过了文件系统的块大小,或者使用到NFS之类的非local存储时,则可能出问题。其中文件系统的块大小(在我的centos5虚拟机上是4096 bytes)可以通过以下命令查看:

sudo /sbin/tune2fs -l /dev/mapper/VolGroup00-LogVol00 | grep -i block

这同样可以通过模拟多种不同情况的fwrite操作来验证,由于比较简单不再赘述代码。

————————-

2012-07-03添加

《unix环境高级编程》里说:Unix系统提供了一种方法使这种操作成为原子操作,即打开文件时,设置O_APPEND操作,就使内核每次对这种文件进行读写之前,都将进程的当前偏移量设置到该文件的尾端处。

而php手册中,指的某些platform应该不包含*nix实现。故可认为,在我们的环境下,php的fwrite函数是原子性的。

在以上几种比较的基础上,初步完成了我们的Log类封装,进行了千行和万行级别的log写入测试,性能提高了3倍,但应该仍然有优化余地。