Немного предыстории, некоторое время назад мы начали испытывать высокое системное время на одной из наших баз данных MySQL. Эта база данных также страдала от высокого использования диска, поэтому мы решили, что эти вещи связаны. И так как у нас уже были планы перенести его на SSD, мы подумали, что это решит обе проблемы.
Это помогло ... но ненадолго.
В течение пары недель после миграции график процессора был таким:
Но теперь мы вернулись к этому:
Это произошло из ниоткуда, без каких-либо видимых изменений в нагрузке или логике приложения.
Статистика БД:
- Версия MySQL - 5.7.20
- ОС - Debian
- Размер БД - 1,2 Тб
- Оперативная память - 700 Гб
- Ядра процессора - 56
- Пиковая нагрузка - около 5 кк / с для чтения, 600 к / с для записи (хотя отдельные запросы часто бывают довольно сложными)
- Резьбы - 50 ходовых, 300 связанных
- В нем около 300 таблиц, все InnoDB
MySQL config:
[client]
port = 3306
socket = /var/run/mysqld/mysqld.sock
[mysqld_safe]
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
nice = 0
[mysqld]
user = mysql
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
port = 3306
basedir = /usr
datadir = /opt/mysql-data
tmpdir = /tmp
lc-messages-dir = /usr/share/mysql
explicit_defaults_for_timestamp
sql_mode = STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
log-error = /opt/mysql-log/error.log
# Replication
server-id = 76
gtid-mode = ON
enforce-gtid-consistency = true
relay-log = /opt/mysql-log/mysql-relay-bin
relay-log-index = /opt/mysql-log/mysql-relay-bin.index
replicate-wild-do-table = dbname.%
log-bin = /opt/mysql-log/mysql-bin.log
expire_logs_days = 7
max_binlog_size = 1024M
binlog-format = ROW
log-bin-trust-function-creators = 1
log_slave_updates = 1
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0
# * IMPORTANT: Additional settings that can override those from this file!
# The files must end with '.cnf', otherwise they'll be ignored.
#
!includedir /etc/mysql/conf.d/
# Here goes
skip_name_resolve = 1
general_log = 0
slow_query_log = 1
slow_query_log_file = /opt/mysql-log/slow.log
long_query_time = 3
max_allowed_packet = 16M
max_connections = 700
max_execution_time = 200000
open_files_limit = 32000
table_open_cache = 8000
thread_cache_size = 128
innodb_buffer_pool_size = 550G
innodb_buffer_pool_instances = 28
innodb_log_file_size = 15G
innodb_log_files_in_group = 2
innodb_flush_method = O_DIRECT
max_heap_table_size = 16M
tmp_table_size = 128M
join_buffer_size = 1M
sort_buffer_size = 2M
innodb_lru_scan_depth = 256
query_cache_type = 0
query_cache_size = 0
innodb_temp_data_file_path = ibtmp1:12M:autoextend:max:30G
Другие наблюдения
Производительность процесса mysql во время пиковой нагрузки:
68,31% 68,31% mysqld [kernel.kallsyms] [k] _raw_spin_lock
- _raw_spin_lock
+ 51,63% 0x7fd118e9dbd9
+ 48,37% 0x7fd118e9dbab
+ 37,36% 0,02% mysqld libc-2.19.so [.] 0x00000000000f4bd9
+ 33,83% 0,01% mysqld libc-2.19.so [.] 0x00000000000f4bab
+ 26,92% 0,00% mysqld libpthread-2.19.so [.] start_thread
+ 26,82% 0,00% mysqld mysqld [.] pfs_spawn_thread
+ 26,82% 0,00% mysqld mysqld [.] handle_connection
+ 26,81% 0,01% mysqld mysqld [.] do_command(THD*)
+ 26,65% 0,02% mysqld mysqld [.] dispatch_command(THD*, COM_DATA const*, enum_server_command)
+ 26,29% 0,01% mysqld mysqld [.] mysql_parse(THD*, Parser_state*)
+ 24,85% 0,01% mysqld mysqld [.] mysql_execute_command(THD*, bool)
+ 23,61% 0,00% mysqld mysqld [.] handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long)
+ 23,54% 0,00% mysqld mysqld [.] 0x0000000000374103
+ 19,78% 0,00% mysqld mysqld [.] JOIN::exec()
+ 19,13% 0,15% mysqld mysqld [.] sub_select(JOIN*, QEP_TAB*, bool)
+ 13,86% 1,48% mysqld mysqld [.] row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)
+ 8,48% 0,25% mysqld mysqld [.] ha_innobase::general_fetch(unsigned char*, unsigned int, unsigned int)
+ 7,93% 0,00% mysqld [unknown] [.] 0x00007f40c4d7a6f8
+ 7,57% 0,00% mysqld mysqld [.] 0x0000000000828f74
+ 7,25% 0,11% mysqld mysqld [.] handler::ha_index_next_same(unsigned char*, unsigned char const*, unsigned int)
Это показывает, что mysql тратит много времени на spin_locks . Я надеялся понять, откуда взялись эти замки, к сожалению, не повезло.
Профиль запроса во время высокой нагрузки показывает большое количество переключений контекста. Я использовал select * from MyTable, где pk = 123 , MyTable имеет около 90M строк. Вывод профиля:
Status Duration CPU_user CPU_system Context_voluntary Context_involuntary Block_ops_in Block_ops_out Messages_sent Messages_received Page_faults_major Page_faults_minor Swaps Source_function Source_file Source_line
starting 0,000756 0,028000 0,012000 81 1 0 0 0 0 0 0 0
checking permissions 0,000057 0,004000 0,000000 4 0 0 0 0 0 0 0 0 check_access sql_authorization.cc 810
Opening tables 0,000285 0,008000 0,004000 31 0 0 40 0 0 0 0 0 open_tables sql_base.cc 5650
init 0,000304 0,012000 0,004000 31 1 0 0 0 0 0 0 0 handle_query sql_select.cc 121
System lock 0,000303 0,012000 0,004000 33 0 0 0 0 0 0 0 0 mysql_lock_tables lock.cc 323
optimizing 0,000196 0,008000 0,004000 20 0 0 0 0 0 0 0 0 optimize sql_optimizer.cc 151
statistics 0,000885 0,036000 0,012000 99 6 0 0 0 0 0 0 0 optimize sql_optimizer.cc 367
preparing 0,000794 0,000000 0,096000 76 2 32 8 0 0 0 0 0 optimize sql_optimizer.cc 475
executing 0,000067 0,000000 0,000000 10 1 0 0 0 0 0 0 0 exec sql_executor.cc 119
Sending data 0,000469 0,000000 0,000000 54 1 32 0 0 0 0 0 0 exec sql_executor.cc 195
end 0,000609 0,000000 0,016000 64 4 0 0 0 0 0 0 0 handle_query sql_select.cc 199
query end 0,000063 0,000000 0,000000 3 1 0 0 0 0 0 0 0 mysql_execute_command sql_parse.cc 4968
closing tables 0,000156 0,000000 0,000000 20 4 0 0 0 0 0 0 0 mysql_execute_command sql_parse.cc 5020
freeing items 0,000071 0,000000 0,004000 7 1 0 0 0 0 0 0 0 mysql_parse sql_parse.cc 5596
cleaning up 0,000533 0,024000 0,008000 62 0 0 0 0 0 0 0 0 dispatch_command sql_parse.cc 1902
Петр Зайцев недавно сделал сообщение о переключении контекста, где он говорит:
В реальном мире, тем не менее, я бы не стал беспокоиться о том, что раздоры будут большой проблемой, если у вас менее десяти переключений контекста на запрос.
Но это показывает более 600 переключателей!
Что может вызвать эти симптомы и что с этим можно сделать? Я буду признателен за любые указания или информацию по этому вопросу, все, с чем я сталкиваюсь, довольно старое и / или неубедительное.
PS Я с удовольствием предоставлю дополнительную информацию, если потребуется.
Вывод SHOW GLOBAL STATUS и SHOW VARIABLES
Я не могу опубликовать это здесь, потому что содержание превышает ограничение размера сообщения.
ПОКАЗАТЬ ГЛОБАЛЬНОЕ СОСТОЯНИЕ
ПОКАЗАТЬ ПЕРЕМЕННЫЕ
IOSTAT
avg-cpu: %user %nice %system %iowait %steal %idle
7,35 0,00 5,44 0,20 0,00 87,01
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 8,00 0,00 32,00 32,00 0,00 32,00 0,00
sda 0,04 2,27 0,13 0,96 0,86 46,52 87,05 0,00 2,52 0,41 2,80 0,28 0,03
sdb 0,21 232,57 30,86 482,91 503,42 7769,88 32,21 0,34 0,67 0,83 0,66 0,34 17,50
avg-cpu: %user %nice %system %iowait %steal %idle
9,98 0,00 77,52 0,46 0,00 12,04
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00
sda 0,00 1,60 0,00 0,60 0,00 8,80 29,33 0,00 0,00 0,00 0,00 0,00 0,00
sdb 0,00 566,40 55,60 981,60 889,60 16173,60 32,90 0,84 0,81 0,76 0,81 0,51 53,28
avg-cpu: %user %nice %system %iowait %steal %idle
11,83 0,00 72,72 0,35 0,00 15,10
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00
sda 0,00 2,60 0,00 0,40 0,00 12,00 60,00 0,00 0,00 0,00 0,00 0,00 0,00
sdb 0,00 565,20 51,60 962,80 825,60 15569,60 32,32 0,85 0,84 0,98 0,83 0,54 54,56
Обновление 2018-03-15
> show global status like 'uptime%'
Uptime;720899
Uptime_since_flush_status;720899
> show global status like '%rollback'
Com_rollback;351422
Com_xa_rollback;0
Handler_rollback;371088
Handler_savepoint_rollback;0
select * from MyTable where pk = 123
в среднем?global status
, не связано ли что-либо с увеличением загрузки процессора. Я не верю, что что-либо может быть достигнуто с доступными на данный момент данными. Я задам другой вопрос, если найду что-то новое.Ответы:
Скорость записи 600q / s со сбросом на коммит, вероятно, достигает предела ваших текущих вращающихся дисков. Переход на SSD уменьшит давление.
Быстрое исправление (до получения SSD), вероятно, изменится на этот параметр:
Но прочитайте предостережения о внесении этого изменения.
Наличие этой настройки и SSD позволит вам расти дальше.
Другое возможное исправление - объединить несколько записей в один
COMMIT
(где логика не нарушена).Почти всегда высокая загрузка ЦП и / или ввода / вывода обусловлена плохими индексами и / или плохой формулировкой запросов. Включите медленный журнал с
long_query_time=1
, подождите немного , затем посмотрите, что получится. С запросами в руке, обеспечиваютSELECT
,EXPLAIN SELECT ...
иSHOW CREATE TABLE
. То же самое касается запросов на запись. Из них мы, вероятно, можем приручить процессор и / или ввод / вывод. Даже с вашей текущей настройкой3
,pt-query-digest
возможно, найдете некоторые интересные вещи.Обратите внимание, что с 50 «запущенными» потоками возникает много споров; это может быть причиной переключения и т. д., что вы заметили. Нам нужно, чтобы запросы заканчивались быстрее. С 5.7 система может опрокинуться с 100 работающими потоками. Если значения превышают 64, переключатели контекста, мьютексы, блокировки и т. Д. Способствуют замедлению каждого потока, что не приводит к улучшению пропускной способности, в то время как задержка выходит за рамки.
Для другого подхода к анализу проблемы, пожалуйста, укажите
SHOW VARIABLES
иSHOW GLOBAL STATUS
? Больше обсуждения здесь .Анализ ПЕРЕМЕННЫХ И СОСТОЯНИЯ
(Извините, ничего не выскакивает при решении вашего вопроса.)
Замечания:
Более важные вопросы:
Многие временные таблицы, особенно дисковые, создаются для сложных запросов. Будем надеяться, что медленный журнал идентифицирует некоторые запросы, которые можно улучшить (с помощью индексации / переформулировки / и т. Д.). Другие индикаторы - это объединения без индексов и sort_merge_passes; однако ни один из них не является окончательным, нам нужно увидеть запросы.
Max_used_connections = 701
is> =Max_connections = 700
, поэтому, вероятно, некоторые соединения отказались. Кроме того , если это указано больше , чем, скажем, 64 потоков работает , то производительность системы , вероятно sufferd в то время. Рассмотрите возможность регулирования количества соединений путем регулирования количества клиентов. Вы используете Apache, Tomcat или что-то еще? 70Threads_running
указывает на то, что в данный моментSHOW
система была в беде.Увеличение количества утверждений в каждом
COMMIT
(когда это целесообразно) может помочь производительности некоторых.innodb_log_file_size
, на 15 ГБ, больше, чем необходимо, но я вижу, не нужно менять его.Тысячи столов обычно не очень хороший дизайн.
eq_range_index_dive_limit = 200
касается меня, но я не знаю, как советовать. Был ли это осознанный выбор?Почему так много CREATE + DROP ПРОЦЕДУРА?
Почему так много команд SHOW?
Подробности и другие наблюдения:
( Innodb_buffer_pool_pages_flushed ) = 523,716,598 / 3158494 = 165 /sec
- пишет (сбрасывает) - проверьте innodb_buffer_pool_size( table_open_cache ) = 10,000
- Количество дескрипторов таблиц для кэширования - обычно несколько сотен - это хорошо.( (Innodb_buffer_pool_reads + Innodb_buffer_pool_pages_flushed) ) = ((61,040,718 + 523,716,598) ) / 3158494 = 185 /sec
- InnoDB I / O( Innodb_dblwr_pages_written/Innodb_pages_written ) = 459,782,684/523,717,889 = 87.8%
- Похоже, эти значения должны быть равны?( Innodb_os_log_written ) = 1,071,443,919,360 / 3158494 = 339226 /sec
- Это показатель того, насколько занят InnoDB. - Очень занят InnoDB.( Innodb_log_writes ) = 110,905,716 / 3158494 = 35 /sec
( Innodb_os_log_written / (Uptime / 3600) / innodb_log_files_in_group / innodb_log_file_size ) = 1,071,443,919,360 / (3158494 / 3600) / 2 / 15360M = 0.0379
- Соотношение - (см. Минуты)( Uptime / 60 * innodb_log_file_size / Innodb_os_log_written ) = 3,158,494 / 60 * 15360M / 1071443919360 = 791
- минуты между ротациями журналов InnoDB Начиная с 5.6.8, это может быть изменено динамически; не забудьте также изменить my.cnf. - (Рекомендация 60 минут между поворотами несколько произвольна.) Настройте innodb_log_file_size. (Невозможно изменить в AWS.)( Com_rollback ) = 770,457 / 3158494 = 0.24 /sec
- Откат в InnoDB. - Чрезмерная частота откатов может указывать на неэффективную логику приложения.( Innodb_row_lock_waits ) = 632,292 / 3158494 = 0.2 /sec
- Как часто происходит задержка получения блокировки строки. - Может быть вызвано сложными запросами, которые могут быть оптимизированы.( Innodb_dblwr_writes ) = 97,725,876 / 3158494 = 31 /sec
- «Doublewrite buffer» записывает на диск. «Двойные надписи» являются признаком надежности. Некоторым более новым версиям / конфигурациям они не нужны. - (Симптом других проблем)( Innodb_row_lock_current_waits ) = 13
- Количество блокировок строк, ожидаемых в данный момент операциями с таблицами InnoDB. Ноль довольно нормально. - Что-то большое происходит?( innodb_print_all_deadlocks ) = OFF
- Нужно ли регистрировать все тупики. - Если вы страдаете от тупиков, включите это. Внимание: если у вас много взаимоблокировок, это может привести к записи на диск.( local_infile ) = ON
- local_infile = ON - потенциальная проблема безопасности( bulk_insert_buffer_size / _ram ) = 8M / 716800M = 0.00%
- Буфер для многорядных INSERT и LOAD DATA - Слишком большой может угрожать размеру оперативной памяти. Слишком маленький может помешать таким операциям.( Questions ) = 9,658,430,713 / 3158494 = 3057 /sec
- Запросы (вне SP) - «qps» -> 2000 может быть нагрузкой на сервер( Queries ) = 9,678,805,194 / 3158494 = 3064 /sec
- Запросы (в том числе внутри SP) -> 3000 могут быть нагрузкой на сервер( Created_tmp_tables ) = 1,107,271,497 / 3158494 = 350 /sec
- Частота создания «временных» таблиц в составе сложных SELECT.( Created_tmp_disk_tables ) = 297,023,373 / 3158494 = 94 /sec
- Частота создания дисковых «временных» таблиц в составе сложных команд SELECT - увеличение tmp_table_size и max_heap_table_size. Проверьте правила для временных таблиц, когда MEMORY используется вместо MyISAM. Возможно, незначительные изменения схемы или запроса могут избежать MyISAM. Лучшие индексы и переформулировка запросов, скорее всего, помогут.( (Com_insert + Com_update + Com_delete + Com_replace) / Com_commit ) = (693300264 + 214511608 + 37537668 + 0) / 1672382928 = 0.565
- Заявления на коммит (при условии, что все InnoDB) - Низкий: может помочь объединить запросы в транзакции; Высокий: длительные транзакции напрягают разные вещи.( Select_full_join ) = 338,957,314 / 3158494 = 107 /sec
- соединения без индекса - добавить подходящие индексы в таблицы, используемые в соединениях.( Select_full_join / Com_select ) = 338,957,314 / 6763083714 = 5.0%
-% отборов, которые являются безиндексными объединениями - добавить подходящие индексы в таблицы, используемые в соединениях.( Select_scan ) = 124,606,973 / 3158494 = 39 /sec
- полное сканирование таблицы - добавление индексов / оптимизация запросов (если они не являются крошечными таблицами)( Sort_merge_passes ) = 1,136,548 / 3158494 = 0.36 /sec
- Здоровые сортировки - Увеличьте sort_buffer_size и / или оптимизируйте сложные запросы.( Com_insert + Com_delete + Com_delete_multi + Com_replace + Com_update + Com_update_multi ) = (693300264 + 37537668 + 198418338 + 0 + 214511608 + 79274476) / 3158494 = 387 /sec
- write / sec - 50 write / sec + log-flush, вероятно, максимально увеличат емкость записи ввода-вывода обычных дисков( ( Com_stmt_prepare - Com_stmt_close ) / ( Com_stmt_prepare + Com_stmt_close ) ) = ( 39 - 38 ) / ( 39 + 38 ) = 1.3%
- Вы закрываете свои подготовленные заявления? - Добавить закрывается.( Com_stmt_close / Com_stmt_prepare ) = 38 / 39 = 97.4%
- Подготовленные заявления должны быть закрыты. - Проверьте, все ли подготовленные заявления являются «закрытыми».( innodb_autoinc_lock_mode ) = 1
- Галера: желания 2 - 2 = «чередование»; 1 = "последовательный" типичный; 0 = "традиционный".( Max_used_connections / max_connections ) = 701 / 700 = 100.1%
- Пиковый% соединений - увеличить max_connections и / или уменьшить wait_timeout( Threads_running - 1 ) = 71 - 1 = 70
- Активные потоки (параллелизм при сборе данных) - Оптимизация запросов и / или схемыНеобычно большой: (Большинство из них проистекает из очень загруженной системы.)
(Продолжение)
источник
innodb_flush_log_at_trx_commit = 2
кажется, не имеет никакого эффекта, и конфликт потоков также не является проблемой, потому что даже при умеренных нагрузках (Threads runnig <50) CPU sys / CPU user что-то вроде 3 к 1.Мы никогда не выясняли, в чем именно заключалась причина этой проблемы, но, чтобы предложить некоторое закрытие, я собираюсь рассказать, что я могу.
Наша команда провела несколько нагрузочных тестов и пришла к выводу, что у
MySQL
нее проблемы с распределением памяти. Поэтому они попытались использоватьjemalloc
вместо,glibc
и проблема исчезла. Мы используемjemalloc
в производстве более 6 месяцев, и больше никогда не видели эту проблему.Я не говорю, что
jemalloc
это лучше, или что каждый должен использовать это сMySQL
. Но, похоже, что для нашего конкретного случаяglibc
просто не работает должным образом.источник
Мои 2цента
Запустите «iostat -xk 5», чтобы проверить, не возникла ли проблема с диском. Также система ЦП связана с системным кодом (Kernell), дважды проверьте новый диск / drivers / config.
источник
Предложения для my.cnf / ini [mysqld] раздела для вашего ОЧЕНЬ ЗАНЯТОГО
Я ожидаю постепенного уменьшения результатов SHOW GLOBAL STATUS LIKE 'innodb_buffer_pool_pages_dirty'; с этими предложениями. 13.01.18 у вас было более 4 миллионов грязных страниц.
Я надеюсь, что это поможет. Они могут быть динамически изменены. Существует гораздо больше возможностей, если вы хотите их, дайте мне знать.
источник
С проверкой IOPS на 30K (нам нужно несколько IOPS для случайных записей), рассмотрите это предложение для раздела my.cnf / ini [mysqld]
может быть динамически изменено с помощью SET GLOBAL и должно быстро уменьшить innodb_buffer_pool_pages_dirty.
Причина COM_ROLLBACK, составляющего в среднем 1 раз в 4 секунды, останется проблемой производительности до тех пор, пока не будет устранена.
@chimmi, 9 апреля 2018 г. Выберите этот сценарий MySQL по адресу https://pastebin.com/aZAu2zZ0 для быстрой проверки ресурсов глобального состояния, используемых или освобождаемых в течение nn секунд, которые можно установить в режиме SLEEP. Это позволит вам увидеть, помог ли кто-нибудь снизить вашу частоту COM_ROLLBACK. Хотел бы услышать от вас по электронной почте.
источник
Ваше ШОУ ГЛОБАЛЬНОЕ СТАТУС указывает, что innodb_buffer_pool_pages_dirty были 4,291,574.
Чтобы отслеживать текущий счет,
Чтобы способствовать уменьшению этого количества,
Через час запустите запрос монитора, чтобы увидеть, где вы стоите с грязными страницами.
Пожалуйста, дайте мне знать ваши счета в начале и через час.
Примените изменения в вашем my.cnf для долгосрочного улучшения здоровья страниц.
источник