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

苏丹发布于2019-07-01 10:12 / 3004人阅读

摘要：顺风车运营研发团队黄桃现象在线上脚本机器写入单条日志过长时会出现交叉打印的现象被交叉的日志很有规律，都是单条日志过长被截断的，建议优化下此处写入日志的字符串长度为原因分析脚本服务写入日志代码如下在调用方法写入，为什么在写入超长字符串是交叉

顺风车运营研发团队黄桃

现象

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

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

专线服务云服务器定位问题云服务器问题定位消息队列线上问题机器图像识别定位技术

文章版权归作者所有，未经允许请勿转载,若此文章存在违规行为，您可以联系管理员删除。

转载请注明本文地址：https://www.ucloud.cn/yun/28905.html

【PHP问题定位】2018-07-02 fpm掉底分析

摘要：顺风车运营研发团队黄桃问题现象某机器这段时间出现掉地的报警如图原因分析查看当时的监控，等今天出现两次突降，一次是点左右，一次是左右，查看整周也经常出现突降，如图在分时突然升高也在时出现大量写当时短暂出现降低，之后出现徒顺风车运营研发团队黄桃问题现象某机器这段时间出现cpu-idle掉地的报警如图： showImg(https://segmentfault.com/img/bVb...

Code4App 2019-07-01 10:15 评论0 收藏0
线上大量CLOSE_WAIT原因深入分析

摘要：因此负载均衡器在达到的时候主动触发了操作，但是通过抓包发现，服务端并没有进行回应，这是因为代码中的事务没有处理，因此从而导致大量的端口连接资源被占用。这一次重启真的无法解决问题了：一次 MySQL 主动关闭，导致服务出现大量 CLOSE_WAIT 的全流程排查过程。近日遇到一个线上服务 socket 资源被不断打满的情况。通过各种工具分析线上问题,定位到问题代码。这里对该问题发现、...

elva 2019-08-08 10:44 评论0 收藏0
不改一行代码定位线上性能问题

摘要：背景最近时运不佳，几乎天天被线上问题骚扰。工具分析所以最好的方式就是不改动一行代码把这个问题分析出来。我们选用了阿里以前开源的来使用。因为这个项目阿里多年没有维护了，还残留一些我在它原有的基础上修复了个影响使用的，同时做了一些优化。 showImg(https://segmentfault.com/img/remote/1460000016978923?w=1920&h=1080); ...

DangoSky 2019-08-16 13:40 评论0 收藏0
企业互联网应用高性能解决之道

摘要：本文介绍了企业互联网开发及运维的一些实践，深入剖析了互联网项目开发及上线过程中的各种痛点及解决之道。线上出错，我们通过收集服务器端应用性能数据的方式，实时展示应用的调用拓扑图，并根据出现异常的请求，进行下钻，定位出具体出现问题的代码。本文介绍了企业互联网开发及运维的一些实践，深入剖析了互联网项目开发及上线过程中的各种痛点及解决之道。一个互联网项目的上线并不是那么容易，需要经过很多的环...

Alan 2019-05-28 17:11 评论0 收藏0
线上系统性问题定位与方法论

摘要：很显然对于不同规模，不同功能的系统，这个问题无法一概而论。生产事件上报客服上报此类问题往往来自用户投诉，最重要的就是问题现象的复现。线上问题处理的核心是快速修复。以上说的都是问题发生后的消极应对措施。前言一线程序员在工作中经常需要处理线上的问题或者故障，但工作几年下来发现，有些同事其实并不知道该如何去分析和解决这些问题，毫无章法的猜测和尝试，虽然在很多时候可以最终解决问题，但往往也会浪费大...

leonardofed 2019-04-25 17:23 评论0 收藏0