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 строчек кода :)) И куча инклудов