一次php5.6的error_log函数跟踪

笔记有点乱，先记下，改天再整理。

PHP：

error_log(self::formatMessage(), self::$_fileLog, self::$_logFilePath . date('YmdH'));

转换后：
formatMessage()：

$this->_logParams['time'] = date("Y-m-d H:i:s");//Data_Util::getmicrotime();
        return json_encode($this->_logParams) . PHP_EOL;


============>


error_log(string "json_string+\n", int 3, "/xxx/test.log.2018060101");

=============>


C Ext:


error_log 源码跟踪分析：


/*
1st arg = error message
2nd arg = error option
3rd arg = optional parameters (email address or tcp address)
4th arg = used for additional headers if email


error options:
0 = send to php_error_log (uses syslog or file depending on ini setting)
1 = send via email to 3rd parameter 4th option = additional headers
2 = send via tcp/ip to 3rd parameter (name or ip:port)
3 = save to file in 3rd parameter
4 = send to SAPI logger directly
*/


/* {{{ proto bool error_log(string message [, int message_type [, string destination [, string extra_headers]]])
   Send an error message somewhere */
PHP_FUNCTION(error_log)
{
char *message, *opt = NULL, *headers = NULL;
int message_len, opt_len = 0, headers_len = 0;
int opt_err = 0, argc = ZEND_NUM_ARGS();
long erropt = 0;
//解析 error_log的参数，
/**
*  "s|lps"
* 
* s 代表第一个参数为字符串，对应message,为非二进制安全，
* C语言中处理字符串结尾会以\0 为结束符，如果字符串中有这样的特殊字符，会被提早结束，丢失后面的内容
* 
* | 代表前面的参数为必填后面的参数为可选
* 
* l 带符号的长整
* 
* p 字符串指针
* 
* s 字符串指针和长度
* 
* 
* **/
if (zend_parse_parameters(argc TSRMLS_CC, "s|lps", &message, &message_len, &erropt, &opt, &opt_len, &headers, &headers_len) == FAILURE) {
return;
}
//如果参数大于1, 默认的错误处理方式被替换为输入的参数
if (argc > 1) {
opt_err = erropt;
}


if (_php_error_log_ex(opt_err, message, message_len, opt, headers TSRMLS_CC) == FAILURE) {
RETURN_FALSE;
}


RETURN_TRUE;
}
/* }}} */


========================================》
PHPAPI int _php_error_log_ex(int opt_err, char *message, int message_len, char *opt, char *headers TSRMLS_DC) /* {{{ */
{
php_stream *stream = NULL;


switch (opt_err)
{
case 1: /*send an email */
if (!php_mail(opt, "PHP error_log message", message, headers, NULL TSRMLS_CC)) {
return FAILURE;
}
break;


case 2: /*send to an address */
php_error_docref(NULL TSRMLS_CC, E_WARNING, "TCP/IP option not available!");
return FAILURE;
break;


case 3: /*save to a file */
stream = php_stream_open_wrapper(opt, "a", IGNORE_URL_WIN | REPORT_ERRORS, NULL);
if (!stream) {
return FAILURE;
}
php_stream_write(stream, message, message_len);
php_stream_close(stream);
break;


case 4: /* send to SAPI */
if (sapi_module.log_message) {
sapi_module.log_message(message TSRMLS_CC);
} else {
return FAILURE;
}
break;

default:
php_log_err(message TSRMLS_CC);
break;
}
return SUCCESS;
}
/* }}} */






==============>


关键部分：


case 3: /*save to a file */
stream = php_stream_open_wrapper(opt, "a", IGNORE_URL_WIN | REPORT_ERRORS, NULL);
if (!stream) {
return FAILURE;
}
php_stream_write(stream, message, message_len);
php_stream_close(stream);


php_stream_open_wrapper(opt, "a", IGNORE_URL_WIN | REPORT_ERRORS, NULL);


===》
php_stream_open_wrapper(文件地址, 追加方式, 8, NULL);
=====》


PHPAPI php_stream *_php_stream_open_wrapper_ex(const char *path, const char *mode, int options,
char **opened_path, php_stream_context *context STREAMS_DC TSRMLS_DC)




if (opened_path) {
*opened_path = NULL;
}
========》


gdb: error_log("test",3,"/tmp/error_log.log");




php 首先注册 stdin stdout stderr 三个数据流操作并且以文件handle形式注册到流的处理方法


cli_register_file_handles () at /opt/coding/php_source/php-5.6.36-source/sapi/cli/php_cli.c:570


然后再执行：


1, _php_error_log_ex (opt_err=3, message=0x7ffff7eb2198 "test", message_len=4, opt=0x7ffff7eb21e8 "/tmp/php_test_error_log.log", headers=0x0)


2,PHPAPI int _php_error_log_ex(int opt_err, char *message, int message_len, char *opt, char *headers TSRMLS_DC) 


3,_php_stream_open_wrapper_ex (path=0x7ffff7eb21e8 "/tmp/php_test_error_log.log", mode=mode@entry=0xdaa3e8 "a", options=options@entry=8, opened_path=opened_path@entry=0x0, 
    context=context@entry=0x0) at /opt/coding/php_source/php-5.6.36-source/main/streams/streams.c:2016


4,_php_stream_free (stream=stream@entry=0x7ffff7fb60b8, close_options=close_options@entry=3) at /opt/coding/php_source/php-5.6.36-source/main/streams/streams.c:384


p *stream
$11 = {ops = 0x115ee00 <php_stream_stdio_ops>, abstract = 0x7ffff7fb6fd8, readfilters = {head = 0x0, tail = 0x0, stream = 0x7ffff7fb60b8}, writefilters = {head = 0x0, tail = 0x0, 
    stream = 0x7ffff7fb60b8}, wrapper = 0x115ed20 <php_plain_files_wrapper>, wrapperthis = 0x0, wrapperdata = 0x0, fgetss_state = 0, is_persistent = 0, mode = "a", '\000' <repeats 14 times>, rsrc_id = 4, 
  in_free = 0, fclose_stdiocast = 0, stdiocast = 0x0, orig_path = 0x7ffff7fb6fa8 "/tmp/php_test_error_log.log", context = 0x0, flags = 0, position = 4, readbuf = 0x0, readbuflen = 0, readpos = 0, 
  writepos = 0, chunk_size = 8192, eof = 0, enclosing_stream = 0x0}


========= 数据写入关键：


/* Writes a buffer directly to a stream, using multiple of the chunk size */
static size_t _php_stream_write_buffer(php_stream *stream, const char *buf, size_t count TSRMLS_DC)
{
size_t didwrite = 0, towrite, justwrote;


  /* if we have a seekable stream we need to ensure that data is written at the
  * current stream->position. This means invalidating the read buffer and then
* performing a low-level seek */
if (stream->ops->seek && (stream->flags & PHP_STREAM_FLAG_NO_SEEK) == 0 && stream->readpos != stream->writepos) {
stream->readpos = stream->writepos = 0;


stream->ops->seek(stream, stream->position, SEEK_SET, &stream->position TSRMLS_CC);
}


// 调用流的 write handle 根据块大小写入文件
while (count > 0) {
towrite = count;
if (towrite > stream->chunk_size)
towrite = stream->chunk_size;


justwrote = stream->ops->write(stream, buf, towrite TSRMLS_CC);


/* convert justwrote to an integer, since normally it is unsigned */
if ((int)justwrote > 0) {
buf += justwrote;
count -= justwrote;
didwrite += justwrote;


/* Only screw with the buffer if we can seek, otherwise we lose data
* buffered from fifos and sockets */
if (stream->ops->seek && (stream->flags & PHP_STREAM_FLAG_NO_SEEK) == 0) {
stream->position += justwrote;
}
} else {
break;
}
}
return didwrite;


}




=====》 文件流写入函数，php内核自己实现，非标准IO，类似ANSI C的stdio库的翻版，但是可以自己控制缓冲区大小，避免占用过大内存
使用的是POSIX 的文件操作函数


static size_t php_stdiop_write(php_stream *stream, const char *buf, size_t count TSRMLS_DC)
{
php_stdio_stream_data *data = (php_stdio_stream_data*)stream->abstract;


assert(data != NULL);


if (data->fd >= 0) {
int bytes_written = write(data->fd, buf, count);
if (bytes_written < 0) return 0;
return (size_t) bytes_written;
} else {


#if HAVE_FLUSHIO
if (!data->is_pipe && data->last_op == 'r') {
fseek(data->file, 0, SEEK_CUR);
}
data->last_op = 'w';
#endif


return fwrite(buf, 1, count, data->file);
}
}




==========》


POSIX 函数是对内核接口的封装，write调用的是sys_write函数。


三、常规文件(ext2)对write系统调用的实现
sys_write-->>vfs_write--->>>do_sync_write-->>generic_file_aio_write
 mutex_lock(&inode->i_mutex); 
 ret = __generic_file_aio_write_nolock(iocb, iov, nr_segs, &iocb->ki_pos); 
 mutex_unlock(&inode->i_mutex);
从这个调用关系中可以看到，整个文件的写入经过了系统级的mutex锁，所以这个写入是原子性的。也就是说，对于一次write系统调用写入的内容不会与系统中任意一个系统调用写入的内容重叠。




=========》


总结：


1、php的写文件操作在高并发的场景，并且每次写入的数据大于8k情况下，无法保证单次操作的原子性;
2、php写文件调用的是posix 的write函数，并没有缓存，从posix再到系统的函数调用链上看，单次的write操作是原子性的并且是有锁的，所以从内核的角度是有锁等待的，只是感知问题；
3、php不同进程对文件的操作所操作的fd是相同的，但是偏移量的位置只保存在每个进程的php_stream结构体中，可能会出现各不相同的情况，也就是写花日志的情况；
4、php error_log 不支持 options = 2的tcp ip协议；