Как определить источник повышенного потребления ресурсов? (мускул в xen ест диск)

[SLEDopit]

Есть сервер, на сервере xen, в xenе порядка десятка виртуалок.
Мониторинг показывает, что одна из виртуалок стала много использовать дисковую систему (в несколько раз больше чем все остальные вместе взятые). Хотя раньше такого не было (изображение прикреплено).
Как видно из мониторинга, используется раздел virtual, ну я делаю вывод, что виновата одна из виртуалок.
Иду в xentop и вижу, что значение VBD_WSECT у одной из машин существенно превышает все остальные. Делаю вывод, что виновата именно она и иду внутрь.
И собственно дальше я в растерянности:
iostat показывает всплески активности:

Код: Выделить всё

 # iostat -d -x 5 10
Linux 2.6.32-5-xen-amd64 (hostname)        10/13/2011      _x86_64_        (1 CPU)

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdfp2            0.31   641.94    0.74   69.50    23.69  5689.75    81.33     0.77   11.00   0.73   5.11
xvdfp1            0.00     0.00    0.00    0.00     0.01     0.00     8.00     0.00    0.08   0.08   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdfp2            0.00     1.08    0.00    0.86     0.00    15.50    18.00     0.02   27.00  27.00   2.33
xvdfp1            0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdfp2            0.00     0.40    0.00    0.40     0.00     6.41    16.00     0.01   18.00  18.00   0.72
xvdfp1            0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdfp2            0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
xvdfp1            0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdfp2            0.00     0.50    0.00    2.40     0.00    23.22     9.67     0.01    3.67   3.67   0.88
xvdfp1            0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdfp2            0.00     0.10    0.00    2.76     0.00    22.88     8.30     0.00    0.00   0.00   0.00
xvdfp1            0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdfp2            0.00  3455.44    0.00  379.18     0.00 30676.96    80.90     0.75    1.98   0.08   2.95
xvdfp1            0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdfp2            0.00  6410.70    0.24  644.11     1.92 56438.46    87.59     5.67    8.09   0.77  49.81
xvdfp1            0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdfp2            0.00     1.19    0.00    0.65     0.00    14.70    22.67     0.05  711.33  76.00   4.93
xvdfp1            0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
xvdfp2            0.00     0.41    0.00    0.41     0.00     6.54    16.00     0.01   22.00  22.00   0.90
xvdfp1            0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

По iotop я отлавливаю, что бешенно начинает писать mysql

Код: Выделить всё

  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND
   374 be/4 root        3.93 K/s   47.17 K/s  0.00 % 14.28 % [flush-202:82]
17218 be/4 mysql       0.00 B/s   81.44 M/s  0.00 %  0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql
 --user=~ld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306

Однако в самом mysql отловить, что именно вызывает такую регулярную нагрузку не могу.
Сначала думал, что логи, но они пустые. Бинлоги отключены. Общий размер всех баз совсем смешной: 175 мегабайт.
3-4 дня назад он был примерно таким же.
Конфиг mysql'a вполне стандартненький:

Код: Выделить всё

[client]
port            = 3306
socket          = /var/run/mysqld/mysqld.sock
[mysqld_safe]
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         = /var/lib/mysql
tmpdir          = /tmp
language        = /usr/share/mysql/english
skip-external-locking
bind-address            = 127.0.0.1
key_buffer              = 16M
max_allowed_packet      = 16M
thread_stack            = 192K
thread_cache_size       = 8
myisam-recover         = BACKUP
query_cache_limit       = 1M
query_cache_size        = 16M
[mysqldump]
quick
quote-names
max_allowed_packet      = 16M
[mysql]
[isamchk]
key_buffer              = 16M
[mysqld_safe]
syslog

Куда можно еще покопать? И вообще, я правильно делаю, что пытаюсь найти тут какую-то проблему?

[neol]

Created_tmp_files
Created_tmp_disk_tables
не растет?

[sash-kan]

$ lsof -p <pid>
в помощь

если не поможет, то
$ strace -f -e write <программа с параметрами>

[SLEDopit]

Created_tmp_files
Created_tmp_disk_tables
не растет?

Посравнивал с другими виртуалками - created_tmp_files везде в пределах 10 за достаточно продолжительный период, а тут за полчаса после рестарта перевалило за сотню. Created_tmp_disk_tables в пределах нормы.
зы.

Код: Выделить всё

for i in `seq 4` ; do date; mysql -uroot -p -e "SHOW GLOBAL STATUS like 'Created_tmp%';" ;  sleep 1m; done
Thu Oct 13 22:10:25 MSK 2011
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 100   |
| Created_tmp_files       | 109   |
| Created_tmp_tables      | 245   |
+-------------------------+-------+
Thu Oct 13 22:11:25 MSK 2011
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 103   |
| Created_tmp_files       | 114   |
| Created_tmp_tables      | 249   |
+-------------------------+-------+
Thu Oct 13 22:12:25 MSK 2011
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 106   |
| Created_tmp_files       | 121   |
| Created_tmp_tables      | 253   |
+-------------------------+-------+
Thu Oct 13 22:13:25 MSK 2011
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 108   |
| Created_tmp_files       | 125   |
| Created_tmp_tables      | 256   |
+-------------------------+-------+

Это наверное не очень хорошо. Пойду поищу как регулируются эти параметры и как можно исправить ситуацию. Я с того конца подхожу?

$ lsof -p <pid>
в помощь

А как оно может помочь? Да, оно показывает список используемых файлов. Т.е. таким образом мы ограничили круг, куда мускул что-то может записать. Но нигде ничего необычного не происходит. Более того, даже не меняется размер этих файлов:

Код: Выделить всё

$ lsof -p $(ps -U mysql | grep mysqld | awk '{print $1}') > 1
$ sleep 5m
$ lsof -p $(ps -U mysql | grep mysqld | awk '{print $1}') > 2
$ diff 1 2
$

strace -f -e write

Тем не менее strace показывает очень много подобных write'ов:

Код: Выделить всё

[pid  9664] write(63, "\0010\215\4\377\10\376\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 131072) = 131072
<..>
[pid  9664] write(65, "\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377"..., 65536) = 65536

Таких строк очень много (около половины из того, что я насобирал).
Поэтому чем именно lsof и strace могут здесь помочь, я пока слабо представляю.

[KiWi]

strace -f -e write

Тем не менее strace показывает очень много подобных write'ов:

Код: Выделить всё

[pid  9664] write(63, "\0010\215\4\377\10\376\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 131072) = 131072
<..>
[pid  9664] write(65, "\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377\377"..., 65536) = 65536

Таких строк очень много (около половины из того, что я насобирал).
Поэтому чем именно lsof и strace могут здесь помочь, я пока слабо представляю.

В смысле "около половины"?
strace -e write показывает только записи. Очевидно, что всё, что вы там увидели -- это записи.
Собственно, там и указано куда пишут -- можно пойти в /proc/9664/fd и посмотреть что это за файлы.

А, собственно, понять кто создаёт временные файлы на диске, можно, например, так: http://www.mysqlperformanceblog.com/2008/0...og_slow_filter/
Но для этого надо использовать Percona Server.

[diesel]

SLEDopit,
show process list
show full process list
посмотрите в тот момент когда оно создает кучу tmp, там можно словить процесс создания tmp таблиц и запросы которые их создают

[neol]

Это наверное не очень хорошо. Пойду поищу как регулируются эти параметры и как можно исправить ситуацию. Я с того конца подхожу?

Я бы врубил slow-log и чуть позже (чтобы были видны изменения) увеличил tmp_table_size, max_heap_table_size, sort_buffer_size, join_buffer_size (только без фанатизма в этом деле, а то придет злой OOM killer (: ).
В slow-log посмотрите сортировки и объединения с участием полей типа blob и text, возможно в этом проблема (тогда вышеназванные параметры ничем не помогут, только запросы переделывать, емнип).

[SLEDopit]

А, собственно, понять кто создаёт временные файлы на диске, можно, например, так: http://www.mysqlperformanceblog.com/2008/0...og_slow_filter/
Но для этого надо использовать Percona Server.

Да, интересный вариант. Спасибо за наводку. Есть куда покопать.

посмотрите в тот момент когда оно создает кучу tmp

Так, судя по всему, они постоянно по немногу создаются. А в целом, я посмотрел - там практически одни селекты с кучей join'ов идут:

Query 1 Writing to net SELECT CONCAT_WS( '/', s.title, cc.title ) AS section, a.id, a.title, a.introtext as text, a.fulltext, a.created, a.modified, a.created_by, a.hits, a.images, a.metakey, a.metadesc, a.attribs, '0' AS featured, '1' AS is_article, CASE WHEN CHAR_LENGTH(a.alias) THEN CONCAT(':', a.alias) ELSE '' END as slug, CASE WHEN CHAR_LENGTH(cc.alias) THEN CONCAT_WS(':', cc.id, cc.alias) ELSE a.catid END as catslug, CHAR_LENGTH( a.`fulltext` ) AS readmore, CASE WHEN CHAR_LENGTH(a.created_by_alias) THEN a.created_by_alias ELSE u.name END as author, CONCAT('index.php?option=com_content&view=article&id=', a.id) AS href, CONCAT('index.php?option=com_content&view=article&id=', a.id) AS reallink, ROUND(v.rating_sum/v.rating_count) AS rating, v.rating_count FROM dxj_content AS a LEFT JOIN dxj_sections AS s ON a.sectionid = s.id LEFT JOIN dxj_categories AS cc ON a.catid = cc.id LEFT JOIN dxj_users AS u ON u.id = a.created_by LEFT JOIN dxj_groups AS g ON a.access = g.id LEFT JOIN dxj_content_rating AS v ON a.id = v.content_id WHERE a.sectionid > '0' AND a.sectionid = '8' AND ( ( a.created_by = 0 ) OR (a.state = '1') AND ( a.publish_up = '0000-00-00 00:00:00' OR a.publish_up <= '2011-10-14 06:00:00' ) AND ( a.publish_down = '0000-00-00 00:00:00' OR a.publish_down >= '2011-10-14 06:00:00' ) ) AND a.access <= 0 ORDER BY featured DESC, a.title ASC

В slow-log посмотрите сортировки и объединения с участием полей типа blob и text, возможно в этом проблема (тогда вышеназванные параметры ничем не помогут, только запросы переделывать, емнип).

Код: Выделить всё

 # service mysql status
/usr/bin/mysqladmin  Ver 8.42 Distrib 5.1.49, for debian-linux-gnu on x86_64
Copyright 2000-2008 MySQL AB, 2008 Sun Microsystems, Inc.
This software comes with ABSOLUTELY NO WARRANTY. This is free software,
and you are welcome to modify and redistribute it under the GPL license

Server version          5.1.49-3
Protocol version        10
Connection              Localhost via UNIX socket
UNIX socket             /var/run/mysqld/mysqld.sock
Uptime:                 12 hours 8 min 33 sec

Threads: 1  Questions: 382377  Slow queries: 0  Opens: 2366  Flush tables: 1  Open tables: 64  Queries per second avg: 8.747.

Так slow queries и так на нуле. Есть ли смысл все это проделывать?
Да и к тому же, в скриптах тех не меняли ничего уже несколько месяцев. С чего бы им вдруг так резко изменить свое стандартное поведение?

[neol]

Так slow queries и так на нуле. Есть ли смысл все это проделывать?

Может и нет, но long_query_time у вас в конфиге не указан (или я его не заметил), а по умолчанию он равен 10.

Да и к тому же, в скриптах тех не меняли ничего уже несколько месяцев. С чего бы им вдруг так резко изменить свое стандартное поведение?

Искусственный интеллект, не иначе (:

[SLEDopit]

Может и нет, но long_query_time у вас в конфиге не указан (или я его не заметил), а по умолчанию он равен 10.

Я сегодня с утра выставил его равным 2. За 3 часа все равно ни одного медленного запроса не нашлось.

Искусственный интеллект, не иначе (:

Я так и знал. (:

[diesel]

посмотрите в тот момент когда оно создает кучу tmp

Так, судя по всему, они постоянно по немногу создаются. А в целом, я посмотрел - там практически одни селекты с кучей join'ов идут:

select'ы с кучей join'ов как раз таки и могут сбрасывать данные на диск, некоторые, тогда там появляется status "Copying to tmp table on disk"(в вашем примере запроса он уже пишет результаты), в основном если получается очень большой результат join'а над которым предполагается выполнить груповые операции, или сортировку, или что-то в этом духе

If an internal temporary table is created initially as an in-memory table but becomes too large, MySQL automatically converts it to an on-disk table. The maximum size for in-memory temporary tables is the minimum of the tmp_table_size and max_heap_table_size values.

могло получится что у вас просто сильно подросло количество данных в "промежуточной" выборке, и в память оно уже не помещается, для какого-то конкретного запроса.