From c5deb4726f6d0e875554f35ee8d5b3b114b49d62 Mon Sep 17 00:00:00 2001 From: YJSoft Date: Sat, 14 Jun 2014 15:55:53 +0900 Subject: [PATCH 1/6] =?UTF-8?q?#785=20slow=20trigger=20=EA=B8=B0=EB=A1=9D?= =?UTF-8?q?=20=EA=B8=B0=EB=8A=A5=20=EC=B6=94=EA=B0=80?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- classes/module/ModuleHandler.class.php | 43 ++++++++++++++++++++++++++ 1 file changed, 43 insertions(+) diff --git a/classes/module/ModuleHandler.class.php b/classes/module/ModuleHandler.class.php index 75cf81bc1..bec81826c 100644 --- a/classes/module/ModuleHandler.class.php +++ b/classes/module/ModuleHandler.class.php @@ -1145,12 +1145,17 @@ class ModuleHandler extends Handler { return new Object(); } + + //store before trigger call time + $before_trigger_time = microtime(true); foreach($triggers as $item) { $module = $item->module; $type = $item->type; $called_method = $item->called_method; + + $before_each_trigger_time = microtime(true); // todo why don't we call a normal class object ? $oModule = getModule($module, $type); @@ -1165,6 +1170,44 @@ class ModuleHandler extends Handler return $output; } unset($oModule); + + $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 = 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/_db_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(); From 024e64d2e2ff56ae0838aedc9f869cf501b8beba Mon Sep 17 00:00:00 2001 From: YJSoft Date: Sat, 14 Jun 2014 15:57:15 +0900 Subject: [PATCH 2/6] =?UTF-8?q?#785=20slow=20trigger=20=EA=B4=80=EB=A0=A8?= =?UTF-8?q?=20=EC=84=A4=EC=A0=95=20=EC=B6=94=EA=B0=80?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- config/config.inc.php | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/config/config.inc.php b/config/config.inc.php index 14058f34f..28ddd5373 100644 --- a/config/config.inc.php +++ b/config/config.inc.php @@ -173,6 +173,20 @@ if(!defined('__LOG_SLOW_QUERY__')) define('__LOG_SLOW_QUERY__', 0); } +if(!defined('__LOG_SLOW_TRIGGER__')) +{ + /** + * Trigger excute time log + * + * 
+	 * 0: Do not leave a log
+	 * > 0: leave a log when the trigger takes over specified milliseconds
+	 * Log file is saved as ./files/_db_slow_trigger.php file
+	 *
+ */ + define('__LOG_SLOW_TRIGGER__', 0); +} + if(!defined('__DEBUG_QUERY__')) { /** From 02c1f8b5f683149c73a7f6829de961ad610d88eb Mon Sep 17 00:00:00 2001 From: YJSoft Date: Sat, 14 Jun 2014 18:00:57 +0900 Subject: [PATCH 3/6] =?UTF-8?q?=EC=A1=B0=EA=B1=B4=EC=8B=9D=20=EC=88=98?= =?UTF-8?q?=EC=A0=95?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- classes/module/ModuleHandler.class.php | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/classes/module/ModuleHandler.class.php b/classes/module/ModuleHandler.class.php index bec81826c..1c7cfce31 100644 --- a/classes/module/ModuleHandler.class.php +++ b/classes/module/ModuleHandler.class.php @@ -1175,7 +1175,7 @@ class ModuleHandler extends Handler $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__) + if(__LOG_SLOW_TRIGGER__> 0 && $elapsed_time_trigger > __LOG_SLOW_TRIGGER__) { $buff = ''; $log_file = _XE_PATH_ . 'files/_db_slow_trigger.php'; @@ -1196,7 +1196,7 @@ class ModuleHandler extends Handler $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__) + if(__LOG_SLOW_TRIGGER__> 0 && $elapsed_time > __LOG_SLOW_TRIGGER__) { $buff = ''; $log_file = _XE_PATH_ . 'files/_db_slow_trigger.php'; From 4ed0c75d05d7d58addb2273f519ffe45a6424306 Mon Sep 17 00:00:00 2001 From: YJSoft Date: Sat, 5 Jul 2014 21:44:30 +0900 Subject: [PATCH 4/6] =?UTF-8?q?=EC=83=81=EC=88=98=EA=B0=80=20=EC=84=A0?= =?UTF-8?q?=EC=96=B8=EB=90=98=EC=96=B4=20=EC=9E=88=EC=A7=80=20=EC=95=8A?= =?UTF-8?q?=EC=9C=BC=EB=A9=B4=20=EA=B3=84=EC=82=B0=20=EC=95=88=ED=95=A8=20?= =?UTF-8?q?&=20=EC=83=9D=EC=84=B1=EB=90=98=EB=8A=94=20=ED=8C=8C=EC=9D=BC?= =?UTF-8?q?=20=EC=9D=B4=EB=A6=84=20=EB=B3=80=EA=B2=BD?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit microtime이나 $elapsed_time 계산 부분을 제외 생성되는 파일 이름을 _db_slow_trigger.php에서 _slow_trigger.php로 변경(_db 삭제) --- classes/module/ModuleHandler.class.php | 21 +++++++++++++++------ 1 file changed, 15 insertions(+), 6 deletions(-) diff --git a/classes/module/ModuleHandler.class.php b/classes/module/ModuleHandler.class.php index 1c7cfce31..0d03b3a04 100644 --- a/classes/module/ModuleHandler.class.php +++ b/classes/module/ModuleHandler.class.php @@ -1147,7 +1147,11 @@ class ModuleHandler extends Handler } //store before trigger call time - $before_trigger_time = microtime(true); + $before_trigger_time = NULL; + if(!defined('__LOG_SLOW_TRIGGER__')) + { + $before_trigger_time = microtime(true); + } foreach($triggers as $item) { @@ -1191,15 +1195,20 @@ class ModuleHandler extends Handler } //store after trigger call time - $after_trigger_time = microtime(true); - - $elapsed_time = ($after_trigger_time - $before_trigger_time) * 1000; - + $after_trigger_time = NULL; + //init value to 0 + $elapsed_time = 0; + if(!defined('__LOG_SLOW_TRIGGER__')) + { + $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/_db_slow_trigger.php'; + $log_file = _XE_PATH_ . 'files/_slow_trigger.php'; if(!file_exists($log_file)) { $buff = '' . "\n"; From 2e7a223b6159c94544f1c85fdb9ed7b3558c2269 Mon Sep 17 00:00:00 2001 From: YJSoft Date: Sat, 5 Jul 2014 21:48:22 +0900 Subject: [PATCH 5/6] =?UTF-8?q?=EC=A1=B0=EA=B1=B4=EC=8B=9D=20=EC=88=98?= =?UTF-8?q?=EC=A0=95=20&=20=EA=B0=9C=EB=B3=84=20trigger=EC=97=90=EB=8F=84?= =?UTF-8?q?=20=EC=A0=81=EC=9A=A9?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 정의 되었을때 계산해야 하므로.. 헷갈렸네요 --- classes/module/ModuleHandler.class.php | 22 +++++++++++++++++----- 1 file changed, 17 insertions(+), 5 deletions(-) diff --git a/classes/module/ModuleHandler.class.php b/classes/module/ModuleHandler.class.php index 0d03b3a04..5d97ba525 100644 --- a/classes/module/ModuleHandler.class.php +++ b/classes/module/ModuleHandler.class.php @@ -1148,7 +1148,7 @@ class ModuleHandler extends Handler //store before trigger call time $before_trigger_time = NULL; - if(!defined('__LOG_SLOW_TRIGGER__')) + if(defined('__LOG_SLOW_TRIGGER__')) { $before_trigger_time = microtime(true); } @@ -1159,7 +1159,11 @@ class ModuleHandler extends Handler $type = $item->type; $called_method = $item->called_method; - $before_each_trigger_time = microtime(true); + $before_each_trigger_time = NULL; + if(defined('__LOG_SLOW_TRIGGER__')) + { + $before_each_trigger_time = microtime(true); + } // todo why don't we call a normal class object ? $oModule = getModule($module, $type); @@ -1175,8 +1179,16 @@ class ModuleHandler extends Handler } unset($oModule); - $after_each_trigger_time = microtime(true); - $elapsed_time_trigger = ($after_each_trigger_time - $before_each_trigger_time) * 1000; + //store after trigger call time + $after_each_trigger_time = NULL; + //init value to 0 + $elapsed_time_trigger = 0; + + if(defined('__LOG_SLOW_TRIGGER__')) + { + $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__) @@ -1198,7 +1210,7 @@ class ModuleHandler extends Handler $after_trigger_time = NULL; //init value to 0 $elapsed_time = 0; - if(!defined('__LOG_SLOW_TRIGGER__')) + if(defined('__LOG_SLOW_TRIGGER__')) { $after_trigger_time = microtime(true); $elapsed_time = ($after_trigger_time - $before_trigger_time) * 1000; From f9e5a23ad38fbf07a0b696238861e13003896d99 Mon Sep 17 00:00:00 2001 From: YJSoft Date: Sun, 6 Jul 2014 12:06:33 +0900 Subject: [PATCH 6/6] =?UTF-8?q?=EC=A1=B0=EA=B1=B4=EC=8B=9D=20=EB=B3=80?= =?UTF-8?q?=EA=B2=BD(>0)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit __LOG_SLOW_TRIGGER__는 config.inc.php에서 항상 정의되므로 --- classes/module/ModuleHandler.class.php | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/classes/module/ModuleHandler.class.php b/classes/module/ModuleHandler.class.php index 5d97ba525..df4f24af9 100644 --- a/classes/module/ModuleHandler.class.php +++ b/classes/module/ModuleHandler.class.php @@ -1148,7 +1148,7 @@ class ModuleHandler extends Handler //store before trigger call time $before_trigger_time = NULL; - if(defined('__LOG_SLOW_TRIGGER__')) + if(__LOG_SLOW_TRIGGER__> 0) { $before_trigger_time = microtime(true); } @@ -1160,7 +1160,7 @@ class ModuleHandler extends Handler $called_method = $item->called_method; $before_each_trigger_time = NULL; - if(defined('__LOG_SLOW_TRIGGER__')) + if(__LOG_SLOW_TRIGGER__> 0) { $before_each_trigger_time = microtime(true); } @@ -1184,7 +1184,7 @@ class ModuleHandler extends Handler //init value to 0 $elapsed_time_trigger = 0; - if(defined('__LOG_SLOW_TRIGGER__')) + if(__LOG_SLOW_TRIGGER__> 0) { $after_each_trigger_time = microtime(true); $elapsed_time_trigger = ($after_each_trigger_time - $before_each_trigger_time) * 1000; @@ -1210,7 +1210,7 @@ class ModuleHandler extends Handler $after_trigger_time = NULL; //init value to 0 $elapsed_time = 0; - if(defined('__LOG_SLOW_TRIGGER__')) + if(__LOG_SLOW_TRIGGER__> 0) { $after_trigger_time = microtime(true); $elapsed_time = ($after_trigger_time - $before_trigger_time) * 1000;