Un poco de historia de fondo, hace algún tiempo comenzamos a experimentar un alto tiempo de sistema de CPU en una de nuestras bases de datos MySQL. Esta base de datos también sufría una alta utilización del disco, por lo que pensamos que esas cosas están conectadas. Y dado que ya teníamos planes de migrarlo a SSD, pensamos que resolvería ambos problemas.
Ayudó ... pero no por mucho tiempo.
Durante un par de semanas después de la migración, el gráfico de la CPU fue así:
Pero ahora volvemos a esto:
Esto sucedió de la nada, sin cambios aparentes en la carga o la lógica de la aplicación.
Estadísticas de DB:
- Versión MySQL - 5.7.20
- OS - Debian
- Tamaño de DB - 1.2Tb
- RAM - 700Gb
- Núcleos de CPU - 56
- Peek load: aproximadamente 5kq / s de lectura, 600q / s de escritura (aunque las consultas seleccionadas a menudo son bastante complejas)
- Subprocesos: 50 en ejecución, 300 conectados
- Tiene alrededor de 300 mesas, todas InnoDB
Configuración de MySQL:
[client]
port = 3306
socket = /var/run/mysqld/mysqld.sock
[mysqld_safe]
pid-file = /var/run/mysqld/mysqld.pid
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 = /opt/mysql-data
tmpdir = /tmp
lc-messages-dir = /usr/share/mysql
explicit_defaults_for_timestamp
sql_mode = STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION
log-error = /opt/mysql-log/error.log
# Replication
server-id = 76
gtid-mode = ON
enforce-gtid-consistency = true
relay-log = /opt/mysql-log/mysql-relay-bin
relay-log-index = /opt/mysql-log/mysql-relay-bin.index
replicate-wild-do-table = dbname.%
log-bin = /opt/mysql-log/mysql-bin.log
expire_logs_days = 7
max_binlog_size = 1024M
binlog-format = ROW
log-bin-trust-function-creators = 1
log_slave_updates = 1
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0
# * IMPORTANT: Additional settings that can override those from this file!
# The files must end with '.cnf', otherwise they'll be ignored.
#
!includedir /etc/mysql/conf.d/
# Here goes
skip_name_resolve = 1
general_log = 0
slow_query_log = 1
slow_query_log_file = /opt/mysql-log/slow.log
long_query_time = 3
max_allowed_packet = 16M
max_connections = 700
max_execution_time = 200000
open_files_limit = 32000
table_open_cache = 8000
thread_cache_size = 128
innodb_buffer_pool_size = 550G
innodb_buffer_pool_instances = 28
innodb_log_file_size = 15G
innodb_log_files_in_group = 2
innodb_flush_method = O_DIRECT
max_heap_table_size = 16M
tmp_table_size = 128M
join_buffer_size = 1M
sort_buffer_size = 2M
innodb_lru_scan_depth = 256
query_cache_type = 0
query_cache_size = 0
innodb_temp_data_file_path = ibtmp1:12M:autoextend:max:30G Otras observaciones
rendimiento del proceso mysql durante la carga máxima:
68,31% 68,31% mysqld [kernel.kallsyms] [k] _raw_spin_lock
- _raw_spin_lock
+ 51,63% 0x7fd118e9dbd9
+ 48,37% 0x7fd118e9dbab
+ 37,36% 0,02% mysqld libc-2.19.so [.] 0x00000000000f4bd9
+ 33,83% 0,01% mysqld libc-2.19.so [.] 0x00000000000f4bab
+ 26,92% 0,00% mysqld libpthread-2.19.so [.] start_thread
+ 26,82% 0,00% mysqld mysqld [.] pfs_spawn_thread
+ 26,82% 0,00% mysqld mysqld [.] handle_connection
+ 26,81% 0,01% mysqld mysqld [.] do_command(THD*)
+ 26,65% 0,02% mysqld mysqld [.] dispatch_command(THD*, COM_DATA const*, enum_server_command)
+ 26,29% 0,01% mysqld mysqld [.] mysql_parse(THD*, Parser_state*)
+ 24,85% 0,01% mysqld mysqld [.] mysql_execute_command(THD*, bool)
+ 23,61% 0,00% mysqld mysqld [.] handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long)
+ 23,54% 0,00% mysqld mysqld [.] 0x0000000000374103
+ 19,78% 0,00% mysqld mysqld [.] JOIN::exec()
+ 19,13% 0,15% mysqld mysqld [.] sub_select(JOIN*, QEP_TAB*, bool)
+ 13,86% 1,48% mysqld mysqld [.] row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)
+ 8,48% 0,25% mysqld mysqld [.] ha_innobase::general_fetch(unsigned char*, unsigned int, unsigned int)
+ 7,93% 0,00% mysqld [unknown] [.] 0x00007f40c4d7a6f8
+ 7,57% 0,00% mysqld mysqld [.] 0x0000000000828f74
+ 7,25% 0,11% mysqld mysqld [.] handler::ha_index_next_same(unsigned char*, unsigned char const*, unsigned int) Muestra que mysql está pasando mucho tiempo en spin_locks . Tenía la esperanza de obtener alguna pista de dónde provienen esas cerraduras, lamentablemente, no tuve suerte.
El perfil de consulta durante una carga alta muestra una cantidad extrema de cambios de contexto. Solía SELECT * FROM MyTable donde pk = 123 , MiTabla tiene cerca de 90 millones filas. Salida de perfil:
Status 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
starting 0,000756 0,028000 0,012000 81 1 0 0 0 0 0 0 0
checking permissions 0,000057 0,004000 0,000000 4 0 0 0 0 0 0 0 0 check_access sql_authorization.cc 810
Opening tables 0,000285 0,008000 0,004000 31 0 0 40 0 0 0 0 0 open_tables sql_base.cc 5650
init 0,000304 0,012000 0,004000 31 1 0 0 0 0 0 0 0 handle_query sql_select.cc 121
System lock 0,000303 0,012000 0,004000 33 0 0 0 0 0 0 0 0 mysql_lock_tables lock.cc 323
optimizing 0,000196 0,008000 0,004000 20 0 0 0 0 0 0 0 0 optimize sql_optimizer.cc 151
statistics 0,000885 0,036000 0,012000 99 6 0 0 0 0 0 0 0 optimize sql_optimizer.cc 367
preparing 0,000794 0,000000 0,096000 76 2 32 8 0 0 0 0 0 optimize sql_optimizer.cc 475
executing 0,000067 0,000000 0,000000 10 1 0 0 0 0 0 0 0 exec sql_executor.cc 119
Sending data 0,000469 0,000000 0,000000 54 1 32 0 0 0 0 0 0 exec sql_executor.cc 195
end 0,000609 0,000000 0,016000 64 4 0 0 0 0 0 0 0 handle_query sql_select.cc 199
query end 0,000063 0,000000 0,000000 3 1 0 0 0 0 0 0 0 mysql_execute_command sql_parse.cc 4968
closing tables 0,000156 0,000000 0,000000 20 4 0 0 0 0 0 0 0 mysql_execute_command sql_parse.cc 5020
freeing items 0,000071 0,000000 0,004000 7 1 0 0 0 0 0 0 0 mysql_parse sql_parse.cc 5596
cleaning up 0,000533 0,024000 0,008000 62 0 0 0 0 0 0 0 0 dispatch_command sql_parse.cc 1902Peter Zaitsev hizo una publicación recientemente sobre cambios de contexto, donde dice:
Sin embargo, en el mundo real, no me preocuparía que la contención sea un gran problema si tiene menos de diez cambios de contexto por consulta.
¡Pero muestra más de 600 interruptores!
¿Qué puede causar estos síntomas y qué se puede hacer al respecto? Apreciaré cualquier sugerencia o información sobre el asunto, todo lo que encuentro hasta ahora es bastante viejo y / o no concluyente.
PD: con mucho gusto proporcionaré información adicional, si es necesario.
Salida de SHOW GLOBAL STATUS y SHOW VARIABLES
No puedo publicarlo aquí porque el contenido excede el límite de tamaño de publicación.
MOSTRAR ESTADO GLOBAL
MOSTRAR VARIABLES
iostat
avg-cpu: %user %nice %system %iowait %steal %idle
7,35 0,00 5,44 0,20 0,00 87,01
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 8,00 0,00 32,00 32,00 0,00 32,00 0,00
sda 0,04 2,27 0,13 0,96 0,86 46,52 87,05 0,00 2,52 0,41 2,80 0,28 0,03
sdb 0,21 232,57 30,86 482,91 503,42 7769,88 32,21 0,34 0,67 0,83 0,66 0,34 17,50
avg-cpu: %user %nice %system %iowait %steal %idle
9,98 0,00 77,52 0,46 0,00 12,04
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00
sda 0,00 1,60 0,00 0,60 0,00 8,80 29,33 0,00 0,00 0,00 0,00 0,00 0,00
sdb 0,00 566,40 55,60 981,60 889,60 16173,60 32,90 0,84 0,81 0,76 0,81 0,51 53,28
avg-cpu: %user %nice %system %iowait %steal %idle
11,83 0,00 72,72 0,35 0,00 15,10
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
fd0 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00 0,00
sda 0,00 2,60 0,00 0,40 0,00 12,00 60,00 0,00 0,00 0,00 0,00 0,00 0,00
sdb 0,00 565,20 51,60 962,80 825,60 15569,60 32,32 0,85 0,84 0,98 0,83 0,54 54,56Actualizar 15-03-2018
> show global status like 'uptime%'
Uptime;720899
Uptime_since_flush_status;720899
> show global status like '%rollback'
Com_rollback;351422
Com_xa_rollback;0
Handler_rollback;371088
Handler_savepoint_rollback;0
select * from MyTable where pk = 123tarda en promedio?global statuspara ver si algo se correlaciona con el aumento del uso de la CPU. No creo que se pueda lograr nada con los datos disponibles en este momento. Haré otra pregunta si encuentro algo nuevo.Respuestas:
La escritura de 600q / s con una descarga por confirmación probablemente esté llegando al límite de sus discos giratorios actuales. Cambiar a SSD aliviaría la presión.
La solución rápida (antes de obtener SSD) es probablemente cambiar a esta configuración:
Pero lea las advertencias sobre cómo hacer ese cambio.
Tener esa configuración y los SSD te permitirán crecer más.
Otra posible solución es combinar algunas escrituras en una sola
COMMIT(donde no se viola la lógica).Casi siempre, CPU alta y / o E / S se deben a índices pobres y / o formulación pobre de consultas. Active el registro lento con
long_query_time=1, espere un momento y luego vea qué aparece. Con las consultas en parte, proporcionarSELECT,EXPLAIN SELECT ...ySHOW CREATE TABLE. Lo mismo para las consultas de escritura. De ellos, probablemente podamos domar la CPU y / o E / S. Incluso con su configuración actual de3,pt-query-digestpodría encontrar algunas cosas interesantes.Tenga en cuenta que con 50 hilos "en ejecución", hay mucha contención; esto puede estar causando el cambio, etc., que usted notó. Necesitamos obtener consultas para terminar más rápido. Con 5.7, el sistema puede colapsar con 100 hilos en ejecución . Al aumentar más allá de aproximadamente 64, los cambios de contexto, mutexes, bloqueos, etc., conspiran para ralentizar cada subproceso, lo que no conduce a una mejora en el rendimiento mientras la latencia se dispara.
Para un enfoque diferente para analizar el problema, proporcione
SHOW VARIABLESySHOW GLOBAL STATUS? Más discusión aquí .Análisis de VARIABLES Y ESTADO
(Lo siento, nada sobresale como abordar su pregunta).
Observaciones:
Los asuntos más importantes:
Se crean muchas tablas temporales, especialmente basadas en disco, para consultas complejas. Esperemos que el registro lento identifique algunas consultas que pueden mejorarse (mediante indexación / reformulación / etc.) Otros indicadores son uniones sin índices y sort_merge_passes; sin embargo, ninguno de estos es concluyente, necesitamos ver las consultas.
Max_used_connections = 701es> =Max_connections = 700, por lo que probablemente se rechazaron algunas conexiones. Además, si eso indica más de, digamos, 64 subprocesos en ejecución , entonces el rendimiento del sistema probablemente se vio afectado en ese momento. Considere limitar el número de conexiones al limitar los clientes. ¿Estás usando Apache, Tomcat o alguna otra cosa? 70Threads_runningindica que, en el momento de hacer estoSHOW, el sistema estaba en problemas.Aumentar el número de declaraciones en cada
COMMIT(cuando sea razonable) puede ayudar al rendimiento de algunos.innodb_log_file_size, con 15 GB, es más grande de lo necesario, pero no veo la necesidad de cambiarlo.Miles de mesas no suelen ser un buen diseño.
eq_range_index_dive_limit = 200me preocupa, pero no sé cómo aconsejar. ¿Fue una elección deliberada?¿Por qué tantos PROCEDIMIENTOS CREATE + DROP?
¿Por qué tantos comandos SHOW?
Detalles y otras observaciones:
( Innodb_buffer_pool_pages_flushed ) = 523,716,598 / 3158494 = 165 /sec- Escribe (ruboriza) - comprueba innodb_buffer_pool_size( table_open_cache ) = 10,000- Número de descriptores de tabla para almacenar en caché - Varios cientos generalmente es bueno.( (Innodb_buffer_pool_reads + Innodb_buffer_pool_pages_flushed) ) = ((61,040,718 + 523,716,598) ) / 3158494 = 185 /sec- InnoDB I / O( Innodb_dblwr_pages_written/Innodb_pages_written ) = 459,782,684/523,717,889 = 87.8%- Parece que estos valores deberían ser iguales?( Innodb_os_log_written ) = 1,071,443,919,360 / 3158494 = 339226 /sec- Este es un indicador de lo ocupado que está InnoDB. - Muy ocupado InnoDB.( Innodb_log_writes ) = 110,905,716 / 3158494 = 35 /sec( Innodb_os_log_written / (Uptime / 3600) / innodb_log_files_in_group / innodb_log_file_size ) = 1,071,443,919,360 / (3158494 / 3600) / 2 / 15360M = 0.0379- Ratio - (ver minutos)( Uptime / 60 * innodb_log_file_size / Innodb_os_log_written ) = 3,158,494 / 60 * 15360M / 1071443919360 = 791- Minutos entre rotaciones de registros InnoDB Comenzando con 5.6.8, esto se puede cambiar dinámicamente; asegúrese de cambiar también my.cnf. - (La recomendación de 60 minutos entre rotaciones es algo arbitraria). Ajuste innodb_log_file_size. (No se puede cambiar en AWS).( Com_rollback ) = 770,457 / 3158494 = 0.24 /sec- ROLLBACKs en InnoDB. - Una frecuencia excesiva de retrocesos puede indicar una lógica de aplicación ineficiente.( Innodb_row_lock_waits ) = 632,292 / 3158494 = 0.2 /sec- Con qué frecuencia hay un retraso en el bloqueo de una fila. - Puede ser causado por consultas complejas que podrían optimizarse.( Innodb_dblwr_writes ) = 97,725,876 / 3158494 = 31 /sec- "Doublewrite buffer" escribe en el disco. "Doublewrites" son una característica de fiabilidad. Algunas versiones / configuraciones más nuevas no las necesitan. - (Síntoma de otros problemas)( Innodb_row_lock_current_waits ) = 13- El número de bloqueos de fila que las operaciones esperan actualmente en las tablas InnoDB. Cero es bastante normal. - Algo grande está pasando?( innodb_print_all_deadlocks ) = OFF- Si se deben registrar todos los puntos muertos. - Si estás plagado de Deadlocks, enciéndelo. Precaución: si tiene muchos puntos muertos, esto puede escribir mucho en el disco.( local_infile ) = ON- local_infile = ON es un posible problema de seguridad( bulk_insert_buffer_size / _ram ) = 8M / 716800M = 0.00%- Buffer para INSERTOS de varias filas y CARGAR DATOS - Demasiado grande podría amenazar el tamaño de la RAM. Demasiado pequeño podría obstaculizar tales operaciones.( Questions ) = 9,658,430,713 / 3158494 = 3057 /sec- Consultas (fuera de SP) - "qps" -> 2000 puede estar estresando al servidor( Queries ) = 9,678,805,194 / 3158494 = 3064 /sec- Consultas (incluso dentro del SP) -> 3000 pueden estar estresando al servidor( Created_tmp_tables ) = 1,107,271,497 / 3158494 = 350 /sec- Frecuencia de creación de tablas "temp" como parte de SELECT complejos.( Created_tmp_disk_tables ) = 297,023,373 / 3158494 = 94 /sec- Frecuencia de creación de tablas "temp" de disco como parte de SELECTs complejos: aumente tmp_table_size y max_heap_table_size. Verifique las reglas para las tablas temporales cuando se utiliza MEMORY en lugar de MyISAM. Quizás cambios menores en el esquema o la consulta pueden evitar MyISAM. Los mejores índices y la reformulación de las consultas tienen más probabilidades de ayudar.( (Com_insert + Com_update + Com_delete + Com_replace) / Com_commit ) = (693300264 + 214511608 + 37537668 + 0) / 1672382928 = 0.565- Declaraciones por confirmación (asumiendo todo InnoDB) - Bajo: podría ayudar a agrupar consultas en transacciones; Alto: las transacciones largas tensan varias cosas.( Select_full_join ) = 338,957,314 / 3158494 = 107 /sec- Uniones sin índice: agregue índice (es) adecuado (s) a las tablas utilizadas en JOIN.( Select_full_join / Com_select ) = 338,957,314 / 6763083714 = 5.0%-% de selecciones que son uniones sin índice - Agregue índices adecuados a las tablas utilizadas en JOIN.( Select_scan ) = 124,606,973 / 3158494 = 39 /sec- escaneos completos de tablas - Agregue índices / optimice consultas (a menos que sean tablas pequeñas)( Sort_merge_passes ) = 1,136,548 / 3158494 = 0.36 /sec- Tipos pesados: aumente sort_buffer_size y / u optimice consultas complejas.( Com_insert + Com_delete + Com_delete_multi + Com_replace + Com_update + Com_update_multi ) = (693300264 + 37537668 + 198418338 + 0 + 214511608 + 79274476) / 3158494 = 387 /sec- escrituras / seg. - 50 escrituras / seg. + descargas de registro probablemente maximizarán la capacidad de escritura de E / S de las unidades normales( ( Com_stmt_prepare - Com_stmt_close ) / ( Com_stmt_prepare + Com_stmt_close ) ) = ( 39 - 38 ) / ( 39 + 38 ) = 1.3%- ¿Estás cerrando tus declaraciones preparadas? - Añadir Cierra.( Com_stmt_close / Com_stmt_prepare ) = 38 / 39 = 97.4%- Las declaraciones preparadas deben estar cerradas. - Compruebe si todas las declaraciones preparadas están "cerradas".( innodb_autoinc_lock_mode ) = 1- Galera: deseos 2 - 2 = "intercalados"; 1 = "consecutivo" es típico; 0 = "tradicional".( Max_used_connections / max_connections ) = 701 / 700 = 100.1%-% de picos de conexiones - aumenta max_ connections y / o disminuye wait_timeout( Threads_running - 1 ) = 71 - 1 = 70- Subprocesos activos (concurrencia cuando se recopilan datos) - Optimizar consultas y / o esquemaAnormalmente grande: (La mayoría de estos se derivan de ser un sistema muy ocupado).
(continuado)
fuente
innodb_flush_log_at_trx_commit = 2no parece tener ningún efecto y la contención de hilos tampoco parece ser el problema porque incluso con cargas moderadas (hilos ejecutando <50) CPU sys / usuario de CPU es algo así como 3 a 1.Nunca descubrimos cuál era la causa exacta de este problema, pero para ofrecer un cierre, voy a decir lo que pueda.
Nuestro equipo realizó algunas pruebas de carga y concluyó que
MySQLtenía problemas para asignar memoria. Entonces intentaron usar enjemalloclugar deglibcy el problema desapareció. Llevamosjemallocmás de 6 meses en producción, sin volver a ver este problema.No digo que
jemallocsea mejor, o que todos deberían usarloMySQL. Pero parece que nuestro caso específicoglibcsimplemente no funcionaba correctamente.fuente
Mis 2 centavos
Ejecute "iostat -xk 5" para intentar ver si el disco sigue siendo un problema. Además, el sistema de la CPU está relacionado con el código del sistema (kernell), verifique dos veces el nuevo disco / controladores / configuración.
fuente
Sugerencias para la sección my.cnf / ini [mysqld] para su MUY OCUPADO
Mi expectativa es una disminución gradual en los resultados de SHOW GLOBAL STATUS LIKE 'innodb_buffer_pool_pages_dirty'; con estas sugerencias aplicadas. El 13/01/18 tenías más de 4 millones de páginas sucias.
Espero que estos ayuden. Estos pueden ser modificados dinámicamente. Existen muchas más oportunidades, si las quieres, házmelo saber.
fuente
Con IOPS a 30K probado (necesitamos una cantidad de IOPS para escrituras aleatorias), considere esta sugerencia para la sección my.cnf / ini [mysqld]
puede cambiarse dinámicamente con SET GLOBAL y debería reducir innodb_buffer_pool_pages_dirty rápidamente.
La causa de que COM_ROLLBACK promedia 1 cada 4 segundos seguirá siendo un problema de rendimiento hasta que se resuelva.
@chimmi 9 de abril de 2018 Elija este script de MySQL en https://pastebin.com/aZAu2zZ0 para una verificación rápida de los recursos de estado global utilizados o liberados durante nn segundos que puede configurar en SLEEP. Esto le permitirá ver si alguien ha ayudado a reducir su frecuencia COM_ROLLBACK. Me gustaría saber de usted por correo electrónico.
fuente
Su estado global de SHOW indica que innodb_buffer_pool_pages_dirty fueron 4,291,574.
Para monitorear el conteo actual,
Para alentar a reducir este recuento,
En una hora, ejecute la solicitud del monitor para ver dónde está parado con las páginas sucias.
Por favor, hágame saber sus cuentas al principio y una hora más tarde.
Aplique el cambio a su my.cnf para una mejor salud a largo plazo de la reducción sucia de páginas.
fuente