MySQL Database Monitoring: Must, Good and Nice to Have

MySQL Database Monitoring:
Must, Good and Nice to Have
Sveta Smirnova
Principal Support Engineering Coordinator

• MySQL Support Engineer
• Author
MySQL Troubleshooting
MySQL Cookbook, 4th Edition
• JSON UDF functions
• FILTER clause for MySQL
• Speaker
• Percona Live, OOW, Fosdem,
DevConf, HighLoad...
Sveta Smirnova

• Solving Support cases
• Sometimes we cannot resolve the issue
because necessary information was not
collected in time
• Reasons are
• Lack of knowledge
• Fear of performance impact
• Let’s discuss what can help and for
which price!
Motivation
3
© Copyright 2023 Percona ® LLC. All rights reserved

must Should be always ON
Must-Good-Nice
4

good Useful data, little effect on overall
performance
Must-Good-Nice
5

good Useful data, little effect on overall
performance
nice May slow down database but very
useful in certain situations
Must-Good-Nice
6

2023-05-16T12:44:14.776227Z 0 [System] [MY-011323] [Server]
X Plugin ready for connections.
Bind-address: ’::’ port: 13020, socket: /tmp/mysqlx.1.sock
/home/sveta/Percona-Server-8.0.32-24/bin/mysqld: ready for connections.
Version: ’8.0.32-24’ socket: ’/tmp/mysqld.1.sock’ port: 13000
Percona Server (GPL), Release 24, Revision e5c6e9d2.
Error Log: Normal Operation
7

/Percona-Server-8.0.32-24/bin/mysqld (mysqld 8.0.32-24) starting as process 2006397
2023-05-16T21:01:34.103406Z 0 [Warning] [MY-010091] [Server] Can’t create test file
/Percona-Server-8.0.32-24/data/mysqld_tmp_file_case_insensitive_test.lower-test
2023-05-16T21:01:34.152150Z 0 [ERROR] [MY-010187] [Server] Could not open file
’/Percona-Server-8.0.32-24/data/Delly-7390.err’ for error logging: Permission denied
2023-05-16T21:01:34.152288Z 0 [ERROR] [MY-010119] [Server] Aborting
/Percona-Server-8.0.32-24/bin/mysqld: Shutdown complete (mysqld 8.0.32-24)
Percona Server (GPL), Release 24, Revision e5c6e9d2-debug.
Error Log: Immediate Answer
8

2023-05-17T00:06:38.658777Z 11 [ERROR] [MY-012639] [InnoDB] Write to file
./test/joinit7.ibd failed at offset 80740352, 1048576 bytes should have been written,
only 929792 were written. Operating system error number 28. Check that your OS and
file system support files of this size. Check also that the disk is not full or
a disk quota exceeded.
2023-05-17T00:06:38.658801Z 11 [ERROR] [MY-012640] [InnoDB] Error number 28 means
’No space left on device’
2023-05-17T00:06:38.658820Z 11 [Warning] [MY-012145] [InnoDB] Error while writing
4194304 zeroes to ./test/joinit7.ibd starting at offset 79691776
2023-05-17T00:06:38.669221Z 11 [ERROR] [MY-013132] [Server] The table ’joinit7’ is full
Error Log: Invisible Issue
9

2023-05-17T06:50:19.749143Z 0 [ERROR] InnoDB: Operating system error number 2 in a
file operation.
May 17 13:50:22 Delly mysqld[24814]: 2023-05-17T06:50:19.429496Z 0 [Note]
InnoDB: Apply batch completed
May 17 13:50:22 Delly mysqld[24814]: InnoDB: Progress in percent: 12 13 14 15 16 17
18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39
May 17 13:50:22 Delly mysqld[24814]: 2023-05-17T06:50:19.304439Z 0 [Note]
InnoDB: Starting an apply batch of log records to the database...
Error Log: "Unexpected" Corruption
10

• Always ON
• Keep outside of data directory
• Do not rotate too often
• MUST HAVE
Error Log: Best Practices
11

Database Performance Influencers
12

Database Performance Influencers
13

• Collects slow queries
Slow Query Log
15

• Tunable parameters
• long_query_time
• log_slow_admin_statements
• log_queries_not_using_indexes
• min_examined_row_limit
• log_slow_replica_statements
Slow Query Log
16

• Tunable parameters
• Tunable verbosity
log_slow_extra
log_slow_verbosity
Slow Query Log
17

# Time: 2023-05-17T11:08:23.065564Z
# User@Host: root[root] @ localhost [] Id: 29
# Schema: employees Last_errno: 0 Killed: 0
# Query_time: 0.003821 Lock_time: 0.000018 Rows_sent: 1 Rows_examined: 1
Rows_affected: 0 Bytess_sent: 187
SET timestamp=1684321703;
SELECT * FROM ‘departments‘ WHERE dept_no=’d003’;
Slow Query Log: minimal Verbosity
18

# Time: 2023-05-17T11:08:30.038499Z
Rows_affected: 0 Bytes
_sent: 187
# Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
Slow Query Log: standard Verbosity
19

# Time: 2023-05-17T11:08:36.662992Z
Rows_affected: 0 Bytes_sent: 187
# Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 0
# Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 1
Slow Query Log: full Verbosity
20

# Time: 2023-05-17T11:08:43.170370Z
Rows_affected: 0 Bytes_sent: 187
# Profile_starting: 0.000675 Profile_starting_cpu: 0.000405
Profile_Executing_hook_on_transaction_begin.: 0.000025
Profile_Executing_hook_on_transaction_begin._cpu: 0.000023
Profile_starting: 0.000046 Profile_starting_cpu: 0.000046
...
Profile_closing_tables_cpu: 0.000075 Profile_freeing_items: 0.000075
Profile_freeing_items_cpu: 0.000075 Profile_logging_slow_query: 0.000006
Profile_logging_slow_query_cpu: 0.000006
# Profile_total: 0.001829 Profile_total_cpu: 0.001556
Slow Query Log: profiling verbosity
21

# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ======= ===== ==============
# 1 0x61C2A843B38413D1 63.1758 99.9% 4 15.7939 1.81 SELECT titles
# 2 0x6B17FAAA0C13F2B4 0.0307 0.0% 11 0.0028 0.00 SELECT departments
# 3 0x90C659E5DE65EC22 0.0174 0.0% 1 0.0174 0.00 SELECT information_...
# 4 0xE3A3649C5FAC418D 0.0151 0.0% 21 0.0007 0.00 SELECT
# 5 0x02BBA8FDF2596F42 0.0121 0.0% 2 0.0060 0.01 SELECT departments
# MISC 0xMISC 0.0077 0.0% 13 0.0006 0.0 <4 ITEMS>
...
Slow Query Log by pt_query_digest
22

# Query 2: 0.00 QPS, 0.00x concurrency, ID 0x6B17FAAA0C13F2B4 at byte 20896111
# Scores: V/M = 0.00
# Time range: 2023-05-17T10:27:00 to 2023-05-17T11:08:43
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 21 11
# Exec time 0 31ms 1ms 10ms 3ms 4ms 2ms 2ms
# Lock time 52 324us 17us 64us 29us 40us 12us 23us
# Rows sent 12 10 0 1 0.91 0.99 0.29 0.99
...
# SHOW TABLE STATUS FROM ‘test‘ LIKE ’departments’G
# SHOW CREATE TABLE ‘test‘.‘departments‘G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT * FROM ‘departments‘ WHERE dept_no=’d003’G
Slow Query Log by pt_query_digest
23

• Can grow fast with long_query_time=0
• Does not depend on the database size
• Depends on the query activity
• Higher query rate - faster log growth
• Safe to use with comparatively low load
• For high load: plan log rotation
• NICE TO HAVE
Slow Query Log: Disk IO
24

• Statements events
• Prepared statements
• Statements digests
• Stages events
Performance Schema
25

• Examine more rows than return/change
• Use disk instead of memory
• Full table scan instead of index
• This is not full list!
Why statements are slow?
26

mysql> SELECT THREAD_ID TID, SUBSTR(SQL_TEXT, 1, 50) SQL_TEXT, ROWS_SENT RS,
-> ROWS_EXAMINED RE,CREATED_TMP_TABLES,NO_INDEX_USED,NO_GOOD_INDEX_USED
-> FROM performance_schema.events_statements_history
-> WHERE NO_INDEX_USED=1 OR NO_GOOD_INDEX_USED=1G
********************** 1. row **********************
TID: 10124
SQL_TEXT: select emp_no, first_name, last_name from employee
RS: 97750
RE: 397774
CREATED_TMP_TABLES: 0
NO_INDEX_USED: 1
NO_GOOD_INDEX_USED: 0
...
Which Queries Do Not Use Indexes?
27

• CREATED_TMP_DISK_TABLES
• CREATED_TMP_TABLES
• SELECT_FULL_JOIN
• SELECT_RANGE_CHECK
• SELECT_SCAN
• SORT_MERGE_PASSES
• SORT_SCAN
Important Field Names
30

mysql> select DIGEST, DIGEST_TEXT, COUNT_STAR, SUM_CREATED_TMP_DISK_TABLES,
-> SUM_SELECT_FULL_JOIN, SUM_SELECT_RANGE , SUM_SELECT_SCAN , SUM_NO_INDEX_USED,
-> SUM_ROWS_SENT, SUM_ROWS_EXAMINED
-> from events_statements_summary_by_digest where SUM_NO_INDEX_USED > 0G
*************************** 1. row ***************************
DIGEST: 3884185b07312b354c4918f2368d8fe2c431aeb8e39bf8ff5c3dcc6837
DIGEST_TEXT: SELECT ‘c‘ FROM ‘sbtest1‘ WHERE ‘id‘ BETWEEN ? AND ?
COUNT_STAR: 1501791
SUM_CREATED_TMP_DISK_TABLES: 0
SUM_SELECT_FULL_JOIN: 0
SUM_SELECT_RANGE: 1501840
SUM_SELECT_SCAN: 4
SUM_NO_INDEX_USED: 4
SUM_ROWS_SENT: 150872400
SUM_ROWS_EXAMINED: 152872000
...
Digests: Which Do Not Use Indexes?
31

• Combined statistics
• events_statements_summary_by_account_by_event_name
• events_statements_summary_by_host_by_event_name
• events_statements_summary_by_thread_by_event_name
• events_statements_summary_by_user_by_event_name
• events_statements_summary_global_by_event_name
5.7+: events_statements_summary_by_program
Digest Tables
32

• Histogram Summary
• events_statements_histogram_by_digest
• events_statements_histogram_global
• Do NOT mix with Optimizer histograms!
Digest Tables
33

• Histogram Summary
• events_statements_summary_by_digest
• SCHEMA_NAME
• DIGEST
• DIGEST_TEXT
8.0+: QUERY_SAMPLE_TEXT
Digest Tables
34

mysql> SELECT query, total_latency, no_index_used_count, rows_sent,
-> rows_examined
-> FROM sys.statements_with_full_table_scans
-> WHERE db=’employees’ AND query NOT LIKE ’%performance_schema%’G
********************** 1. row **********************
query: SELECT COUNT ( ‘emp_no‘ ) FROM ... ‘emp_no‘ ) WHERE ‘title‘ = ?
total_latency: 805.37 ms
no_index_used_count: 1
rows_sent: 1
rows_examined: 397774
...
sys: Which Do Not Use Indexes?
36

• statement_analysis
• statements_with_full_table_scans
• statements_with_runtimes_in_95th_percentile
• statements_with_sorting
• statements_with_temp_tables
• statements_with_errors_or_warnings
Important Views in sys Schema
37

• Contains current prepared statements
Table prepared_statements_instances
38

• Contains current prepared statements
• Statistics by
• Which thread owns the statement
• How many times executed
• Optimizer statistics, similar to
events_statements_*
Table prepared_statements_instances
39

• Instruments
statement/sql/prepare_sql
statement/sql/execute_sql
statement/com/Prepare
statement/com/Execute
Prepared Statements: configuration
40

• Instruments
• Consumers
• prepared_statements_instances
41

• Instruments
• Consumers
• Size
mysql> select @@performance_schema_max_prepared_statements_instancesG
*************************** 1. row ***************************
@@performance_schema_max_prepared_statements_instances: -1
1 row in set (0.00 sec)
42

mysql1> prepare stmt from ’select count(*) from employees where hire_date > ?’;
Query OK, 0 rows affected (0.00 sec)
Statement prepared
mysql1> set @hd=’1995-01-01’;
mysql1> execute stmt using @hd;
+----------+
| count(*) |
+----------+
| 34004 |
+----------+
Example: Prepared Statement
43

mysql1> prepare stmt from ’select count(*) from employees where hire_date > ?’;
Statement prepared
mysql1> set @hd=’1995-01-01’;
mysql1> execute stmt using @hd;
+----------+
| count(*) |
+----------+
| 34004 |
+----------+
• Try EXECUTE with different values
Example: Prepared Statement
44

mysql2> select statement_name, sql_text, owner_thread_id, count_reprepare,
-> count_execute, sum_timer_execute from prepared_statements_instancesG
*************************** 1. row ***************************
statement_name: stmt
sql_text: select count(*) from employees where hire_date > ?
owner_thread_id: 22
count_reprepare: 0
count_execute: 3
sum_timer_execute: 4156561368000
mysql1> drop prepare stmt;
mysql2> select * from prepared_statements_instancesG
Empty set (0.00 sec)
Example: diagnosis
45

• Instrumented instruction called
• Corresponding field updated
• Counter incremented
• Time recorded
• Query recorded
• ...
• More often you call instruction - higher
overhead!
How Performance Schema Works?
46

Performance Schema Impact
47

• Performance Schema triggers data
collection when hits event
• For statement instrumentation this
usually means once per statement
• Low impact
• GOOD TO HAVE
Statements Instrumentation: Impact
48

• events_stages_* tables
Statements Deep Dive
49

• Same information as in table
INFORMATION_SCHEMA.PROCESSLIST or SHOW
PROCESSLIST output
• init
• executing
• Opening tables
50

PROCESSLIST output
• init
• executing
• Opening tables
• Replacement for SHOW PROFILE
51

PROCESSLIST output
• init
• executing
• Opening tables
• Replacement for SHOW PROFILE
• Only server-level
• No storage engine information!
52

• Instruments
mysql> select name from setup_instruments where name like ’stage%’;
+----------------------------------------------------+
| name |
+----------------------------------------------------+
| stage/sql/After create |
| stage/sql/allocating local table |
| stage/sql/preparing for alter table |
| stage/sql/altering table |
| stage/sql/committing alter table to storage engine |
| stage/sql/Changing master |
| stage/sql/Checking master version |
...
• Enable those you want to examine
Stages: configuration
53

• Everything, related to temporary tables
• EVENT_NAME LIKE ’stage/sql/%tmp%’
• Everything, related to locks
• EVENT_NAME LIKE ’stage/sql/%lock%’
• Everything in state "Waiting for"
• EVENT_NAME LIKE ’stage/%/Waiting for%’
• Frequently met issues
Stages Shortcuts
55

• Everything, related to temporary tables
• Everything, related to locks
• Everything in state "Waiting for"
• Frequently met issues
• EVENT_NAME=’stage/sql/freeing items’
• EVENT_NAME=’stage/sql/Sending data’
• EVENT_NAME=’stage/sql/cleaning up’
• EVENT_NAME=’stage/sql/closing tables’
• EVENT_NAME=’stage/sql/end’
Stages Shortcuts
56

mysql> SELECT eshl.event_name, sql_text, eshl.timer_wait/1000000000000 w_s
-> FROM performance_schema.events_stages_history_long eshl
-> JOIN performance_schema.events_statements_history_long esthl
-> ON (eshl.nesting_event_id = esthl.event_id)
-> WHERE eshl.timer_wait > 1*10000000000G
*************************** 1. row ***************************
event_name: stage/sql/Sending data
sql_text: SELECT COUNT(emp_no) FROM employees JOIN salaries USING(emp_no)
WHERE hire_date=from_date
w_s: 0.8170
Stages: Which Run Critically Long?
57

• Calculated several times per query
• NICE TO HAVE
Stages Performance
58

• Graphical interface
• Query statistics
• EXPLAIN
• Everything you need to tune your
queries!
Query Analytics (QAN) in PMM
59

Example 1: QAN in PMM
60

61

62

63

64

65

• Uses either slow query log of
Performance Schema statement
digests
• Same performance impact as for the
slow query log or Performance Schema
statement digests
• Nice GUI
• GOOD TO HAVE
Query Analytics (QAN) in PMM
66

Transaction 1 Table Rows Transaction 2
Read 1 Read
2
Read 3
Read 4 Read
5 Read
6
Read 7 Read
Parallel Reads
68

Transaction 1 Table Rows Transaction 2
Write 1 Read
2
Read 3
Write 4 Write
5 Read
6
Read 7 Write
Parallel Writes
69

Transaction 1 Table Rows Transaction 2 MDL
Write 1 Read Conflict
2 Allowed
Read 3 Conflict
Write 4 Write Conflict
5 Read Conflict
6
Read 7 Write Conflict
Parallel DDL
70

• Table METADATA_LOCKS in Performance
Schema
MDL Diagnostics
71

Schema
• Which thread is waiting for a lock
MDL Diagnostics
72

Schema
• Which thread holds the lock
MDL Diagnostics
73

Schema
• Which thread holds the lock
• Not only for tables:
GLOBAL, SCHEMA, TABLE, FUNCTION, PROCEDURE, EVENT, COMMIT, USER LEVEL
LOCK, TABLESPACE
MDL Diagnostics
74

• Instruments
• wait/lock/metadata/sql/mdl
METADATA_LOCKS: configuration
75

• Instruments
• wait/lock/metadata/sql/mdl
• Consumers
• METADATA_LOCKS
METADATA_LOCKS: configuration
76

mysql> select processlist_id, object_type, lock_type, lock_status, source
-> from metadata_locks join threads on (owner_thread_id=thread_id)
-> where object_schema=’employees’ and object_name=’titles’G
*************************** 1. row ***************************
processlist_id: 4
object_type: TABLE
lock_type: EXCLUSIVE
lock_status: PENDING -- waits
source: mdl.cc:3263
*************************** 2. row ***************************
processlist_id: 5
object_type: TABLE
lock_type: SHARED_READ
lock_status: GRANTED -- holds
source: sql_parse.cc:5707
METADATA_LOCKS: example
77

• Approximately once per statement
• Almost no impact
• MUST HAVE
METADATA_LOCKS: impact
78

• Information about locks, held by engine
Table DATA_LOCKS
79

• Only for engines with own locking
models
Table DATA_LOCKS
80

models
• Currently only InnoDB
Table DATA_LOCKS
81

models
• Currently only InnoDB
• Replacement for I_S tables
• INNODB_LOCKS
• INNODB_LOCK_WAITS
Table DATA_LOCKS
82

• Which lock is held
*************************** 4. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 2408:0:393:2
ENGINE_TRANSACTION_ID: 2408
THREAD_ID: 34
OBJECT_SCHEMA: test
OBJECT_NAME: t
INDEX_NAME: PRIMARY
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: GRANTED
LOCK_DATA: 12345
Table DATA_LOCKS
83

• Which lock is requested
*************************** 2. row ***************************
ENGINE: INNODB
ENGINE_LOCK_ID: 2409:0:393:2
ENGINE_TRANSACTION_ID: 2409
THREAD_ID: 36
OBJECT_SCHEMA: test
OBJECT_NAME: t
INDEX_NAME: PRIMARY
LOCK_TYPE: RECORD
LOCK_MODE: X
LOCK_STATUS: WAITING
LOCK_DATA: 12345
Table DATA_LOCKS
84

• Which lock is requested
• Both record-level and table level
p_s> select * from data_locksG
*************************** 1. row ***************************
...
LOCK_TYPE: TABLE
LOCK_MODE: IX
LOCK_STATUS: GRANTED
LOCK_DATA: NULL
*************************** 2. row ***************************
...
LOCK_TYPE: RECORD
Table DATA_LOCKS
85

• Maps lock waits with granted locks
Table DATA_LOCK_WAITS
86

• Maps lock waits with granted locks
• Only granted blocking other
transactions
p_s> select ENGINE, ... from data_lock_waitsG
*************************** 1. row ***************************
ENGINE: INNODB
REQUESTING_ENGINE_LOCK_ID: 2409:0:393:2
REQUESTING_ENGINE_TRANSACTION_ID: 2409
REQUESTING_THREAD_ID: 36
BLOCKING_ENGINE_LOCK_ID: 2408:0:393:2
BLOCKING_ENGINE_TRANSACTION_ID: 2408
BLOCKING_THREAD_ID: 34
1 row in set (0,01 sec)
Table DATA_LOCK_WAITS
87

• Partition
• Subpartition
• Lock data
• Requesting and blocking thread id
New in DATA_LOCKS, missed in I_S
88

• View innodb_lock_waits
In sys Schema
89

• Takes additional information from
INFORMATION_SCHEMA.INNODB_TRX
In sys Schema
90

sys> select locked_table, ...
-> from innodb_lock_waitsG
*************************** 1. row ***************************
locked_table: ‘test‘.‘t‘ blocking_pid: 4
locked_index: PRIMARY blocking_query: NULL
locked_type: RECORD blocking_trx_rows_locked: 1
waiting_trx_rows_locked: 1 blocking_trx_rows_modified: 1
waiting_trx_rows_modified: 0 sql_kill_blocking_query: KILL QUERY 4
waiting_pid: 6 sql_kill_blocking_connection: KILL 4
waiting_query: UPDATE t SET f=’bar’ WHERE id=12345
In sys Schema
91

Unlike most Performance Schema data collection,
there are no instruments for controlling whether data lock
information is collected or system variables for controlling
data lock table sizes. The Performance Schema collects
information that is already available in the server, so there
is no memory or CPU overhead to generate this informa-
tion or need for parameters that control its collection.
MySQL User Reference Manual
• MUST HAVE
Data Locks: Impact
92

• All information about what is running
inside InnoDB
• Writes to file every 15 seconds
• Same information is available if run
SHOW ENGINE INNODB STATUS interactively
• Can generate a lot of data
• NICE TO HAVE
InnoDB Status File
93

• Table INNODB_METRICS in Information
Schema
• All information about what is running
inside InnoDB
• Same information can be found in
SHOW ENGINE INNODB STATUS
• Easier to process
• NICE TO HAVE
INNODB_METRICS: InnoDB Monitor
94

• Logs all deadlocks into the file
• Latest deadlock is visible in the
SHOW ENGINE INNODB STATUS
• Useful when debugging frequent
deadlocks
• NICE TO HAVE
InnoDB Deadlock Logger
95

• Memory, used by internal mysqld
structures
Memory Diagnostic in P_S
97

structures
• Aggregated by
• Global
• Thread
• Account
• Host
• User
98

structures
• Aggregated by
• Global
• Thread
• Account
• Host
• User
• Nice views in sys schema
99

MySQL Database Monitoring: Must, Good and Nice to Have

MySQL Database Monitoring: Must, Good and Nice to Have

More Related Content

What's hot

Similar to MySQL Database Monitoring: Must, Good and Nice to Have

More from Sveta Smirnova

Recently uploaded

MySQL Database Monitoring: Must, Good and Nice to Have