diff --git a/classes/db/DB.class.php b/classes/db/DB.class.php index 25a7cdb10..849f6ea3a 100644 --- a/classes/db/DB.class.php +++ b/classes/db/DB.class.php @@ -447,7 +447,8 @@ class DB $log['act'] = Context::get('act'); $log['time'] = date('Y-m-d H:i:s'); - $bt = debug_backtrace(); + $bt = version_compare(PHP_VERSION, '5.3.6', '>=') ? debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS) : debug_backtrace(); + foreach($bt as $no => $call) { if($call['function'] == 'executeQuery' || $call['function'] == 'executeQueryArray') @@ -455,6 +456,7 @@ class DB $call_no = $no; $call_no++; $log['called_file'] = $bt[$call_no]['file'].':'.$bt[$call_no]['line']; + $log['called_file'] = str_replace(_XE_PATH_ , '', $log['called_file']); $call_no++; $log['called_method'] = $bt[$call_no]['class'].$bt[$call_no]['type'].$bt[$call_no]['function']; break; @@ -487,20 +489,12 @@ class DB $this->setQueryLog($log); - // if __LOG_SLOW_QUERY__ if defined, check elapsed time and leave query log - if(__LOG_SLOW_QUERY__ > 0 && $elapsed_time > __LOG_SLOW_QUERY__) - { - $buff = ''; - $log_file = _XE_PATH_ . 'files/_db_slow_query.php'; - if(!file_exists($log_file)) - { - $buff = '' . "\n"; - } - - $buff .= sprintf("%s\t%s\n\t%0.6f sec\tquery_id:%s\n\n", date("Y-m-d H:i"), $this->query, $elapsed_time, $this->query_id); - - @file_put_contents($log_file, $buff, FILE_APPEND|LOCK_EX); - } + $log_args = new stdClass; + $log_args->query = $this->query; + $log_args->query_id = $this->query_id; + $log_args->caller = $log['called_method'] . '() in ' . $log['called_file']; + $log_args->connection = $log['connection']; + writeSlowlog('query', $elapsed_time, $log_args); } /** diff --git a/classes/module/ModuleHandler.class.php b/classes/module/ModuleHandler.class.php index fde57e049..f47aaf4f0 100644 --- a/classes/module/ModuleHandler.class.php +++ b/classes/module/ModuleHandler.class.php @@ -1152,7 +1152,7 @@ class ModuleHandler extends Handler $before_trigger_time = NULL; if(__LOG_SLOW_TRIGGER__> 0) { - $before_trigger_time = microtime(true); + $before_trigger_time = microtime(true); } foreach($triggers as $item) @@ -1160,12 +1160,6 @@ class ModuleHandler extends Handler $module = $item->module; $type = $item->type; $called_method = $item->called_method; - - $before_each_trigger_time = NULL; - if(__LOG_SLOW_TRIGGER__> 0) - { - $before_each_trigger_time = microtime(true); - } // todo why don't we call a normal class object ? $oModule = getModule($module, $type); @@ -1174,63 +1168,24 @@ class ModuleHandler extends Handler continue; } + $before_each_trigger_time = microtime(true); + $output = $oModule->{$called_method}($obj); + + $after_each_trigger_time = microtime(true); + $elapsed_time_trigger = $after_each_trigger_time - $before_each_trigger_time; + + $slowlog = new stdClass; + $slowlog->caller = $trigger_name . '.' . $called_position; + $slowlog->called = $module . '.' . $called_method; + $slowlog->called_extension = $module; + if($trigger_name != 'XE.writeSlowlog') writeSlowlog('trigger', $elapsed_time_trigger, $slowlog); + if(is_object($output) && method_exists($output, 'toBool') && !$output->toBool()) { return $output; } unset($oModule); - - //store after trigger call time - $after_each_trigger_time = NULL; - //init value to 0 - $elapsed_time_trigger = 0; - - if(__LOG_SLOW_TRIGGER__> 0) - { - $after_each_trigger_time = microtime(true); - $elapsed_time_trigger = ($after_each_trigger_time - $before_each_trigger_time) * 1000; - } - - // if __LOG_SLOW_TRIGGER__ is defined, check elapsed time and leave trigger time log - if(__LOG_SLOW_TRIGGER__> 0 && $elapsed_time_trigger > __LOG_SLOW_TRIGGER__) - { - $buff = ''; - $log_file = _XE_PATH_ . 'files/_db_slow_trigger.php'; - if(!file_exists($log_file)) - { - $buff = '' . "\n"; - } - - $buff .= sprintf("%s\t%s.%s.%s.%s(%s)\n\t%0.6f msec\n\n", date("Y-m-d H:i"), $item->trigger_name,$item->module,$item->called_method,$item->called_position,$item->type, $elapsed_time_trigger); - - @file_put_contents($log_file, $buff, FILE_APPEND|LOCK_EX); - } - } - - //store after trigger call time - $after_trigger_time = NULL; - //init value to 0 - $elapsed_time = 0; - if(__LOG_SLOW_TRIGGER__> 0) - { - $after_trigger_time = microtime(true); - $elapsed_time = ($after_trigger_time - $before_trigger_time) * 1000; - } - - // if __LOG_SLOW_TRIGGER__ is defined, check elapsed time and leave trigger time log - if(__LOG_SLOW_TRIGGER__> 0 && $elapsed_time > __LOG_SLOW_TRIGGER__) - { - $buff = ''; - $log_file = _XE_PATH_ . 'files/_slow_trigger.php'; - if(!file_exists($log_file)) - { - $buff = '' . "\n"; - } - - $buff .= sprintf("%s\t%s.totaltime\n\t%0.6f msec\n\n", date("Y-m-d H:i"), $trigger_name,$elapsed_time); - - @file_put_contents($log_file, $buff, FILE_APPEND|LOCK_EX); } return new Object(); diff --git a/config/func.inc.php b/config/func.inc.php index 08a9c4a33..c6cf6d952 100644 --- a/config/func.inc.php +++ b/config/func.inc.php @@ -838,6 +838,60 @@ function debugPrint($debug_output = NULL, $display_option = TRUE, $file = '_debu } } +/** + * @param string $type query, trigger + * @param float $elapsed_time + * @param object $obj + */ +function writeSlowlog($type, $elapsed_time, $obj) +{ + static $log_filename = array( + 'query' => 'files/_slowlog_query.php', + 'trigger' => 'files/_slowlog_trigger.php', + 'addon' => 'files/_slowlog_addon.php' + ); + $write_file = true; + + $log_file = _XE_PATH_ . $log_filename[$type]; + + $buff = array(); + $buff[] = ''; + $buff[] = date('c'); + + if($type == 'trigger' && __LOG_SLOW_TRIGGER__ > 0 && $elapsed_time > __LOG_SLOW_TRIGGER__) + { + $buff[] = "\tCaller : " . $obj->caller; + $buff[] = "\tCalled : " . $obj->called; + } + else if($type == 'query' && __LOG_SLOW_QUERY__ > 0 && $elapsed_time > __LOG_SLOW_QUERY__) + { + + $buff[] = $obj->query; + $buff[] = "\tQuery ID : " . $obj->query_id; + $buff[] = "\tCaller : " . $obj->caller; + $buff[] = "\tConnection : " . $obj->connection; + } + else + { + $write_file = false; + } + + if($write_file) + { + $buff[] = sprintf("\t%0.6f sec", $elapsed_time); + $buff[] = PHP_EOL . PHP_EOL; + file_put_contents($log_file, implode(PHP_EOL, $buff), FILE_APPEND); + } + + $trigger_args = $obj; + $trigger_args->_log_type = $type; + $trigger_args->_elapsed_time = $elapsed_time; + if($type != 'query') + { + ModuleHandler::triggerCall('XE.writeSlowlog', 'after', $trigger_args); + } +} + /** * microtime() return *