void fpm_request_end(void) /* {{{ */
{
struct fpm_scoreboard_proc_s *proc;
struct timeval now;
#ifdef HAVE_TIMES
struct tms cpu;
#endif
size_t memory = zend_memory_peak_usage(1);
fpm_clock_get(&now);
#ifdef HAVE_TIMES
times(&cpu);
#endif
proc = fpm_scoreboard_proc_acquire(NULL, -1, 0);
if (proc == NULL) {
zlog(ZLOG_WARNING, "failed to acquire proc scoreboard");
return;
}
proc->request_stage = FPM_REQUEST_FINISHED;
proc->tv = now;
timersub(&now, &proc->accepted, &proc->duration);
#ifdef HAVE_TIMES
timersub(&proc->tv, &proc->accepted, &proc->cpu_duration);
proc->last_request_cpu.tms_utime = cpu.tms_utime - proc->cpu_accepted.tms_utime;
proc->last_request_cpu.tms_stime = cpu.tms_stime - proc->cpu_accepted.tms_stime;
proc->last_request_cpu.tms_cutime = cpu.tms_cutime - proc->cpu_accepted.tms_cutime;
proc->last_request_cpu.tms_cstime = cpu.tms_cstime - proc->cpu_accepted.tms_cstime;
#endif
proc->memory = memory;
fpm_scoreboard_proc_release(proc);
}
void fpm_request_check_timed_out(struct fpm_child_s *child, struct timeval *now, int terminate_timeout, int slowlog_timeout) /* {{{ */
{
struct fpm_scoreboard_proc_s proc, *proc_p;
proc_p = fpm_scoreboard_proc_acquire(child->wp->scoreboard, child->scoreboard_i, 1);
if (!proc_p) {
zlog(ZLOG_WARNING, "failed to acquire scoreboard");
return;
}
proc = *proc_p;
fpm_scoreboard_proc_release(proc_p);
#if HAVE_FPM_TRACE
if (child->slow_logged.tv_sec) {
if (child->slow_logged.tv_sec != proc.accepted.tv_sec || child->slow_logged.tv_usec != proc.accepted.tv_usec) {
child->slow_logged.tv_sec = 0;
child->slow_logged.tv_usec = 0;
}
}
#endif
if (proc.request_stage > FPM_REQUEST_ACCEPTING && proc.request_stage < FPM_REQUEST_END) {
char purified_script_filename[sizeof(proc.script_filename)];
struct timeval tv;
timersub(now, &proc.accepted, &tv);
#if HAVE_FPM_TRACE
if (child->slow_logged.tv_sec == 0 && slowlog_timeout &&
proc.request_stage == FPM_REQUEST_EXECUTING && tv.tv_sec >= slowlog_timeout) {
str_purify_filename(purified_script_filename, proc.script_filename, sizeof(proc.script_filename));
child->slow_logged = proc.accepted;
child->tracer = fpm_php_trace;
fpm_trace_signal(child->pid);
zlog(ZLOG_WARNING, "[pool %s] child %d, script '%s' (request: \"%s %s\") executing too slow (%d.%06d sec), logging",
child->wp->config->name, (int) child->pid, purified_script_filename, proc.request_method, proc.request_uri,
(int) tv.tv_sec, (int) tv.tv_usec);
}
else
#endif
if (terminate_timeout && tv.tv_sec >= terminate_timeout) {
str_purify_filename(purified_script_filename, proc.script_filename, sizeof(proc.script_filename));
fpm_pctl_kill(child->pid, FPM_PCTL_TERM);
zlog(ZLOG_WARNING, "[pool %s] child %d, script '%s' (request: \"%s %s\") execution timed out (%d.%06d sec), terminating",
child->wp->config->name, (int) child->pid, purified_script_filename, proc.request_method, proc.request_uri,
(int) tv.tv_sec, (int) tv.tv_usec);
}
}
}
void fpm_request_info() /* {{{ */
{
struct fpm_scoreboard_proc_s *proc;
char *request_uri = fpm_php_request_uri();
char *request_method = fpm_php_request_method();
char *script_filename = fpm_php_script_filename();
char *query_string = fpm_php_query_string();
char *auth_user = fpm_php_auth_user();
size_t content_length = fpm_php_content_length();
struct timeval now;
fpm_clock_get(&now);
proc = fpm_scoreboard_proc_acquire(NULL, -1, 0);
if (proc == NULL) {
zlog(ZLOG_WARNING, "failed to acquire proc scoreboard");
return;
}
proc->request_stage = FPM_REQUEST_INFO;
proc->tv = now;
if (request_uri) {
strlcpy(proc->request_uri, request_uri, sizeof(proc->request_uri));
}
if (request_method) {
strlcpy(proc->request_method, request_method, sizeof(proc->request_method));
}
if (query_string) {
strlcpy(proc->query_string, query_string, sizeof(proc->query_string));
}
if (auth_user) {
strlcpy(proc->auth_user, auth_user, sizeof(proc->auth_user));
}
proc->content_length = content_length;
/* if cgi.fix_pathinfo is set to "1" and script cannot be found (404)
the sapi_globals.request_info.path_translated is set to NULL */
if (script_filename) {
strlcpy(proc->script_filename, script_filename, sizeof(proc->script_filename));
}
fpm_scoreboard_proc_release(proc);
}
void fpm_request_finished() /* {{{ */
{
struct fpm_scoreboard_proc_s *proc;
struct timeval now;
fpm_clock_get(&now);
proc = fpm_scoreboard_proc_acquire(NULL, -1, 0);
if (proc == NULL) {
zlog(ZLOG_WARNING, "failed to acquire proc scoreboard");
return;
}
proc->request_stage = FPM_REQUEST_FINISHED;
proc->tv = now;
fpm_scoreboard_proc_release(proc);
}
void fpm_request_reading_headers() /* {{{ */
{
struct fpm_scoreboard_proc_s *proc;
struct timeval now;
clock_t now_epoch;
#ifdef HAVE_TIMES
struct tms cpu;
#endif
fpm_clock_get(&now);
now_epoch = time(NULL);
#ifdef HAVE_TIMES
times(&cpu);
#endif
proc = fpm_scoreboard_proc_acquire(NULL, -1, 0);
if (proc == NULL) {
zlog(ZLOG_WARNING, "failed to acquire proc scoreboard");
return;
}
proc->request_stage = FPM_REQUEST_READING_HEADERS;
proc->tv = now;
proc->accepted = now;
proc->accepted_epoch = now_epoch;
#ifdef HAVE_TIMES
proc->cpu_accepted = cpu;
#endif
proc->requests++;
proc->request_uri[0] = '\0';
proc->request_method[0] = '\0';
proc->script_filename[0] = '\0';
proc->query_string[0] = '\0';
proc->query_string[0] = '\0';
proc->auth_user[0] = '\0';
proc->content_length = 0;
fpm_scoreboard_proc_release(proc);
/* idle--, active++, request++ */
fpm_scoreboard_update(-1, 1, 0, 0, 1, 0, 0, FPM_SCOREBOARD_ACTION_INC, NULL);
}
void fpm_request_accepting() /* {{{ */
{
struct fpm_scoreboard_proc_s *proc;
struct timeval now;
fpm_clock_get(&now);
proc = fpm_scoreboard_proc_acquire(NULL, -1, 0);
if (proc == NULL) {
zlog(ZLOG_WARNING, "failed to acquire proc scoreboard");
return;
}
proc->request_stage = FPM_REQUEST_ACCEPTING;
proc->tv = now;
fpm_scoreboard_proc_release(proc);
/* idle++, active-- */
fpm_scoreboard_update(1, -1, 0, 0, 0, 0, 0, FPM_SCOREBOARD_ACTION_INC, NULL);
}
int fpm_log_write(char *log_format) /* {{{ */
{
char *s, *b;
char buffer[FPM_LOG_BUFFER+1];
int token, test;
size_t len, len2;
struct fpm_scoreboard_proc_s proc, *proc_p;
struct fpm_scoreboard_s *scoreboard;
char tmp[129];
char format[129];
time_t now_epoch;
#ifdef HAVE_TIMES
clock_t tms_total;
#endif
if (!log_format && (!fpm_log_format || fpm_log_fd == -1)) {
return -1;
}
if (!log_format) {
log_format = fpm_log_format;
test = 0;
} else {
test = 1;
}
now_epoch = time(NULL);
if (!test) {
scoreboard = fpm_scoreboard_get();
if (!scoreboard) {
zlog(ZLOG_WARNING, "unable to get scoreboard while preparing the access log");
return -1;
}
proc_p = fpm_scoreboard_proc_acquire(NULL, -1, 0);
if (!proc_p) {
zlog(ZLOG_WARNING, "[pool %s] Unable to acquire shm slot while preparing the access log", scoreboard->pool);
return -1;
}
proc = *proc_p;
fpm_scoreboard_proc_release(proc_p);
}
token = 0;
memset(buffer, '\0', sizeof(buffer));
b = buffer;
len = 0;
s = log_format;
while (*s != '\0') {
/* Test is we have place for 1 more char. */
if (len >= FPM_LOG_BUFFER) {
zlog(ZLOG_NOTICE, "the log buffer is full (%d). The access log request has been truncated.", FPM_LOG_BUFFER);
len = FPM_LOG_BUFFER;
break;
}
if (!token && *s == '%') {
token = 1;
memset(format, '\0', sizeof(format)); /* reset format */
s++;
continue;
}
if (token) {
token = 0;
len2 = 0;
switch (*s) {
case '%': /* '%' */
*b = '%';
len2 = 1;
break;
#ifdef HAVE_TIMES
case 'C': /* %CPU */
if (format[0] == '\0' || !strcasecmp(format, "total")) {
if (!test) {
tms_total = proc.last_request_cpu.tms_utime + proc.last_request_cpu.tms_stime + proc.last_request_cpu.tms_cutime + proc.last_request_cpu.tms_cstime;
}
} else if (!strcasecmp(format, "user")) {
if (!test) {
tms_total = proc.last_request_cpu.tms_utime + proc.last_request_cpu.tms_cutime;
}
} else if (!strcasecmp(format, "system")) {
if (!test) {
tms_total = proc.last_request_cpu.tms_stime + proc.last_request_cpu.tms_cstime;
}
} else {
zlog(ZLOG_WARNING, "only 'total', 'user' or 'system' are allowed as a modifier for %%%c ('%s')", *s, format);
return -1;
}
format[0] = '\0';
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.2f", tms_total / fpm_scoreboard_get_tick() / (proc.cpu_duration.tv_sec + proc.cpu_duration.tv_usec / 1000000.) * 100.);
}
break;
#endif
case 'd': /* duration µs */
/* seconds */
if (format[0] == '\0' || !strcasecmp(format, "seconds")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec + proc.duration.tv_usec / 1000000.);
}
/* miliseconds */
} else if (!strcasecmp(format, "miliseconds") || !strcasecmp(format, "mili")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%.3f", proc.duration.tv_sec * 1000. + proc.duration.tv_usec / 1000.);
}
/* microseconds */
} else if (!strcasecmp(format, "microseconds") || !strcasecmp(format, "micro")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", proc.duration.tv_sec * 1000000UL + proc.duration.tv_usec);
}
} else {
zlog(ZLOG_WARNING, "only 'seconds', 'mili', 'miliseconds', 'micro' or 'microseconds' are allowed as a modifier for %%%c ('%s')", *s, format);
return -1;
}
format[0] = '\0';
break;
case 'e': /* fastcgi env */
if (format[0] == '\0') {
zlog(ZLOG_WARNING, "the name of the environment variable must be set between embraces for %%%c", *s);
return -1;
}
if (!test) {
char *env = fcgi_getenv((fcgi_request*) SG(server_context), format, strlen(format));
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", env ? env : "-");
}
format[0] = '\0';
break;
case 'f': /* script */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.script_filename ? proc.script_filename : "-");
}
break;
case 'l': /* content length */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.content_length);
}
break;
case 'm': /* method */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.request_method ? proc.request_method : "-");
}
break;
case 'M': /* memory */
/* seconds */
if (format[0] == '\0' || !strcasecmp(format, "bytes")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%zu", proc.memory);
}
/* kilobytes */
} else if (!strcasecmp(format, "kilobytes") || !strcasecmp(format, "kilo")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", proc.memory / 1024);
}
/* megabytes */
} else if (!strcasecmp(format, "megabytes") || !strcasecmp(format, "mega")) {
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%lu", proc.memory / 1024 / 1024);
}
} else {
zlog(ZLOG_WARNING, "only 'bytes', 'kilo', 'kilobytes', 'mega' or 'megabytes' are allowed as a modifier for %%%c ('%s')", *s, format);
return -1;
}
format[0] = '\0';
break;
case 'n': /* pool name */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", scoreboard->pool[0] ? scoreboard->pool : "-");
}
break;
case 'o': /* header output */
if (format[0] == '\0') {
zlog(ZLOG_WARNING, "the name of the header must be set between embraces for %%%c", *s);
return -1;
}
if (!test) {
sapi_header_struct *h;
zend_llist_position pos;
sapi_headers_struct *sapi_headers = &SG(sapi_headers);
size_t format_len = strlen(format);
h = (sapi_header_struct*)zend_llist_get_first_ex(&sapi_headers->headers, &pos);
while (h) {
char *header;
if (!h->header_len) {
h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
continue;
}
if (!strstr(h->header, format)) {
h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
continue;
}
/* test if enought char after the header name + ': ' */
if (h->header_len <= format_len + 2) {
h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
continue;
}
if (h->header[format_len] != ':' || h->header[format_len + 1] != ' ') {
h = (sapi_header_struct*)zend_llist_get_next_ex(&sapi_headers->headers, &pos);
continue;
}
header = h->header + format_len + 2;
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", header && *header ? header : "-");
/* found, done */
break;
}
if (!len2) {
len2 = 1;
*b = '-';
}
}
format[0] = '\0';
break;
case 'p': /* PID */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getpid());
}
break;
case 'P': /* PID */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%ld", (long)getppid());
}
break;
case 'q': /* query_string */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.query_string);
}
break;
case 'Q': /* '?' */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", *proc.query_string ? "?" : "");
}
break;
case 'r': /* request URI */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.request_uri);
}
break;
case 'R': /* remote IP address */
if (!test) {
const char *tmp = fcgi_get_last_client_ip();
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp ? tmp : "-");
}
break;
case 's': /* status */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%d", SG(sapi_headers).http_response_code);
}
break;
case 'T':
case 't': /* time */
if (!test) {
time_t *t;
if (*s == 't') {
t = &proc.accepted_epoch;
} else {
t = &now_epoch;
}
if (format[0] == '\0') {
strftime(tmp, sizeof(tmp) - 1, "%d/%b/%Y:%H:%M:%S %z", localtime(t));
} else {
strftime(tmp, sizeof(tmp) - 1, format, localtime(t));
}
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", tmp);
}
format[0] = '\0';
break;
case 'u': /* remote user */
if (!test) {
len2 = snprintf(b, FPM_LOG_BUFFER - len, "%s", proc.auth_user);
}
break;
case '{': /* complex var */
token = 1;
{
char *start;
size_t l;
start = ++s;
while (*s != '\0') {
if (*s == '}') {
l = s - start;
if (l >= sizeof(format) - 1) {
l = sizeof(format) - 1;
}
memcpy(format, start, l);
format[l] = '\0';
break;
}
s++;
}
if (s[1] == '\0') {
zlog(ZLOG_WARNING, "missing closing embrace in the access.format");
return -1;
}
}
break;
default:
zlog(ZLOG_WARNING, "Invalid token in the access.format (%%%c)", *s);
return -1;
}
if (*s != '}' && format[0] != '\0') {
zlog(ZLOG_WARNING, "embrace is not allowed for modifier %%%c", *s);
return -1;
}
s++;
if (!test) {
b += len2;
len += len2;
}
continue;
}
if (!test) {
// push the normal char to the output buffer
*b = *s;
b++;
len++;
}
s++;
}
if (!test && strlen(buffer) > 0) {
buffer[len] = '\n';
write(fpm_log_fd, buffer, len + 1);
}
return 0;
}
// 初始化fpm_request_info
void fpm_request_info() /* {{{ */
{
TSRMLS_FETCH();
// 记分牌,记录请求的相关信息
struct fpm_scoreboard_proc_s *proc;
//从SG全局变量中拿各种数据
/*
* uri
* method
* filename
* query_string
* 等等
*/
char *request_uri = fpm_php_request_uri(TSRMLS_C);
char *request_method = fpm_php_request_method(TSRMLS_C);
char *script_filename = fpm_php_script_filename(TSRMLS_C);
char *query_string = fpm_php_query_string(TSRMLS_C);
char *auth_user = fpm_php_auth_user(TSRMLS_C);
size_t content_length = fpm_php_content_length(TSRMLS_C);
struct timeval now;
fpm_clock_get(&now);
// 拿到进程,加锁
proc = fpm_scoreboard_proc_acquire(NULL, -1, 0);
if (proc == NULL) {
zlog(ZLOG_WARNING, "failed to acquire proc scoreboard");
return;
}
proc->request_stage = FPM_REQUEST_INFO;
proc->tv = now;
if (request_uri) {
strlcpy(proc->request_uri, request_uri, sizeof(proc->request_uri));
}
if (request_method) { // post, get, delete, or...
strlcpy(proc->request_method, request_method, sizeof(proc->request_method));
}
if (query_string) {
strlcpy(proc->query_string, query_string, sizeof(proc->query_string));
}
if (auth_user) {
strlcpy(proc->auth_user, auth_user, sizeof(proc->auth_user));
}
proc->content_length = content_length;
/* if cgi.fix_pathinfo is set to "1" and script cannot be found (404)
the sapi_globals.request_info.path_translated is set to NULL */
if (script_filename) {
strlcpy(proc->script_filename, script_filename, sizeof(proc->script_filename));
}
// 释放锁
fpm_scoreboard_proc_release(proc);
}
