Как узнать какие процессы тратят CPU system time?

Question

[Serj0333]

Всем привет.
Есть виртуальная машина c CentOS 7 на борту, 12 ядер и 85G RAM.
На этой машине крутится сервер mysql, БД весит 300G.

Имеем проблему с тем, что CPU System Time поднимается до 30% - 40% и система начинает тупить.

Вот вывод top:
top - 12:10:29 up 4 days, 6:05, 5 users, load average: 5,20, 4,70, 5,16
Tasks: 332 total, 1 running, 331 sleeping, 0 stopped, 0 zombie
%Cpu(s): 36,7 us, 18,4 sy, 0,0 ni, 42,8 id, 1,8 wa, 0,0 hi, 0,3 si, 0,0 st
KiB Mem: 90574896 total, 90266192 used, 308708 free, 306288 buffers
KiB Swap: 0 total, 0 used, 0 free. 33777148 cached Mem

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
29422 mysql 20 0 58,544g 0,051t 7328 S 664,3 60,6 4698:12 mysqld
46008 root 20 0 123800 1884 1176 R 0,7 0,0 0:00.04 top
74 root 20 0 0 0 0 S 0,3 0,0 2:25.17 rcu_sched
1374 root 20 0 0 0 0 S 0,3 0,0 18:13.28 jbd2/sdb1-8
8718 root 20 0 190040 4936 1808 S 0,3 0,0 3:32.98 vmtoolsd
1 root 20 0 47592 3608 1948 S 0,0 0,0 0:04.15 systemd
2 root 20 0 0 0 0 S 0,0 0,0 0:00.05 kthreadd
3 root 20 0 0 0 0 S 0,0 0,0 0:36.52 ksoftirqd/0
5 root 0 -20 0 0 0 S 0,0 0,0 0:00.00 kworker/0:0H
6 root 20 0 0 0 0 S 0,0 0,0 0:00.00 kworker/u128:0
8 root rt 0 0 0 0 S 0,0 0,0 0:01.42 migration/0
9 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcu_bh
10 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/0
11 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/1
12 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/2
13 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/3
14 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/4
15 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/5
16 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/6
17 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/7
18 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/8
19 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/9
20 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/10
21 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/11
22 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/12
23 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/13
24 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/14
25 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/15
26 root 20 0 0 0 0 S 0,0 0,0 0:00.00 rcuob/16

Вопрос в том как отдебажить эту ситуацию, какими средствами мы можем определить какой именно системный процесс начинает так активно работать.

Спасибо всем откликнувшимся! =)

Comments

[Serj0333]

Воспользовался утилитой perf top и получил такой результат:

10,21% mysqld [.] row_sel_store_mysql_field_func
9,64% mysqld [.] rec_get_offsets_func
7,93% mysqld [.] row_sel_field_store_in_mysql_format_func
7,42% mysqld [.] btr_search_guess_on_hash
6,19% mysqld [.] row_search_for_mysql
4,86% mysqld [.] row_sel_enqueue_cache_row_for_mysql
3,59% libc-2.17.so [.] __memcpy_ssse3_back
2,76% mysqld [.] row_sel_store_mysql_rec
2,19% [kernel] [k] _raw_spin_unlock_irqrestore
1,69% libc-2.17.so [.] _int_malloc
1,68% mysqld [.] btr_cur_search_to_nth_level
1,41% mysqld [.] buf_page_get_known_nowait
1,41% mysqld [.] buf_page_optimistic_get
1,29% mysqld [.] rec_get_nth_field_offs
1,22% mysqld [.] my_strnncollsp_utf8
1,15% [kernel] [k] _raw_spin_lock
1,10% [kernel] [k] finish_task_switch
0,98% mysqld [.] end_table_io_wait_v1
0,95% mysqld [.] buf_page_get_gen
0,87% mysqld [.] cmp_dtuple_rec_with_match_low
0,80% mysqld [.] mtr_commit
0,73% libc-2.17.so [.] _int_free
0,67% libc-2.17.so [.] malloc
0,63% mysqld [.] ha_innobase::rnd_next
0,63% mysqld [.] btr_pcur_store_position
0,60% mysqld [.] buf_block_align
0,51% mysqld [.] lock_clust_rec_cons_read_sees
0,50% mysqld [.] row_mysql_store_true_var_len
0,48% mysqld [.] my_timer_cycles
0,46% mysqld [.] Item::val_bool

=====================================================

_raw_spin_lock часто выбивается в самый верх и как я понимаю это системный процесс.

Что это? Какие мнения? Я гуглить.)

Answer 1

[Макс]

ну наверное для начала стоит запустить в такие периоды mytop.
по top видно, что главный "проглот" - mysqld

Comments

[Serj0333]

Это да, но если я правильно понимаю, то mysql - это CPU User time, а не system time. Рост system time может быть вызван какими-то системными процессами.

Answer 2

[Пума Тайланд]

систем тайм может легко отжираться приложением, если у вас нет ничего кроме мускула там то логично что это мускул
посмотрите шоу процесс лист в м омент затупов например
посмотрите иотоп

Comments

[Serj0333]

В show processlist много sleep процессов, а те которые работают все выполняются в пределах 20 секунд.
Что я должен увидеть в show processlist, на что ориентироваться и какие выводы из этого делать?

Относительно iotop вот вывод:
Total DISK READ : 41.13 K/s | Total DISK WRITE : 7.31 M/s
Actual DISK READ: 41.13 K/s | Actual DISK WRITE: 4.72 M/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
1374 be/3 root 0.00 B/s 14.24 K/s 0.00 % 6.84 % [jbd2/sdb1-8]
29451 be/4 mysql 0.00 B/s 3.70 M/s 0.00 % 3.38 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48684 be/4 mysql 0.00 B/s 17.40 K/s 0.00 % 0.24 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48934 be/4 mysql 0.00 B/s 3.95 K/s 0.00 % 0.21 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48387 be/4 mysql 3.16 K/s 0.00 B/s 0.00 % 0.20 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
29449 be/4 mysql 34.80 K/s 809.91 B/s 0.00 % 0.17 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48841 be/4 mysql 3.16 K/s 0.00 B/s 0.00 % 0.14 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48952 be/4 mysql 0.00 B/s 1619.82 B/s 0.00 % 0.13 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48961 be/4 mysql 0.00 B/s 3.16 K/s 0.00 % 0.11 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48689 be/4 mysql 0.00 B/s 4.75 K/s 0.00 % 0.10 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48866 be/4 mysql 0.00 B/s 3.16 K/s 0.00 % 0.10 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48686 be/4 mysql 0.00 B/s 3.95 K/s 0.00 % 0.07 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48885 be/4 mysql 0.00 B/s 2.37 K/s 0.00 % 0.07 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48679 be/4 mysql 0.00 B/s 2.37 K/s 0.00 % 0.07 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
47700 be/4 mysql 0.00 B/s 3.95 K/s 0.00 % 0.07 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48895 be/4 mysql 0.00 B/s 3.16 K/s 0.00 % 0.05 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48972 be/4 mysql 0.00 B/s 1619.82 B/s 0.00 % 0.05 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48675 be/4 mysql 0.00 B/s 1619.82 B/s 0.00 % 0.05 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48938 be/4 mysql 0.00 B/s 3.16 K/s 0.00 % 0.05 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48876 be/4 mysql 0.00 B/s 809.91 B/s 0.00 % 0.04 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48971 be/4 mysql 0.00 B/s 1619.82 B/s 0.00 % 0.04 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48832 be/4 mysql 0.00 B/s 2.37 K/s 0.00 % 0.04 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48848 be/4 mysql 0.00 B/s 809.91 B/s 0.00 % 0.03 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48970 be/4 mysql 0.00 B/s 1619.82 B/s 0.00 % 0.03 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48891 be/4 mysql 0.00 B/s 809.91 B/s 0.00 % 0.03 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48843 be/4 mysql 0.00 B/s 809.91 B/s 0.00 % 0.03 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48527 be/4 mysql 0.00 B/s 2.37 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
25733 be/3 root 0.00 B/s 0.00 B/s 0.00 % 0.02 % [jbd2/sdc1-8]
48850 be/4 mysql 0.00 B/s 3.95 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48053 be/4 mysql 0.00 B/s 3.95 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48853 be/4 mysql 0.00 B/s 1619.82 B/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48951 be/4 mysql 0.00 B/s 6.33 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48932 be/4 mysql 0.00 B/s 4.75 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48861 be/4 mysql 0.00 B/s 3.16 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48986 be/4 mysql 0.00 B/s 2.37 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48692 be/4 mysql 0.00 B/s 3.16 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48837 be/4 mysql 0.00 B/s 2.37 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48869 be/4 mysql 0.00 B/s 3.16 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48996 be/4 mysql 0.00 B/s 3.16 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48957 be/4 mysql 0.00 B/s 2.37 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
47188 be/4 mysql 0.00 B/s 1619.82 B/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48988 be/4 mysql 0.00 B/s 2.37 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48851 be/4 mysql 0.00 B/s 3.16 K/s 0.00 % 0.02 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48874 be/4 mysql 0.00 B/s 3.16 K/s 0.00 % 0.01 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
47703 be/4 mysql 0.00 B/s 1619.82 B/s 0.00 % 0.01 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
48933 be/4 mysql 0.00 B/s 2.37 K/s 0.00 % 0.01 % mysqld --basedir=/usr --datadir=/db-data-drive/mysql --plugin-di~ar/run/mysqld/mysqld.pid --socket=/db-data-drive/mysql/mysql.sock
37301 be/4 root 0.00 B/s 0.00 B/s 0.00 % 0.01 % [kworker/1:0]

И такой же вопрос, на какие параметры смотреть и какие выводы из этого делать.

Просто сейчас, смотря на эти цифры, мне кажется что все нормально, не такие уж и высокие значения.

[Serj0333]

DISK WRITE поднимался примерно до 20MB/s

[Serj0333]

Плюс глядя сюда %Cpu(s): 36,7 us, 18,4 sy, 0,0 ni, 42,8 id, 1,8 wa, 0,0 hi, 0,3 si, 0,0 st
кажется что в io мы вообще не упираемся.

Answer 3

[Dima Kim]

как правильно диагностировать по CPU, что означает CPU user time