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 entries
liczba doing SYNC index
przesuwał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 number
i Pages flushed up to
od „log” wyjść sekcyjnych o SHOW ENGINE INNODB STATUS
każ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_pct
poziomu 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]) / 1024
z 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.log
ma wpisów pokrywających się ze straganami. SHOW INNODB STATUS
fragmenty 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_locks
sprawdzenie, 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_size
do 128 mln - zabawy z
innodb_adaptive_flushing
,innodb_max_dirty_pages_pct
a odpowiednie_lwm
wartości (były one ustawione na domyślne przed moimi zmianami) - zwiększenie
innodb_io_capacity
(2000) iinnodb_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
noop
lubdeadline
Odpowiedzi:
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 :
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
źródło
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_size
wartości 4G są teraz zupełnie bezpieczne) i upewnij się, żeinnodb_io_capacity
iinnodb_lru_scan_depth
są ustawione na realistycznych wartości. Adaptacyjne spłukiwanie 10%innodb_adaptive_flushing_lwm
to coś, na co nie rozciągasz się zbyt daleko, to raczej mechanizm obronny przed brakiem miejsca.źródło
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_threads
MySQL 5.5 wynosiła 0 z maksimum 1. W MySQL 5.6 wartością domyślną jest 1 z maksimum 32.Co
innodb_purge_threads
właściwie robi ustawienie ?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
my.cnf
AKTUALIZACJA 2014-09-03 11:06 EDT
Konieczna może być zmiana zachowania spłukiwania
Spróbuj ustawić następujące dynamicznie
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
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 !!!
źródło
sar -d
jest to, żeawait
podczas jednego z przeciągnięć rośnie prawie dziesięciokrotnie, a przepustowość spada. Czy uważasz, że prawdopodobnie występują tutaj problemy poza MySQL, na przykład z harmonogramem we / wy lub kronikowaniem systemu plików?SHOW GLOBAL VARIABLES LIKE '%io_threads';