专栏首页PHP饭米粒【PHP问题定位】线上机器打日志混乱问题定位分析

【PHP问题定位】线上机器打日志混乱问题定位分析

"每个小问题,都值得深入!!"

现象

在线上脚本机器写入单条日志过长时会出现交叉打印的现象:

被交叉的日志很有规律,都是单条日志过长被截断的,建议优化下 /*/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/...

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

----------伟大的分割线-----------

本文分享自微信公众号 - PHP饭米粒(phpfamily),作者:黄桃

原文出处及转载信息见文内详细说明,如有侵权,请联系 yunjia_community@tencent.com 删除。

原始发表时间:2019-04-04

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

我来说两句

0 条评论
登录 后参与评论

相关文章

  • 一次PHP Hive客户端协议问题分析

    由于项目需要使用hive client,我们就找了hive的php版本的client,首先看一段网上找的demo

    桶哥
  • Swoft 2 Beta 发布,基于 Swoole 的云原生协程框架

    Swoft 是首个基于 Swoole 原生协程的框架,从开发到发布据今已有2年多。

    桶哥
  • swoole 协程知识点小结

    swoole 一直保持着 颇为快速 的迭代速度, 快到什么程度呢 -- 「快别更新了, 学不动了」

    桶哥
  • 两个非常棒的 Laravel 权限管理包推荐

    overtrue
  • 看一下小程序中接入广告的具体步骤

    昨天,很多小程序开发者都收到了“流量主测试邀请”。连胜老师也就尝试了给自家小程序添加广告。 之前有不少小程序开发者,都尝试过在小程序中变现,红包类小程序可以说最...

    连胜
  • tf.gather

    根据索引从params坐标轴中收集切片。标必须是任何维度(通常是0-D或1-D)的整数张量。产生一个带有形状参数的输出张量,其中: params.shape[...

    于小勇
  • jQuery实现本地input选择图片实时显示

    在写图片上传功能时,如果可以实时预览就好了,我们可以通过 jQuery 实现这一效果。

    德顺
  • pytest+yaml实现接口自动化

    最近在学pytest的使用,不同于httprunner自动化测试框架,创建项目的时候就能把所有的项目文件目录整理出来,需要手动创建文件分类,不管怎么样,先学会用...

    小雯子打豆豆
  • httprunner学习5-参数化与数据驱动

    参数化是自动化测试离不开的话题,httprunner里面只要把上一篇声明变量学会了,参数化也就自然会了。 不同的地方在于声明变量时对应值只有一个,参数化是多个值...

    上海-悠悠
  • go结构体中的匿名变量在json.marshal中隐藏的坑

    在昨天的工作中,遇到一个诡异的小问题,调试了一段时间,在网上也没有找到相关材料(可能谷歌能力有限,搜索不到,要用百度)。先来看一段简单的简化后的代码,...

    谢盼

扫码关注云+社区

领取腾讯云代金券