顺风车运营研发团队 黄桃
现象
在线上脚本机器写入单条日志过长时会出现交叉打印的现象:
被交叉的日志很有规律, 都是单条日志过长被截断的, 建议优化下 /*/ruleanalysis.php:68 此处写入日志的字符串长度为: int(25909)
原因分析
脚本服务写入日志代码如下:
- if ($this->isCli == true) {
- return file_put_contents($messageLogFile, $strLogMsg, FILE_APPEND);
- // 在调用 file_put_contents 方法写入, 为什么在写入超长字符串是交叉写呢?
- // 跟进下 file_put_contents 函数的实现?
- }
查看 file_put_contents 的源码实现, 最终写文件会执行到_php_stream_write_buffer 函数, 里面有这样一处代码:
明确几个变量的含义:
count: 需写入文件的字符串长度
stream->chunk_size : 默认为 8192 (8k)
从上面代码可以看出, 当写入的字符串长度 大于 8192 时, 则拆为多次 <=8192 的字符串, 然后调用 php_stdiop_write 函数写入文件, php_stdiop_write 函数实现如下:
- static size_t php_stdiop_write(php_stream *stream, const char *buf, size_t count)
- {
- php_stdio_stream_data *data = (php_stdio_stream_data*)stream->abstract;
- assert(data != NULL);
- if (data->fd>= 0) {
- #ifdef PHP_WIN32
- int bytes_written;
- if (ZEND_SIZE_T_UINT_OVFL(count)) {
- count = UINT_MAX;
- }
- bytes_written = _write(data->fd, buf, (unsigned int)count);
- #else
- int bytes_written = write(data->fd, buf, count);
- #endif
- if (bytes_written <0) return 0;
- return (size_t) bytes_written;
- } else {
- #if HAVE_FLUSHIO
- if (!data->is_pipe && data->last_op == 'r') {
- zend_fseek(data->file, 0, SEEK_CUR);
- }
- data->last_op = 'w';
- #endif
- return fwrite(buf, 1, count, data->file);
- }
- }
php_stdiop_write 则调用的 write 函数 写入文件; write 函数是能保证一次写入的完整的.
所以日志写串的原因也就能分析出来了, 调用链接为: file_put_contents ->_php_stream_write_buffer ->php_stdiop_write(多次调用, 每次最多写入 8192 字节) ->write(), 是在 多次调用 php_stdiop_write 函数时出的问题; 第一次写完, 紧接着在高并发的情况下, 被其他进程的 write 函数追着写, 此时就出现写串, 也就是前面示例中日志;
为了证实此观点, 我对报错的代码 /**/ruleanalysis.php:68 写了如下伪代码:
public function run()
{
$this->mysqlConnect();
$sql = "select * from *** where ***=1";
$pidRet = $this->db->run($sql);
Utils\Logger::notice('tiger_project_info:'.json_encode($pidRet));
die;
}
vim ~/*****/logger.php
- if ($this->isCli == true) {
- var_dump(substr($strLogMsg ,16084 ,400 )); // 在字符串的 8192 倍数的位置打出附近的字符串 16384 = 8192 * 2
- return file_put_contents($messageLogFile, $strLogMsg, FILE_APPEND);
- }
执行代码看打串日志的地方是否为 8192 倍数的位置, 结果如下:
截断的位置非常接近 8192 的倍数值; 但因为定位时间不是当时的时间点, 期间数据库存在部分改动, 所以出现偏移, 那么也能验证我们之前的猜想, 正是 file_put_contents 多次调用 write 函数的时候出现交叉打印.
问题解决:
1, 修改打日志处代码, 这么巨大的日志写入文件是否合理?
2, 需要写入巨大日志又不希望不被交叉打印, 加上 LOCK_EX 标识;
file_put_contents 函数相关的知识点问答
1,file_put_contents(filename,msg ,FILE_APPEND ) 末尾追加实现?
FILE_APPEND 文件追加的形式, 这个是怎么实现的呢?
先标识 mode[0] ='a'
紧接着转换成: O_CREAT|O_APPEND
调用 open 函数 ,fd = open(realpath, open_flags, 0666);
通过 C 底层函数保证, 写入默认追加写;
2,file_put_contents(filename,msg ,FILE_APPEND|LOCK_EX ) 中的 LOCK_EX 实现? 作用?
file_put_contents 在调用_php_stream_write_buffer 前加一个锁 php_stream_supports_lock(stream) ->flock()
得到文件锁定后 调用_php_stream_write_buffer-> 多次 write();
写完后释放文件锁
php_stream_close(stream)->close(data->fd); // 直接关闭
总结: LOCK_EX 保证了一个巨大字符串的完整, 不会被写串;
3, 多进程, file_put_contents() 数据覆盖吗?
write 调用路径: file_put_contents ->_php_stream_write_buffer ->php_stdiop_write(多次调用, 每次最多写入 8192 字节) ->write()
file_put_contents($messageLogFile, $strLogMsg, FILE_APPEND);
write 函数在 O_APPEND 模式下, 偏移到文件末尾与写文件是原子性的, 不存在被覆盖的情况;
4, 以 O_APPEND 方式打开文件, 然后使用 lseek, 定位到文件首部, 然后调用 write 会怎样? 是写在文件结尾吗?
还是写在文件尾部, 参考文章: https://blog.csdn.net/dog250/article/details/29185821
write 函数代码如下:
- +static inline loff_t file_pos_read_lock(struct file *file)
- {
- + if (file->f_mode & FMODE_LSEEK)
- + mutex_lock(&file->f_pos_lock);
- return file->f_pos;
- }
- +static inline void file_pos_write_unlock(struct file *file, loff_t pos)
- {
- file->f_pos = pos;
- + if (file->f_mode & FMODE_LSEEK)
- + mutex_unlock(&file->f_pos_lock);
- }
修改 sys_write 系统调用:
- file = fget_light(fd, &fput_needed);
- if (file) {
- - loff_t pos = file_pos_read(file);
- + loff_t pos = file_pos_read_lock(file);
- ret = vfs_write(file, buf, count, &pos);
- - file_pos_write(file, pos);
- + file_pos_write_unlock(file, pos);
- fput_light(file, fput_needed);
- }
5, 进程内多次 file_put_contents,open 和 close 只有一次还是多次?
open 调用路径: file_put_contents->php_stream_open_wrapper_ex->php_plain_files_stream_opener->php_stream_fopen_rel->fd = open(realpath, open_flags, 0666);
close 调用路径: file_put_contents->php_stream_close->php_stdiop_close->ret = close(data->fd);
每次都会执行 open 和 close
来源: https://segmentfault.com/a/1190000015356209