Задать вопрос
@yuriyant
web программист
linux

Проседание производительности mariadb, linux. Почему растет Load Average до 30-40?

Всем привет.
В наличии есть сервер с 8-ми ядерным CPU, RAM 32GB, 2 SSD RAID 1 (mdadm, lvm), Centos 7.
База данных: 10.3.16-MariaDB. На сервере крутится проект на Битрикс.

Средняя нагрузка на базу от 1 до 4 тыс. запросов в секунду. С такой нагрузкой сервер работал ~4 мес. и load average сервера составлял порядка 0.7-2. Нагрузка mysqld составляла от 50% до 200%.

Но что-то пошло не так, производительность начала резко деградировать.
Сейчас демон базы грузит систему по top на 400-600%, а load average достигает 40. И такой load average может быть и при 400% и при 600% нагрузки даваемой mysqld.

По наблюдениям бывают моменты и производительность возвращается не надолго. При равных метриках базы данных по кол. запросов нагрузка может на какое-то время прийти в норму до load average: 1-2.

Перезагрузка сервера или mysqld не дает ни какого эффекта.

Потратил несколько дней в поисках связи метрик базы данных и операционной системы в целях найти связь в отклонениях, но пока не смог.

Теоретически это может быть даже не база данных, железо или еще что-то.

Изначально подумал, что возможно что-то не так с дисками, но trim включен, по данным atop дисковая система нагружена на 3-7%.

Модель SSD дисков
Model Family:     Intel S4510/S4610/S4500/S4600 Series SSDs
Device Model:     INTEL SSDSC2KB240G8


Данные мониторинга за disk latency
Read: sda  	min: 0.13 ms,	max: 30.04 ms, avg: 0.66 ms
Read: sdb 	min: 0.01 ms,	max: 27.37 ms, avg: 0.90 ms
Write: sda	min: 0.09 ms,	max: 8.33 ms,	avg: 1.34 ms
Write: sdb	min: 0.09 ms,	max: 10.48 ms,  avg: 1.41 ms


gmv8q3YSqMvPwA.png


Настройки базы
[mysqld]
key-buffer-size = 32M
long_query_time=1
performance_schema=on
read_rnd_buffer_size=128K
sort_buffer_size=1M
read_buffer_size=128K
join_buffer_size=512K
max_allowed_packet=64M
sql_mode=
transaction-isolation=READ-COMMITTED
innodb_io_capacity = 3000
innodb_io_capacity_max = 6000
innodb_read_io_threads = 64
innodb_write_io_threads = 64
innodb_thread_concurrency=10
innodb_lru_scan_depth=100
open_files_limit = 65535
table_open_cache=5000
query_cache_min_res_unit=3000
thread_cache_size=500
innodb_flush_method=O_DIRECT
innodb_file_per_table = 1
innodb_flush_log_at_trx_commit=2
innodb_log_buffer_size=12M
query_cache_type=1
query_cache_size=128M
query_cache_limit=1M
query_cache_min_res_unit=3500
tmp_table_size=1024M
max_heap_table_size=1024M
innodb_buffer_pool_size=15G
innodb_log_file_size=1G
innodb_log_files_in_group=3
innodb_buffer_pool_instances=15


Лимиты системы ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 127750
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 65535
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 65535
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited


SHOW ENGINE INNODB STATUS
=====================================
2019-07-30 06:57:50 0x7f9e40f63700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 1 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1621 srv_active, 0 srv_shutdown, 1 srv_idle
srv_master_thread log flush and writes: 1622
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 320574
--Thread 140317647853312 has waited at btr0sea.cc line 1476 for 0.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x55fd09116700 created in file btr0sea.cc line 243
a writer (thread id 140317647853312) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time write locked in file btr0sea.cc line 1557
--Thread 140317668058880 has waited at btr0sea.cc line 934 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x55fd09116700 created in file btr0sea.cc line 243
a writer (thread id 140317647853312) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time write locked in file btr0sea.cc line 1557
--Thread 140317670516480 has waited at btr0sea.cc line 934 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x55fd09116700 created in file btr0sea.cc line 243
a writer (thread id 140317647853312) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time write locked in file btr0sea.cc line 1557
--Thread 140317639866112 has waited at btr0sea.cc line 934 for 0.00 seconds the semaphore:
S-lock on RW-latch at 0x55fd09116700 created in file btr0sea.cc line 243
a writer (thread id 140317647853312) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffff
Last time write locked in file btr0sea.cc line 1557
OS WAIT ARRAY INFO: signal count 10122942
RW-shared spins 0, rounds 40759553, OS waits 237147
RW-excl spins 0, rounds 994262, OS waits 71533
RW-sx spins 220, rounds 1828, OS waits 40
Spin rounds per wait: 40759553.00 RW-shared, 994262.00 RW-excl, 8.31 RW-sx
------------
TRANSACTIONS
------------

.......
ROW OPERATIONS
--------------
10 queries inside InnoDB, 1 queries in queue
10 read views open inside InnoDB
Process ID=9541, Main thread ID=140317842663168, state: sleeping
Number of rows inserted 17731, updated 22665, deleted 12861, read 5275053684
2.00 inserts/s, 19.98 updates/s, 0.00 deletes/s, 4063602.40 reads/s
Number of system rows inserted 0, updated 0, deleted 0, read 0
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================


mysqltuner. Он рекомендует отключить кеш, но это не помогает. У CMS Битрикс много подзаропросов в запросах на которые из приложения особо не повлиять и с кешем работает быстрей. 

-------- Recommendations ---------------------------------------------------------------------------
General recommendations:
    Control warning line(s) into /var/log/mariadb/mysql_error.log file
    Control error line(s) into /var/log/mariadb/mysql_error.log file
    MySQL was started within the last 24 hours - recommendations may be inaccurate
    Increasing the query_cache size over 128M may reduce performance
    Adjust your join queries to always utilize indexes
    Consider installing Sys schema from https://github.com/mysql/mysql-sys
Variables to adjust:
    query_cache_size (=0)
    query_cache_type (=0)
    query_cache_size (> 128M) [see warning above]
    join_buffer_size (> 512.0K, or always use indexes with JOINs)


Системные метрики за 12 часов.
p27W5ORhKxWzQ2.png

Статистика по использованию кеш mariadb за 12 часов. Я пробовал и отключать его - результат становился немного хуже. Кеш на этом проекте все же дает прирост производительности.

Grq1LzYS4YkP4r.png

Статистика по типам запросов
BA09pM6uMVPn1r.png

MAj31GzSjLxPZr.png

Innidb метрики
Rmz9qeYuY5RPwr.png
v29LW4OuZYzoLm.png

По журналу медленных запросов я конечно сделал анализ, один из долгих запросов составляет порядка 80% медленных запросов, но его отключение не влияет на производительность и нагрузку на сервере.

А так выглядит мой atop последние несколько дней.
5d3fc662d857a562743413.png

К сожалению расширенный мониторинг был настроен уже после проседания производительности и данных по серверу в лучшее его время нет.

Но по CPU график есть.
D2PKD4esq100em.png

Update 30.07.2019 16:00
Перенес базу данных на другой сервер, ситуация особо не поменялась.
Проблемы с железом отменяются, видимо на нагрузку влияют запросы, но почему в разные моменты времени по разному еще не выяснил.

Скорей всего запросы стали оказывать влияние на метрики innodb:
RW Locks S OS Waits, RW Locks X OS Waits, RW Locks S Spin Rounds, RW Locks X Spin Rounds.

Буду благодарен за любую помощь или совет в поиске причин такого провала производительности.
  • Вопрос задан
  • 3027 просмотров
2 комментария
Подписаться 8 Простой 2 комментария
Решения вопроса 2
@yuriyant Автор вопроса
web программист
Всем спасибо за помощь и советы!

Было сделано сразу две манипуляции способствующие решению проблемы. Какая из них решила проблему точно уже не скажу.

У Битрикс есть таблица с купонами скидок каталога, в ней у нас было 300 тыс. купонов. Так как изменить запрос нет возможности из-за его системности и обновления Битрикс все затрут, то были проведены тесты с данными. Удаление из таблицы 200 тыс. старых купонов позволило ускорить медленный запрос с ~1.3 сек. до 0.01 сек. В таблице осталось 60 тыс. купонов.
Будем дорабатывать систему автоматической очистки купонов и писать обращение в Битрикс с просьбой оптимизации запроса. Хотя медленный запрос по данным мониторинга и отрабатывал ~3.7 раз в секунду, но это не мешало ему душить процессор.

Второе мероприятие это переход с mariadb (10.1, 10.3 - обе версии тестировались по несколько дней) на percona 8. Предположение пало на проблему базы данных с нашим набором данных и запросами, была мысль, а вдруг в перконе знаю и устранили ошибку.

Я все же полагаю, что ключевой фактор тут был указанный Vitaly Karasik на медленный запрос.
Видимо на наших данных этот запрос вызывал блокировки и высокую нагрузку на CPU из за повышения значений метрик RW Locks S OS Waits, RW Locks X OS Waits, RW Locks S Spin Rounds, RW Locks X Spin Rounds. Купонов становилось больше и в какой-то момент времени их кол. стало критичным для запроса.

Плавающий LA независящий от количества запросов к базе данных оказался влиянием вызова заданий по крону на выгрузку в яндекс маркет каталогов. Буду привязывать отображение заданий агентов Бирикс (крон задачи) на графиках, чтобы в будущем более явно строить связи нагрузки и работу приложения.

UPDATE 09.08.2019

Базу данных вернул на mariadb 10.3. Выяснился еще один запрос повышающий нагрузку на CPU. У нас около 1 млн. сессий в база данных. Так вот Битрикс в методе Sale\Fuser::getIdByUserId($ID) получения одной записи не выставляет лимит и еще и сортирует всю выборку. Если передается FALSE, то он сортировал в нашем случае около 1 млн. записей + добавлял туда каждый раз еще 1 запись. Обращение в Битрикс отправлено, они его приняли и судя по всему скоро будет выпущено обновление.
Кому нужно решение сейчас - измените метод прямо в ядре Sale\Fuser::getIdByUserId таким образом. 

$res = FuserTable::getList(array(
                       'filter' => array(
                               'USER_ID' => $userId
                       ),
                       'select' => array(
                               'ID'
                       ),
                       'limit' => 1, // Добавить лимит
                       // 'order' => array('ID' => "DESC") // Убрать эту сортировку
               ));
Ответ написан
3 комментария
3 комментария
@vitaly_il1
DevOps Consulting
А slow query log у вас был включен раньше, до проблемы? Если да, то интересно сравнить.
Я бы продолжил оптимизировать/убирать проблематичные запросы.
Ответ написан
5 комментариев
5 комментариев
Пригласить эксперта
Ответы на вопрос 1
@skvarovski
php yii laravel, js node vue, linux server, c++
много всего интересного, но не увидел тип движков таблиц.
возможно где-то есть таблица MyISAM которая блокируется, а еще в первой строчке key-buffer-size = 32M написан неправильно, он как раз влияет на скорость работы MyISAM таблиц, при такой конфигурации можно 1G поставить

key_buffer_size = 1G
myisam_sort_buffer_size = 128M
myisam_max_sort_file_size = 10G
myisam_max_extra_sort_file_size = 10G
Ответ написан
11 комментариев
11 комментариев
Ваш ответ на вопрос

Войдите, чтобы написать ответ

Похожие вопросы
Вакансии с Хабр Карьеры
Системный администратор Astra Linux
Гринатом • Новосибирск
До 60 000 ₽
Системный администратор Linux
ГК «Finbridge» • Ростов-на-Дону
от 180 000 до 220 000 ₽
Системный инженер (Windows/Astra Linux)
Гринатом • Новосибирск
До 57 000 ₽
Ещё вакансии
Заказы с Хабр Фриланса
3д сцены
23 дек. 2024, в 04:30
10000 руб./за проект
Разработать телеграм бота с реферальной системой, Юкассой и ChatGPT
23 дек. 2024, в 02:13
20000 руб./за проект
Собрать из исходного кода и запустить в докере рабочее приложение с бд
22 дек. 2024, в 22:57
500 руб./за проект
Ещё заказы