(migration) log cumulative mysql timing info everywhere

add.php

@@ -24,3 +24,4 @@
 } else {
     show_error($config['msg']['notadmin']);
 }
+log_timing();

ajax/add_book_tag.php

@@ -11,4 +11,5 @@
 }
 
 echo '<?xml version="1.0" encoding="utf-8" standalone="yes"?><result ok="'.$result.'"/>';
+log_timing(true);
 ?>

ajax/anaphora.php

@@ -41,4 +41,5 @@
     $res['error'] = 1;
 }
 
+log_timing(true);
 die(json_encode($res));

ajax/annot.php

@@ -30,5 +30,6 @@
 catch (Exception $e) {
     $result = 0;
 }
+log_timing(true);
 echo '<result ok="'.$result.'"/>';
 ?>

ajax/bind_book.php

@@ -37,4 +37,5 @@
 catch (Exception $e) {
     echo '<result ok="0"/>';
 }
+log_timing(true);
 ?>

ajax/clck_log.php

@@ -13,3 +13,4 @@
 }
 
 echo '<?xml version="1.0" encoding="utf-8" standalone="yes"?><result ok="'.$result.'"/>';
+log_timing(true);

ajax/dict_pending.php

@@ -23,4 +23,5 @@
 }
 
 echo '<?xml version="1.0" encoding="utf-8" standalone="yes"?><result ok="'.(int)$res.'"/>';
+log_timing(true);
 ?>

ajax/dict_reload.php

@@ -24,4 +24,5 @@
     echo '</tfr>';
 }
 echo '</response>';
+log_timing(true);
 ?>

ajax/dict_substring_search.php

@@ -6,4 +6,5 @@
 foreach ($res as $line) {
    echo $line['lemma_text'] . '|' . $line['gr'] . '|' . $line['lemma_id'] ."\n";
 }
+log_timing(true);
 ?>

ajax/download_url.php

@@ -10,4 +10,5 @@
 catch (Exception $e) {
     echo '<response ok="0"/>';
 }
+log_timing(true);
 ?>

ajax/game_mark_shown.php

@@ -25,3 +25,4 @@
 }
 
 echo '<?xml version="1.0" encoding="utf-8" standalone="yes"?><result ok="'.(int)$res.'"/>';
+log_timing(true);

ajax/get_comments.php

@@ -21,6 +21,7 @@
 recursive_print(0);
 
 echo '</comments>';
+log_timing(true);
 
 function recursive_print($id) {
     global $comm;

ajax/get_context.php

@@ -11,4 +11,5 @@
     }
 }
 echo '</context>';
+log_timing(true);
 ?>

ajax/lastpar.php

@@ -15,4 +15,5 @@
 $txt .= $r['end'];
 
 echo '<?xml version="1.0" encoding="utf-8" standalone="yes"?><response num="'.$num.'">'.htmlspecialchars($txt).'</response>';
+log_timing(true);
 ?>

ajax/lemma_search.php

@@ -7,4 +7,5 @@
     echo '<lemma id="'.$r['lemma_id'].'"/>';
 }
 echo '</lemmata>';
+log_timing(true);
 ?>

ajax/merge_tokens.php

@@ -15,4 +15,5 @@
 catch (Exception $e) {
     echo '<result ok="0"/>';
 }
+log_timing(true);
 ?>

ajax/ner.php

@@ -87,4 +87,5 @@
     $res['error'] = 1;
 }
 
+log_timing(true);
 die(json_encode($res));

ajax/own_book.php

@@ -26,3 +26,4 @@
 catch (Exception $e) {
     echo '<result ok="0"/>';
 }
+log_timing(true);

ajax/paradigm_info.php

@@ -10,4 +10,5 @@
     }
 }
 echo '</response>';
+log_timing(true);
 ?>

ajax/post_comment.php

@@ -38,5 +38,6 @@
 }
 catch (Exception $e) {
     echo '<response ok="0"/>';
+log_timing(true);
 }
 ?>

ajax/publish_update.php

@@ -14,5 +14,6 @@
 echo '<success>' . ($published['success'] ? 'ok' : 'failed') . '</success>';
 echo '<output>' . htmlspecialchars($published['output']) . '</output>';
 echo '</response>';
+log_timing(true);
 
 ?>

ajax/run_generator.php

@@ -14,5 +14,6 @@
 echo '<success>' . ($result['success'] ? 'ok' : 'failed') . '</success>';
 echo '<output>' . htmlspecialchars($result['output']) . '</output>';
 echo '</response>';
+log_timing(true);
 
 ?>

ajax/run_test.php

@@ -14,5 +14,6 @@
 echo '<success>' . ($result['success'] ? 'ok' : 'failed') . '</success>';
 echo '<output>' . htmlspecialchars($result['output']) . '</output>';
 echo '</response>';
+log_timing(true);
 
 ?>

ajax/save_check.php

@@ -31,4 +31,5 @@
     $result = 0;
 }
 echo '<result ok="'.$result.'"/></response>';
+log_timing(true);
 ?>

ajax/select_book.php

@@ -9,4 +9,5 @@
 }
 
 echo '<?xml version="1.0" encoding="utf-8" standalone="yes"?><response>'.$out.'</response>';
+log_timing(true);
 ?>

ajax/set_option.php

@@ -15,4 +15,5 @@
     $res['error'] = 1;
 }
 
+log_timing(true);
 die(json_encode($res));

ajax/syntax_group.php

@@ -81,4 +81,5 @@
     $res['error'] = 1;
 }
 
+log_timing(true);
 die(json_encode($res));

ajax/tag_autocomplete.php

@@ -6,4 +6,5 @@
 foreach ($res as $line) {
    echo $line['tag_name']."\n";
 }
+log_timing(true);
 ?>

ajax/tokenizer_monitor.php

@@ -10,5 +10,6 @@
 header('Content-Type: application/x-json; charset=utf-8');
 
 echo json_encode(get_monitor_data($_GET['from'], $_GET['until']));
+log_timing(true);
 
 ?>

api.php

@@ -50,5 +50,6 @@ function json_encode_readable($arr)
         $answer['error'] = 'Unknown action';
 }
 
+log_timing();
 die(json_encode_readable($answer));
 ?>

books.php

@@ -128,4 +128,5 @@
 } else {
     show_error($config['msg']['notadmin']);
 }
+log_timing();
 ?>

comments.php

@@ -7,4 +7,5 @@
 $smarty->assign('comments', get_latest_comments($skip));
 $smarty->assign('skip', $skip);
 $smarty->display('comments.tpl');
+log_timing();
 ?>

config.default.ini

@@ -70,3 +70,4 @@ morph_annot_moder_context_size = 4
 morph_annot_moder_page_size = 15
 morph_annot_timeout = 600
 morph_annot_user_context_size = 4
+timing_log_threshold = 2

dict.php

@@ -125,4 +125,5 @@
         }
         $smarty->display('dict/main.tpl', (int)user_has_permission('perm_dict'));
 }
+log_timing();
 ?>

dict_diff.php

@@ -6,4 +6,5 @@
 $set_id = (int)$_GET['set_id'];
 $smarty->assign('diff', dict_diff($lemma_id, $set_id));
 $smarty->display('dict/diff.tpl');
+log_timing();
 ?>

dict_history.php

@@ -10,4 +10,5 @@
 $smarty->assign('history', dict_history($lemma_id, $skip));
 $smarty->assign('skip', $skip);
 $smarty->display('dict/history.tpl');
+log_timing();
 ?>

diff.php

@@ -7,4 +7,5 @@
 $rev_id = isset($_GET['rev_id']) ? (int)$_GET['rev_id'] : 0;
 $smarty->assign('diff', main_diff($sent_id, $set_id, $rev_id));
 $smarty->display('diff.tpl');
+log_timing();
 ?>

game_admin.php

@@ -17,4 +17,5 @@
         $smarty->assign('badges', get_badges_info());
         $smarty->display('game_admin.tpl');
 }
+log_timing();
 ?>

generator_cp.php

@@ -28,4 +28,5 @@
 else {
     show_error($config['msg']['notadmin']);
 }
+log_timing();
 ?>

history.php

@@ -24,4 +24,5 @@
     $smarty->assign('maa', $maa);
 }
 $smarty->display('history.tpl', $cache_id);
+log_timing();
 ?>

index.php

@@ -93,4 +93,5 @@
     }
     $smarty->display('index.tpl');
 }
+log_timing();
 ?>

lib/common.php

@@ -44,19 +44,19 @@ function sql_query($q, $debug=1, $override_readonly=0) {
     if (file_exists('/var/lock/oc_readonly.lock') && stripos(trim($q), 'select') > 1 && !$override_readonly)
         throw new Exception("Database in readonly mode");
     $debug = isset($_SESSION['debug_mode']) && $debug;
+    $time_start = microtime(true);
     if ($debug) {
-        $time_start = microtime(true);
         $q = str_ireplace('select ', 'SELECT SQL_NO_CACHE ', $q);
     }
 
     try {
         if ($debug)
             printf("<table class='debug' width='100%%'><tr><td valign='top' width='20'>%d<td>SQL: %s</td>", $total_queries, htmlspecialchars($q));
         $res = $pdo_db->query($q);
+        $time = microtime(true)-$time_start;
+        $total_time += $time;
+        $total_queries++;
         if ($debug) {
-            $time = microtime(true)-$time_start;
-            $total_time += $time;
-            $total_queries++;
             printf("<td width='100'>%.4f сек.</td><td width='100'>%.4f сек.</td></tr></table>\n", $time, $total_time);
         }
     }
@@ -80,11 +80,16 @@ function sql_insert_id() {
 }
 function sql_prepare($q) {
     global $pdo_db;
+    global $total_time;
     $debug = isset($_SESSION['debug_mode']);
+    $time_start = microtime(true);
     if ($debug)
         printf("<table class='debug' width='100%%'><tr><td valign='top' width='20'>*</td><td colspan='3'>PREPARE: %s</td></tr></table>\n", htmlspecialchars($q));
     try {
-        return $pdo_db->prepare($q);
+        $q = $pdo_db->prepare($q);
+        $time = microtime(true)-$time_start;
+        $total_time += $time;
+        return $q;
     }
     catch (PDOException $e) {
         if ($debug)
@@ -97,15 +102,14 @@ function sql_execute($res, $params) {
     global $total_time;
     global $total_queries;
     $debug = isset($_SESSION['debug_mode']);
-    if ($debug)
-        $time_start = microtime(true);
+    $time_start = microtime(true);
 
     try {
         $res->execute($params);
+        $time = microtime(true)-$time_start;
+        $total_time += $time;
+        $total_queries++;
         if ($debug) {
-            $time = microtime(true)-$time_start;
-            $total_time += $time;
-            $total_queries++;
             printf("<table class='debug' width='100%%'><tr><td valign='top' width='20'>%d<td>SQL: %s</td><td width='100'>%.4f сек.</td><td width='100'>%.4f сек.</td></tr></table>\n", $total_queries, "(prepared statement)", $time, $total_time);
         }
     }

lib/header.php

@@ -8,6 +8,7 @@
 require_once('vendor/autoload.php'); // Smarty, something else which was installed via Composer
 require_once('common.php');
 require_once('lib_awards.php');
+require_once('timer.php');
 
 $smarty = new Smarty(); // no need to require the Smarty.php, it was autoloaded
 $smarty->template_dir = $config['smarty']['template_dir'];

lib/header_ajax.php

@@ -7,6 +7,7 @@
 $config = parse_ini_file(__DIR__ . '/../config.ini', true);
 
 require_once('common.php');
+require_once('timer.php');
 
 $transaction_counter = 0;
 $nested_transaction_counter = 0;

login.php

@@ -20,6 +20,7 @@
         } else {
             header('Location:login.php?act=error');
         }
+        log_timing();
         exit();
     case 'login_openid':
         $r = user_login_openid($_POST['token']);
@@ -36,9 +37,11 @@
             default:
                 header('Location:login.php?act=error');
         }
+        log_timing();
         exit();
     case 'login_openid2':
         user_login_openid_agree(isset($_POST['agree']));
+        log_timing();
         header('Location:index.php');
         exit();
     case 'logout':
@@ -48,6 +51,7 @@
         } else {
             header('Location:index.php');
         }
+        log_timing();
         exit();
     case 'reg_done':
         $reg_status = user_register($_POST);
@@ -71,6 +75,7 @@
         $smarty->assign('change_status', user_change_shown_name($_POST['shown_name']));
         break;
 }
+log_timing();
 
 if (
     isset($_SERVER['HTTP_REFERER']) &&

manual.php

@@ -10,4 +10,5 @@
     $smarty->assign('content', get_wiki_page("Инструкция по интерфейсу для снятия омонимии"));
 
 $smarty->display('static/doc/annotation.tpl');
+log_timing();
 ?>

migrations/20140930101915_add_timer.php

@@ -0,0 +1,22 @@
+<?php
+
+use Phinx\Migration\AbstractMigration;
+
+class AddTimer extends AbstractMigration
+{
+    public function up()
+    {
+        $this->execute("CREATE TABLE timing (
+            `timestamp`  TIMESTAMP NOT NULL DEFAULT CURRENT_TIMESTAMP,
+            `user_id`    SMALLINT UNSIGNED NOT NULL DEFAULT 0,
+            `page`       VARCHAR(255) NOT NULL,
+            `total_time` FLOAT NOT NULL,
+            `is_ajax`    TINYINT UNSIGNED NOT NULL
+        ) ENGINE=INNODB");
+    }
+
+    public function down()
+    {
+        $this->dropTable("timing");
+    }
+}

ner.php

@@ -26,3 +26,4 @@
         $smarty->assign('page', get_books_with_NE());
         $smarty->display('ner/main.tpl');
 }
+log_timing();