Всем хорошего дня!

Debian, MySQL 5.6.19.
Работал сайт прекрасно, вдруг недавно начались проблемы с запросами, при чем с любыми (select, update, insert).
Например:

# Query_time: 28.738771 Lock_time: 0.000094 Rows_sent: 0 Rows_examined: 1
update `user` set `timeZone`='Europe/Moscow' where `id`='2';

Его explain:

id select_type table type possible_keys key key_len ref rows filtered Extra'1' 'SIMPLE' 'user' 'range' 'PRIMARY' 'PRIMARY' '8' 'const' '1' '100.00' 'Using where'

Это вообще что-то его личное:
# Query_time: 27.254406 Lock_time: 0.000266 Rows_sent: 0 Rows_examined: 210
select count(*) into @discard from `information_schema`.`PARTITIONS`;
# Query_time: 23.213852 Lock_time: 0.000166 Rows_sent: 2 Rows_examined: 126
SELECT ENGINE,SUM(DATA_LENGTH),COUNT(ENGINE) FROM information_schema.TABLES WHERE TABLE_SCHEMA NOT IN ('information_schema','mysql') AND ENGINE IS NOT NULL GROUP BY ENGINE ORDER BY ENGINE ASC;

А вот моё:
# Query_time: 2.580645 Lock_time: 1.431141 Rows_sent: 1 Rows_examined: 12
SET timestamp=1411141756;
select count(1) cnt from `lib` where createdate >= '2014-09-19 15:48:58';
Индексов в этой таблице нет, но там сейчас около 10 записей, в любом случае такого времени не должно быть.
Есть свои селекты и на десятки секунд.

Короче итог такой, что в любой момент любой запрос может зависнуть на произвольное время.
Кучу параметров уже наменял в my, ничего не меняется. После перезапуска mysql проблема сразу наблюдается. Сейчас innodb_flush_log_at_trx_commit = 0. Но ведь не только с update проблемы.
Короче, я уже не знаю что делать, второй день сижу над этим.
Есть лог медленных запросов примерно за пол года - нет там таких долгих запросов, а тут вдруг началось такое.

Что подскажете?
Кстати, можно ли выполнить explain update с выполнением самого update? То есть чтобы на выполненном запросе увидеть, что происходит?

LumixprogrammisterКстати, можно ли выполнить explain update с выполнением самого update? То есть чтобы на выполненном запросе увидеть, что происходит?

только в mysql версии 5.6 и выше

И как это сделать? При explain сам update не выполняется.

Ясно. Тогда может в целом что-нибудь подскажете?

netwindprogrammisterЯсно. Тогда может в целом что-нибудь подскажете?
Обратиться к хостеру.
Прекратить ожидать от унылых VPS производительности выше чем древний ноутбук. Вы же не один на сервере.

Это Ажур :)

ScareCrowperfomance_scema

Спасибо, узрел я эту штуку в workbench. Что-то там столько всего :). Можете подсказать куда в моём случае лучше смотреть там? :)

ScareCrow,

вот, кстати, один из основных проблемных запросов:

Query Full Table Scan Executed (#) Errors (#) Warnings (#) Total Time Max Time Avg Time Rows Sent (#) Avg. Rows Sent (#) Rows Scanned (#) Avg. Rows Scanned (#) Temp. Tables (#) Temp. Disk Tables (#) Rows Sorted (#) Sort Merge Passes (#) DigestUPDATE `user` SET `timeZone` = ? WHERE `id` = ? 227 0 0 58799743.94 7674932.65 259029.71 0 0.0 227 1.0 0 0 0 0 826222397d4b7b4637ca7c69c368fbeb

miksoftprogrammisterЯсно. Тогда может в целом что-нибудь подскажете?Поищите настоящие долгие запросы. В т.ч. последите, не создаются ли временные таблицы диске. Последить можно как глазами (по наличию файлов в /tmp), там и по статус-переменным в MySQL.

Долгие запросы-то я и так знаю :). Как можно подробно изучить конкретный уже выполненный запрос или в процессе выполнения?

miksoft,

по отчётам этот запрос не создаёт временных таблиц.
В Full Table Scan его тоже нет.

miksoftprogrammisterДолгие запросы-то я и так знаю :).А нам показать?programmisterКак можно подробно изучить конкретный уже выполненный запрос или в процессе выполнения?Для начала посмотреть план.

Я же показал в первом посте и запрос, и его план. :)
Вот его за основу взял. Там поиск про ключу и обновление поля.
update `user` set `timeZone`='Europe/Moscow' where `id`='2';

miksoftprogrammisterЯ же показал в первом посте и запрос, и его план. :)
Вот его за основу взял. Там поиск про ключу и обновление поля.
update `user` set `timeZone`='Europe/Moscow' where `id`='2';Не, это не настоящие долгие запросы, это "наведенные". Имхо, они чего-то долго ждали. Либо соседей по серверу (о чем говорил netwind), либо ресурсов, занятых вашими настоящими долгим запросами.

1. Я этот запрос тестировал просто из своего локального workbench, когда на сайте никого нет, то есть больше нет никаких запросов.
2. В slow-логе часто идёт ТОЛЬКО этот запрос, то есть перед ним или после него нет долгих запросов, а этот может от 5 до 70 секунд висеть.

miksoftКакая текущая схема(база) при выполнении этого запроса? mysql или другая?

Другая. И в workbench, и в php при подключении параметр dbname=...
Я сейчас остановил веб-сервер и от себя поотправлял этот update - иногда зависает на 5-10 сек.

miksoftprogrammisterДругаяТ.е. таблица user - это ваша таблица?
Какой движок у таблицы? Полный DDL можете показать? Сколько записей?

Да, это всё своя схема.
Напомню, что долго стали висеть ещё и другие запросы. И селекты, и инсёрты.
Да, есть ощущение, что что-то встречает в работу бд, из-за чего теперь любой запрос может долго выполняться. И не просто долго, а десятками секунд. При этом вся база пока очень маленькая.

Записей около 200.

miksoft,

Это что-то с чем-то.
Опять всё отключил на сервере, и через консоль зашёл в mysql и начал отправлять запросы - один из 5-10 запросов длиться 3-8 сек.

miksoftАвтокоммит включен? Как вообще коммит происходит?

Ну, в php транзакция явно открывается только в редких случаях (когда по логике нужно несколько запросов сделать). А так для одного запроса, типа этого, своей транзакции нет.
В консоле тем более никаких транзакций не открываю. Сейчас при тесте просто update отправлял.
В workbench по умолчанию нажата autocommit.

В самом mysql autocommit = ON
innodb_commit_concurrency = 0
innodb_flush_log_at_trx_commit = 0

miksoftУвы, у меня мысли закончились все, кроме той, о чем говорил netwind ( 16598731 ).

Клёва :))
Типа у майкрософта проблемы с дисками (где моя машина крутится)?

miksoft,

Ну а проследить весь путь запроса во время исполнения в mysql никак нельзя?

ScareCrowperfomance_scema

Вот что нарыл:

QUERY_ID SEQ STATE 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'72' '2' 'starting' '0.000081' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' NULL NULL NULL'72' '3' 'checking permissions' '0.000013' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'check_access' 'sql_parse.cc' '5268''72' '4' 'Opening tables' '0.000029' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'open_tables' 'sql_base.cc' '4934''72' '5' 'init' '0.000041' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '262''72' '6' 'System lock' '0.000071' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_lock_tables' 'lock.cc' '304''72' '7' 'updating' '15.860026' '0.008000' '0.004000' '365' '0' '0' '160' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '715''72' '8' 'end' '0.000028' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '967''72' '9' 'query end' '0.000050' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_execute_command' 'sql_parse.cc' '4967''72' '10' 'closing tables' '0.000020' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_execute_command' 'sql_parse.cc' '5015''72' '11' 'freeing items' '0.000083' '0.000000' '0.000000' '1' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_parse' 'sql_parse.cc' '6294''72' '12' 'logging slow query' '0.000073' '0.000000' '0.000000' '0' '0' '0' '8' '0' '0' '0' '0' '0' 'log_slow_do' 'sql_parse.cc' '1869''72' '13' 'cleaning up' '0.000043' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'dispatch_command' 'sql_parse.cc' '1774'

miksoft,

Майкрософт тут при том, что это их облако. Я понимаю, что это массивы дисков, но за нагрузкой они следят, да и раньше никогда такого не было. Тем более чтобы постоянно такая проблема была.

miksoftprogrammistermiksoft,

Ну а проследить весь путь запроса во время исполнения в mysql никак нельзя?Можно попробовать сделать профилирование . Но это нечасто оказывается полезным, имхо.

Да, я как раз выше уже выложил. :)

miksoft,

что за CONTEXT_VOLUNTARY и BLOCK_OPS_OUT? В них большие значения.

miksoftprogrammistermiksoft,

что за CONTEXT_VOLUNTARY и BLOCK_OPS_OUT? В них большие значения. http://dev.mysql.com/doc/refman/5.6/en/profiling-table.html CONTEXT_VOLUNTARY and CONTEXT_INVOLUNTARY indicate how many voluntary and involuntary context switches occurred.

BLOCK_OPS_IN and BLOCK_OPS_OUT indicate the number of block input and output operations.Но зачем было записано 160 блоков - даже представить не могу.

Случаем, триггеров на этой таблице нет?

Да, спасибо, доку я видел, но всё равно не понимаю, что это за поля.
Нет триггеров :)

QUERY_ID SEQ STATE 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'386' '2' 'starting' '0.000054' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' NULL NULL NULL'386' '3' 'checking permissions' '0.000013' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'check_access' 'sql_parse.cc' '5268''386' '4' 'Opening tables' '0.000026' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'open_tables' 'sql_base.cc' '4934''386' '5' 'init' '0.000039' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '262''386' '6' 'System lock' '0.000068' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_lock_tables' 'lock.cc' '304''386' '7' 'updating' '3.294129' '0.000000' '0.012001' '175' '0' '0' '1872' '0' '0' '0' '247' '0' 'mysql_update' 'sql_update.cc' '715''386' '8' 'end' '0.000034' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '967''386' '9' 'query end' '0.082086' '0.000000' '0.000000' '10' '0' '0' '8' '0' '0' '0' '0' '0' 'mysql_execute_command' 'sql_parse.cc' '4967''386' '10' 'closing tables' '0.000064' '0.000000' '0.000000' '1' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_execute_command' 'sql_parse.cc' '5015''386' '11' 'freeing items' '0.000124' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_parse' 'sql_parse.cc' '6294''386' '12' 'logging slow query' '0.000151' '0.000000' '0.000000' '0' '0' '0' '8' '0' '0' '0' '0' '0' 'log_slow_do' 'sql_parse.cc' '1869''386' '13' 'cleaning up' '0.000097' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'dispatch_command' 'sql_parse.cc' '1774'

miksoftprogrammisterPAGE_FAULTS_MINOR '247'Эм, а свопа в системе нету? Свободная оперативка есть?

Tasks: 125 total, 1 running, 124 sleeping, 0 stopped, 0 zombie
%Cpu(s): 0.2 us, 0.0 sy, 0.0 ni, 0.0 id, 99.7 wa, 0.0 hi, 0.2 si, 0.0 st
KiB Mem: 3538464 total, 1747504 used, 1790960 free, 152980 buffers
KiB Swap: 0 total, 0 used, 0 free, 574932 cached

miksoftprogrammister99.7 waО, а это почему? Постоянно так держится?

Да нет, в основном 0 :)

top - 12:15:03 up 21:45, 1 user, load average: 0.34, 0.43, 0.50
Tasks: 124 total, 1 running, 123 sleeping, 0 stopped, 0 zombie
%Cpu(s): 2.9 us, 0.0 sy, 0.0 ni, 97.1 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem: 3538464 total, 1705956 used, 1832508 free, 153296 buffers
KiB Swap: 0 total, 0 used, 0 free, 471600 cached

miksoft,

нужно сделать своп?
Кстати, что за кэш 471600 в строке свопа? Где он лежит и какой предел?

miksoftprogrammisterКстати, что за кэш 471600 в строке свопа? Где он лежит и какой предел? Тут есть кое-какое объяснение.

Спасибо!
Есть ещё идеи? :))

Господа, есть ещё идеи?

Вот запрос в нормальном виде:

QUERY_ID SEQ STATE 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'24' '2' 'starting' '0.000082' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' NULL NULL NULL'24' '3' 'checking permissions' '0.000012' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'check_access' 'sql_parse.cc' '5268''24' '4' 'Opening tables' '0.000028' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'open_tables' 'sql_base.cc' '4934''24' '5' 'init' '0.000038' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '262''24' '6' 'System lock' '0.000078' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_lock_tables' 'lock.cc' '304''24' '7' 'updating' '0.000178' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '715''24' '8' 'end' '0.000013' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '967''24' '9' 'query end' '0.000158' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_execute_command' 'sql_parse.cc' '4967''24' '10' 'closing tables' '0.000018' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_execute_command' 'sql_parse.cc' '5015''24' '11' 'freeing items' '0.000047' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_parse' 'sql_parse.cc' '6294''24' '12' 'cleaning up' '0.000024' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'dispatch_command' 'sql_parse.cc' '1774'

А вот он же через 2 секунды:

QUERY_ID SEQ STATE 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'25' '2' 'starting' '0.000072' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' NULL NULL NULL'25' '3' 'checking permissions' '0.000012' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'check_access' 'sql_parse.cc' '5268''25' '4' 'Opening tables' '0.000028' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'open_tables' 'sql_base.cc' '4934''25' '5' 'init' '0.000041' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '262''25' '6' 'System lock' '0.000070' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_lock_tables' 'lock.cc' '304''25' '7' 'updating' '5.193575' '0.000000' '0.000000' '125' '0' '0' '96' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '715''25' '8' 'end' '0.000025' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_update' 'sql_update.cc' '967''25' '9' 'query end' '0.000054' '0.000000' '0.004000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_execute_command' 'sql_parse.cc' '4967''25' '10' 'closing tables' '0.000021' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_execute_command' 'sql_parse.cc' '5015''25' '11' 'freeing items' '0.000065' '0.000000' '0.000000' '1' '0' '0' '0' '0' '0' '0' '0' '0' 'mysql_parse' 'sql_parse.cc' '6294''25' '12' 'logging slow query' '0.000082' '0.000000' '0.000000' '0' '0' '0' '8' '0' '0' '0' '0' '0' 'log_slow_do' 'sql_parse.cc' '1869''25' '13' 'cleaning up' '0.000028' '0.000000' '0.000000' '0' '0' '0' '0' '0' '0' '0' '0' '0' 'dispatch_command' 'sql_parse.cc' '1774'

miksoftprogrammister,

Полуштука - слазить в файл sql_update.cc и посмотреть что там в строке 715.


THD_STAGE_INFO(thd, stage_updating);

:)

miksoftПохоже, что это как раз фиксация события для профилирования. А до нее что?

Угу.
714 строчек кода :)) И куча инклудов

netwindprogrammistermiksoft,

Майкрософт тут при том, что это их облако. Я понимаю, что это массивы дисков, но за нагрузкой они следят, да и раньше никогда такого не было. Тем более чтобы постоянно такая проблема была.
А microsoft теперь вместо azure предоставляет прям натуральный linux VPS ?
Ну значит закончились деньги и диски в microsoft. Все,загибается IT.
Начните с обращения к хостеру. Там все объяснят.

И дайте ссылку на условия предоставления услуг. Попытайтесь сами найти там сколько именно операций ввода-вывода в какой промежуток времени вам гарантируют ( скорее всего ничего не гарантируют). Все же небезынтересно посмотреть что там Microsoft.

Почему вместо? :) В ажуре есть виртуальные машины, куда можно поставить любую ось. Обращение уже сделал, жду. Так как объяснений проблеме не нахожу, то на данный момент нужно разобраться с дисками, так пару раз уже диск с линуксом переходил в состоятие read-only (видимо, автоматический ре-mount срабатывает при проблеме с диском).

Ажур не скрывается :) - http://azure.microsoft.com/ru-ru/. В моём случае iops = 2000.

netwindprogrammister, не вижу сколько это стоит и что именно гарантируется.

Наверху есть раздел Цены. И ссылки на sla там есть.