摘要：順風(fēng)車(chē)運(yùn)營(yíng)研發(fā)團(tuán)隊(duì)黃桃現(xiàn)象在線上腳本機(jī)器寫(xiě)入單條日志過(guò)長(zhǎng)時(shí)會(huì)出現(xiàn)交叉打印的現(xiàn)象被交叉的日志很有規(guī)律，都是單條日志過(guò)長(zhǎng)被截?cái)嗟?，建議優(yōu)化下此處寫(xiě)入日志的字符串長(zhǎng)度為原因分析腳本服務(wù)寫(xiě)入日志代碼如下在調(diào)用方法寫(xiě)入，為什么在寫(xiě)入超長(zhǎng)字符串是交叉

順風(fēng)車(chē)運(yùn)營(yíng)研發(fā)團(tuán)隊(duì) 黃桃

在線上腳本機(jī)器寫(xiě)入單條日志過(guò)長(zhǎng)時(shí)會(huì)出現(xiàn)交叉打印的現(xiàn)象：

被交叉的日志很有規(guī)律，都是單條日志過(guò)長(zhǎng)被截?cái)嗟模ㄗh優(yōu)化下 /*/ruleanalysis.php:68 此處寫(xiě)入日志的字符串長(zhǎng)度為： int(25909)

腳本服務(wù)寫(xiě)入日志代碼如下：

if ($this->isCli == true) {
    return file_put_contents($messageLogFile, $strLogMsg, FILE_APPEND);
    //在調(diào)用file_put_contents 方法寫(xiě)入，為什么在寫(xiě)入超長(zhǎng)字符串是交叉寫(xiě)呢？
    //跟進(jìn)下file_put_contents函數(shù)的實(shí)現(xiàn)？
}

查看file_put_contents 的源碼實(shí)現(xiàn)，最終寫(xiě)文件會(huì)執(zhí)行到_php_stream_write_buffer 函數(shù)，里面有這樣一處代碼：

明確幾個(gè)變量的含義：
count：需寫(xiě)入文件的字符串長(zhǎng)度
stream->chunk_size ：默認(rèn)為8192 (8k)

從上面代碼可以看出，當(dāng)寫(xiě)入的字符串長(zhǎng)度 大于8192時(shí)，則拆為多次<=8192的字符串，然后調(diào)用php_stdiop_write函數(shù)寫(xiě)入文件，php_stdiop_write函數(shù)實(shí)現(xiàn)如下：

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 則調(diào)用的 write函數(shù) 寫(xiě)入文件；write函數(shù)是能保證一次寫(xiě)入的完整的。

所以日志寫(xiě)串的原因也就能分析出來(lái)了，調(diào)用鏈接為：file_put_contents ->_php_stream_write_buffer ->php_stdiop_write(多次調(diào)用，每次最多寫(xiě)入8192字節(jié)) ->write()，是在 多次調(diào)用php_stdiop_write 函數(shù)時(shí)出的問(wèn)題；第一次寫(xiě)完，緊接著在高并發(fā)的情況下，被其他進(jìn)程的 write 函數(shù)追著寫(xiě)，此時(shí)就出現(xiàn)寫(xiě)串，也就是前面示例中日志；

為了證實(shí)此觀點(diǎn),我對(duì)報(bào)錯(cuò)的代碼 /**/ruleanalysis.php:68 寫(xiě)了如下偽代碼：

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倍數(shù)的位置打出附近的字符串  16384 = 8192 * 2 
    return file_put_contents($messageLogFile, $strLogMsg, FILE_APPEND);
}

執(zhí)行代碼看打串日志的地方是否為8192倍數(shù)的位置，結(jié)果如下:

截?cái)嗟奈恢梅浅＝咏?192的倍數(shù)值；但因?yàn)槎ㄎ粫r(shí)間不是當(dāng)時(shí)的時(shí)間點(diǎn)，期間數(shù)據(jù)庫(kù)存在部分改動(dòng)，所以出現(xiàn)偏移，那么也能驗(yàn)證我們之前的猜想，正是file_put_contents 多次調(diào)用write函數(shù)的時(shí)候出現(xiàn)交叉打印。

1、修改打日志處代碼，這么巨大的日志寫(xiě)入文件是否合理？
2、需要寫(xiě)入巨大日志又不希望不被交叉打印，加上LOCK_EX 標(biāo)識(shí)；

FILE_APPEND文件追加的形式，這個(gè)是怎么實(shí)現(xiàn)的呢？
先標(biāo)識(shí) mode[0] =‘a(chǎn)’

緊接著轉(zhuǎn)換成：O_CREAT|O_APPEND

調(diào)用 open函數(shù) ，fd = open(realpath, open_flags, 0666);

通過(guò) C底層函數(shù)保證，寫(xiě)入默認(rèn)追加寫(xiě)；

file_put_contents在調(diào)用_php_stream_write_buffer 前加一個(gè)鎖 php_stream_supports_lock(stream) ->flock()
得到文件鎖定后 調(diào)用_php_stream_write_buffer->多次 write();

寫(xiě)完后釋放文件鎖

php_stream_close(stream)->close(data->fd); //直接關(guān)閉

總結(jié)：LOCK_EX 保證了一個(gè)巨大字符串的完整，不會(huì)被寫(xiě)串；

write調(diào)用路徑：file_put_contents ->_php_stream_write_buffer ->php_stdiop_write(多次調(diào)用，每次最多寫(xiě)入8192字節(jié)) ->write()
file_put_contents($messageLogFile, $strLogMsg, FILE_APPEND);
write函數(shù)在O_APPEND模式下，偏移到文件末尾與寫(xiě)文件是原子性的，不存在被覆蓋的情況；

還是寫(xiě)在文件尾部，參考文章：https://blog.csdn.net/dog250/...

write函數(shù)代碼如下:

+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系統(tǒng)調(diào)用：
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);
}

open調(diào)用路徑：file_put_contents->php_stream_open_wrapper_ex->php_plain_files_stream_opener->php_stream_fopen_rel->fd = open(realpath, open_flags, 0666);
close調(diào)用路徑：file_put_contents->php_stream_close->php_stdiop_close->ret = close(data->fd);

每次都會(huì)執(zhí)行 open和close