Masalah

Sebuah instance dari MySQL 5.6.20 yang menjalankan (kebanyakan hanya) sebuah database dengan tabel-tabel InnoDB memamerkan kios-kios sesekali untuk semua operasi pembaruan selama 1-4 menit dengan semua kueri INSERT, UPDATE, dan DELETE yang tersisa dalam status "Query end". Ini jelas sangat disayangkan. Log kueri lambat MySQL sedang mencatat bahkan kueri paling sepele dengan waktu kueri gila, ratusan di antaranya dengan stempel waktu yang sama sesuai dengan titik waktu warung telah diselesaikan:

# Query_time: 101.743589  Lock_time: 0.000437 Rows_sent: 0  Rows_examined: 0
SET timestamp=1409573952;
INSERT INTO sessions (redirect_login2, data, hostname, fk_users_primary, fk_users, id_sessions, timestamp) VALUES (NULL, NULL, '192.168.10.151', NULL, 'anonymous', '64ef367018099de4d4183ffa3bc0848a', '1409573850');

Dan statistik perangkat menunjukkan peningkatan, meskipun tidak beban I / O yang berlebihan dalam kerangka waktu ini (dalam hal ini pembaruan terhenti 14:17:30 - 14:19:12 menurut stempel waktu dari pernyataan di atas):

# sar -d
[...]
02:15:01 PM       DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz     await     svctm     %util
02:16:01 PM    dev8-0     41.53    207.43   1227.51     34.55      0.34      8.28      3.89     16.15
02:17:01 PM    dev8-0     59.41    137.71   2240.32     40.02      0.39      6.53      4.04     24.00
02:18:01 PM    dev8-0    122.08   2816.99   1633.44     36.45      3.84     31.46      1.21      2.88
02:19:01 PM    dev8-0    253.29   5559.84   3888.03     37.30      6.61     26.08      1.85      6.73
02:20:01 PM    dev8-0    101.74   1391.92   2786.41     41.07      1.69     16.57      3.55     36.17
[...]
# sar
[...]
02:15:01 PM     CPU     %user     %nice   %system   %iowait    %steal     %idle
02:16:01 PM     all     15.99      0.00     12.49      2.08      0.00     69.44
02:17:01 PM     all     13.67      0.00      9.45      3.15      0.00     73.73
02:18:01 PM     all     10.64      0.00      6.26     11.65      0.00     71.45
02:19:01 PM     all      3.83      0.00      2.42     24.84      0.00     68.91
02:20:01 PM     all     20.95      0.00     15.14      6.83      0.00     57.07

Lebih sering daripada tidak, saya perhatikan di log lambat mysql bahwa penundaan permintaan tertua adalah INSERT ke tabel ish besar (~ 10 M) dengan kunci primer VARCHAR dan indeks pencarian teks lengkap:

CREATE TABLE `files` (
  `id_files` varchar(32) NOT NULL DEFAULT '',
  `filename` varchar(100) NOT NULL DEFAULT '',
  `content` text,
  PRIMARY KEY (`id_files`),
  KEY `filename` (`filename`),
  FULLTEXT KEY `content` (`content`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1

Penyelidikan lebih lanjut (yaitu SHOW ENGINE INNODB STATUS) telah menunjukkan bahwa itu memang selalu merupakan pembaruan ke tabel menggunakan indeks teks lengkap yang menyebabkan kios. Bagian TRANSAKSI masing-masing dari "SHOW ENGINE INNODB STATUS" memiliki entri seperti ini untuk transaksi tertua yang berjalan:

---TRANSACTION 162269409, ACTIVE 122 sec doing SYNC index
6 lock struct(s), heap size 1184, 0 row lock(s), undo log entries 19942
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_1" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_2" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_3" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_4" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_5" trx id 162269409 lock mode IX
TABLE LOCK table "vw"."FTS_000000000000224a_00000000000036b9_INDEX_6" trx id 162269409 lock mode IX
---TRANSACTION 162269408, ACTIVE (PREPARED) 122 sec committing
mysql tables in use 1, locked 1
1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
MySQL thread id 165998, OS thread handle 0x7fe0e239c700, query id 91208956 192.168.10.153 root query end
INSERT INTO files (id_files, filename, content) VALUES ('f19e63340fad44841580c0371bc51434', '1237716_File_70380a686effd6b66592bb5eeb3d9b06.doc', '[...]
TABLE LOCK table `vw`.`files` trx id 162269408 lock mode IX

Jadi ada beberapa tindakan indeks teks lengkap yang terjadi di sana ( doing SYNC index) menghentikan SEMUA pembaruan berikutnya ke tabel APAPUN .

Dari log sepertinya undo log entriesangka untuk doing SYNC indexmaju pada ~ 150 / s hingga mencapai 20.000, di mana titik operasi dilakukan.

Ukuran FTS dari tabel spesifik ini cukup mengesankan:

# du -c FTS_000000000000224a_00000000000036b9_*
614404  FTS_000000000000224a_00000000000036b9_INDEX_1.ibd
2478084 FTS_000000000000224a_00000000000036b9_INDEX_2.ibd
1576964 FTS_000000000000224a_00000000000036b9_INDEX_3.ibd
1630212 FTS_000000000000224a_00000000000036b9_INDEX_4.ibd
1978372 FTS_000000000000224a_00000000000036b9_INDEX_5.ibd
1159172 FTS_000000000000224a_00000000000036b9_INDEX_6.ibd
9437208 total

meskipun masalah ini juga dipicu oleh tabel dengan ukuran data FTS yang secara signifikan lebih kecil seperti ini:

# du -c FTS_0000000000002467_0000000000003a21_INDEX*
49156   FTS_0000000000002467_0000000000003a21_INDEX_1.ibd
225284  FTS_0000000000002467_0000000000003a21_INDEX_2.ibd
147460  FTS_0000000000002467_0000000000003a21_INDEX_3.ibd
135172  FTS_0000000000002467_0000000000003a21_INDEX_4.ibd
155652  FTS_0000000000002467_0000000000003a21_INDEX_5.ibd
106500  FTS_0000000000002467_0000000000003a21_INDEX_6.ibd
819224  total

Waktu kios dalam kasus-kasus itu kira-kira sama juga. Saya telah membuka bug di bugs.mysql.com sehingga para devs dapat melihat hal ini.

Sifat warung pertama yang membuat saya curiga aktivitas pembilasan log menjadi biang keladinya dan artikel Percona ini tentang masalah kinerja pembilasan log dengan MySQL 5.5 menggambarkan gejala yang sangat mirip, tetapi kejadian lebih lanjut menunjukkan bahwa operasi INSERT ke dalam tabel MyISAM tunggal dalam database ini. dipengaruhi oleh kios juga, jadi ini sepertinya bukan masalah InnoDB saja.

Meskipun demikian, saya memutuskan untuk melacak nilai Log sequence numberdan Pages flushed up todari output bagian "LOG"SHOW ENGINE INNODB STATUS setiap 10 detik. Itu memang terlihat seperti aktivitas pembilasan sedang berlangsung selama kios karena penyebaran antara dua nilai menurun:

Mon Sep 1 14:17:08 CEST 2014 LSN: 263992263703, Pages flushed: 263973405075, Difference: 18416 K
Mon Sep 1 14:17:19 CEST 2014 LSN: 263992826715, Pages flushed: 263973811282, Difference: 18569 K
Mon Sep 1 14:17:29 CEST 2014 LSN: 263993160647, Pages flushed: 263974544320, Difference: 18180 K
Mon Sep 1 14:17:39 CEST 2014 LSN: 263993539171, Pages flushed: 263974784191, Difference: 18315 K
Mon Sep 1 14:17:49 CEST 2014 LSN: 263993785507, Pages flushed: 263975990474, Difference: 17377 K
Mon Sep 1 14:17:59 CEST 2014 LSN: 263994298172, Pages flushed: 263976855227, Difference: 17034 K
Mon Sep 1 14:18:09 CEST 2014 LSN: 263994670794, Pages flushed: 263978062309, Difference: 16219 K
Mon Sep 1 14:18:19 CEST 2014 LSN: 263995014722, Pages flushed: 263983319652, Difference: 11420 K
Mon Sep 1 14:18:30 CEST 2014 LSN: 263995404674, Pages flushed: 263986138726, Difference: 9048 K
Mon Sep 1 14:18:40 CEST 2014 LSN: 263995718244, Pages flushed: 263988558036, Difference: 6992 K
Mon Sep 1 14:18:50 CEST 2014 LSN: 263996129424, Pages flushed: 263988808179, Difference: 7149 K
Mon Sep 1 14:19:00 CEST 2014 LSN: 263996517064, Pages flushed: 263992009344, Difference: 4402 K
Mon Sep 1 14:19:11 CEST 2014 LSN: 263996979188, Pages flushed: 263993364509, Difference: 3529 K
Mon Sep 1 14:19:21 CEST 2014 LSN: 263998880477, Pages flushed: 263993558842, Difference: 5196 K
Mon Sep 1 14:19:31 CEST 2014 LSN: 264001013381, Pages flushed: 263993568285, Difference: 7270 K
Mon Sep 1 14:19:41 CEST 2014 LSN: 264001933489, Pages flushed: 263993578961, Difference: 8158 K
Mon Sep 1 14:19:51 CEST 2014 LSN: 264004225438, Pages flushed: 263993585459, Difference: 10390 K

Dan pada pukul 14:19:11 sebaran telah mencapai tingkat minimum, jadi aktivitas pembilasan tampaknya telah berhenti di sini, hanya bertepatan dengan akhir kios. Tetapi poin-poin ini membuat saya mengabaikan log InnoDB yang memerah karena:

• untuk operasi pembilasan untuk memblokir semua pembaruan ke database, ia harus "sinkron", yang berarti bahwa 7/8 ruang log harus ditempati
• itu akan didahului oleh fase pembilasan "asinkron" mulai dari innodb_max_dirty_pages_pctlevel pengisian - yang tidak saya lihat
• LSN terus meningkat bahkan selama kios, sehingga aktivitas log tidak berhenti sepenuhnya
• INSERT tabel MyISAM juga terpengaruh
• utas page_cleaner untuk pembilasan adaptif tampaknya melakukan tugasnya dan membersihkan log tanpa menyebabkan kueri DML berhenti:

^{(angka berasal ([Log Sequence Number] - [Pages flushed up to]) / 1024dari SHOW ENGINE INNODB STATUS)}

Masalahnya agak berkurang dengan pengaturan innodb_adaptive_flushing_lwm=1, memaksa pembersih halaman untuk melakukan lebih banyak pekerjaan daripada sebelumnya.

The error.logtidak mempunyai catatan bertepatan dengan kios-kios. SHOW INNODB STATUSkutipan setelah sekitar 24 jam operasi terlihat seperti ini:

SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 789330
OS WAIT ARRAY INFO: signal count 1424848
Mutex spin waits 269678, rounds 3114657, OS waits 65965
RW-shared spins 941620, rounds 20437223, OS waits 442474
RW-excl spins 451007, rounds 13254440, OS waits 215151
Spin rounds per wait: 11.55 mutex, 21.70 RW-shared, 29.39 RW-excl
------------------------
LATEST DETECTED DEADLOCK
------------------------
2014-09-03 10:33:55 7fe0e2e44700
[...]
--------
FILE I/O
--------
[...]
932635 OS file reads, 2117126 OS file writes, 1193633 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 17.00 writes/s, 1.20 fsyncs/s
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Main thread process no. 54745, id 140604272338688, state: sleeping
Number of rows inserted 528904, updated 1596758, deleted 99860, read 3325217158
5.40 inserts/s, 10.40 updates/s, 0.00 deletes/s, 122969.21 reads/s

Jadi, ya, database memang memiliki deadlock, tetapi mereka sangat jarang (yang "terbaru" telah ditangani sekitar 11 jam sebelum statistik dibaca).

Saya mencoba melacak nilai bagian "SEMAPHORES" selama periode waktu tertentu, terutama dalam situasi operasi normal dan selama kios (saya menulis skrip kecil memeriksa daftar proses server MySQL dan menjalankan beberapa perintah diagnostik ke dalam output log jika-kalau dari kios yang jelas). Karena angka telah diambil dari kerangka waktu yang berbeda, saya telah menormalkan hasilnya ke acara / detik:

                          normal   stall
                          1h avg  1m avg
OS WAIT ARRAY INFO: 
    reservation count      5,74    1,00
    signal count          24,43    3,17
Mutex spin waits           1,32    5,67
    rounds                 8,33   25,85
    OS waits               0,16    0,43
RW-shared spins            9,52    0,76
    rounds               140,73    13,39
    OS waits               2,60    0,27
RW-excl spins              6,36    1,08
    rounds               178,42   16,51
    OS waits               2,38    0,20

Saya tidak begitu yakin tentang apa yang saya lihat di sini. Sebagian besar angka telah turun dengan urutan besarnya - mungkin karena operasi pembaruan yang dihentikan, "Putaran mutex menunggu" dan "Putaran putaran mutex" namun keduanya meningkat dengan faktor 4.

Menyelidiki ini lebih lanjut, daftar SHOW ENGINE INNODB MUTEXmutex ( ) memiliki ~ 480 entri mutex terdaftar baik dalam operasi normal maupun selama warung. Saya telah mengaktifkan innodb_status_output_locksuntuk melihat apakah itu akan memberi saya lebih banyak detail.

Variabel konfigurasi

(Saya telah mengutak-atik sebagian besar dari mereka tanpa keberhasilan yang pasti):

mysql> show global variables where variable_name like 'innodb_adaptive_flush%';
+------------------------------+-------+
| Variable_name                | Value |
+------------------------------+-------+
| innodb_adaptive_flushing     | ON    |
| innodb_adaptive_flushing_lwm | 1     |
+------------------------------+-------+
mysql> show global variables where variable_name like 'innodb_max_dirty_pages_pct%';
+--------------------------------+-------+
| Variable_name                  | Value |
+--------------------------------+-------+
| innodb_max_dirty_pages_pct     | 50    |
| innodb_max_dirty_pages_pct_lwm | 10    |
+--------------------------------+-------+
mysql> show global variables where variable_name like 'innodb_log_%';
+-----------------------------+-----------+
| Variable_name               | Value     |
+-----------------------------+-----------+
| innodb_log_buffer_size      | 8388608   |
| innodb_log_compressed_pages | ON        |
| innodb_log_file_size        | 268435456 |
| innodb_log_files_in_group   | 2         |
| innodb_log_group_home_dir   | ./        |
+-----------------------------+-----------+
mysql> show global variables where variable_name like 'innodb_double%';
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| innodb_doublewrite | ON    |
+--------------------+-------+
mysql> show global variables where variable_name like 'innodb_buffer_pool%';
+-------------------------------------+----------------+
| Variable_name                       | Value          |
+-------------------------------------+----------------+
| innodb_buffer_pool_dump_at_shutdown | OFF            |
| innodb_buffer_pool_dump_now         | OFF            |
| innodb_buffer_pool_filename         | ib_buffer_pool |
| innodb_buffer_pool_instances        | 8              |
| innodb_buffer_pool_load_abort       | OFF            |
| innodb_buffer_pool_load_at_startup  | OFF            |
| innodb_buffer_pool_load_now         | OFF            |
| innodb_buffer_pool_size             | 29360128000    |
+-------------------------------------+----------------+
mysql> show global variables where variable_name like 'innodb_io_capacity%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| innodb_io_capacity     | 200   |
| innodb_io_capacity_max | 2000  |
+------------------------+-------+
mysql> show global variables where variable_name like 'innodb_lru_scan_depth%';
+-----------------------+-------+
| Variable_name         | Value |
+-----------------------+-------+
| innodb_lru_scan_depth | 1024  |
+-----------------------+-------+

Banyak hal sudah dicoba

• menonaktifkan cache permintaan oleh SET GLOBAL query_cache_size=0
• meningkat innodb_log_buffer_sizemenjadi 128 juta
• bermain-main dengan innodb_adaptive_flushing, innodb_max_dirty_pages_pctdan nilai masing-masing _lwm(mereka ditetapkan ke default sebelum perubahan saya)
• meningkat innodb_io_capacity(2000) dan innodb_io_capacity_max(4000)
• pengaturan innodb_flush_log_at_trx_commit = 2
• berjalan dengan innodb_flush_method = O_DIRECT (ya, kami memang menggunakan SAN dengan cache tulis persisten)
• mengatur / sys / block / sda / queue / scheduler ke noopataudeadline

Kami melihat masalah yang sama pada dua server pada versi 5.6.12 dan 5.6.16 yang berjalan pada Windows, dengan masing-masing sepasang budak. Kami bingung, seperti Anda, selama hampir dua bulan.

Solusi :

set global binlog_order_commits = 0;

Lihat https://dev.mysql.com/doc/refman/5.6/en/replication-options-binary-log.html#sysvar_binlog_order_commits untuk perincian variabel.

Penjelasan :

Teks lengkap InnoDB menggunakan cache (secara default 8M) yang berisi perubahan yang perlu diterapkan pada indeks teks lengkap aktual pada disk.

Setelah cache terisi, beberapa transaksi dibuat untuk melakukan pekerjaan menggabungkan data yang terkandung dalam cache - ini cenderung menjadi sejumlah besar IO acak, jadi kecuali seluruh indeks teks lengkap Anda dapat dimasukkan ke dalam buffer pool, ini adalah transaksi yang panjang dan lambat.

Dengan binlog_order_commits disetel ke true, semua transaksi yang mengandung sisipan dan pembaruan, dimulai setelah transaksi fts_sync_index yang telah berjalan lama, harus menunggu sampai selesai sebelum mereka dapat melakukan.

Ini hanya masalah jika pencatatan biner diaktifkan

Biarkan saya mungkin mencoba dan menjelaskan masalah historis dengan pembilasan log dan bagaimana pembilasan adaptif bekerja:

• Redo log adalah desain buffer cincin . Mereka hanya pernah ditulis untuk (tidak pernah membaca dari dalam operasi normal) dan menyediakan pemulihan crash. Saya suka menggambarkan penyangga cincin sebagai mirip dengan tapak tangki.

• InnoDB tidak akan dapat menimpa ruang file log jika berisi perubahan yang belum dimodifikasi pada disk. Jadi secara historis, apa yang akan terjadi adalah bahwa InnoDB akan mencoba sejumlah pekerjaan per detik (dikonfigurasikan oleh innodb_io_capacity) dan jika itu tidak cukup, Anda akan mencapai ruang log penuh. Sebuah kios akan terjadi karena pembilasan sinkron yang diperlukan untuk tiba-tiba membebaskan ruang, membuat apa yang biasanya merupakan tugas latar belakang tiba-tiba menjadi latar depan.

• Untuk mengatasi masalah ini, pembilasan adaptif diperkenalkan. Di mana pada 10% (default) ruang log yang dikonsumsi, pekerjaan latar belakang mulai semakin agresif. Tujuan dari ini bukan kedai yang tiba-tiba, Anda memiliki lebih banyak 'penurunan pendek' dalam kinerja.

• Tidak tergantung pada flushing adaptif, penting untuk memiliki ruang log yang cukup untuk beban kerja Anda ( innodb_log_file_sizenilai-nilai 4G sekarang cukup aman), dan pastikan bahwa innodb_io_capacitydan innodb_lru_scan_depthdisetel ke nilai realistis. Adaptasi pembilasan 10% innodb_adaptive_flushing_lwmadalah sesuatu yang Anda tidak lakukan terlalu jauh, itu lebih merupakan mekanisme pertahanan terhadap ruang.

Hanya untuk membawa InnoDB sedikit pertentangan, Anda bisa bermain dengannya innodb_purge_threads.

Sebelum MySQL 5.6, Master Thread melakukan semua pembilasan halaman. Di MySQL 5.6, utas terpisah dapat menanganinya. Nilai default untuk innodb_purge_threadsdalam MySQL 5.5 adalah 0 dengan maksimum 1. Pada MySQL 5.6, standarnya adalah 1 dengan maksimum 32.

Apa yang innodb_purge_threadssebenarnya dilakukan pengaturan ?

Nilai bukan nol menjalankan operasi pembersihan dalam satu atau lebih utas latar belakang, yang dapat mengurangi pertikaian internal dalam InnoDB, meningkatkan skalabilitas. Meningkatkan nilai menjadi lebih dari 1 menciptakan banyak thread purge yang terpisah, yang dapat meningkatkan efisiensi pada sistem di mana operasi DML dilakukan pada beberapa tabel.

Saya akan memulai dengan mengatur innodb_purge_threads ke 4 dan melihat apakah pembilasan halaman InnoDB berkurang.

UPDATE 2014-09-02 12:33 EDT

Morgan Tocker menunjukkan dalam komentar di bawah bahwa pembersih halaman adalah korban dan MySQL 5.7 dapat mengatasinya . Meskipun demikian, situasi Anda ada di MySQL 5.6.

Saya melihat kedua dan melihat bahwa Anda memiliki innodb_max_dirty_pages_pct di 50.

Default untuk innodb_max_dirty_pages_pct di MySQL 5.5+ adalah 75. Menurunkannya akan meningkatkan kejadian warung dari pembilasan. Saya akan melakukan tiga (3) hal

• Tingkatkan innodb_max_dirty_pages_pct menjadi 90 (Itu adalah default untuk MySQL 5.1)
• Set innodb_max_dirty_pages_pct_lwm = 0 (default) atau hapus darimy.cnf
• Tingkatkan innodb_log_buffer_size menjadi 128M (setengah dari innodb_log_file_size )

UPDATE 2014-09-03 11:06 EDT

Anda mungkin perlu mengubah perilaku memerah Anda

Coba atur hal berikut secara dinamis

SET GLOBAL flush = 1;
SET GLOBAL flush_time = 10;

Variabel-variabel ini, flush dan flush_time , akan membuat pembilasan lebih agresif dengan menutup pegangan file terbuka pada tabel setiap 10 detik. MyISAM pasti dapat mengambil manfaat darinya karena tidak menyimpan data. Semua menulis ke tabel MyISAM membutuhkan kunci tabel penuh, diikuti oleh penulisan atom, dan bergantung pada OS untuk perubahan disk.

Pembilasan InnoDB seperti itu akan membutuhkan restart mysql. Opsi untuk dilihat adalah innodb_flush_log_at_trx_commit dan innodb_flush_method .

Sebelum Anda memulai kembali, silakan tambahkan ini

[mysqld]
flush = 1
flush_time = 10
innodb_flush_log_at_trx_commit = 0
innodb_flush_method = O_DIRECT

Sebelum menempuh rute ini, Anda harus memeriksa apakah penjurnalan adalah masalah. Saya melihat postingan mysqlperformanceblog yang keren ini di O_DIRECT dipalsukan karena kernel. Posting yang sama juga menyebutkan MyISAM sedang terpengaruh.

Saya menulis tentang posting ini sebelumnya: ib_logfile dibuka dengan O_SYNC ketika innodb_flush_method = O_DSYNC

Cobalah !!!