MySQL Slow Query Log

တစ်ခါတစ်ရံမှာ သုံးနေရင်းနဲ့ MySQL ဟာ Response အရမ်းကြာတာတွေဖြစ်လာတယ် တတ်နိုင်ရင်တော့ Query ကိုရှင်းရှင်းလင်းလင်း ရေးလေ့ရှိပေမယ့်လည်း မလွှဲသာရင်တော့ ရှုပ်ရှုပ်ထွေးထွေး Aggregation တွေလည်းရေးရတော့တယ်။ အဲဒီလို Query တွေများများလာရင် ဘယ် Query ကြောင့်နှေးမှန်းကို မသိတော့တဲ့အခြေအနေလည်း ရောက်လာတတ်တယ်။

general_log_file = /var/log/mysql/mysql.log
general_log      = 1

အဲလိုအခြေအနေရောက်ရင် ပထမဆုံးတစ်နည်းက General Query Log ကို Enable လုပ်ပြီးတော့ ဝင်လာသမျှ Query တွေကို Log File ထဲကိုရေးခိုင်းလိုက်လို့ရတယ်။ ဝင်လာသမျှ Query တွေကိုကြည့်လို့ရတော့ အကောင်းဆုံးလို့ပြောလို့ရပေမယ့် Query တိုင်းကို မှတ်ထားတဲ့အတွက် တစ်နေကုန်သာ Log လုပ်ထားရင် Log File ဟာအတော်ကိုကြီးပါလိမ့်မယ် အဆက်မပြတ်သုံးနေတဲ့ Database ဖြစ်ခဲ့ရင်တော့ Gigabye အရွယ်အစားဖိုင်ကြီးကို Analyze လုပ်ရပါလိမ့်မယ်။ အဲဒီတော့ General Query Log ဟာ မတတ်သာမှပဲ လုပ်လို့အဆင်ပြေပါတယ်။

slow_query_log
min_examined_row_limit
long_query_time

တကယ်တော့ Query တွေအကုန်လုံးလည်း သိစရာတော့မလိုဘူး တကယ်သိချင်တာက နှေးတဲ့ Query တွေကိုသိရင် ဘာဆက်လုပ်ရမလဲ ဆုံးဖြတ်လို့ရတယ် MySQL မှာတစ်ခုအဆင်ပြေတာက Log ကိုအားလုံးမလုပ်ပဲ နှေးတဲ့ Query တွေကိုပဲ Log လုပ်တဲ့ Slow Query Log ရှိတယ်။ ဒီနေရာမှာနှေးတယ်ဆိုတာ ဘယ်လိုသတ်မှတ်သလဲ ဆုံးဖြတ်ပေးလို့ရတယ် အချိန်နဲ့ဆိုရင် long_query_time မှာ သတ်မှတ်ထားပေးရင် အဲဒီ့အချိန်ထက်ပိုတဲ့ Query တွေဟာ Slow လို့သတ်မှတ်တယ် အချိန်နဲ့မဟုတ်ဘူး Scan လုပ်ခဲ့တဲ့ Row အရေအတွက်နဲ့ တိုင်းချင်ရင်လည်း min_examined_row_limit သတ်မှတ်ပေးပြီး အဲဒီအရေအတွက်ထက်ပိုရင် Slow Query လို့သတ်မှတ်လို့ရတယ်။

log_queries_not_using_indexes

Log လုပ်ထားတဲ့ Query တွေကို Anlyze လုပ်တဲ့ပထမဆုံးအဆင့်က Slow Query ကိုရှာတယ် အဲဒီတော့ Slow Query Log ဆိုရင်ပဲ ပထမတစ်ဆင့် အဆင်ပြေပါတယ်။ နောက်တစ်ဆင့်အနေနဲ့ Slow Query တွေကို Optimize လုပ်မယ်ဆိုရင် လိုအပ်တဲ့ Index မရှိလို့နှေးနေတာက အဖြစ်အများဆုံးဆိုတော့ Join တွေ Condition တွေမှာ သုံးထားတဲ့ Column တွေမှာ သင့်လျော်တဲ့ Index ရှိမရှိကြည့်ရတယ်။ Index မသုံးပဲ Table Scan လုပ်နေတဲ့ Query တွေကို Log လုပ်ခိုင်းထားနိုင်ရင် ပိုအဆင်ပြေတယ်။ log_queries_not_using_indexes ကို Enable လုပ်ထားရင် အလွယ်တကူပဲ Log ထဲမှာခွဲလို့ရတယ်။

# Time: 130425  4:13:47
# User@Host: myhost[myhost] @ myhost []
# Query_time: 0.000984  Lock_time: 0.000443 Rows_sent: 0  Rows_examined: 4
SET timestamp=1366863227;
select count(*) into @discard from `information_schema`.`PARAMETERS`;
# Time: 130425  4:18:36
# User@Host: myhost[myhost] @ myhost []
# Query_time: 0.001904  Lock_time: 0.000091 Rows_sent: 386  Rows_examined: 439
use myambook;
SET timestamp=1366863516;
SELECT option_name, option_value FROM wp_options WHERE autoload = 'yes';

Index တွေသင့်သလို ထည့်ပေးလို့မှ မပြေလည်သေးရင်တော့ အသေးစိတ်စပြီးတော့ Analyze လုပ်ဖို့လိုပါပြီ ဒီနေရာမှာတော့ DBA ကို Tools အစားထိုးလို့မရတော့ဘူး။ Log ထဲမှာ Time, timestamp, Query_time, Lock_time, Rows_sent, Rows_examined, Query အဲဒါတွေကို အသေအချာယှဉ်ကြည့်ရတော့တယ်။ Manual ယှဉ်ကြည့်ရင်တော့ များတာနဲ့အမျှ မျက်စေ့လည်ပြီးတော့ ဘယ်နားကဖြစ်မှန်း မသိဆုံးဖြတ်ရခက်တော့ Log File တွေကို Analyze လုပ်တဲ့ Tools တွေသုံးရတော့တယ်။ MySQL အတွက် Percona Toolkit ဟာအသုံးများပါတယ်။

$ pt-query-digest mysql-slow.log

Percona ရဲ့ pt-query-digest နဲ့ Slow Query Log တွေကို အလွယ်တကူ Summarize လုပ်လို့ရတယ်။ Overview အနေနဲ့ Exec time, Lock time, Rows sent, Rows examine, Query size တွေကြည့်လို့ရတာဟာ ဘယ်နေရာမှာအဓိကကြာနေသလဲ ဆုံးဖြတ်တဲ့နေရာမှာ အထောက်အကူပြုတယ်။ Exec time ပိုကြာရင်တော့ Index လိုနေသလား ပိုနေသလားကြည့်ရင် အများအားဖြင့်အဆင်ပြေတယ်။ Lock time များနေရင်တော့ Query တွေရဲ့ အချိန်တွေကိုကြည့်ပြီး Parallel ဖြစ်နေတဲ့ Query တွေကိုရှာ အဲဒီကတစ်ဆင့် Dead Lock ဖြစ်နိုင်တဲ့ Query တွေရှာရမယ် အဲဒါတွေတော့ Manual Process ဖြစ်တော့ပြောရခက်တယ် တစ်ခါတစ်ရံလည်း အလွယ်တကူပြဿနာကိုရှာတွေ့တယ် အခုတော့ဘယ်လိုမှ ရှာမတွေ့သေးတော့ ရုံးရောက်လိုက် Log File ဖွင့်လိုက်နဲ့ လည်နေတယ်။ ရှာတွေ့ရင်တော့ Example တစ်ခုနဲ့ ရေးစရာတစ်ခုတော့ရမယ်ထင်ပါတယ် အခုတော့ ခေါင်းလည်းကိုက် အိပ်ရေးလည်းပျက်ပြီ နှေးလည်းသည်းခံစောင့်ကြလိမ့်မယ် အိမ်ပြန်အိပ်တာပဲကောင်းတယ်။

# 220ms user time, 40ms system time, 19.50M rss, 68.16M vsz
# Current date: Thu Apr 25 05:55:47 2013
# Hostname: myhost
# Files: mysql-slow.log
# Overall: 26 total, 20 unique, 0.05 QPS, 0.05x concurrency ______________
# Time range: 2013-04-25 04:13:47 to 04:22:27
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            24s   137us     10s   929ms      3s      3s     1ms
# Lock time            5ms    41us   443us   187us   384us   123us   148us
# Rows sent          1.21k       0     387   47.50  258.32  111.08    0.99
# Rows examine       6.54M       0   2.86M 257.66k 830.38k 756.98k   84.10
# Query size         3.92k      63     503  154.42  381.65  133.14   69.19