Masalah kinerja adalah masalah umum saat mengelola database MySQL. Terkadang masalah ini sebenarnya disebabkan oleh kueri yang lambat. Di blog ini, kami akan menangani kueri lambat dan cara mengidentifikasinya.
Memeriksa Log Kueri Lambat Anda
MySQL memiliki kemampuan untuk memfilter dan mencatat kueri yang lambat. Ada berbagai cara Anda dapat menyelidiki ini, tetapi cara yang paling umum dan efisien adalah dengan menggunakan log kueri lambat.
Anda harus menentukan terlebih dahulu apakah log kueri lambat Anda diaktifkan. Untuk mengatasinya, Anda dapat pergi ke server Anda dan menanyakan variabel berikut:
MariaDB [(none)]> show global variables like 'slow%log%';
+---------------------+-------------------------------+
| Variable_name | Value |
+---------------------+-------------------------------+
| slow_query_log | ON |
| slow_query_log_file | /var/log/mysql/mysql-slow.log |
+---------------------+-------------------------------+
2 rows in set (0.001 sec)Anda harus memastikan bahwa variabel slow_query_log disetel ke ON, sedangkan file slow_query_log_menentukan jalur di mana Anda perlu menempatkan log kueri lambat Anda. Jika variabel ini tidak disetel, variabel ini akan menggunakan DATA_DIR dari direktori data MySQL Anda.
Disertai dengan variabel slow_query_log adalah long_query_time dan min_examined_row_limit yang memengaruhi cara kerja pencatatan kueri lambat. Pada dasarnya, log kueri lambat berfungsi sebagai pernyataan SQL yang membutuhkan lebih dari detik_query_time untuk dieksekusi dan juga memerlukan setidaknya baris min_examined_row_limit untuk diperiksa. Ini dapat digunakan untuk menemukan kueri yang membutuhkan waktu lama untuk dieksekusi dan oleh karena itu merupakan kandidat untuk pengoptimalan dan kemudian Anda dapat menggunakan alat eksternal untuk membawa laporan untuk Anda, yang akan dibicarakan nanti.
Secara default, pernyataan administratif (ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, dan REPAIR TABLE) tidak termasuk dalam log kueri lambat. Untuk melakukan ini, Anda perlu mengaktifkan variabel log_slow_admin_statements.
Daftar Proses Kueri dan Monitor Status InnoDB
Dalam rutinitas DBA normal, langkah ini adalah cara paling umum untuk menentukan kueri yang berjalan lama atau kueri yang berjalan aktif yang menyebabkan penurunan kinerja. Bahkan mungkin menyebabkan server Anda macet diikuti oleh antrian yang menumpuk yang perlahan meningkat karena kunci yang ditutupi oleh kueri yang sedang berjalan. Anda cukup menjalankan,
SHOW [FULL] PROCESSLIST;atau
SHOW ENGINE INNODB STATUS \GJika Anda menggunakan ClusterControl, Anda dapat menemukannya dengan menggunakan
atau menggunakan
Menganalisis Query MySQL
Log kueri lambat akan menampilkan daftar kueri yang telah diidentifikasi sebagai lambat, berdasarkan nilai yang diberikan dalam variabel sistem seperti yang disebutkan sebelumnya. Definisi kueri lambat mungkin berbeda dalam kasus yang berbeda karena ada kesempatan tertentu bahkan kueri 10 detik dapat diterima dan masih tidak lambat. Namun, jika aplikasi Anda adalah OLTP, sangat umum bahwa kueri 10 detik atau bahkan 5 detik menjadi masalah atau menyebabkan penurunan kinerja ke database Anda. Log kueri MySQL memang membantu Anda, tetapi itu tidak cukup untuk membuka file log karena tidak memberi Anda gambaran umum tentang kueri apa itu, bagaimana kinerjanya, dan frekuensi kemunculannya. Oleh karena itu, alat pihak ketiga dapat membantu Anda dalam hal ini.
pt-query-digest
Menggunakan Percona Toolkit, yang bisa saya katakan sebagai alat DBA paling umum, adalah dengan menggunakan pt-query-digest. pt-query-digest memberi Anda gambaran umum yang bersih tentang laporan tertentu yang berasal dari log kueri lambat Anda. Misalnya, laporan khusus ini menunjukkan perspektif yang bersih dalam memahami laporan kueri lambat di node tertentu:
# A software update is available:
# 100ms user time, 100ms system time, 29.12M rss, 242.41M vsz
# Current date: Mon Feb 3 20:26:11 2020
# Hostname: testnode7
# Files: /var/log/mysql/mysql-slow.log
# Overall: 24 total, 14 unique, 0.00 QPS, 0.02x concurrency ______________
# Time range: 2019-12-12T10:01:16 to 2019-12-12T15:31:46
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 345s 1s 98s 14s 30s 19s 7s
# Lock time 1s 0 1s 58ms 24ms 252ms 786us
# Rows sent 5.72M 0 1.91M 244.14k 1.86M 629.44k 0
# Rows examine 15.26M 0 1.91M 651.23k 1.86M 710.58k 961.27k
# Rows affecte 9.54M 0 1.91M 406.90k 961.27k 546.96k 0
# Bytes sent 305.81M 11 124.83M 12.74M 87.73M 33.48M 56.92
# Query size 1.20k 25 244 51.17 59.77 40.60 38.53
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== ================================ ============= ===== ======= =====
# 1 0x00C8412332B2795DADF0E55C163... 98.0337 28.4% 1 98.0337 0.00 UPDATE sbtest?
# 2 0xDEF289292EA9B2602DC12F70C7A... 74.1314 21.5% 3 24.7105 6.34 ALTER TABLE sbtest? sbtest3
# 3 0x148D575F62575A20AB9E67E41C3... 37.3039 10.8% 6 6.2173 0.23 INSERT SELECT sbtest? sbtest
# 4 0xD76A930681F1B4CC9F748B4398B... 32.8019 9.5% 3 10.9340 4.24 SELECT sbtest?
# 5 0x7B9A47FF6967FD905289042DD3B... 20.6685 6.0% 1 20.6685 0.00 ALTER TABLE sbtest? sbtest3
# 6 0xD1834E96EEFF8AC871D51192D8F... 19.0787 5.5% 1 19.0787 0.00 CREATE
# 7 0x2112E77F825903ED18028C7EA76... 18.7133 5.4% 1 18.7133 0.00 ALTER TABLE sbtest? sbtest3
# 8 0xC37F2569578627487D948026820... 15.0177 4.3% 2 7.5088 0.00 INSERT SELECT sbtest? sbtest
# 9 0xDE43B2066A66AFA881D6D45C188... 13.7180 4.0% 1 13.7180 0.00 ALTER TABLE sbtest? sbtest3
# MISC 0xMISC 15.8605 4.6% 5 3.1721 0.0 <5 ITEMS>
# Query 1: 0 QPS, 0x concurrency, ID 0x00C8412332B2795DADF0E55C1631626D at byte 5319
# Scores: V/M = 0.00
# Time range: all events occurred at 2019-12-12T13:23:15
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 4 1
# Exec time 28 98s 98s 98s 98s 98s 0 98s
# Lock time 1 25ms 25ms 25ms 25ms 25ms 0 25ms
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 12 1.91M 1.91M 1.91M 1.91M 1.91M 0 1.91M
# Rows affecte 20 1.91M 1.91M 1.91M 1.91M 1.91M 0 1.91M
# Bytes sent 0 67 67 67 67 67 0 67
# Query size 7 89 89 89 89 89 0 89
# String:
# Databases test
# Hosts localhost
# Last errno 0
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ ################################################################
# Tables
# SHOW TABLE STATUS FROM `test` LIKE 'sbtest3'\G
# SHOW CREATE TABLE `test`.`sbtest3`\G
update sbtest3 set c=substring(MD5(RAND()), -16), pad=substring(MD5(RAND()), -16) where 1\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select c=substring(MD5(RAND()), -16), pad=substring(MD5(RAND()), -16) from sbtest3 where 1\G
# Query 2: 0.00 QPS, 0.01x concurrency, ID 0xDEF289292EA9B2602DC12F70C7A041A9 at byte 3775
# Scores: V/M = 6.34
# Time range: 2019-12-12T12:41:47 to 2019-12-12T15:25:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 12 3
# Exec time 21 74s 6s 36s 25s 35s 13s 30s
# Lock time 0 13ms 1ms 8ms 4ms 8ms 3ms 3ms
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 0 0 0 0 0 0 0
# Rows affecte 0 0 0 0 0 0 0 0
# Bytes sent 0 144 44 50 48 49.17 3 49.17
# Query size 8 99 33 33 33 33 0 33
# String:
# Databases test
# Hosts localhost
# Last errno 0 (2/66%), 1317 (1/33%)
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################
# 10s+ ################################################################
# Tables
# SHOW TABLE STATUS FROM `test` LIKE 'sbtest3'\G
# SHOW CREATE TABLE `test`.`sbtest3`\G
ALTER TABLE sbtest3 ENGINE=INNODB\GMenggunakan performance_schema
Log kueri yang lambat mungkin menjadi masalah jika Anda tidak memiliki akses langsung ke file seperti menggunakan RDS atau menggunakan layanan database yang terkelola sepenuhnya seperti Google Cloud SQL atau Azure SQL. Meskipun Anda mungkin memerlukan beberapa variabel untuk mengaktifkan fitur ini, ini berguna saat menanyakan kueri yang masuk ke sistem Anda. Anda dapat memesannya dengan menggunakan pernyataan SQL standar untuk mengambil sebagian hasil. Misalnya,
mysql> SELECT SCHEMA_NAME, DIGEST, DIGEST_TEXT, COUNT_STAR, SUM_TIMER_WAIT/1000000000000 SUM_TIMER_WAIT_SEC, MIN_TIMER_WAIT/1000000000000 MIN_TIMER_WAIT_SEC, AVG_TIMER_WAIT/1000000000000 AVG_TIMER_WAIT_SEC, MAX_TIMER_WAIT/1000000000000 MAX_TIMER_WAIT_SEC, SUM_LOCK_TIME/1000000000000 SUM_LOCK_TIME_SEC, FIRST_SEEN, LAST_SEEN FROM events_statements_summary_by_digest;
+--------------------+----------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------+--------------------+--------------------+--------------------+--------------------+-------------------+---------------------+---------------------+
| SCHEMA_NAME | DIGEST | DIGEST_TEXT | COUNT_STAR | SUM_TIMER_WAIT_SEC | MIN_TIMER_WAIT_SEC | AVG_TIMER_WAIT_SEC | MAX_TIMER_WAIT_SEC | SUM_LOCK_TIME_SEC | FIRST_SEEN | LAST_SEEN |
+--------------------+----------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------+--------------------+--------------------+--------------------+--------------------+-------------------+---------------------+---------------------+
| NULL | 390669f3d1f72317dab6deb40322d119 | SELECT @@`skip_networking` , @@`skip_name_resolve` , @@`have_ssl` = ? , @@`ssl_key` , @@`ssl_ca` , @@`ssl_capath` , @@`ssl_cert` , @@`ssl_cipher` , @@`ssl_crl` , @@`ssl_crlpath` , @@`tls_version` | 1 | 0.0373 | 0.0373 | 0.0373 | 0.0373 | 0.0000 | 2020-02-03 20:22:54 | 2020-02-03 20:22:54 |
| NULL | fba95d44e3d0a9802dd534c782314352 | SELECT `UNIX_TIMESTAMP` ( ) | 2 | 0.0002 | 0.0001 | 0.0001 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | 18c649da485456d6cdf12e4e6b0350e9 | SELECT @@GLOBAL . `SERVER_ID` | 2 | 0.0001 | 0.0001 | 0.0001 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | dd356b8a5a6ed0d7aee2abd939cdb6c9 | SET @? = ? | 6 | 0.0003 | 0.0000 | 0.0001 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | 1c5ae643e930af6d069845d74729760d | SET @? = @@GLOBAL . `binlog_checksum` | 2 | 0.0001 | 0.0001 | 0.0001 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | ad5208ffa004a6ad7e26011b73cbfb4c | SELECT @? | 2 | 0.0001 | 0.0000 | 0.0000 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | ed0d1eb982c106d4231b816539652907 | SELECT @@GLOBAL . `GTID_MODE` | 2 | 0.0001 | 0.0000 | 0.0000 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | cb47e22372fdd4441486b02c133fb94f | SELECT @@GLOBAL . `SERVER_UUID` | 2 | 0.0001 | 0.0000 | 0.0000 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | 73301368c301db5d2e3db5626a21b647 | SELECT @@GLOBAL . `rpl_semi_sync_master_enabled` | 2 | 0.0001 | 0.0000 | 0.0000 | 0.0000 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | 0ff7375c5f076ba5c040e78a9250a659 | SELECT @@`version_comment` LIMIT ? | 1 | 0.0001 | 0.0001 | 0.0001 | 0.0001 | 0.0000 | 2020-02-03 20:45:59 | 2020-02-03 20:45:59 |
| NULL | 5820f411e67a393f987c6be5d81a011d | SHOW TABLES FROM `performance_schema` | 1 | 0.0008 | 0.0008 | 0.0008 | 0.0008 | 0.0002 | 2020-02-03 20:46:11 | 2020-02-03 20:46:11 |
| NULL | a022a0ab966c51eb820da1521349c7ef | SELECT SCHEMA ( ) | 1 | 0.0005 | 0.0005 | 0.0005 | 0.0005 | 0.0000 | 2020-02-03 20:46:29 | 2020-02-03 20:46:29 |
| performance_schema | e4833a7c1365b0b4492e9a514f7b3bd4 | SHOW SCHEMAS | 1 | 0.1167 | 0.1167 | 0.1167 | 0.1167 | 0.0001 | 2020-02-03 20:46:29 | 2020-02-03 20:46:29 |
| performance_schema | 1107f048fe6d970cb6a553bd4727a1b4 | SHOW TABLES | 1 | 0.0002 | 0.0002 | 0.0002 | 0.0002 | 0.0000 | 2020-02-03 20:46:29 | 2020-02-03 20:46:29 |
...Anda dapat menggunakan tabel performance_schema.events_statements_summary_by_digest. Meskipun ada kemungkinan bahwa entri pada tabel dari performance_schema akan di-flush, Anda dapat memutuskan untuk menyimpannya di tabel tertentu. Lihatlah posting eksternal ini dari intisari kueri Percona MySQL dengan Skema Kinerja.
Jika Anda bertanya-tanya mengapa kami perlu membagi kolom waktu tunggu (SUM_TIMER_WAIT, MIN_TIMER_WAIT_SEC, AVG_TIMER_WAIT_SEC), kolom ini menggunakan picoseconds sehingga Anda mungkin perlu melakukan beberapa perhitungan atau pembulatan untuk membuatnya itu lebih mudah dibaca oleh Anda.
Menganalisis Kueri Lambat Menggunakan ClusterControl
Jika Anda menggunakan ClusterControl, ada berbagai cara untuk mengatasinya. Misalnya, dalam Cluster MariaDB yang saya miliki di bawah, ini menunjukkan kepada Anda tab berikut (Pemantau Kueri) dan item drop-downnya (Kueri Teratas, Kueri Berjalan, Pencilan Kueri):
- Kueri Teratas - daftar gabungan dari semua kueri teratas Anda yang berjalan di semua node kluster database Anda
- Menjalankan Kueri - Lihat kueri yang sedang berjalan di cluster database Anda mirip dengan perintah SHOW FULL PROCESSLIST di MySQL
- Query Outliers - Menampilkan kueri yang outlier. Outlier adalah kueri yang membutuhkan waktu lebih lama daripada kueri normal dari jenis tersebut.
Selain itu, ClusterControl juga menangkap kinerja kueri menggunakan grafik yang memberi Anda gambaran singkat tentang kinerja sistem database Anda dalam kaitannya dengan kinerja kueri. Lihat di bawah,
Tunggu, ini belum berakhir. ClusterControl juga menawarkan metrik resolusi tinggi menggunakan Prometheus dan menampilkan metrik yang sangat detail dan menangkap statistik waktu nyata dari server. Kami telah membahas ini di blog kami sebelumnya yang dibagi menjadi dua bagian seri blog. Lihat bagian 1 dan kemudian bagian 2 blog. Ini menawarkan Anda tentang cara memantau secara efisien tidak hanya kueri lambat tetapi juga kinerja keseluruhan server database MySQL, MariaDB, atau Percona Anda.
Ada juga alat lain di ClusterControl yang memberikan petunjuk dan petunjuk yang dapat menyebabkan kinerja kueri lambat meskipun belum terjadi atau ditangkap oleh log kueri yang lambat. Lihat Tab Performa seperti yang terlihat di bawah ini,
item ini memberi Anda hal berikut:
- Ikhtisar - Anda dapat melihat grafik penghitung basis data yang berbeda di halaman ini
- Penasihat - Daftar hasil penasihat terjadwal yang dibuat di ClusterControl> Kelola> Developer Studio menggunakan ClusterControl DSL.
- Status DB - Status DB memberikan gambaran singkat tentang status MySQL di semua node database Anda, mirip dengan pernyataan SHOW STATUS
- Variabel DB - Variabel DB memberikan gambaran singkat tentang variabel MySQL yang ditetapkan di semua node database Anda, mirip dengan pernyataan SHOW GLOBAL VARIABLES
- Pertumbuhan DB - Memberikan ringkasan pertumbuhan database dan tabel Anda setiap hari selama 30 hari terakhir.
- Status InnoDB - Mengambil keluaran monitor InnoDB saat ini untuk host yang dipilih, mirip dengan perintah SHOW ENGINE INNODB STATUS.
- Schema Analyzer - Menganalisis skema database Anda untuk menemukan kunci utama yang hilang, indeks yang berlebihan, dan tabel menggunakan mesin penyimpanan MyISAM.
- Log Transaksi - Mencantumkan transaksi yang berjalan lama dan kebuntuan di seluruh klaster basis data tempat Anda dapat dengan mudah melihat transaksi apa yang menyebabkan kebuntuan. Ambang waktu kueri default adalah 30 detik.
Kesimpulan
Menelusuri masalah Kinerja MySQL Anda tidak terlalu sulit dengan MySQL. Ada berbagai alat eksternal yang memberi Anda efisiensi dan kemampuan yang Anda cari. Yang terpenting adalah, mudah digunakan dan Anda mampu memberikan produktivitas di tempat kerja. Perbaiki masalah yang paling menonjol atau bahkan hindari bencana tertentu sebelum itu bisa terjadi.
