Загадочное поведение slow.log

123 4
Sergey Petrenko
На сайте с 23.10.2000
Offline
482
4044

Вот интересно у нас себя ведет лог тяжелых запросов. Или mySQL вообще.

MySQL 5.1.11-beta-log.

long-query-time=5

Slow.log - пуст вообще.

Когда смотришь mytop, практически ни один запрос не держится дольше одного "тика", т.е. рефреша.

При этом и сам mytop и утилита mysqlreport исправно показывают, что медленных запросов наблюдается по 2-3 в секунду - что-то около 5% от общего количества.

Slow.log, напомню, пуст.

MySQL собран с поддержкой lib_thr.

Не подскажете, куда копать и надо ли копать вообще?

K
На сайте с 24.03.2004
Offline
223
#1
Gray:
Не подскажете, куда копать и надо ли копать вообще?

Никуда копать не надо. Если slow есть, то они в processlist видны, а mytop как раз его и показывает.

PS. Если память не изменяет, то slow там в минутах была когда-то...

проверенная ддос защита (http://ddos-protection.ru) -> http://ddos-protection.ru (http://ddos-protection.ru), бесплатный тест, цена от размера атаки не зависит.
Sergey Petrenko
На сайте с 23.10.2000
Offline
482
#2

Ладно, спишем на неадекватность утилиток - mysqladmin status показывает ноль медленных запросов. Правда, mysqladmin extended-status показывает их за 100к...

K
На сайте с 24.03.2004
Offline
223
#3
Gray:
Ладно, спишем на неадекватность утилиток - mysqladmin status показывает ноль медленных запросов. Правда, mysqladmin extended-status показывает их за 100к...

extended status показывает что-то из variables, а про какую конкретно идет речь?

Sergey Petrenko
На сайте с 23.10.2000
Offline
482
#4
kostich:
про какую

Про какую чего?

K
На сайте с 24.03.2004
Offline
223
#5
Gray:
Про какую чего?

"Правда, mysqladmin extended-status показывает их за 100к..."

Сергей, давайте кусочек extended-status в студию... imho там не про slow запросы речь идет.

HP
На сайте с 30.05.2006
Offline
175
#6

А ты вообще логирование медленных запросов включил? поставь 0.1 секунду и проверь пишеться ли что нибуть в файл.

Либо ты не туда смотришь либо логирование не включил. Тебе нужно смотреть на значение slow_query.

HP
На сайте с 30.05.2006
Offline
175
#7

Посмотри show variables like '%slow_quer%'

Должно выдать:

log_slow_queries | ON

Sergey Petrenko
На сайте с 23.10.2000
Offline
482
#8

kostich, вот два результата, взяты почти одновременно:

#mysqladmin status

Uptime: 62715 Threads: 60 Questions: 2408733 Slow queries: 0 Opens: 0 Flush tables: 1 Open tables: 564 Queries per second avg: 38.408

+-----------------------------------+------------+

| Variable_name | Value |
+-----------------------------------+------------+
| Aborted_clients | 310 |
| Aborted_connects | 1008 |
| Binlog_cache_disk_use | 0 |
| Binlog_cache_use | 0 |
| Bytes_received | 644843209 |
| Bytes_sent | 968642800 |
| Com_admin_commands | 144190 |

| Com_replace | 5322 |

| Com_select | 878106 |
| Com_set_option | 129 |
| Com_show_binlog_events | 0 |
| Com_show_binlogs | 14 |
| Com_show_charsets | 35 |

| Com_show_slave_status | 0 |
| Com_show_status | 27 |
| Com_show_storage_engines | 0 |
| Com_show_tables | 147 |
| Com_show_triggers | 0 |
| Com_show_variables | 113 |
| Com_show_warnings | 0 |
| Com_slave_start | 0 |
| Com_slave_stop | 0 |
| Com_stmt_close | 0 |
| Com_stmt_execute | 0 |
| Com_stmt_fetch | 0 |
| Com_stmt_prepare | 0 |
| Com_stmt_reset | 0 |
| Com_stmt_send_long_data | 0 |
| Com_truncate | 0 |
| Com_unlock_tables | 0 |
| Com_update | 268189 |
| Com_update_multi | 0 |
| Com_xa_commit | 0 |
| Com_xa_end | 0 |
| Com_xa_prepare | 0 |
| Com_xa_recover | 0 |
| Com_xa_rollback | 0 |
| Com_xa_start | 0 |
| Compression | OFF |
| Connections | 69709 |
| Created_tmp_disk_tables | 10617 |
| Created_tmp_files | 0 |
| Created_tmp_tables | 17184 |
| Delayed_errors | 0 |
| Delayed_insert_threads | 0 |
| Delayed_writes | 0 |
| Flush_commands | 1 |
| Handler_commit | 0 |
| Handler_delete | 21643 |
| Handler_discover | 0 |
| Handler_prepare | 0 |
| Handler_read_first | 107963 |
| Handler_read_key | 52945357 |
| Handler_read_next | 186289462 |
| Handler_read_prev | 673026 |
| Handler_read_rnd | 4724405 |
| Handler_read_rnd_next | 3743057720 |
| Handler_rollback | 0 |
| Handler_savepoint | 0 |
| Handler_savepoint_rollback | 0 |
| Handler_update | 337158 |
| Handler_write | 3571755 |
| Innodb_buffer_pool_pages_data | 0 |
| Innodb_buffer_pool_pages_dirty | 0 |
| Innodb_buffer_pool_pages_flushed | 0 |
| Innodb_buffer_pool_pages_free | 0 |
| Innodb_buffer_pool_pages_latched | 0 |
| Innodb_buffer_pool_pages_misc | 0 |
| Innodb_buffer_pool_pages_total | 0 |
| Innodb_buffer_pool_read_ahead_rnd | 0 |
| Innodb_buffer_pool_read_ahead_seq | 0 |
| Innodb_buffer_pool_read_requests | 0 |
| Innodb_buffer_pool_reads | 0 |
| Innodb_buffer_pool_wait_free | 0 |
| Innodb_buffer_pool_write_requests | 0 |
| Innodb_data_fsyncs | 0 |
| Innodb_data_pending_fsyncs | 0 |
| Innodb_data_pending_reads | 0 |
| Innodb_data_pending_writes | 0 |
| Innodb_data_read | 0 |
| Innodb_data_reads | 0 |
| Innodb_data_writes | 0 |
| Innodb_data_written | 0 |
| Innodb_dblwr_pages_written | 0 |
| Innodb_dblwr_writes | 0 |
| Innodb_log_waits | 0 |
| Innodb_log_write_requests | 0 |
| Innodb_log_writes | 0 |
| Innodb_os_log_fsyncs | 0 |
| Innodb_os_log_pending_fsyncs | 0 |
| Innodb_os_log_pending_writes | 0 |
| Innodb_os_log_written | 0 |
| Innodb_page_size | 0 |
| Innodb_pages_created | 0 |
| Innodb_pages_read | 0 |
| Innodb_pages_written | 0 |
| Innodb_row_lock_current_waits | 0 |
| Innodb_row_lock_time | 0 |
| Innodb_row_lock_time_avg | 0 |
| Innodb_row_lock_time_max | 0 |
| Innodb_row_lock_waits | 0 |
| Innodb_rows_deleted | 0 |
| Innodb_rows_inserted | 0 |
| Innodb_rows_read | 0 |
| Innodb_rows_updated | 0 |
| Key_blocks_not_flushed | 0 |
| Key_blocks_unused | 361639 |
| Key_blocks_used | 102281 |
| Key_read_requests | 166648997 |
| Key_reads | 104000 |
| Key_write_requests | 391302 |
| Key_writes | 280553 |
| Last_query_cost | 0.000000 |
| Max_used_connections | 132 |
| Not_flushed_delayed_rows | 0 |
| Open_files | 970 |
| Open_streams | 0 |
| Open_table_definitions | 417 |
| Open_tables | 564 |
| Opened_tables | 589 |
| Qcache_free_blocks | 5187 |
| Qcache_free_memory | 18669640 |
| Qcache_hits | 859698 |
| Qcache_inserts | 865201 |
| Qcache_lowmem_prunes | 6315 |
| Qcache_not_cached | 13286 |
| Qcache_queries_in_cache | 9451 |
| Qcache_total_blocks | 24360 |
| Questions | 2408147 |
| Rpl_status | NULL |
| Select_full_join | 53 |
| Select_full_range_join | 0 |
| Select_range | 200424 |
| Select_range_check | 0 |
| Select_scan | 124969 |
| Slave_open_temp_tables | 0 |
| Slave_retried_transactions | 0 |
| Slave_running | OFF |
| Slow_launch_threads | 0 |
| Slow_queries | 125224 |
| Sort_merge_passes | 0 |
| Sort_range | 235583 |
| Sort_rows | 22679826 |
| Sort_scan | 21563 |
| Table_locks_immediate | 2540523 |
| Table_locks_waited | 7206 |
| Tc_log_max_pages_used | 0 |
| Tc_log_page_size | 0 |
| Tc_log_page_waits | 0 |
| Threads_cached | 19 |
| Threads_connected | 62 |
| Threads_created | 424 |
| Threads_running | 1 |
| Uptime | 62703 |
+-----------------------------------+------------+

В одном случае есть медленные запросы, в другом нет.

HruPifPaf:
А ты вообще логирование медленных запросов включил? поставь 0.1 секунду и проверь пишеться ли что нибуть в файл.

Либо ты не туда смотришь либо логирование не включил. Тебе нужно смотреть на значение slow_query.

А я вообще не идиот. Либо вы не прочли топик, либо вам пофиг, кто что спрашивает, лишь бы "умом" блеснуть.

HruPifPaf:
Посмотри

Топик прочти. Фактически ни один запрос не живет дольше секунды, что и показывает mytop.

K
На сайте с 24.03.2004
Offline
223
#9

2Gray:

Действительно, замечательно... а инкремент её засечь не можешь? Т.е. надо понять, оно там действительно увеличивается или стоит вот в этом значении?

Кстати, по поводу time я ошибся в 5.1 "The slow query log consists of all SQL statements that took more than long_query_time seconds to execute."

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

Админчик патчи никакие на тему таймингов не ставил?

ЗЫ. Сейчас в сорцы гляну... может они этот момент не провряют просто, т.к. если бы проверяли, то в главном логе было бы про то, что он файл не может открыть или создать....

--------------------------------------------------------------------------------------

Там так же как и с основным логом... что-то с правами доступа к файлу или с настройками. Он может не писать туда, т.к. думает что надо писать совсем в другое место, а там этот файл нельзя создать и т.д... посмотрите логи.

[Удален]
#10

Привет! :)

1) Если в slow log не пишется - значит просто эта опция не включа (а она по умолчанию не включена). Чтобы включить - нужно в /etc/my.cnf вписать директиву log-slow-queries

2) а) Один тик mytop - это не одна секудна, а пять по дефолту. long_query_time округляется вверх - то есть таковыми считаются все запросы от 4 секунд и более.

б) Если в my.cnf прописан log-long-format - то slow считаются все запросы, не использующие index lookup по первой таблице джойна, вне зависимости от фактического времени, затраченного на обслуживание запроса.

3) mysqladmin status - это задокументированная ошибка в mysqladmin/mysqld:

http://bugs.mysql.com/bug.php?id=18669

Она была исправлена в июньском релизе ветки 5.0, в 5.1 ее похоже вообще забыли закоммитить - за малозначимостью.

123 4

Авторизуйтесь или зарегистрируйтесь, чтобы оставить комментарий