From: Andrey Hristov Date: Fri, 22 Oct 2010 15:46:26 +0000 (+0000) Subject: profiling in trace mode X-Git-Tag: php-5.4.0alpha1~191^2~773 X-Git-Url: https://granicus.if.org/sourcecode?a=commitdiff_plain;h=fe719c5e42dc8d729133957abdd651d44c2f1ce9;p=php profiling in trace mode --- diff --git a/ext/mysqlnd/mysqlnd.c b/ext/mysqlnd/mysqlnd.c index 9274eed27b..bb7967c093 100644 --- a/ext/mysqlnd/mysqlnd.c +++ b/ext/mysqlnd/mysqlnd.c @@ -2338,10 +2338,11 @@ MYSQLND_METHOD(mysqlnd_conn, init)(MYSQLND * conn TSRMLS_DC) PHPAPI MYSQLND * _mysqlnd_init(zend_bool persistent TSRMLS_DC) { size_t alloc_size = sizeof(MYSQLND) + mysqlnd_plugin_count() * sizeof(void *); - MYSQLND *ret = mnd_pecalloc(1, alloc_size, persistent); + MYSQLND *ret; DBG_ENTER("mysqlnd_init"); DBG_INF_FMT("persistent=%u", persistent); + ret = mnd_pecalloc(1, alloc_size, persistent); if (!ret) { DBG_RETURN(NULL); } diff --git a/ext/mysqlnd/mysqlnd_debug.c b/ext/mysqlnd/mysqlnd_debug.c index 0c5c5153b6..304b50dae1 100644 --- a/ext/mysqlnd/mysqlnd_debug.c +++ b/ext/mysqlnd/mysqlnd_debug.c @@ -27,6 +27,7 @@ #include "mysqlnd_wireprotocol.h" #include "mysqlnd_statistics.h" #include "zend_builtin_functions.h" +#include "inttypes.h" static const char * const mysqlnd_debug_default_trace_file = "/tmp/mysqlnd.trace"; @@ -287,7 +288,6 @@ MYSQLND_METHOD(mysqlnd_debug, log_va)(MYSQLND_DEBUG *self, flags & MYSQLND_DEBUG_DUMP_LEVEL? level_buffer:"", pipe_buffer, type? type:"", buffer); efree(buffer); - ret = php_stream_write(self->stream, message_line, message_line_len)? PASS:FAIL; efree(message_line); /* allocated by spprintf */ @@ -307,6 +307,7 @@ MYSQLND_METHOD(mysqlnd_debug, func_enter)(MYSQLND_DEBUG * self, unsigned int line, const char * const file, const char * const func_name, unsigned int func_name_len) { + uint64_t some_time = 0; if ((self->flags & MYSQLND_DEBUG_DUMP_TRACE) == 0 || self->file_name == NULL) { return FALSE; } @@ -319,6 +320,7 @@ MYSQLND_METHOD(mysqlnd_debug, func_enter)(MYSQLND_DEBUG * self, while (*p) { if (*p == func_name) { zend_stack_push(&self->call_stack, "", sizeof("")); + zend_stack_push(&self->call_time_stack, &some_time, sizeof(some_time)); return FALSE; } p++; @@ -326,6 +328,7 @@ MYSQLND_METHOD(mysqlnd_debug, func_enter)(MYSQLND_DEBUG * self, } zend_stack_push(&self->call_stack, func_name, func_name_len + 1); + zend_stack_push(&self->call_time_stack, &some_time, sizeof(some_time)); if (zend_hash_num_elements(&self->not_filtered_functions) && 0 == zend_hash_exists(&self->not_filtered_functions, func_name, strlen(func_name) + 1)) @@ -341,9 +344,12 @@ MYSQLND_METHOD(mysqlnd_debug, func_enter)(MYSQLND_DEBUG * self, /* {{{ mysqlnd_res_meta::func_leave */ static enum_func_status -MYSQLND_METHOD(mysqlnd_debug, func_leave)(MYSQLND_DEBUG * self, unsigned int line, const char * const file) +MYSQLND_METHOD(mysqlnd_debug, func_leave)(MYSQLND_DEBUG * self, unsigned int line, const char * const file, uint64_t call_time) { char *func_name; + uint64_t * parent_non_own_time_ptr = NULL, * mine_non_own_time_ptr = NULL; + uint64_t mine_non_own_time; + if ((self->flags & MYSQLND_DEBUG_DUMP_TRACE) == 0 || self->file_name == NULL) { return PASS; } @@ -353,15 +359,34 @@ MYSQLND_METHOD(mysqlnd_debug, func_leave)(MYSQLND_DEBUG * self, unsigned int lin zend_stack_top(&self->call_stack, (void **)&func_name); + + zend_stack_top(&self->call_time_stack, (void **)&mine_non_own_time_ptr); + mine_non_own_time = *mine_non_own_time_ptr; + zend_stack_del_top(&self->call_time_stack); /* callee - removing ourselves */ + if (func_name[0] == '\0') { ; /* don't log that function */ } else if (!zend_hash_num_elements(&self->not_filtered_functions) || 1 == zend_hash_exists(&self->not_filtered_functions, func_name, strlen(func_name) + 1)) { - self->m->log_va(self, line, file, zend_stack_count(&self->call_stack) - 1, NULL, "<%s", func_name); + self->m->log_va(self, line, file, zend_stack_count(&self->call_stack) - 1, NULL, "<%s (total=%u own=%u in_calls=%u)", + func_name, (unsigned int) call_time, (unsigned int) (call_time - mine_non_own_time), (unsigned int) mine_non_own_time + ); } - return zend_stack_del_top(&self->call_stack) == SUCCESS? PASS:FAIL; + { + enum_func_status ret = zend_stack_del_top(&self->call_stack) == SUCCESS? PASS:FAIL; + if ((uint) zend_stack_count(&self->call_time_stack)) { + uint64_t parent_non_own_time = 0; + + zend_stack_top(&self->call_time_stack, (void **)&parent_non_own_time_ptr); + parent_non_own_time = *parent_non_own_time_ptr; + parent_non_own_time += call_time; + zend_stack_del_top(&self->call_time_stack); /* the caller */ + zend_stack_push(&self->call_time_stack, &parent_non_own_time, sizeof(parent_non_own_time)); /* add back the caller */ + } + return ret; + } } /* }}} */ @@ -389,6 +414,7 @@ MYSQLND_METHOD(mysqlnd_debug, free)(MYSQLND_DEBUG * self) self->file_name = NULL; } zend_stack_destroy(&self->call_stack); + zend_stack_destroy(&self->call_time_stack); zend_hash_destroy(&self->not_filtered_functions); efree(self); return PASS; @@ -613,6 +639,7 @@ mysqlnd_debug_init(const char * skip_functions[] TSRMLS_DC) ret->nest_level_limit = 0; ret->pid = getpid(); zend_stack_init(&ret->call_stack); + zend_stack_init(&ret->call_time_stack); zend_hash_init(&ret->not_filtered_functions, 0, NULL, NULL, 0); ret->m = & mysqlnd_mysqlnd_debug_methods; @@ -640,6 +667,9 @@ PHPAPI void _mysqlnd_debug(const char * mode TSRMLS_DC) while (zend_stack_count(&dbg->call_stack)) { zend_stack_del_top(&dbg->call_stack); } + while (zend_stack_count(&dbg->call_time_stack)) { + zend_stack_del_top(&dbg->call_time_stack); + } #endif } /* }}} */ diff --git a/ext/mysqlnd/mysqlnd_debug.h b/ext/mysqlnd/mysqlnd_debug.h index 5e7e0382be..100578745e 100644 --- a/ext/mysqlnd/mysqlnd_debug.h +++ b/ext/mysqlnd/mysqlnd_debug.h @@ -35,7 +35,7 @@ struct st_mysqlnd_debug_methods unsigned int level, const char * type, const char *format, ...); zend_bool (*func_enter)(MYSQLND_DEBUG *self, unsigned int line, const char * const file, const char * const func_name, unsigned int func_name_len); - enum_func_status (*func_leave)(MYSQLND_DEBUG *self, unsigned int line, const char * const file); + enum_func_status (*func_leave)(MYSQLND_DEBUG *self, unsigned int line, const char * const file, uint64_t call_time); enum_func_status (*close)(MYSQLND_DEBUG *self); enum_func_status (*free_handle)(MYSQLND_DEBUG *self); }; @@ -52,6 +52,7 @@ struct st_mysqlnd_debug int pid; char * file_name; zend_stack call_stack; + zend_stack call_time_stack; HashTable not_filtered_functions; struct st_mysqlnd_debug_methods *m; const char ** skip_functions; @@ -63,16 +64,38 @@ PHPAPI MYSQLND_DEBUG * mysqlnd_debug_init(const char * skip_functions[] TSRMLS_D PHPAPI char * mysqlnd_get_backtrace(uint max_levels, size_t * length TSRMLS_DC); -/* Variadic Macros were introduced in VC 2005, which is _MSC_VER 1400 */ -#if defined(__GNUC__) || (defined(_MSC_VER) && _MSC_VER >= 1400) +#if defined(__GNUC__) || (defined(_MSC_VER) && (_MSC_VER >= 1400)) +#define DBG_PROFILE_TIMEVAL_TO_DOUBLE(tp) ((tp.tv_sec * 1000000LL)+ tp.tv_usec) +#define DBG_PROFILE_DECLARE_TIMEVARS struct timeval __tp = {0}; uint64_t __start = 0; /* initialization is needed */ +#define DBG_PROFILE_START_TIME() gettimeofday(&__tp, NULL); __start = DBG_PROFILE_TIMEVAL_TO_DOUBLE(__tp); +#define DBG_PROFILE_END_TIME(duration) gettimeofday(&__tp, NULL); (duration) = (DBG_PROFILE_TIMEVAL_TO_DOUBLE(__tp) - __start); + #define DBG_INF_EX(dbg_obj, msg) do { if (dbg_skip_trace == FALSE) (dbg_obj)->m->log((dbg_obj), __LINE__, __FILE__, -1, "info : ", (msg)); } while (0) #define DBG_ERR_EX(dbg_obj, msg) do { if (dbg_skip_trace == FALSE) (dbg_obj)->m->log((dbg_obj), __LINE__, __FILE__, -1, "error: ", (msg)); } while (0) #define DBG_INF_FMT_EX(dbg_obj, ...) do { if (dbg_skip_trace == FALSE) (dbg_obj)->m->log_va((dbg_obj), __LINE__, __FILE__, -1, "info : ", __VA_ARGS__); } while (0) #define DBG_ERR_FMT_EX(dbg_obj, ...) do { if (dbg_skip_trace == FALSE) (dbg_obj)->m->log_va((dbg_obj), __LINE__, __FILE__, -1, "error: ", __VA_ARGS__); } while (0) -#define DBG_ENTER_EX(dbg_obj, func_name) zend_bool dbg_skip_trace = TRUE; if ((dbg_obj)) dbg_skip_trace = !(dbg_obj)->m->func_enter((dbg_obj), __LINE__, __FILE__, func_name, strlen(func_name)); -#define DBG_RETURN_EX(dbg_obj, value) do { if ((dbg_obj)) (dbg_obj)->m->func_leave((dbg_obj), __LINE__, __FILE__); return (value); } while (0) -#define DBG_VOID_RETURN_EX(dbg_obj) do { if ((dbg_obj)) (dbg_obj)->m->func_leave((dbg_obj), __LINE__, __FILE__); return; } while (0) +#define DBG_ENTER_EX(dbg_obj, func_name) DBG_PROFILE_DECLARE_TIMEVARS; zend_bool dbg_skip_trace = TRUE; \ + if ((dbg_obj)) dbg_skip_trace = !(dbg_obj)->m->func_enter((dbg_obj), __LINE__, __FILE__, func_name, strlen(func_name)); \ + do { DBG_PROFILE_START_TIME(); } while (0); +#define DBG_RETURN_EX(dbg_obj, value) \ + do {\ + if ((dbg_obj)) { \ + uint64_t this_call_duration = 0; \ + DBG_PROFILE_END_TIME(this_call_duration); \ + (dbg_obj)->m->func_leave((dbg_obj), __LINE__, __FILE__, this_call_duration); \ + } \ + return (value);\ + } while (0) +#define DBG_VOID_RETURN_EX(dbg_obj) \ + do {\ + if ((dbg_obj)) { \ + uint64_t this_call_duration = 0; \ + DBG_PROFILE_END_TIME(this_call_duration); \ + (dbg_obj)->m->func_leave((dbg_obj), __LINE__, __FILE__, this_call_duration); \ + } \ + return;\ + } while (0) #else static inline void DBG_INF_EX(MYSQLND_DEBUG * dbg_obj, const char * const msg) {} diff --git a/ext/pdo_mysql/php_pdo_mysql_int.h b/ext/pdo_mysql/php_pdo_mysql_int.h index c6cc9fc5fc..7a9439e1b7 100755 --- a/ext/pdo_mysql/php_pdo_mysql_int.h +++ b/ext/pdo_mysql/php_pdo_mysql_int.h @@ -41,8 +41,8 @@ #define PDO_DBG_INF_FMT(...) do { if (dbg_skip_trace == FALSE) PDO_MYSQL_G(dbg)->m->log_va(PDO_MYSQL_G(dbg), __LINE__, __FILE__, -1, "info : ", __VA_ARGS__); } while (0) #define PDO_DBG_ERR_FMT(...) do { if (dbg_skip_trace == FALSE) PDO_MYSQL_G(dbg)->m->log_va(PDO_MYSQL_G(dbg), __LINE__, __FILE__, -1, "error: ", __VA_ARGS__); } while (0) #define PDO_DBG_ENTER(func_name) zend_bool dbg_skip_trace = TRUE; if (PDO_MYSQL_G(dbg)) dbg_skip_trace = !PDO_MYSQL_G(dbg)->m->func_enter(PDO_MYSQL_G(dbg), __LINE__, __FILE__, func_name, strlen(func_name)); -#define PDO_DBG_RETURN(value) do { if (PDO_MYSQL_G(dbg)) PDO_MYSQL_G(dbg)->m->func_leave(PDO_MYSQL_G(dbg), __LINE__, __FILE__); return (value); } while (0) -#define PDO_DBG_VOID_RETURN do { if (PDO_MYSQL_G(dbg)) PDO_MYSQL_G(dbg)->m->func_leave(PDO_MYSQL_G(dbg), __LINE__, __FILE__); return; } while (0) +#define PDO_DBG_RETURN(value) do { if (PDO_MYSQL_G(dbg)) PDO_MYSQL_G(dbg)->m->func_leave(PDO_MYSQL_G(dbg), __LINE__, __FILE__, 0); return (value); } while (0) +#define PDO_DBG_VOID_RETURN do { if (PDO_MYSQL_G(dbg)) PDO_MYSQL_G(dbg)->m->func_leave(PDO_MYSQL_G(dbg), __LINE__, __FILE__, 0); return; } while (0) #else #define PDO_DBG_ENABLED 0