Problem

Instancja MySQL 5.6.20 z uruchomioną (przeważnie tylko) bazą danych z tabelami InnoDB od czasu do czasu wyświetla utknięcie we wszystkich operacjach aktualizacji na czas 1-4 minut przy wszystkich zapytaniach INSERT, UPDATE i DELETE pozostających w stanie „Koniec zapytania”. To oczywiście najbardziej niefortunne. Dziennik powolnych zapytań MySQL rejestruje nawet najbardziej trywialne zapytania z szalonymi czasami zapytań, setki z tym samym znacznikiem czasu odpowiadającym momentowi, w którym przeciągnięcie zostało rozwiązane:

# 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');

Statystyki urządzeń pokazują zwiększone, choć nie nadmierne obciążenie we / wy w tym przedziale czasowym (w tym przypadku aktualizacje opóźniały się 14:17:30 - 14:19:12 zgodnie ze znacznikami czasu z powyższej instrukcji):

# 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

Częściej niż nie zauważam w dzienniku powolnym mysql, że najstarsze przeciąganie zapytania to INSERT w tabeli o dużej (~ 10 M wierszy) z kluczem podstawowym VARCHAR i indeksem wyszukiwania pełnotekstowego:

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

Dalsze dochodzenie (tj. POKAŻ STATUS INNODBU SILNIKA) wykazało, że rzeczywiście zawsze jest to aktualizacja tabeli przy użyciu indeksów pełnotekstowych, która powoduje przeciągnięcie. Odpowiednia sekcja TRANSAKCJE „POKAŻ STATUS INNODB SILNIKA” zawiera wpisy takie jak te dla najstarszych uruchomionych transakcji:

---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

Tak więc dzieje się tam intensywna akcja indeksu pełnotekstowego ( doing SYNC index), która zatrzymuje WSZYSTKIE PÓŹNIEJSZE aktualizacje do DOWOLNEJ tabeli.

Z dzienników wygląda to trochę tak, jakby undo log entriesliczba doing SYNC indexprzesuwała się z prędkością ~ 150 / s, aż osiągnie 20 000, w którym to momencie operacja jest wykonywana.

Rozmiar FTS tej konkretnej tabeli jest imponujący:

# 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

chociaż problem jest wywoływany również przez tabele ze znacznie mniejszymi rozmiarami danych FTS, takimi jak ten:

# 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

W takich przypadkach czas przeciągnięcia jest mniej więcej taki sam. Otworzyłem błąd na bugs.mysql.com, aby twórcy mogli się tym zająć.

Charakter przeciągnięć po raz pierwszy zmusił mnie do podejrzenia, że ​​winowajcą jest działanie opróżniania logów, a ten artykuł Percona na temat problemów z wydajnością opróżniania logów w MySQL 5.5 opisuje bardzo podobne objawy, ale kolejne wystąpienia wykazały, że operacje INSERT w pojedynczej tabeli MyISAM w tej bazie danych wpływają również na przeciągnięcie, więc nie wydaje się to problemem wyłącznie z InnoDB.

Niemniej jednak, postanowiłem śledzić wartości Log sequence numberi Pages flushed up tood „log” wyjść sekcyjnych o SHOW ENGINE INNODB STATUSkażde 10 sekund. Rzeczywiście wygląda na to, że aktywność spłukiwania trwa podczas przeciągnięcia, ponieważ rozpiętość między dwiema wartościami maleje:

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

O 14:19:11 rozpiętość osiągnęła minimum, więc wydaje się, że aktywność spłukiwania ustała tutaj, zbiegając się z końcem przeciągnięcia. Ale te punkty sprawiły, że odrzuciłem opróżnianie dziennika InnoDB jako przyczynę:

• operacja opróżniania w celu zablokowania wszystkich aktualizacji bazy danych musi być „synchroniczna”, co oznacza, że ​​7/8 miejsca w dzienniku musi być zajęte
• byłby poprzedzony „asynchroniczną” fazą spłukiwania rozpoczynającą się od innodb_max_dirty_pages_pctpoziomu napełnienia - czego nie widzę
• LSN stale rosną nawet podczas przeciągnięcia, więc aktywność dziennika nie kończy się całkowicie
• Wpływa to również na WSTAWKI tabeli MyISAM
• wydaje się, że wątek page_cleaner do adaptacyjnego opróżniania działa i opróżnia dzienniki, nie powodując zatrzymania zapytań DML:

^{(numery pochodzą ([Log Sequence Number] - [Pages flushed up to]) / 1024z SHOW ENGINE INNODB STATUS)}

Problem wydaje się nieco złagodzony przez ustawienie innodb_adaptive_flushing_lwm=1, zmuszając urządzenie czyszczące do strony do wykonania większej ilości pracy niż wcześniej.

Nie error.logma wpisów pokrywających się ze straganami. SHOW INNODB STATUSfragmenty po około 24 godzinach pracy wyglądają następująco:

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

Tak więc, baza danych ma zakleszczenia, ale są one bardzo rzadkie („najnowszy” został obsłużony około 11 godzin przed odczytaniem statystyk).

Próbowałem śledzić wartości sekcji „SEMAPHORES” przez pewien czas, szczególnie w sytuacji normalnej pracy i podczas przeciągnięcia (napisałem mały skrypt sprawdzający listę procesów serwera MySQL i uruchamiając kilka komend diagnostycznych na wyjściu dziennika w przypadku oczywistego przeciągnięcia). Ponieważ liczby zostały przejęte w różnych ramach czasowych, znormalizowałem wyniki do zdarzeń / sekundę:

                          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

Nie jestem pewien, co tu widzę. Większość liczb spadła o rząd wielkości - prawdopodobnie z powodu zaprzestania operacji aktualizacji, „Mutex Spin Waits” i „Mutex Spin Rounds” wzrosły jednak o współczynnik 4.

Przy dalszym badaniu, lista muteksów ( SHOW ENGINE INNODB MUTEX) zawiera ~ 480 wpisów muteksów wymienionych zarówno podczas normalnej pracy, jak i podczas przeciągnięcia. Umożliwiłem innodb_status_output_lockssprawdzenie, czy da mi to więcej szczegółów.

Zmienne konfiguracyjne

(Majstrowałem przy większości z nich bez definitywnego sukcesu):

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  |
+-----------------------+-------+

Rzeczy już próbowałem

• wyłączenie bufora zapytań przez SET GLOBAL query_cache_size=0
• wzrasta innodb_log_buffer_sizedo 128 mln
• zabawy z innodb_adaptive_flushing, innodb_max_dirty_pages_pcta odpowiednie _lwmwartości (były one ustawione na domyślne przed moimi zmianami)
• zwiększenie innodb_io_capacity(2000) i innodb_io_capacity_max(4000)
• oprawa innodb_flush_log_at_trx_commit = 2
• działa z innodb_flush_method = O_DIRECT (tak, używamy SAN z trwałym cache zapisu)
• ustawienie / sys / block / sda / queue / scheduler na nooplubdeadline

Ten sam problem występował na dwóch serwerach w wersjach 5.6.12 i 5.6.16 działających w systemie Windows, każdy z parą urządzeń podrzędnych. Przez prawie dwa miesiące byliśmy zaskoczeni, tak jak ty.

Rozwiązanie :

set global binlog_order_commits = 0;

Zobacz https://dev.mysql.com/doc/refman/5.6/en/replication-options-binary-log.html#sysvar_binlog_order_commits, aby uzyskać szczegółowe informacje na temat zmiennej.

Objaśnienie :

Pełny tekst InnoDB wykorzystuje pamięć podręczną (domyślnie rozmiar 8 MB) zawierającą zmiany, które należy zastosować do faktycznego indeksu pełnotekstowego na dysku.

Gdy pamięć podręczna się zapełni, zostaje utworzonych kilka transakcji w celu scalenia danych zawartych w pamięci podręcznej - zazwyczaj jest to duża liczba losowych operacji we / wy, więc chyba że można załadować cały indeks pełnotekstowy do pula buforów, jest to długa i wolna transakcja.

Przy ustawieniu binlog_order_commits na wartość true wszystkie transakcje zawierające wstawki i aktualizacje, rozpoczęte po długotrwałej transakcji fts_sync_index, muszą poczekać na zakończenie, zanim będą mogły zatwierdzić.

Jest to problem tylko wtedy, gdy włączone jest rejestrowanie binarne

Pozwól, że spróbuję opisać historyczny problem z płukaniem logów i działaniem płukania adaptacyjnego:

• Dzienniki ponawiania mają postać bufora pierścieniowego . Są one zapisywane tylko do (nigdy nie czytane podczas normalnej pracy) i zapewniają przywracanie po awarii. Lubię opisywać bufor pierścieniowy jako podobny do bieżnika czołgu.

• InnoDB nie będzie w stanie zastąpić przestrzeni plików dziennika, jeśli zawiera zmiany, które nie zostały jeszcze zmodyfikowane na dysku. Historycznie rzecz biorąc, to co by się wydarzyło, to że InnoDB spróbuje wykonać pewną ilość pracy na sekundę (skonfigurowaną przez innodb_io_capacity), a jeśli to nie wystarczy, osiągniesz pełne miejsce w dzienniku. Stall pojawiłby się, ponieważ musiało nastąpić synchroniczne spłukiwanie, aby nagle zwolnić miejsce, powodując nagle to, co zwykle jest zadaniem w tle, na pierwszym planie.

• Aby rozwiązać ten problem, wprowadzono adaptacyjne płukanie. Przy zużyciu 10% (domyślnie) miejsca na dziennik praca w tle zaczyna być coraz bardziej agresywna. Ma to na celu raczej niż nagłe opóźnienie, a więcej „krótkiego spadku” wydajności.

• Niezależnie od adaptacyjnego spłukiwania, ważne jest, aby mieć wystarczającą ilość miejsca dla dziennika obciążenia ( innodb_log_file_sizewartości 4G są teraz zupełnie bezpieczne) i upewnij się, że innodb_io_capacityi innodb_lru_scan_depthsą ustawione na realistycznych wartości. Adaptacyjne spłukiwanie 10% innodb_adaptive_flushing_lwmto coś, na co nie rozciągasz się zbyt daleko, to raczej mechanizm obronny przed brakiem miejsca.

Aby przynieść InnoDB ulgę w sporze, możesz się z nim pobawić innodb_purge_threads.

Przed MySQL 5.6 wątek główny wyczyścił całą stronę. W MySQL 5.6 może to obsłużyć osobny wątek. Domyślna wartość dla innodb_purge_threadsMySQL 5.5 wynosiła 0 z maksimum 1. W MySQL 5.6 wartością domyślną jest 1 z maksimum 32.

Co innodb_purge_threadswłaściwie robi ustawienie ?

Wartości niezerowe uruchamiają operację czyszczenia w co najmniej jednym wątku w tle, co może zmniejszyć wewnętrzną rywalizację w InnoDB, poprawiając skalowalność. Zwiększenie wartości do wartości większej niż 1 powoduje utworzenie wielu osobnych wątków czyszczenia, co może poprawić wydajność w systemach, w których operacje DML są wykonywane na wielu tabelach.

Zacznę od ustawienia innodb_purge_threads na 4 i zobaczę, czy płukanie strony InnoDB jest zmniejszone.

AKTUALIZACJA 2014-09-02 12:33 EDT

Morgan Tocker wskazał w komentarzu poniżej, że narzędzie do czyszczenia stron jest ofiarą, a MySQL 5.7 może temu zaradzić . Niezależnie od tego Twoja sytuacja dotyczy MySQL 5.6.

Spojrzałem po raz drugi i zauważyłem, że masz innodb_max_dirty_pages_pct na 50.

Domyślna wartość dla innodb_max_dirty_pages_pct w MySQL 5.5+ wynosi 75. Obniżenie go zwiększyłoby częstość utknięć z opróżniania. Zrobiłbym trzy (3) rzeczy

• Zwiększ innodb_max_dirty_pages_pct do 90 (To był domyślny dla MySQL 5.1)
• Ustaw innodb_max_dirty_pages_pct_lwm = 0 (domyślnie) lub usuń go zmy.cnf
• Zwiększ rozmiar innodb_log_buffer_size do 128M (połowa twojego rozmiaru innodb_log_file_sile )

AKTUALIZACJA 2014-09-03 11:06 EDT

Konieczna może być zmiana zachowania spłukiwania

Spróbuj ustawić następujące dynamicznie

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

Te zmienne, flush i flush_time , zwiększą agresywność opróżniania, zamykając otwarte uchwyty plików w tabelach co 10 sekund. MyISAM z pewnością może na tym skorzystać, ponieważ nie buforuje danych. Wszystkie zapisy w tabelach MyISAM wymagają pełnych blokad tabel, a następnie zapisów atomowych i zależą od systemu operacyjnego w przypadku zmian dysku.

Opróżnianie InnoDB w ten sposób wymagałoby ponownego uruchomienia mysql. Dostępne opcje to innodb_flush_log_at_trx_commit i innodb_flush_method .

Przed ponownym uruchomieniem dodaj je

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

Przed wybraniem tej trasy należy sprawdzić, czy problem dotyczy księgowania. Widziałem ten fajny post na blogu mysqlperformance na O_DIRECT, który został sfałszowany z powodu jądra. Ten sam post wspomina także o wpływie na MyISAM.

Pisałem o tym poście wcześniej: plik ib_logf otwarty przy pomocy O_SYNC, gdy innodb_flush_method = O_DSYNC

Spróbuj !!!