Patch php_fpm_log_utime_stime.patch for FPM related Bug #62951

Patch version 2012-09-27 14:50 UTC

Obsolete patches:

• php_fpm_log_utime_stime.patch, revision 2012-08-27 14:13 UTC

• 2012-09-27 14:50 UTC [diff to current]
• 2012-08-27 14:13 UTC [diff to current]

Developer: rainer-phpbugs@7val.com

diff -rU 7 fpm_log.c fpm_log.c
--- fpm_log.c	2012-07-13 00:17:37.000000000 +0200
+++ fpm_log.c	2012-08-10 12:28:22.980515968 +0200
@@ -102,14 +102,17 @@
 	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;
+#ifdef HAVE_GETRUSAGE
+	struct timeval tv;
+#endif
 #endif
 
 	if (!log_format && (!fpm_log_format || fpm_log_fd == -1)) {
 		return -1;
 	}
 
 	if (!log_format) {
@@ -169,32 +172,44 @@
 					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;
+							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) * 1000 / fpm_scoreboard_get_tick();
 						}
 					} else if (!strcasecmp(format, "user")) {
 						if (!test) {
-							tms_total = proc.last_request_cpu.tms_utime + proc.last_request_cpu.tms_cutime;
+							tms_total = (proc.last_request_cpu.tms_utime + proc.last_request_cpu.tms_cutime) * 1000 / fpm_scoreboard_get_tick();
 						}
 					} else if (!strcasecmp(format, "system")) {
 						if (!test) {
-							tms_total = proc.last_request_cpu.tms_stime + proc.last_request_cpu.tms_cstime;
+							tms_total = (proc.last_request_cpu.tms_stime + proc.last_request_cpu.tms_cstime) * 1000 / fpm_scoreboard_get_tick();
+						}
+#ifdef HAVE_GETRUSAGE
+					} else if (!strcasecmp(format, "ruser")) {
+						if (!test) {
+							timersub(&(proc.last_request_rus.ru_utime), &(proc.rus_accepted.ru_utime), &tv);
+							tms_total = tv.tv_sec*1000+tv.tv_usec/1000; /* milliseconds */
 						}
+					} else if (!strcasecmp(format, "rsystem")) {
+						if (!test) {
+							timersub(&proc.last_request_rus.ru_stime, &proc.rus_accepted.ru_stime, &tv);
+							tms_total = tv.tv_sec*1000+tv.tv_usec/1000; /* milliseconds */
+						}
+#endif
 					} else {
-						zlog(ZLOG_WARNING, "only 'total', 'user' or 'system' are allowed as a modifier for %%%c ('%s')", *s, format);
+						zlog(ZLOG_WARNING, "only 'total', 'user', 'ruser', 'system' or 'rsystem' 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.);
+						len2 = snprintf(b, FPM_LOG_BUFFER - len, "%i", tms_total);
 					}
 					break;
 #endif
 
 				case 'd': /* duration µs */
 					/* seconds */
 					if (format[0] == '\0' || !strcasecmp(format, "seconds")) {
diff -rU 7 fpm_request.c fpm_request.c
--- fpm_request.c	2012-07-13 00:17:37.000000000 +0200
+++ fpm_request.c	2012-08-10 12:28:57.759339006 +0200
@@ -82,14 +82,22 @@
 
 	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;
+#ifdef HAVE_GETRUSAGE
+	if (getrusage(RUSAGE_SELF, &proc->rus_accepted)!=0) {
+		bzero(&proc->rus_accepted, sizeof(proc->rus_accepted));
+	};
+	if (getrusage(RUSAGE_CHILDREN, &proc->ruc_accepted)!=0) {
+		bzero(&proc->ruc_accepted, sizeof(proc->ruc_accepted));
+	};
+#endif
 #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';
@@ -196,14 +204,22 @@
 	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;
+#ifdef HAVE_GETRUSAGE
+	if (getrusage(RUSAGE_SELF, &(proc->last_request_rus))!=0){
+		bzero(&proc->last_request_rus, sizeof(proc->last_request_rus));
+	}
+	if (getrusage(RUSAGE_CHILDREN, &(proc->last_request_ruc))!=0){
+		bzero(&proc->last_request_ruc, sizeof(proc->last_request_ruc));
+	}
+#endif
 #endif
 	proc->memory = memory;
 	fpm_scoreboard_proc_release(proc);
 }
 /* }}} */
 
 void fpm_request_finished() /* {{{ */
diff -rU 7 php-5.3.15/sapi/fpm/fpm/fpm_scoreboard.h ../php-5.3.15/sapi/fpm/fpm/fpm_scoreboard.h
--- php-5.3.15/sapi/fpm/fpm/fpm_scoreboard.h	2012-07-13 00:17:37.000000000 +0200
+++ ../php-5.3.15/sapi/fpm/fpm/fpm_scoreboard.h	2012-08-10 11:49:47.860351421 +0200
@@ -4,14 +4,17 @@
 
 #ifndef FPM_SCOREBOARD_H
 #define FPM_SCOREBOARD_H 1
 
 #include <sys/time.h>
 #ifdef HAVE_TIMES
 #include <sys/times.h>
+#ifdef HAVE_GETRUSAGE
+#include <sys/resource.h>
+#endif
 #endif
 
 #include "fpm_request.h"
 #include "fpm_worker_pool.h"
 #include "fpm_atomic.h"
 
 #define FPM_SCOREBOARD_ACTION_SET 0
@@ -35,16 +38,24 @@
 	char query_string[512];
 	char request_method[16];
 	size_t content_length; /* used with POST only */
 	char script_filename[256];
 	char auth_user[32];
 #ifdef HAVE_TIMES
 	struct tms cpu_accepted;
+#ifdef HAVE_GETRUSAGE
+	struct rusage rus_accepted;
+	struct rusage ruc_accepted;
+#endif
 	struct timeval cpu_duration;
 	struct tms last_request_cpu;
+#ifdef HAVE_GETRUSAGE
+	struct rusage last_request_rus;
+	struct rusage last_request_ruc;
+#endif
 	struct timeval last_request_cpu_duration;
 #endif
 	size_t memory;
 };
 
 struct fpm_scoreboard_s {
 	union {