Simple RDTSC-based instrumentation of PHP 5.5.3

op_counts.php

<?php
/*
 * Simple parser of op_counts file.  Output is desgined to be pasted / imported into spreadsheet
 * for further analysis.
 */
define('PHP_SOURCE_DIR', '~/work/php55');  /* replace as required */
define('OP_COUNT', 164*25);                /* as at PHP 5.5 */
define('OP_COUNT_EXTRAS', 5);
$total_count  = array_fill(0, OP_COUNT + OP_COUNT_EXTRAS, 0);
$total_cycles = array_fill(0, OP_COUNT + OP_COUNT_EXTRAS, 0);

preg_match_all( '!/tmp/\d+.op_counts.lst!', shell_exec('ls -1 /tmp/*.op_counts.lst'), $files);

foreach ( $files[0] as $file) {
	preg_match_all('!(\d+)\t(\d+)\t(\d+)!s', file_get_contents($file), $matches, PREG_SET_ORDER);

	foreach ($matches as $m) {
		list($dummy, $i, $counts, $cycles) = $m;
		$total_count[$i]  += $counts;
		$total_cycles[$i] += $cycles;
	}
}
$opcodes=get_ophandlers();
$opcodes[] = "Extra-1";
$opcodes[] = "Extra-Parse_parameters";
$opcodes[] = "Extra-3";
$opcodes[] = "Extra-4";
$opcodes[] = "Extra-5";

for ($i=0; $i<OP_COUNT+OP_COUNT_EXTRAS; $i++) {
    if ($total_count[$i]>0) {
        printf("%u\t%s\t%u\t%u\t%u\n", $i+1, $opcodes[$i], $total_count[$i], 
                                             $total_cycles[$i], $total_cycles[$i]/$total_count[$i]);
    }
}
exit();

function get_ophandlers() {
	# Pick out list of handlers from zend_vm_execute.h
	$handlers=rtrim(shell_exec( 'egrep -A 9999 "^  static const opcode_handler_t labels" ' .  
                                PHP_SOURCE_DIR . '/Zend/zend_vm_execute.h \
                                                | grep -P \'^\s+ZEND_\w+?_HANDLER,$\'' ));
	return preg_replace( '/^\s+ZEND_(\w+?)_HANDLER,/', '$1', explode ("\n", $handlers) );
}

terry_rdtsc.patch

#
# This is a minimally invasive clock-based instrumentation of PHP runtime execution.  It assumes
# a Linux/GNU C enviroment.  Note that the RDTSC intstructions deliberately do not include a
# barrier before or after as this really slows down execution and the aim is to get per opcode
# clock based timings that average out to a representative value.  This code was written for 64bit 
# systems and needs a few tweeks to make it work on 32bit or 32+64bit systems.
#
# The updates to timer table are outside the timing window, and these typically incur a runtime 
# cost of around 30 clocks per opcode executed.  The timer value include the first rdtsc processing
# so it probably 4 or 5 clocks too high.
#
# This should only be used in a non-ZTS build and the current op_dump_stats() assumes a single 
# request per PHP image startup.  The dumpfile could naming could easily be extended to add a 
# request count if this was be included in a mod_php5, fpm, etc. build
#
# I also have a simple PHP script which aggregates a set of output files to produce an CSV output
# for loading into a spreadsheet for further analysis.
#

--- a/Zend/zend_API.c	2013-08-20 05:46:43.000000000 +0100
+++ b/Zend/zend_API.c	2013-09-07 17:37:17.732630002 +0100
@@ -898,10 +898,22 @@
 	}\
 }
 
+#ifdef TERRY_PATCH
+# include <x86intrin.h>
+# define TERRY_START_RDTSC() 	size_t op_timer = _rdtsc();
+# define TERRY_COLLECT_RDTSC() \
+	op_timer_table[OP_COUNT*25+OP_COUNT_PARSE_PARAM].timer += _rdtsc() - op_timer; \
+	op_timer_table[OP_COUNT*25+OP_COUNT_PARSE_PARAM].count++;
+#else
+# define TERRY_START_RDTSC()
+# define TERRY_COLLECT_RDTSC()
+#endif
+
 ZEND_API int zend_parse_parameters_ex(int flags, int num_args TSRMLS_DC, const char *type_spec, ...) /* {{{ */
 {
 	va_list va;
 	int retval;
+	TERRY_START_RDTSC();
 
 	RETURN_IF_ZERO_ARGS(num_args, type_spec, flags & ZEND_PARSE_PARAMS_QUIET);
 
@@ -909,6 +921,7 @@
 	retval = zend_parse_va_args(num_args, type_spec, &va, flags TSRMLS_CC);
 	va_end(va);
 
+	TERRY_COLLECT_RDTSC();
 	return retval;
 }
 /* }}} */
@@ -917,6 +930,7 @@
 {
 	va_list va;
 	int retval;
+	TERRY_START_RDTSC();
 
 	RETURN_IF_ZERO_ARGS(num_args, type_spec, 0);
 
@@ -924,6 +938,7 @@
 	retval = zend_parse_va_args(num_args, type_spec, &va, 0 TSRMLS_CC);
 	va_end(va);
 
+	TERRY_COLLECT_RDTSC();
 	return retval;
 }
 /* }}} */
@@ -935,6 +950,7 @@
 	const char *p = type_spec;
 	zval **object;
 	zend_class_entry *ce;
+	TERRY_START_RDTSC();
 
 	if (!this_ptr) {
 		RETURN_IF_ZERO_ARGS(num_args, p, 0);
@@ -960,6 +976,7 @@
 		retval = zend_parse_va_args(num_args, p, &va, 0 TSRMLS_CC);
 		va_end(va);
 	}
+	TERRY_COLLECT_RDTSC();
 	return retval;
 }
 /* }}} */
@@ -972,6 +989,7 @@
 	zval **object;
 	zend_class_entry *ce;
 	int quiet = flags & ZEND_PARSE_PARAMS_QUIET;
+	TERRY_START_RDTSC();
 
 	if (!this_ptr) {
 		RETURN_IF_ZERO_ARGS(num_args, p, quiet);
@@ -1001,6 +1019,7 @@
 		retval = zend_parse_va_args(num_args, p, &va, flags TSRMLS_CC);
 		va_end(va);
 	}
+	TERRY_COLLECT_RDTSC();
 	return retval;
 }
 /* }}} */
--- a/Zend/zend_vm_execute.h	2013-08-20 05:46:43.000000000 +0100
+++ b/Zend/zend_vm_execute.h	2013-09-07 18:52:12.064400004 +0100
@@ -327,13 +327,32 @@
 
 #define ZEND_OPCODE_HANDLER_ARGS_PASSTHRU_INTERNAL execute_data TSRMLS_CC
 
+#ifdef TERRY_PATCH
+#include <x86intrin.h>
+ZEND_API void op_dump_stats(void) {
+	char stats_file[sizeof("/tmp/9999999999.op_counts.lst")];
+	FILE *out;
+
+	(void) sprintf(stats_file, "/tmp/%u.op_counts.lst", getpid());
+    out = fopen(stats_file, "wbx");
+
+	if (out) {
+		int i;
+		for (i = 0; i < (OP_COUNT*25+OP_COUNT_EXTRAS); i++ ) {
+			if (op_timer_table[i].count) {
+				(void) fprintf( out, "%u\t%u\t%lu\n", i, op_timer_table[i].count, op_timer_table[i].timer);
+			}
+		}
+		fclose(out);
+	}
+}
+#endif /* TERRY_PATCH */
+
 ZEND_API void execute_ex(zend_execute_data *execute_data TSRMLS_DC)
 {
 	DCL_OPLINE
 	zend_bool original_in_execution;
 
-
-
 	original_in_execution = EG(in_execution);
 	EG(in_execution) = 1;
 
@@ -353,7 +372,25 @@
 		}
 #endif
 
+#ifdef TERRY_PATCH				
+		static const zend_uchar op_type_decode[] = {
+			_UNUSED_CODE, _CONST_CODE,  _TMP_CODE,    _UNUSED_CODE,  _VAR_CODE,    
+			_UNUSED_CODE, _UNUSED_CODE, _UNUSED_CODE, _UNUSED_CODE, _UNUSED_CODE, 
+			_UNUSED_CODE, _UNUSED_CODE, _UNUSED_CODE, _UNUSED_CODE, _UNUSED_CODE,
+			_UNUSED_CODE, _CV_CODE };		
+		int op_ndx    = 25*OPLINE->opcode + 5*op_type_decode[OPLINE->op1_type] + op_type_decode[OPLINE->op2_type];
+		long op_timer =  -_rdtsc();
+
+		ret = OPLINE->handler(execute_data TSRMLS_CC);
+
+		op_timer += _rdtsc();
+		op_timer_table[op_ndx].timer += (size_t) op_timer;
+		op_timer_table[op_ndx].count++;
+
+		if (ret>0) {
+#else
 		if ((ret = OPLINE->handler(execute_data TSRMLS_CC)) > 0) {
+#endif
 			switch (ret) {
 				case 1:
 					EG(in_execution) = original_in_execution;
--- a/Zend/zend_execute_API.c	2013-08-20 05:46:43.000000000 +0100
+++ b/Zend/zend_execute_API.c	2013-09-07 16:51:04.344771931 +0100
@@ -221,6 +221,9 @@
 		/* if we couldn't destruct cleanly, mark all objects as destructed anyway */
 		zend_objects_store_mark_destructed(&EG(objects_store) TSRMLS_CC);
 	} zend_end_try();
+#ifdef TERRY_PATCH
+ 	op_dump_stats();
+#endif
 }
 /* }}} */
 
@@ -334,6 +337,9 @@
 	zend_shutdown_fpu(TSRMLS_C);
 
 	EG(active) = 0;
+#ifdef TERRY_PATCH
+ 	op_dump_stats();
+#endif
 }
 /* }}} */
 
--- a/Zend/zend.c	2013-08-20 05:46:43.000000000 +0100
+++ b/Zend/zend.c	2013-09-07 16:50:58.868772211 +0100
@@ -124,6 +124,10 @@
 static HashTable *global_persistent_list = NULL;
 #endif
 
+#ifdef TERRY_PATCH
+ZEND_API struct _op_stats op_timer_table[OP_COUNT*25+OP_COUNT_EXTRAS];
+#endif
+
 ZEND_API zend_utility_values zend_uv;
 
 ZEND_API zval zval_used_for_init; /* True global variable */
--- a/Zend/zend.h	2013-08-20 05:46:43.000000000 +0100
+++ b/Zend/zend.h	2013-09-07 16:50:58.868772211 +0100
@@ -859,6 +859,20 @@
 #define DEBUG_BACKTRACE_PROVIDE_OBJECT (1<<0)
 #define DEBUG_BACKTRACE_IGNORE_ARGS    (1<<1)
 
+#define TERRY_PATCH 1
+
+#ifdef TERRY_PATCH
+#define OP_COUNT 164
+#define OP_COUNT_EXTRAS      5
+#define OP_COUNT_HASH        0
+#define OP_COUNT_PARSE_PARAM 1
+struct _op_stats {
+	size_t timer;
+	int    count;
+};
+extern struct _op_stats op_timer_table[OP_COUNT*25+OP_COUNT_EXTRAS];
+#endif /* TERRY_PATCH */
+
 #endif /* ZEND_H */
 
 /*