Первоначально Написано Алоком Патхаком
Как DBA / консультант MySQL, моя работа заключается в декодировании двоичных журналов MySQL, и для этого есть ряд причин. В этом посте я объясню, как вы можете получить важную информацию о вашей рабочей нагрузке записи, используя двоичные журналы MySQL на основе строк и простой скрипт awk.
Во-первых, важно понимать, что двоичные журналы на основе строк содержат фактические изменения, внесенные запросом. Например, если я выполню запрос на удаление таблицы, двоичный журнал будет содержать строки, которые были удалены. MySQL предоставляет утилиту mysqlbinlog для декодирования событий, хранящихся в двоичных журналах MySQL. Подробнее о mysqlbinlog вы можете прочитать в справочном руководстве здесь .
Следующий пример иллюстрирует, как mysqlbinlog отображает события строки, которые определяют модификации данных. Они соответствуют событиям с кодами типов WRITE_ROWS_EVENT, UPDATE_ROWS_EVENT и DELETE_ROWS_EVENT.
Мы будем использовать следующие опции mysqlbinlog.
–Base64-output = строки декодирования
–verbose, -v
–start-datetime = «datetime»
–stop-datetime = «datetime»
У нас есть сервер, работающий с двоичным журналированием на основе строк
mysql> show variables like '%binlog_format%'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | binlog_format | ROW | +---------------+-------+ 1 row in set (0.00 sec)
Мы создали тестовую таблицу и выполнили следующую последовательность операторов в транзакции.
use test; CREATE TABLE t ( id INT NOT NULL, name VARCHAR(20) NOT NULL, date DATE NULL ) ENGINE = InnoDB; START TRANSACTION; INSERT INTO t VALUES(1, 'apple', NULL); UPDATE t SET name = 'pear', date = '2009-01-01' WHERE id = 1; DELETE FROM t WHERE id = 1; COMMIT;
Теперь посмотрим, как это представлено в двоичных журналах.
# mysqlbinlog --base64-output=decode-rows -vv --start-datetime="2015-01-12 21:40:00" --stop-datetime="2015-01-12 21:45:00" mysqld-bin.000023 /*!*/; # at 295 #150112 21:40:14 server id 1 end_log_pos 367 CRC32 0x19ab4f0f Query thread_id=108 exec_time=0 error_code=0 SET TIMESTAMP=1421079014/*!*/; BEGIN /*!*/; # at 367 #150112 21:40:14 server id 1 end_log_pos 415 CRC32 0x6b1f2240 Table_map: `test`.`t` mapped to number 251 # at 415 #150112 21:40:14 server id 1 end_log_pos 461 CRC32 0x7725d174 Write_rows: table id 251 flags: STMT_END_F ### INSERT INTO `test`.`t` ### SET ### @1=1 /* INT meta=0 nullable=0 is_null=0 */ ### @2='apple' /* VARSTRING(20) meta=20 nullable=0 is_null=0 */ ### @3=NULL /* VARSTRING(20) meta=0 nullable=1 is_null=1 */ # at 461 #150112 21:40:14 server id 1 end_log_pos 509 CRC32 0x7e44d741 Table_map: `test`.`t` mapped to number 251 # at 509 #150112 21:40:14 server id 1 end_log_pos 569 CRC32 0x0cd1363a Update_rows: table id 251 flags: STMT_END_F ### UPDATE `test`.`t` ### WHERE ### @1=1 /* INT meta=0 nullable=0 is_null=0 */ ### @2='apple' /* VARSTRING(20) meta=20 nullable=0 is_null=0 */ ### @3=NULL /* VARSTRING(20) meta=0 nullable=1 is_null=1 */ ### SET ### @1=1 /* INT meta=0 nullable=0 is_null=0 */ ### @2='pear' /* VARSTRING(20) meta=20 nullable=0 is_null=0 */ ### @3='2009:01:01' /* DATE meta=0 nullable=1 is_null=0 */ # at 569 #150112 21:40:14 server id 1 end_log_pos 617 CRC32 0xf134ad89 Table_map: `test`.`t` mapped to number 251 # at 617 #150112 21:40:14 server id 1 end_log_pos 665 CRC32 0x87047106 Delete_rows: table id 251 flags: STMT_END_F ### DELETE FROM `test`.`t` ### WHERE ### @1=1 /* INT meta=0 nullable=0 is_null=0 */ ### @2='pear' /* VARSTRING(20) meta=20 nullable=0 is_null=0 */ ### @3='2009:01:01' /* DATE meta=0 nullable=1 is_null=0 */ # at 665 #150112 21:40:15 server id 1 end_log_pos 696 CRC32 0x85ffc9ff Xid = 465 COMMIT/*!*/; DELIMITER ; # End of log file ROLLBACK /* added by mysqlbinlog */; /*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/; /*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
- Строка с «Table_map: test.t» определяет имя таблицы, используемой запросом.
- Строки с «Write_rows / Update_rows / Delete_rows» определяют тип события.
- Строки, начинающиеся с «###», определяют фактическую строку, которая была изменена.
- Столбцы представлены как @ 1, @ 2 и так далее.
Теперь взгляните на наш простой скрипт awk, который будет использовать вывод mysqlbinlog, и распечатайте красивую сводку событий INSERT / UPDATE / DELETE из двоичных журналов на основе строк. Просто замените «mysqld-bin.000023» на ваш двоичный файл журнала. Строка «# 15» в третьей строке относится к 2015 году. Если вы декодируете двоичный файл журнала с 2014 года, просто измените его на «# 14». Также рекомендуется использовать опции «–start-datetime» и «–stop-datetime» для декодирования двоичных журналов определенного временного диапазона вместо декодирования большого двоичного файла журнала.
Сценарий:
mysqlbinlog --base64-output=decode-rows -vv --start-datetime="2015-01-12 21:40:00" --stop-datetime="2015-01-12 21:45:00" mysqld-bin.000023 | awk \
'BEGIN {s_type=""; s_count=0;count=0;insert_count=0;update_count=0;delete_count=0;flag=0;} \
{if(match($0, /#15.*Table_map:.*mapped to number/)) {printf "Timestamp : " $1 " " $2 " Table : " $(NF-4); flag=1} \
else if (match($0, /(### INSERT INTO .*..*)/)) {count=count+1;insert_count=insert_count+1;s_type="INSERT"; s_count=s_count+1;} \
else if (match($0, /(### UPDATE .*..*)/)) {count=count+1;update_count=update_count+1;s_type="UPDATE"; s_count=s_count+1;} \
else if (match($0, /(### DELETE FROM .*..*)/)) {count=count+1;delete_count=delete_count+1;s_type="DELETE"; s_count=s_count+1;} \
else if (match($0, /^(# at) /) && flag==1 && s_count>0) {print " Query Type : "s_type " " s_count " row(s) affected" ;s_type=""; s_count=0; } \
else if (match($0, /^(COMMIT)/)) {print "[Transaction total : " count " Insert(s) : " insert_count " Update(s) : " update_count " Delete(s) : " \
delete_count "] \n+----------------------+----------------------+----------------------+----------------------+"; \
count=0;insert_count=0;update_count=0; delete_count=0;s_type=""; s_count=0; flag=0} } '
Выход :
Timestamp : #150112 21:40:14 Table : `test`.`t` Query Type : INSERT 1 row(s) affected Timestamp : #150112 21:40:14 Table : `test`.`t` Query Type : UPDATE 1 row(s) affected Timestamp : #150112 21:40:14 Table : `test`.`t` Query Type : DELETE 1 row(s) affected [Transaction total : 3 Insert(s) : 1 Update(s) : 1 Delete(s) : 1] +----------------------+----------------------+----------------------+----------------------+
Этот скрипт awk будет возвращать следующие столбцы в качестве вывода для каждой транзакции в двоичных журналах.
Отметка времени: отметка времени события, зарегистрированного в двоичном журнале.
Таблица: database.tablename
Тип запроса: Тип запроса, выполняемого для таблицы, и количество строк, затронутых запросом.
[Всего транзакций: 3 Вставка (и): 1 Обновление (я): 1 Удалить (и): 1]
Над строкой выведите сводную информацию о транзакции, она отображает общее количество строк, затронутых транзакцией, общее количество строк, затронутых каждым тип запроса в транзакции.
Давайте выполним еще несколько запросов в базе данных sakila, а затем суммируем их, используя наш скрипт. Мы предполагаем, что мы выполняли эти запросы в период с «2015-01-16 13:30:00» и «2015-01-16 14:00:00»
use sakila;
mysql> update city set city="Acua++" where city_id=4;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1 Changed: 1 Warnings: 0
mysql> delete from country where country_id=4;
Query OK, 1 row affected (0.04 sec)
mysql> insert into country (country_id,country,last_update) values ('4','Angola',now());
Query OK, 1 row affected (0.03 sec)
mysql> create table payment_tmp select * from payment;
Query OK, 16049 rows affected (0.80 sec)
Records: 16049 Duplicates: 0 Warnings: 0
mysql> delete from payment_tmp where payment_id between 10000 and 15000;
Query OK, 5001 rows affected (0.08 sec)
mysql> update payment_tmp set amount=9.99 where payment_id between 1 and 7000;
Query OK, 6890 rows affected (0.08 sec)
Rows matched: 7000 Changed: 6890 Warnings: 0
mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)
mysql> delete from country where country_id=5;
Query OK, 1 row affected (0.00 sec)
mysql> delete from city where country_id=5;
Query OK, 1 row affected (0.00 sec)
mysql> delete from address where city_id=300;
Query OK, 2 rows affected (0.00 sec)
mysql> commit;
Query OK, 0 rows affected (0.01 sec)
Мы сохраним наш скрипт в файле с именем «sumrize_binlogs.sh» и суммируем только что выполненные запросы.
# vim summarize_binlogs.sh
#!/bin/bash
BINLOG_FILE="mysqld-bin.000035"
START_TIME="2015-01-16 13:30:00"
STOP_TIME="2015-01-16 14:00:00"
mysqlbinlog --base64-output=decode-rows -vv --start-datetime="${START_TIME}" --stop-datetime="${STOP_TIME}" ${BINLOG_FILE} | awk \
'BEGIN {s_type=""; s_count=0;count=0;insert_count=0;update_count=0;delete_count=0;flag=0;} \
{if(match($0, /#15.*Table_map:.*mapped to number/)) {printf "Timestamp : " $1 " " $2 " Table : " $(NF-4); flag=1} \
else if (match($0, /(### INSERT INTO .*..*)/)) {count=count+1;insert_count=insert_count+1;s_type="INSERT"; s_count=s_count+1;} \
else if (match($0, /(### UPDATE .*..*)/)) {count=count+1;update_count=update_count+1;s_type="UPDATE"; s_count=s_count+1;} \
else if (match($0, /(### DELETE FROM .*..*)/)) {count=count+1;delete_count=delete_count+1;s_type="DELETE"; s_count=s_count+1;} \
else if (match($0, /^(# at) /) && flag==1 && s_count>0) {print " Query Type : "s_type " " s_count " row(s) affected" ;s_type=""; s_count=0; } \
else if (match($0, /^(COMMIT)/)) {print "[Transaction total : " count " Insert(s) : " insert_count " Update(s) : " update_count " Delete(s) : " \
delete_count "] \n+----------------------+----------------------+----------------------+----------------------+"; \
count=0;insert_count=0;update_count=0; delete_count=0;s_type=""; s_count=0; flag=0} } '
:wq
# chmod u+x summarize_binlogs.sh
Теперь мы запускаем наш скрипт, чтобы получить сводную информацию, записанную в двоичном журнале.
# ./summarize_binlogs.sh Timestamp : #150116 13:41:09 Table : `sakila`.`city` Query Type : UPDATE 1 row(s) affected [Transaction total : 1 Insert(s) : 0 Update(s) : 1 Delete(s) : 0] +----------------------+----------------------+----------------------+----------------------+ Timestamp : #150116 13:41:59 Table : `sakila`.`country` Query Type : DELETE 1 row(s) affected [Transaction total : 1 Insert(s) : 0 Update(s) : 0 Delete(s) : 1] +----------------------+----------------------+----------------------+----------------------+ Timestamp : #150116 13:42:07 Table : `sakila`.`country` Query Type : INSERT 1 row(s) affected [Transaction total : 1 Insert(s) : 1 Update(s) : 0 Delete(s) : 0] +----------------------+----------------------+----------------------+----------------------+ Timestamp : #150116 13:42:13 Table : `sakila`.`payment_tmp` Query Type : INSERT 16049 row(s) affected [Transaction total : 16049 Insert(s) : 16049 Update(s) : 0 Delete(s) : 0] +----------------------+----------------------+----------------------+----------------------+ Timestamp : #150116 13:42:20 Table : `sakila`.`payment_tmp` Query Type : DELETE 5001 row(s) affected [Transaction total : 5001 Insert(s) : 0 Update(s) : 0 Delete(s) : 5001] +----------------------+----------------------+----------------------+----------------------+ Timestamp : #150116 13:42:28 Table : `sakila`.`payment_tmp` Query Type : UPDATE 6890 row(s) affected [Transaction total : 6890 Insert(s) : 0 Update(s) : 6890 Delete(s) : 0] +----------------------+----------------------+----------------------+----------------------+ Timestamp : #150116 13:42:42 Table : `sakila`.`country` Query Type : DELETE 1 row(s) affected Timestamp : #150116 13:42:48 Table : `sakila`.`city` Query Type : DELETE 1 row(s) affected Timestamp : #150116 13:42:53 Table : `sakila`.`address` Query Type : DELETE 2 row(s) affected [Transaction total : 4 Insert(s) : 0 Update(s) : 0 Delete(s) : 4] +----------------------+----------------------+----------------------+----------------------+
Посмотрите, как хорошо наш скрипт суммировал информацию, записанную в двоичном журнале. Для последней транзакции отображаются 3 строки, соответствующие каждой инструкции, выполненной в транзакции, а затем итоговая сводка транзакции, т.е. транзакция затронула всего 4 строки, и все они были удалены.
Именно так мы можем суммировать двоичные журналы на основе строк MySQL в более удобочитаемом формате, используя простой скрипт awk. Это сэкономит ваше время всякий раз, когда вам нужно декодировать двоичные журналы для устранения неполадок. Теперь я покажу вам, как эта обобщенная информация может помочь ответить на некоторые основные, но важные вопросы.
Q1: Какие таблицы получили наибольшее количество операторов вставки / обновления / удаления?
./summarize_binlogs.sh | grep Table |cut -d':' -f5| cut -d' ' -f2 | sort | uniq -c | sort -nr
3 `sakila`.`payment_tmp`
3 `sakila`.`country`
2 `sakila`.`city`
1 `sakila`.`address`
Q2: Какая таблица получила наибольшее количество запросов DELETE?
./summarize_binlogs.sh | grep -E 'DELETE' |cut -d':' -f5| cut -d' ' -f2 | sort | uniq -c | sort -nr
2 `sakila`.`country`
1 `sakila`.`payment_tmp`
1 `sakila`.`city`
1 `sakila`.`address`
Q3: Сколько запросов вставки / обновления / удаления выполнено для таблицы sakila.country?
./summarize_binlogs.sh | grep -i '`sakila`.`country`' | awk '{print $7 " " $11}' | sort -k1,2 | uniq -c
2 `sakila`.`country` DELETE
1 `sakila`.`country` INSERT
Q4: Дайте мне 3 верхних оператора, которые повлияли на максимальное количество строк.
./summarize_binlogs.sh | grep Table | sort -nr -k 12 | head -n 3 Timestamp : #150116 13:42:13 Table : `sakila`.`payment_tmp` Query Type : INSERT 16049 row(s) affected Timestamp : #150116 13:42:28 Table : `sakila`.`payment_tmp` Query Type : UPDATE 6890 row(s) affected Timestamp : #150116 13:42:20 Table : `sakila`.`payment_tmp` Query Type : DELETE 5001 row(s) affected
Посмотрите, как легко определить крупные транзакции.
Q5: Найти DELETE запросов, которые затронули более 1000 строк.
./summarize_binlogs.sh | grep -E 'DELETE' | awk '{if($12>1000) print $0}'
Timestamp : #150116 13:42:20 Table : `sakila`.`payment_tmp` Query Type : DELETE 5001 row(s) affected
Если мы хотим получить все запросы, которые затронули более 1000 строк.
./summarize_binlogs.sh | grep -E 'Table' | awk '{if($12>1000) print $0}'
Timestamp : #150116 13:42:13 Table : `sakila`.`payment_tmp` Query Type : INSERT 16049 row(s) affected
Timestamp : #150116 13:42:20 Table : `sakila`.`payment_tmp` Query Type : DELETE 5001 row(s) affected
Timestamp : #150116 13:42:28 Table : `sakila`.`payment_tmp` Query Type : UPDATE 6890 row(s) affected
Вывод
Информация, записанная в двоичные журналы, действительно полезна для понимания нашей рабочей нагрузки записи. Мы использовали mysqlbinlog + awk для представления содержимого двоичного журнала в более удобочитаемом формате. Далее мы использовали обобщенную информацию, чтобы ответить на некоторые важные вопросы.