diff options
Diffstat (limited to 'ext/mysqlnd/mysqlnd_debug.c')
| -rw-r--r-- | ext/mysqlnd/mysqlnd_debug.c | 218 |
1 files changed, 189 insertions, 29 deletions
diff --git a/ext/mysqlnd/mysqlnd_debug.c b/ext/mysqlnd/mysqlnd_debug.c index 575efacac..692c81ee2 100644 --- a/ext/mysqlnd/mysqlnd_debug.c +++ b/ext/mysqlnd/mysqlnd_debug.c @@ -18,7 +18,7 @@ +----------------------------------------------------------------------+ */ -/* $Id: mysqlnd_debug.c 300635 2010-06-21 15:32:26Z andrey $ */ +/* $Id: mysqlnd_debug.c 305389 2010-11-15 23:46:21Z pajoye $ */ #include "php.h" #include "mysqlnd.h" @@ -36,16 +36,6 @@ static const char * const mysqlnd_debug_default_trace_file = "/tmp/mysqlnd.trace #define MYSQLND_ZTS(self) #endif -#define MYSQLND_DEBUG_DUMP_TIME 1 -#define MYSQLND_DEBUG_DUMP_TRACE 2 -#define MYSQLND_DEBUG_DUMP_PID 4 -#define MYSQLND_DEBUG_DUMP_LINE 8 -#define MYSQLND_DEBUG_DUMP_FILE 16 -#define MYSQLND_DEBUG_DUMP_LEVEL 32 -#define MYSQLND_DEBUG_APPEND 64 -#define MYSQLND_DEBUG_FLUSH 128 -#define MYSQLND_DEBUG_TRACE_MEMORY_CALLS 256 - static const char mysqlnd_emalloc_name[] = "_mysqlnd_emalloc"; static const char mysqlnd_pemalloc_name[] = "_mysqlnd_pemalloc"; static const char mysqlnd_ecalloc_name[] = "_mysqlnd_ecalloc"; @@ -81,6 +71,7 @@ const char * mysqlnd_debug_std_no_trace_funcs[] = NULL /* must be always last */ }; + /* {{{ mysqlnd_debug::open */ static enum_func_status MYSQLND_METHOD(mysqlnd_debug, open)(MYSQLND_DEBUG * self, zend_bool reopen) @@ -287,7 +278,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 */ @@ -301,7 +291,7 @@ MYSQLND_METHOD(mysqlnd_debug, log_va)(MYSQLND_DEBUG *self, /* FALSE - The DBG_ calls won't be traced, TRUE - will be traced */ -/* {{{ mysqlnd_res_meta::func_enter */ +/* {{{ mysqlnd_debug::func_enter */ static zend_bool MYSQLND_METHOD(mysqlnd_debug, func_enter)(MYSQLND_DEBUG * self, unsigned int line, const char * const file, @@ -319,6 +309,12 @@ MYSQLND_METHOD(mysqlnd_debug, func_enter)(MYSQLND_DEBUG * self, while (*p) { if (*p == func_name) { zend_stack_push(&self->call_stack, "", sizeof("")); +#ifndef MYSQLND_PROFILING_DISABLED + if (self->flags & MYSQLND_DEBUG_PROFILE_CALLS) { + uint64_t some_time = 0; + zend_stack_push(&self->call_time_stack, &some_time, sizeof(some_time)); + } +#endif return FALSE; } p++; @@ -326,6 +322,12 @@ MYSQLND_METHOD(mysqlnd_debug, func_enter)(MYSQLND_DEBUG * self, } zend_stack_push(&self->call_stack, func_name, func_name_len + 1); +#ifndef MYSQLND_PROFILING_DISABLED + if (self->flags & MYSQLND_DEBUG_PROFILE_CALLS) { + uint64_t some_time = 0; + zend_stack_push(&self->call_time_stack, &some_time, sizeof(some_time)); + } +#endif if (zend_hash_num_elements(&self->not_filtered_functions) && 0 == zend_hash_exists(&self->not_filtered_functions, func_name, strlen(func_name) + 1)) @@ -338,12 +340,34 @@ MYSQLND_METHOD(mysqlnd_debug, func_enter)(MYSQLND_DEBUG * self, } /* }}} */ +#ifndef MYSQLND_PROFILING_DISABLED +struct st_mysqlnd_dbg_function_profile { + uint64_t calls; + uint64_t min_own; + uint64_t max_own; + uint64_t avg_own; + uint64_t own_underporm_calls; + uint64_t min_in_calls; + uint64_t max_in_calls; + uint64_t avg_in_calls; + uint64_t in_calls_underporm_calls; + uint64_t min_total; + uint64_t max_total; + uint64_t avg_total; + uint64_t total_underporm_calls; +}; +#define PROFILE_UNDERPERFORM_THRESHOLD 10 +#endif -/* {{{ mysqlnd_res_meta::func_leave */ +/* {{{ mysqlnd_debug::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 = 0; + zend_bool profile_calls = self->flags & MYSQLND_DEBUG_PROFILE_CALLS? TRUE:FALSE; + if ((self->flags & MYSQLND_DEBUG_DUMP_TRACE) == 0 || self->file_name == NULL) { return PASS; } @@ -353,12 +377,92 @@ MYSQLND_METHOD(mysqlnd_debug, func_leave)(MYSQLND_DEBUG * self, unsigned int lin zend_stack_top(&self->call_stack, (void **)&func_name); +#ifndef MYSQLND_PROFILING_DISABLED + if (profile_calls) { + 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 */ + } +#endif + 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); +#ifndef MYSQLND_PROFILING_DISABLED + if (FALSE == profile_calls) { +#endif + self->m->log_va(self, line, file, zend_stack_count(&self->call_stack) - 1, NULL, "<%s", func_name); + +#ifndef MYSQLND_PROFILING_DISABLED + } else { + struct st_mysqlnd_dbg_function_profile f_profile_stack = {0}; + struct st_mysqlnd_dbg_function_profile * f_profile = NULL; + uint64_t own_time = call_time - mine_non_own_time; + uint func_name_len = strlen(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) own_time, (unsigned int) mine_non_own_time + ); + + if (SUCCESS == zend_hash_find(&self->function_profiles, func_name, func_name_len + 1, (void **) &f_profile)) { + /* found */ + if (f_profile) { + if (mine_non_own_time < f_profile->min_in_calls) { + f_profile->min_in_calls = mine_non_own_time; + } else if (mine_non_own_time > f_profile->max_in_calls) { + f_profile->max_in_calls = mine_non_own_time; + } + f_profile->avg_in_calls = (f_profile->avg_in_calls * f_profile->calls + mine_non_own_time) / (f_profile->calls + 1); + + if (own_time < f_profile->min_own) { + f_profile->min_own = own_time; + } else if (own_time > f_profile->max_own) { + f_profile->max_own = own_time; + } + f_profile->avg_own = (f_profile->avg_own * f_profile->calls + own_time) / (f_profile->calls + 1); + + if (call_time < f_profile->min_total) { + f_profile->min_total = call_time; + } else if (call_time > f_profile->max_total) { + f_profile->max_total = call_time; + } + f_profile->avg_total = (f_profile->avg_total * f_profile->calls + call_time) / (f_profile->calls + 1); + + ++f_profile->calls; + if (f_profile->calls > PROFILE_UNDERPERFORM_THRESHOLD) { + if (f_profile->avg_in_calls < mine_non_own_time) { + f_profile->in_calls_underporm_calls++; + } + if (f_profile->avg_own < own_time) { + f_profile->own_underporm_calls++; + } + if (f_profile->avg_total < call_time) { + f_profile->total_underporm_calls++; + } + } + } + } else { + /* add */ + f_profile = &f_profile_stack; + f_profile->min_in_calls = f_profile->max_in_calls = f_profile->avg_in_calls = mine_non_own_time; + f_profile->min_total = f_profile->max_total = f_profile->avg_total = call_time; + f_profile->min_own = f_profile->max_own = f_profile->avg_own = own_time; + f_profile->calls = 1; + zend_hash_add(&self->function_profiles, func_name, func_name_len+1, f_profile, sizeof(struct st_mysqlnd_dbg_function_profile), NULL); + } + 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 */ + } + } +#endif } return zend_stack_del_top(&self->call_stack) == SUCCESS? PASS:FAIL; @@ -366,15 +470,57 @@ MYSQLND_METHOD(mysqlnd_debug, func_leave)(MYSQLND_DEBUG * self, unsigned int lin /* }}} */ -/* {{{ mysqlnd_res_meta::close */ +/* {{{ mysqlnd_debug::close */ static enum_func_status MYSQLND_METHOD(mysqlnd_debug, close)(MYSQLND_DEBUG * self) { MYSQLND_ZTS(self); if (self->stream) { +#ifndef MYSQLND_PROFILING_DISABLED + if (!(self->flags & MYSQLND_DEBUG_FLUSH) && (self->flags & MYSQLND_DEBUG_PROFILE_CALLS)) { + struct st_mysqlnd_dbg_function_profile * f_profile; + HashPosition pos_values; + + self->m->log_va(self, __LINE__, __FILE__, 0, "info : ", + "number of functions: %d", zend_hash_num_elements(&self->function_profiles)); + zend_hash_internal_pointer_reset_ex(&self->function_profiles, &pos_values); + while (zend_hash_get_current_data_ex(&self->function_profiles, (void **) &f_profile, &pos_values) == SUCCESS) { + char *string_key = NULL; + uint string_key_len; + ulong num_key; + + zend_hash_get_current_key_ex(&self->function_profiles, &string_key, &string_key_len, &num_key, 0, &pos_values); + + self->m->log_va(self, __LINE__, __FILE__, -1, "info : ", + "%-40s\tcalls=%5llu own_slow=%5llu in_calls_slow=%5llu total_slow=%5llu" + " min_own=%5llu max_own=%7llu avg_own=%7llu " + " min_in_calls=%5llu max_in_calls=%7llu avg_in_calls=%7llu" + " min_total=%5llu max_total=%7llu avg_total=%7llu" + ,string_key + ,(uint64_t) f_profile->calls + ,(uint64_t) f_profile->own_underporm_calls + ,(uint64_t) f_profile->in_calls_underporm_calls + ,(uint64_t) f_profile->total_underporm_calls + + ,(uint64_t) f_profile->min_own + ,(uint64_t) f_profile->max_own + ,(uint64_t) f_profile->avg_own + ,(uint64_t) f_profile->min_in_calls + ,(uint64_t) f_profile->max_in_calls + ,(uint64_t) f_profile->avg_in_calls + ,(uint64_t) f_profile->min_total + ,(uint64_t) f_profile->max_total + ,(uint64_t) f_profile->avg_total + ); + zend_hash_move_forward_ex(&self->function_profiles, &pos_values); + } + } +#endif + php_stream_free(self->stream, PHP_STREAM_FREE_CLOSE); self->stream = NULL; } + /* no DBG_RETURN please */ return PASS; } /* }}} */ @@ -389,7 +535,9 @@ 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); + zend_hash_destroy(&self->function_profiles); efree(self); return PASS; } @@ -433,6 +581,11 @@ MYSQLND_METHOD(mysqlnd_debug, set_mode)(MYSQLND_DEBUG * self, const char * const } if (i + 1 < mode_len && mode[i+1] == ',') { unsigned int j = i + 2; +#ifdef PHP_WIN32 + if (i+4 < mode_len && mode[i+3] == ':' && (mode[i+4] == '\\' || mode[i+5] == '/')) { + j = i + 5; + } +#endif while (j < mode_len) { if (mode[j] == ':') { break; @@ -562,6 +715,10 @@ MYSQLND_METHOD(mysqlnd_debug, set_mode)(MYSQLND_DEBUG * self, const char * const self->flags |= MYSQLND_DEBUG_TRACE_MEMORY_CALLS; state = PARSER_WAIT_COLON; break; + case 'x': /* mysqlnd extension - profile calls */ + self->flags |= MYSQLND_DEBUG_PROFILE_CALLS; + state = PARSER_WAIT_COLON; + break; default: if (state == PARSER_WAIT_MODIFIER) { #if 0 @@ -588,7 +745,6 @@ MYSQLND_METHOD(mysqlnd_debug, set_mode)(MYSQLND_DEBUG * self, const char * const } /* }}} */ - MYSQLND_CLASS_METHODS_START(mysqlnd_debug) MYSQLND_METHOD(mysqlnd_debug, open), MYSQLND_METHOD(mysqlnd_debug, set_mode), @@ -601,7 +757,6 @@ MYSQLND_CLASS_METHODS_START(mysqlnd_debug) MYSQLND_CLASS_METHODS_END; - /* {{{ mysqlnd_debug_init */ PHPAPI MYSQLND_DEBUG * mysqlnd_debug_init(const char * skip_functions[] TSRMLS_DC) @@ -613,11 +768,13 @@ 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); + zend_hash_init(&ret->function_profiles, 0, NULL, NULL, 0); ret->m = & mysqlnd_mysqlnd_debug_methods; ret->skip_functions = skip_functions; - + return ret; } /* }}} */ @@ -634,12 +791,15 @@ PHPAPI void _mysqlnd_debug(const char * mode TSRMLS_DC) return; } } - + dbg->m->close(dbg); dbg->m->set_mode(dbg, mode); 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 } /* }}} */ @@ -650,7 +810,7 @@ PHPAPI void _mysqlnd_debug(const char * mode TSRMLS_DC) #define __zend_filename "/unknown/unknown" #define __zend_lineno 0 #endif - + #define REAL_SIZE(s) (collect_memory_statistics? (s) + sizeof(size_t) : (s)) #define REAL_PTR(p) (collect_memory_statistics && (p)? (((char *)(p)) - sizeof(size_t)) : (p)) #define FAKE_PTR(p) (collect_memory_statistics && (p)? (((char *)(p)) + sizeof(size_t)) : (p)) @@ -1092,7 +1252,9 @@ char * _mysqlnd_pestrdup(const char * const ptr, zend_bool persistent MYSQLND_ME } /* }}} */ -#if MYSQLND_DEBUG_MEMORY +#define MYSQLND_DEBUG_MEMORY 1 + +#if MYSQLND_DEBUG_MEMORY == 0 /* {{{ mysqlnd_zend_mm_emalloc */ static void * mysqlnd_zend_mm_emalloc(size_t size MYSQLND_MEM_D) @@ -1208,8 +1370,6 @@ static char * mysqlnd_zend_mm_pestrdup(const char * const ptr, zend_bool persist #endif -#define MYSQLND_DEBUG_MEMORY 1 - PHPAPI struct st_mysqlnd_allocator_methods mysqlnd_allocator = { #if MYSQLND_DEBUG_MEMORY @@ -1249,7 +1409,7 @@ PHPAPI struct st_mysqlnd_allocator_methods mysqlnd_allocator = /* Follows code borrowed from zend_builtin_functions.c because the functions there are static */ -#if PHP_MAJOR_VERSION >= 6 +#if MYSQLND_UNICODE /* {{{ gettraceasstring() macros */ #define TRACE_APPEND_CHR(chr) \ *str = (char*)erealloc(*str, *len + 1 + 1); \ @@ -1593,14 +1753,14 @@ static int mysqlnd_build_trace_args(zval **arg TSRMLS_DC, int num_args, va_list case IS_OBJECT: { char *class_name; zend_uint class_name_len; - int dup; + int dupl; TRACE_APPEND_STR("Object("); - dup = zend_get_object_classname(*arg, &class_name, &class_name_len TSRMLS_CC); + dupl = zend_get_object_classname(*arg, &class_name, &class_name_len TSRMLS_CC); TRACE_APPEND_STRL(class_name, class_name_len); - if(!dup) { + if (!dupl) { efree(class_name); } |