【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函數的時候出現交叉打印。

問題解決：

一、修改打日誌處代碼，這麼巨大的日誌寫入文件是否合理？
二、須要寫入巨大日誌又不但願不被交叉打印，加上LOCK_EX 標識；

file_put_contents函數相關的知識點問答

一、file_put_contents(filename,msg ,FILE_APPEND ) 末尾追加實現？

FILE_APPEND文件追加的形式，這個是怎麼實現的呢？
先標識 mode[0] =‘a’

緊接着轉換成：O_CREAT|O_APPEND

調用 open函數 ，fd = open(realpath, open_flags, 0666);

經過 C底層函數保證，寫入默認追加寫；

二、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 保證了一個巨大字符串的完整，不會被寫串；

三、多進程，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模式下，偏移到文件末尾與寫文件是原子性的，不存在被覆蓋的狀況；

四、以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);
}

五、進程內屢次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