记录log,对于很多人而言是很简单或者低级的事情。但是,随着项目经验的增长,遇到生产环境中bug数的增多,至少对于我来说,日志的重要性日益增加。
这次,需要对项目中log类进行重构,主要希望实现4个目的:
- 建立日志监控机制,第一时间发现问题
- 协助定位问题,帮助快速解决问题
- 记录用户行为,协助解答客户疑问
- 记录用户行为,协助制定安全与个性化等策略
除了这些功能性的目的,由于log类在一次请求中的调用频率相对较高,且与基本业务无关,如果性能方面有问题的话,就太本末颠倒了,所以先从性能说起。
log一般记录在文件里,所以其本质上是写文件,使用php作为开发语言的话,主要考虑了3个方面:
- 选择fwrite还是file_put_contents?
- 是否使用debug_backtrace函数获取文件名和行号?
- 怎样保证并发写的原子性?
选择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_backtraceif (!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种情况:
- 一次写一行,中间被插入其他内容
- 一次写多行,行与行之间被插入其他内容
- 多次写多行,行与行之间被插入其他内容
对于web访问这种高并发的写日志而言,一条日志一般就是一行,中间绝不允许被截断,覆盖或插入其他数据。但行与行之间,是否被插入其他内容,并不care。既然之前是决定采用fwrite,php手册上说的很清楚:
If
handle
was fopen()ed in append mode, fwrite()s are atomic (unless the size ofstring
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倍,但应该仍然有优化余地。