[MDEV-18831] Mariadb 5.5.56 cost all cpus to 800% by doing nothing Created: 2019-03-06  Updated: 2021-03-08

Status: Open
Project: MariaDB Server
Component/s: None
Affects Version/s: 5.5.56
Fix Version/s: 5.5

Type: Bug Priority: Major
Reporter: zou.xingbing Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: cpu
Environment:

Mariadb runs on CentOS release 6.5 (Final)

Attachments: Zip Archive feedback.zip     Text File localhost-slow.log     File localhost.localdomain.err     Text File mariadb.log     File my.cnf    

 Description   

Attachment files are the logs I can get.
Mariadb cost all cpus even I stopped my application.
my.cnf is the default config.
"show full processlist" can be found in the file mariadb.log.
slow log seems to be nothing valuable.

 Comments   
Comment by Elena Stepanova [ 2019-03-06 ]

All these connections with low values in Time appear to be doing at least something, it's just unclear what, exactly.
If you can, please take several consequent stack traces of all threads from the running mysqld process.
If you can't get stack traces, maybe set up for a few minutes a monitor with a short interval, like each second, which would run SHOW PROCESSLIST and SHOW GLOBAL STATUS LIKE 'Com%'.
SHOW ENGINE InnoDB STATUS might also show something.

Comment by zou.xingbing [ 2019-03-07 ]

Hi Elena, thank you for your attention!
I have tried the second method your supplyed. The “feedback.zip” file contains the information about the cpu usage and the mysql commands result.
I make a shell script to get the following command result:
top / SHOW PROCESSLIST / SHOW GLOBAL STATUS LIKE 'Com%' / SHOW ENGINE InnoDB STATUS.

Comment by zou.xingbing [ 2019-03-19 ]

Hello, Elena! Here is the mysql server process list and thread stack traces. I hope it's useful.

[root@localhost ~]# top -H -p 63674
top - 11:03:23 up 11 days, 20:44, 5 users, load average: 75.03, 75.05, 75.06
Tasks: 109 total, 75 running, 34 sleeping, 0 stopped, 0 zombie
Cpu(s): 99.8%us, 0.1%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.1%si, 0.0%st
Mem: 16260304k total, 10857912k used, 5402392k free, 58932k buffers
Swap: 8126456k total, 859380k used, 7267076k free, 4577752k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
63867 mysql 20 0 1068m 446m 6068 R 5.7 2.8 50:00.43 mysqld
65019 mysql 20 0 1068m 446m 6068 R 5.7 2.8 49:31.34 mysqld
65072 mysql 20 0 1068m 446m 6068 R 5.7 2.8 49:24.69 mysqld
65074 mysql 20 0 1068m 446m 6068 R 5.7 2.8 51:27.50 mysqld
65083 mysql 20 0 1068m 446m 6068 R 5.7 2.8 49:36.15 mysqld
65112 mysql 20 0 1068m 446m 6068 R 5.7 2.8 49:49.09 mysqld
65118 mysql 20 0 1068m 446m 6068 R 5.7 2.8 50:12.16 mysqld
65127 mysql 20 0 1068m 446m 6068 R 5.7 2.8 50:30.24 mysqld
65146 mysql 20 0 1068m 446m 6068 R 5.7 2.8 50:00.39 mysqld
63868 mysql 20 0 1068m 446m 6068 R 5.3 2.8 17:01.68 mysqld
63870 mysql 20 0 1068m 446m 6068 R 5.3 2.8 47:14.10 mysqld
64478 mysql 20 0 1068m 446m 6068 R 5.3 2.8 46:04.05 mysqld
64479 mysql 20 0 1068m 446m 6068 R 5.3 2.8 41:00.01 mysqld
65004 mysql 20 0 1068m 446m 6068 R 5.3 2.8 45:48.60 mysqld
65014 mysql 20 0 1068m 446m 6068 R 5.3 2.8 50:09.41 mysqld
65017 mysql 20 0 1068m 446m 6068 R 5.3 2.8 47:22.58 mysqld
65018 mysql 20 0 1068m 446m 6068 R 5.3 2.8 45:44.16 mysqld
65022 mysql 20 0 1068m 446m 6068 R 5.3 2.8 45:42.47 mysqld
65023 mysql 20 0 1068m 446m 6068 R 5.3 2.8 16:19.51 mysqld
65029 mysql 20 0 1068m 446m 6068 R 5.3 2.8 46:10.65 mysqld
65030 mysql 20 0 1068m 446m 6068 R 5.3 2.8 48:38.21 mysqld
65031 mysql 20 0 1068m 446m 6068 R 5.3 2.8 49:35.70 mysqld
65037 mysql 20 0 1068m 446m 6068 R 5.3 2.8 47:36.15 mysqld
65043 mysql 20 0 1068m 446m 6068 R 5.3 2.8 46:10.04 mysqld
65045 mysql 20 0 1068m 446m 6068 R 5.3 2.8 16:18.33 mysqld
65073 mysql 20 0 1068m 446m 6068 R 5.3 2.8 48:26.33 mysqld
65076 mysql 20 0 1068m 446m 6068 R 5.3 2.8 48:02.64 mysqld
65078 mysql 20 0 1068m 446m 6068 R 5.3 2.8 47:18.94 mysqld
65079 mysql 20 0 1068m 446m 6068 R 5.3 2.8 48:10.55 mysqld
65081 mysql 20 0 1068m 446m 6068 R 5.3 2.8 46:01.06 mysqld
65082 mysql 20 0 1068m 446m 6068 R 5.3 2.8 47:26.02 mysqld
65085 mysql 20 0 1068m 446m 6068 R 5.3 2.8 52:50.75 mysqld
65086 mysql 20 0 1068m 446m 6068 R 5.3 2.8 46:40.63 mysqld
65087 mysql 20 0 1068m 446m 6068 R 5.3 2.8 49:31.78 mysqld
65088 mysql 20 0 1068m 446m 6068 R 5.3 2.8 47:25.05 mysqld
65095 mysql 20 0 1068m 446m 6068 R 5.3 2.8 48:27.98 mysqld
65096 mysql 20 0 1068m 446m 6068 R 5.3 2.8 46:51.63 mysqld
65098 mysql 20 0 1068m 446m 6068 R 5.3 2.8 47:23.16 mysqld
65100 mysql 20 0 1068m 446m 6068 R 5.3 2.8 46:17.14 mysqld
65101 mysql 20 0 1068m 446m 6068 R 5.3 2.8 47:55.97 mysqld
65102 mysql 20 0 1068m 446m 6068 R 5.3 2.8 47:24.08 mysqld
65103 mysql 20 0 1068m 446m 6068 R 5.3 2.8 50:01.88 mysqld
65104 mysql 20 0 1068m 446m 6068 R 5.3 2.8 48:12.00 mysqld
65105 mysql 20 0 1068m 446m 6068 R 5.3 2.8 48:44.29 mysqld
65106 mysql 20 0 1068m 446m 6068 R 5.3 2.8 46:49.03 mysqld
65107 mysql 20 0 1068m 446m 6068 R 5.3 2.8 48:36.20 mysqld
65108 mysql 20 0 1068m 446m 6068 R 5.3 2.8 48:23.70 mysqld
65109 mysql 20 0 1068m 446m 6068 R 5.3 2.8 46:49.67 mysqld
65110 mysql 20 0 1068m 446m 6068 R 5.3 2.8 50:05.61 mysqld

[root@localhost bin]# pstack 65014
Thread 1 (process 65014):
#0 0x00000038fc61154c in ?? () from /lib64/libgcc_s.so.1
#1 0x000000376170e556 in dl_iterate_phdr () from /lib64/libc.so.6
#2 0x00000038fc612207 in _Unwind_Find_FDE () from /lib64/libgcc_s.so.1
#3 0x00000038fc60f603 in ?? () from /lib64/libgcc_s.so.1
#4 0x00000038fc6101f0 in ?? () from /lib64/libgcc_s.so.1
#5 0x00000038fc6102b4 in _Unwind_ForcedUnwind () from /lib64/libgcc_s.so.1
#6 0x0000003761e0de90 in __pthread_unwind () from /lib64/libpthread.so.0
#7 0x0000003761e080a5 in pthread_exit () from /lib64/libpthread.so.0
#8 0x00000000004fa592 in one_thread_per_connection_end(THD*, bool) ()
#9 0x00000000006470ab in do_handle_one_connection(THD*) ()
#10 0x000000000064726c in handle_one_connection ()
#11 0x0000003761e079d1 in start_thread () from /lib64/libpthread.so.0
#12 0x00000037616d800d in clone () from /lib64/libc.so.6
[root@localhost bin]# pstack 63868
Thread 1 (process 63868):
#0 0x00000038fc61153e in ?? () from /lib64/libgcc_s.so.1
#1 0x000000376170e556 in dl_iterate_phdr () from /lib64/libc.so.6
#2 0x00000038fc612207 in _Unwind_Find_FDE () from /lib64/libgcc_s.so.1
#3 0x00000038fc60f603 in ?? () from /lib64/libgcc_s.so.1
#4 0x00000038fc6101f0 in ?? () from /lib64/libgcc_s.so.1
#5 0x00000038fc6102b4 in _Unwind_ForcedUnwind () from /lib64/libgcc_s.so.1
#6 0x0000003761e0de90 in __pthread_unwind () from /lib64/libpthread.so.0
#7 0x0000003761e080a5 in pthread_exit () from /lib64/libpthread.so.0
#8 0x00000000004fa592 in one_thread_per_connection_end(THD*, bool) ()
#9 0x00000000006470ab in do_handle_one_connection(THD*) ()
#10 0x000000000064726c in handle_one_connection ()
#11 0x0000003761e079d1 in start_thread () from /lib64/libpthread.so.0
#12 0x00000037616d800d in clone () from /lib64/libc.so.6
[root@localhost bin]# pstack 65108
Thread 1 (process 65108):
#0 0x00000038fc611532 in ?? () from /lib64/libgcc_s.so.1
#1 0x000000376170e556 in dl_iterate_phdr () from /lib64/libc.so.6
#2 0x00000038fc612207 in _Unwind_Find_FDE () from /lib64/libgcc_s.so.1
#3 0x00000038fc60f603 in ?? () from /lib64/libgcc_s.so.1
#4 0x00000038fc6101f0 in ?? () from /lib64/libgcc_s.so.1
#5 0x00000038fc6102b4 in _Unwind_ForcedUnwind () from /lib64/libgcc_s.so.1
#6 0x0000003761e0de90 in __pthread_unwind () from /lib64/libpthread.so.0
#7 0x0000003761e080a5 in pthread_exit () from /lib64/libpthread.so.0
#8 0x00000000004fa592 in one_thread_per_connection_end(THD*, bool) ()
#9 0x00000000006470ab in do_handle_one_connection(THD*) ()
#10 0x000000000064726c in handle_one_connection ()
#11 0x0000003761e079d1 in start_thread () from /lib64/libpthread.so.0
#12 0x00000037616d800d in clone () from /lib64/libc.so.6

Comment by zou.xingbing [ 2019-03-19 ]

Here is the another kind of pstack result:
[root@localhost bin]# pstack 21086
Thread 1 (process 21086):
#0 0x000000376167ed4b in __memmove_sse2 () from /lib64/libc.so.6
#1 0x000000000067196e in JOIN_CACHE::read_record_field(st_cache_field*, bool) ()
#2 0x00000000006750e2 in JOIN_CACHE::get_record() ()
#3 0x0000000000672702 in JOIN_CACHE::join_matching_records(bool) ()
#4 0x000000000066fbcb in JOIN_CACHE::join_records(bool) ()
#5 0x00000000005c19d8 in evaluate_join_record(JOIN*, st_join_table*, int) ()
#6 0x00000000005c1cb9 in sub_select(JOIN*, st_join_table*, bool) ()
#7 0x00000000005c23ad in do_select(JOIN*, List<Item>, TABLE, Procedure*) ()
#8 0x00000000005d3e2c in JOIN::exec() ()
#9 0x00000000005d63ca in mysql_select(THD*, Item**, TABLE_LIST, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*) ()
#10 0x00000000005d7014 in handle_select(THD*, LEX*, select_result*, unsigned long) ()
#11 0x000000000057fc10 in execute_sqlcom_select(THD*, TABLE_LIST*) ()
#12 0x0000000000585ee2 in mysql_execute_command(THD*) ()
#13 0x0000000000588af1 in mysql_parse(THD*, char*, unsigned int, Parser_state*) ()
#14 0x000000000058aa98 in dispatch_command(enum_server_command, THD*, char*, unsigned int) ()
#15 0x000000000058b053 in do_command(THD*) ()
#16 0x0000000000647123 in do_handle_one_connection(THD*) ()
#17 0x000000000064726c in handle_one_connection ()
#18 0x0000003761e079d1 in start_thread () from /lib64/libpthread.so.0
#19 0x00000037616d800d in clone () from /lib64/libc.so.6
[root@localhost bin]#

Generated at Thu Feb 08 08:47:03 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.