empower my sql server administration with 5.7 instruments
TRANSCRIPT
Empower MySQL administration with 5.7 Intruments
A Beginner guide (?)
Marco “The Grinch” Tusa
2015
About me Marco “The Grinch”• Former UN, MySQL AB, Pythian,
Percona•2 kids, 1 wife• History of Religions;
Ski; Snowboard; Scuba Diving;
My MottoUse the Right Tool for the Job
Why you are here
• You want to understand what PS is
• You know what it is, but want to know a bit more
• You’d like to grill the speaker with some nasty
questions about it (wait for the end!)
Agenda• General definition• Implementation• Filtering• Performance impact• Tracing an ALTER
TABLE
• Get help from Sys schema
• How to use it and dig• Memory utilization• Replication• Command reference
and Steps
Performance Schema - what is it?
? ? ?? ? ? ? ? ?? ? ? ? ?? ? ? ?? ?? ?? ?
Assumption, notes & facts• Based on MySQL 5.7.6• Many difference with previous versions (parameters name and not
only)• Full presentation is > 100 slides (no worries those are for your
reference). • Tests done using multiple Application nodes
– Write (Primary tables 372 bytes, secondary tables 46K)– Reads on Primary (int,Date) & Secondary (int or Varchar)– Some reads on purpose doing table scan
– Deletes by range on int (PK)
Performance Schema - what is it?The PERFORMANCE_SCHEMA is a way to introspect the
internal execution of the server at runtime.
The performance schema focuses primarily on performance data, as opposed to the INFORMATION_SCHEMA whose purpose is to inspect metadata.
Performance Schema – User point of view
From a user point of view, the performance schema consists of:
–dedicated database schema, named PERFORMANCE_SCHEMA,–SQL tables, used to query the server internal state or change configuration settings
PSchema – Internal implementation
From an implementation point of view, the performance
schema is a dedicated Storage Engine which exposes
data collected by 'Instrumentation Points' placed in the
server code.
PSchema interfacesThe performance schema exposes many different interfaces, for different components, and for different purposes:•Instrument interface (is a coding interface provided by implementors)•Compiling interface •Server startup interface•Server bootstrap interface•Runtime configuration interface•Internal audit interface•Query interface
PSchema design principles The primary goal of the performance schema is to measure (instrument) the execution of the server.• The parser is unchanged.• Instrumentation points return "void", no error returned• No dynamic memory allocation, all at start-up• The instrumentation point should not cause thread scheduling
PSchema design principles cont. Low or zero impact while collecting information
• No performance hit (priority to collect faster, pushing complexity to
data retrieval)
• Non intrusive instrumentation (easy to be implemented by
developers)
• Easy deployment (support multiple versions of the instrumentation
interface, and ensure binary compatibility with each version)
PS Runtime Configuration Interface This is the place where we decide what can run• Use standard SQL to define what to use• List of table use to setup
– setup_actors (Identify the threads to monitor by user & host)
– setup_consumers (Receiving tables in PS; query by SQL)
– setup_instruments (Detailed list of instruments)– setup_objects (Used to include/exclude schemas/objects from
monitor)– setup_timers (Define what timer is used for events)
Consumer VS Instrument• Consumers are in short where the information will be
– events_statements_current
(Show tables in PS)• Instruments are the collectors
– statement/sql/select
select * from setup_instruments where name like 'statement/sql/sele%';
Pre-filtering VS Post-filtering• Pre-filtering refer to the possibility to perform selective
monitoring, before storing the information• Post-filtering is perform after data collection, excluding
the undesired data. Mainly using SQL statements:SELECT THREAD_ID, NUMBER_OF_BYTES FROM events_waits_history WHERE EVENT_NAME LIKE 'wait/io/file/%' AND NUMBER_OF_BYTES IS NOT NULL;
• Pre-filtering more efficient, but you need to know what you are looking for, in advance.
Pre-filtering• Pre-filtering
– Choose only the instruments you really need– Choose only the object you are interested in– Filter by user(s)– Filter by Consumer (events_statements_current)
Post-filtering• Post-filtering
– SQL query
– You can create queries using joins cross
performance_schema tables
– Information_schema tables can help you to identify
thread/user
PS Performance impact• In MySQL 5.6 we had between 10-30% (reported by
others)• In MYSQL 5.7 I saw between 0.5-4% (tested by me)
– Couple of spikes at 18% considered anomaly• With BP hot less impact• Write operations less impact• Wait instruments higher impact
Real exampleMonitor activities from one application user coming from different application servers.• Set the actor• Monitor first SQL CRUD • Choose the history level (Consumers)• Then dig more
PS Monitor a specific user• Add user • insert into setup_actors values('%',stress','%','YES');• [performance_schema]>select * from setup_actors;+------+--------+------+---------+| HOST | USER | ROLE | ENABLED |+------+--------+------+---------+| % | % | % | NO || % | stress | % | YES |+------+--------+------+---------+
* Bug 76428 (Oracle says is not a bug, I do not agree)
PS Monitor only SQL CRUD• Set the instruments
update setup_instruments set ENABLED='YES' where NAME='statement/sql/select|update|insert|delete';
select * from setup_instruments where ENABLED='YES';+----------------------+---------+-------+| NAME | ENABLED | TIMED |+----------------------+---------+-------+| statement/sql/select | YES | YES || statement/sql/update | YES | YES || statement/sql/insert | YES | YES || statement/sql/delete | YES | YES |+----------------------+---------+-------+
Check what is going onSELECT TH.PROCESSLIST_USER,ISPL.HOST,ISPL.DB,ISPL.User, TH.PROCESSLIST_ID, ESH.*
from information_schema.processlist ISPL
JOIN threads TH on ISPL.ID=TH.PROCESSLIST_ID
JOIN events_statements_history ESH ON TH.THREAD_ID=ESH.THREAD_ID
Where ISPL.User='stress'
AND (EVENT_NAME like '%select%' OR EVENT_NAME like '%insert%' OR EVENT_NAME like '%update%' OR EVENT_NAME like '%delete%')
Results PROCESSLIST_USER: stress
HOST: 10.0.0.151:53644
DB: test
User: stress
PROCESSLIST_ID: 54
THREAD_ID: 85
EVENT_ID: 20245
END_EVENT_ID: 20245
EVENT_NAME: statement/sql/delete
SOURCE: socket_connection.cc:98
TIMER_START: 7939401943217000
TIMER_END: 7939751199462000
TIMER_WAIT: 349256245000
LOCK_TIME: 63000000
SQL_TEXT: DELETE FROM tbtest4 where a between 2082189 and 2083189
DIGEST: ece618f657b2f637038cb7f72b1cfbf1
DIGEST_TEXT: DELETE FROM tbtest4 WHERE a BETWEEN ? AND ?
CURRENT_SCHEMA: test
OBJECT_TYPE: NULL
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: NULL
MYSQL_ERRNO: 0
RETURNED_SQLSTATE: 00000
MESSAGE_TEXT: NULL
ERRORS: 0
WARNINGS: 0
ROWS_AFFECTED: 23
ROWS_SENT: 0
ROWS_EXAMINED: 23
CREATED_TMP_DISK_TABLES: 0
CREATED_TMP_TABLES: 0
SELECT_FULL_JOIN: 0
SELECT_FULL_RANGE_JOIN: 0
SELECT_RANGE: 0
SELECT_RANGE_CHECK: 0
SELECT_SCAN: 0
SORT_MERGE_PASSES: 0
SORT_RANGE: 0
SORT_ROWS: 0
SORT_SCAN: 0
NO_INDEX_USED: 0
NO_GOOD_INDEX_USED: 0
NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
NESTING_EVENT_LEVEL: 0
I want to know more!Activate Stage tracing• Select the consumers
– update setup_consumers set ENABLED='YES' where name like 'events_stages_%';
• Select Instruments (all)– update setup_instruments set ENABLED='YES' , TIMED='YES'
where name like 'stage/sql/%';
Query the Stage Status• Current
– select ISPL.HOST,ISPL.DB,ISPL.User,ISPL.ID,ESH.*, SUBSTR(ISPL.Info,1,20) SQLT from information_schema.processlist ISPL JOIN threads TH on ISPL.ID=TH.PROCESSLIST_ID JOIN events_stages_current ESH ON TH.THREAD_ID=ESH.THREAD_ID Where ISPL.User='stress' and info is not null order by TIMER_START
• History– select ISPL.HOST,ISPL.DB,ISPL.User,ISPL.ID,ESH.*, SUBSTR(ISPL.Info,1,20) SQLT from
information_schema.processlist ISPL JOIN threads TH on ISPL.ID=TH.PROCESSLIST_ID JOIN events_stages_history ESH ON TH.THREAD_ID=ESH.THREAD_ID Where ISPL.User='stress' AND ID=52 and info is not null order by TIMER_START DES
• History Long– select ISPL.HOST,ISPL.DB,ISPL.User,ISPL.ID,ESH.*, SUBSTR(ISPL.Info,1,20) SQLT from
information_schema.processlist ISPL JOIN threads TH on ISPL.ID=TH.PROCESSLIST_ID JOIN events_stages_history_long ESH ON TH.THREAD_ID=ESH.THREAD_ID Where ISPL.User='stress' AND ID=52 and info is not null order by TIMER_START DESC LIMIT 50;
Stage Status - Current• I KNOW you cannot read it on the screen!
• There is a Session with ID 90 and I will filter using it
Stage Status - History• Same thing I know is small
• I can see all the operations done during the execution and the time taken
Stage Status – History Long• I can compare different executions
• Something to investigate; WHY event ID 16142 takes so long?
• BTW Query cache was disabled!?!? (size 0; mode on!!!)
PS Summary tables
• Summary tables are automatic generated by PS
• You can reset the values with TRUNCATE
• Select query and group by
• Organized by Categories:
– Event Wait, Stage, Statement, Transaction, Object Wait, File I/O,
Table I/O and Lock Wait, Connection,Socket, Memory
How to trace an Alter on a table?• Enable the Instruments to monitor
InnoDB Alter– update setup_instruments set
ENABLED='YES', TIMED='YES' where name like 'stage/innodb/alter%';
• Using WORK_COMPLETED | WORK_ESTIMATED– Status of the operation
HOST: localhost DB: test User: stress ID: 4081 THREAD_ID: 4111 EVENT_ID: 1731 END_EVENT_ID: NULL EVENT_NAME: stage/innodb/alter table (read PK and internal sort) SOURCE: ut0stage.h:241 TIMER_START: 851457100596885000 TIMER_END: NULL TIMER_WAIT: NULL WORK_COMPLETED: 88749 WORK_ESTIMATED: 2214165 NESTING_EVENT_ID: 1594NESTING_EVENT_TYPE: STATEMENT SQLT: alter table tbtest1
Using SYS schema to query PSSYS schema is a convenient way to manage and parse the Performance schema.• Views
– Two versions (pretty print, command usable)• Store Procedure
– Manage the instruments/consumers– Manage configuration– Show histograms
SYS schema setup 1Clean start.• Reset all to defaults
– call sys.ps_setup_reset_to_default(1)*• Set actors
– insert into setup_actors values('%','root','%',NO');– insert into setup_actors values('%','stress','%','YES');
* Given a difference 5.6/5.7 the procedure need a fix to accommodate the additional attribute “ENABLED” in 5.7 (line 20 of the SP)
SYS schema setup 2• Set Consumers
– call sys.ps_setup_disable_consumers(‘%’)
– call sys.ps_setup_enable_consumers('global')
– call sys.ps_setup_enable_consumers('state')
– call sys.ps_setup_enable_consumers('stage')
• Set Instruments– call sys.ps_setup_disable_instrument('%');
– call sys.ps_setup_enable_instrument('statement/');
– call sys.ps_setup_enable_instrument('stage/');
SYS schema setup 3• To verify:
– call sys.ps_setup_show_disabled(0,1); (first instruments, second consumers)
– call sys.ps_setup_show_enabled(1,1); (first instruments, second consumers)
• Reset any information previously stored– call sys.ps_truncate_all_tables(1);
• Save our state– call sys.ps_setup_save(1);
SYS server overviewTo verify: call sys.ps_statement_avg_latency_histogram()\GPerformance Schema Statement Digest Average Latency Histogram:
. = 1 unit * = 2 units # = 3 units
(0 - 83903ms) 145 | ################################################(83903 - 167806ms) 4 | ....(167806 - 251708ms) 0 | (251708 - 335611ms) 0 | (335611 - 419514ms) 0 | (419514 - 503417ms) 0 | (503417 - 587320ms) 0 | (587320 - 671222ms) 0 | (671222 - 755125ms) 0 | (755125 - 839028ms) 0 | (839028 - 922931ms) 0 | (922931 - 1006834ms) 0 | (1006834 - 1090736ms) 0 | (1090736 - 1174639ms) 0 | (1174639 - 1258542ms) 0 | (1258542 - 1342445ms) 1 | .
Total Statements: 151; Buckets: 16; Bucket Size: 83903 ms;
How sys schema organize data• Initial review/Overview• User review• Statement• InnoDB Buffer Pool (from Information Schema)• I/O• Waits• Memory usage
Example how to dig • Which is the most expensive operation on my server?
– Who is doing what– From where– Where is costing more– How much memory is taking
Who is doing what?Using:select * from sys.x$host_summary_by_statement_latency where max_latency > 0;| host | total | total_latency | max_latency | lock_latency | rows_sent | rows_examined | rows_affected | full_scans |+--------------+----------+----------------------+--------------------+------------------+-----------+---------------+---------------+------------+| 10.0.0.153 | 3540524 | 27658534864398068384 | 7574715779257000 | 567306099000000 | 113508806 | 283506393702 | 26396594 | 510331 || 10.0.0.151 | 32963074 | 13892931298629665000 | 5326814750390000 | 1322101732000000 | 162953871 | 147355803 | 57977303 | 410706 || 10.0.0.152 | 1141135 | 9414853354124562000 | 6580206516327000 | 183363968000000 | 140876442 | 34664668021 | 3971379 | 484817 || 10.0.0.13 | 1 | 439140856048176000 | 439140856048176000 | 0 | 0 | 0 | 0 | 0 || localhost | 681 | 1305286713760000 | 1305225252156000 | 25516000000 | 805 | 794 | 0 | 22 || 192.168.51.1 | 635 | 80742106000 | 9207681000 | 14236000000 | 250 | 250 | 0 | 39 |
•All have full table scan and not using properly the index•10.0.0.153 is heavy in read, but doing also modification•10.0.0.151 is mainly inserting•10.0.0.152 is mainly doing reads
From where?Using:select *, total_latency/total as latency_by_operation from sys.x$host_summary_by_stages where host like '10%' order by 6 desc limit 10;
| host | event_name | total | total_latency | avg_latency | latency_by_operation |+------------+------------------------------------------+---------+----------------------+----------------+----------------------+| 10.0.0.153 | stage/sql/updating | 373841 | 9417613923098048000 | 25191495644000 | 25191495644132.2594 || 10.0.0.152 | stage/sql/updating | 100076 | 2141666904448883000 | 21400404736000 | 21400404736888.7945 || 10.0.0.153 | stage/sql/update | 1545766 | 15976559090187292000 | 10335690583000 | 10335690583301.2836 || 10.0.0.152 | stage/sql/Sending data | 486611 | 4684747633406580000 | 9627294971000 | 9627294971561.6375 || 10.0.0.152 | stage/sql/update | 270936 | 2387151366604427000 | 8810757398000 | 8810757398811.6271 || 10.0.0.153 | stage/sql/Sending data | 510331 | 1661917815254503384 | 39403175368000 | 3256548818814.6583 || 10.0.0.151 | stage/sql/update | 3612146 | 7780662705903419000 | 2154027745000 | 2154027745806.3486 || 10.0.0.12 | stage/sql/Finished reading one binlog; | 69 | 126037850052000 | 1826635508000 | 1826635508000.0000 || 10.0.0.151 | stage/sql/updating | 6583069 | 5268439570669058000 | 800301435000 | 800301435495.9758 || 10.0.0.151 | stage/sql/Waiting for table metadata lock| 4 | 2829687324000 | 707421831000 | 707421831000.0000 |
•153 has high single cost while updating & highest total for update•152 has high cost updating but highest total operation cost is in sending data •151 has high total cost for I/O update & updating, also had some wait for meta lock
Thread states page: https://dev.mysql.com/doc/refman/5.7/en/general-thread-states.html
Where is impacting ?Using:select *, (total_latency/total) as latency_by_operation from sys.x$host_summary_by_file_io_type where host like '10%' order by latency_by_operation desc;
| host | event_name | total | total_latency | max_latency | latency_by_operation |+------------+--------------------------------------+-----------+--------------------+---------------+----------------------+| 10.0.0.151 | wait/io/file/innodb/innodb_data_file | 776100 | 9582044272560474 | 6226320185448 | 12346404165.1340 | | 10.0.0.151 | wait/io/file/innodb/innodb_temp_file | 112 | 388246889580 | 99534426684 | 3466490085.5357 | | 10.0.0.153 | wait/io/file/innodb/innodb_data_file | 351676912 | 711163409370582234 | 6365399988684 | 2022206704.8023 || 10.0.0.152 | wait/io/file/innodb/innodb_data_file | 330710179 | 539289583380376642 | 4121174421936 | 1630701495.2218 || 10.0.0.153 | wait/io/file/innodb/innodb_log_file | 678192 | 513123805486446 | 1163658308736 | 756605512.1359 || 10.0.0.152 | wait/io/file/innodb/innodb_log_file | 146807 | 82666645908550 | 993199821504 | 563097440.2348 || 10.0.0.151 | wait/io/file/innodb/innodb_log_file | 3885743 | 1662189534588572 | 2833756738956 | 427766204.4527 || 10.0.0.151 | wait/io/file/sql/binlog | 17036307 | 3722712064636598 | 1535483100228 | 218516375.9162 || 10.0.0.153 | wait/io/file/sql/binlog | 3261695 | 423989529054168 | 2164527273216 | 129990550.6352 || 10.0.0.152 | wait/io/file/sql/binlog | 670508 | 76017536064668 | 357572959854 | 113373048.5910 || 10.0.0.152 | wait/io/file/sql/binlog_index | 104 | 2626007670 | 518135244 | 25250073.7500 || 10.0.0.153 | wait/io/file/sql/binlog_index | 480 | 11682807400 | 1663049784 | 24339182.0833 || 10.0.0.151 | wait/io/file/sql/binlog_index | 811 | 9991732806 | 491726004 | 12320262.3995 || 10.0.0.12 | wait/io/file/sql/binlog | 11193441 | 111323484843142 | 789132285876 | 9945421.1483 || 10.0.0.151 | wait/io/file/sql/FRM | 854 | 6969832320 | 419982156 | 8161396.1593 || 10.0.0.13 | wait/io/file/sql/binlog | 27206 | 218796687318 | 16329710892 | 8042221.8378 || 10.0.0.151 | wait/io/file/archive/data | 11 | 29007528 | 3526248 | 2637048.0000 |
•151 has high single cost on data files & temp file & Ib_log•153 has highest total cost for I/O in data file operations•152 has high total cost for I/O in data file operations
Add a viewI want to analyze by statement type and host.CREATE ALGORITHM = MERGE DEFINER = `root`@`localhost` SQL SECURITY INVOKERVIEW `sys`.`x$statement_analysis_by_host` AS
select EVENT_NAME as event ,COUNT_STAR as exec_count,SUM_TIMER_WAIT as total_latency ,AVG_TIMER_WAIT as avg_latency ,SUM_LOCK_TIME as lock_latency ,SUM_ROWS_AFFECTED as changed_rows ,SUM_ROWS_SENT as sent_rows ,SUM_ROWS_EXAMINED as examined_rows,SUM_CREATED_TMP_DISK_TABLES as tmp_table_on_disk,SUM_CREATED_TMP_TABLES as tmp_table,SUM_SELECT_FULL_JOIN as join_scan,
SUM_SELECT_FULL_JOIN as join_scan,SUM_SELECT_FULL_RANGE_JOIN as join_range,SUM_SELECT_RANGE_CHECK as join_select_check,SUM_SELECT_SCAN as join_full_scan,SUM_SORT_MERGE_PASSES as sort_passes,SUM_SORT_SCAN as sort_scan,SUM_NO_INDEX_USED as no_index_used,SUM_NO_GOOD_INDEX_USED as no_good_indexfromevents_statements_summary_by_host_by_event_name where COUNT_STAR > 0 order by avg_latency
Dig moreWill focus on what is going on, on 10.0.0.153select * from sys.x$statement_analysis_by_host where host='10.0.0.153' limit 3\G
********* 1. row ****** host: 10.0.0.153 event: statement/sql/delete exec_count: 373841 total_latency: 9417687022882291000 avg_latency: 25191691181000 lock_latency: 24799309000000 changed_rows: 6122 sent_rows: 0 examined_rows: 7687tmp_table_on_disk: 0 tmp_table: 0 join_scan: 0 join_range: 0join_select_check: 0 join_full_scan: 0 sort_passes: 0 sort_scan: 0 no_index_used: 0 no_good_index: 0
********* 2. row ****** host: 10.0.0.153 event: statement/sql/insert exec_count: 772883 total_latency: 15977270617320760000 avg_latency: 20672301780000 lock_latency: 423512793000000 changed_rows: 26390472 sent_rows: 0 examined_rows: 0tmp_table_on_disk: 0 tmp_table: 0 join_scan: 0 join_range: 0join_select_check: 0 join_full_scan: 0 sort_passes: 0 sort_scan: 0 no_index_used: 0 no_good_index: 0
********* 3. row ****** host: 10.0.0.153 event: statement/sql/select exec_count: 1274164 total_latency: 2260841894634764384 avg_latency: 16251900044000 lock_latency: 68707120000000 changed_rows: 0 sent_rows: 1078431 examined_rows: 283393955640tmp_table_on_disk: 0 tmp_table: 0 join_scan: 0 join_range: 0join_select_check: 0 join_full_scan: 195733 sort_passes: 0 sort_scan: 0 no_index_used: 195733 no_good_index: 0
Dig more (queries)Will focus on what is going on, on 10.0.0.153select * from sys.x$statement_analysis order by total_latency desc limit 10 \G
********* 1. row ******query: DELETE FROM tbtest1 WHERE a BETWEEN ? AND ? db: test full_scan: exec_count: 1476041total_latency: 7618840631251163000 max_latency: 2141828209362000 avg_latency: 5161672766000 lock_latency: 78640125000000 rows_sent: 0 rows_examined: 26761 rows_affected: 21495 tmp_tables: 0 tmp_disk_tables: 0 rows_sorted: 0sort_merge_passes: 0
********* 2. row ****** query: SELECT tbtest3 …- ? - ? LIMIT ? db: test full_scan: * exec_count: 71828 total_latency: 6219726371992349000 max_latency: 3200860074610000 avg_latency: 86591947040000 lock_latency: 19742168000000 rows_sent: 0 rows_sent_avg: 0 rows_examined: 79995071105rows_examined_avg: 1113703 rows_affected: 0rows_affected_avg: 0 tmp_tables: 0 tmp_disk_tables: 0 rows_sorted: 0sort_merge_passes: 0
********* 6. row ******query: INSERT INTO tbtest1 .... db: test full_scan: exec_count: 342374 total_latency: 4722320670153881000 max_latency: 1458059844761000 avg_latency: 13792871743000 lock_latency: 341116537000000 rows_sent: 0 rows_sent_avg: 0 rows_examined: 0rows_examined_avg: 0 rows_affected: 17457402rows_affected_avg: 51 tmp_tables: 0 tmp_disk_tables: 0 rows_sorted: 0sort_merge_passes: 0
Find waitsI want to find waits, for the threads running from 10.0.0.153 and doing a DELETE operation.•Use PS tables
–events_waits_history–events_stages_history_long –events_statements_history_long–Threads
•Connect the events using NESTING_EVENT_ID
Find waits (query) – hide?SELECT PROCESSLIST_ID,ewh.THREAD_ID,ewh.EVENT_NAME,ewh.SOURCE, sum(ewh.TIMER_WAIT)/1000000000 asWait_ms, ewh.OBJECT_SCHEMA, ewh.OBJECT_NAME, ewh.OBJECT_TYPE, ewh.OPERATION
from events_waits_history ewh
Join events_stages_history_long esth ON ewh.NESTING_EVENT_ID = esth.EVENT_ID
Join events_statements_history_long esh ON esth.NESTING_EVENT_ID =esh.EVENT_ID
Join threads th ON ewh.THREAD_ID = th.THREAD_ID
where PROCESSLIST_HOST like '10.%'
group by EVENT_NAME,PROCESSLIST_ID,ewh.THREAD_ID,ewh.EVENT_NAME,ewh.SOURCE, ewh.OBJECT_SCHEMA, ewh.OBJECT_NAME, ewh.OBJECT_TYPE, ewh.OPERATION
order by ewh.TIMER_WAIT desc limit 50
Finds Waits (results)+---------+-------------------------------------------+-----------------+----------+----------------+-----------+---------------+|THREAD_ID|EVENT_NAME |SOURCE |TWait_ms |OBJECT_NAME |OBJECT_TYPE|OPERATION |+---------+-------------------------------------------+-----------------+----------+----------------+-----------+---------------+| 5053|wait/io/table/sql/handler |handler.cc:2684 |92056.5514|tbtest3 |TABLE |fetch || 5082|wait/io/file/sql/binlog |mf_iocache.c:1538| 0.4015|/binlog.000537 |FILE |write || 5131|wait/io/socket/sql/client_connection |viosocket.c:123 | 0.1717|10.0.0.153:57280|SOCKET |recv || 5131|wait/lock/table/sql/handler |handler.cc:7359 | 0.0080|tbtest2 |TABLE |write external || 5116|wait/synch/mutex/sql/THD::LOCK_query_plan |sql_class.cc:4628| 0.0056|NULL |NULL |lock || 5116|wait/synch/mutex/sql/THD::LOCK_thd_data |sql_class.h:3931 | 0.0044|NULL |NULL |lock || 5116|wait/synch/mutex/sql/THD::LOCK_thd_query |sql_class.cc:4403| 0.0023|NULL |NULL |lock || 5131|wait/synch/sxlock/innodb/index_tree_rw_lock|btr0cur.cc:997 | 0.0005|NULL |NULL |shared_lock || 5131|wait/synch/mutex/innodb/trx_mutex |trx0trx.h:1465 | 0.0005|NULL |NULL |lock |+---------+-------------------------------------------+-----------------+----------+----------------+-----------+---------------+
•Handler (handler::ha_index_read_map)•Binlog (mf_iocache my_b_flush_io_cache) ~5k IOPS 80% R•Handler (ha_external_lock for get_auto_increment() )
Check from a different point oviewWhat is globally impacting (wait wise)SELECT * FROM X$WAITS_GLOBAL_BY_LATENCY LIMIT 10;+---------------------------------------------+--------------+---------------------+-------------+------------------+| events | total | total_latency | avg_latency | max_latency |+---------------------------------------------+--------------+---------------------+-------------+------------------+| wait/io/table/sql/handler | 342361426614 | 3161103906035857146 | 224756510 | 2500749275685276 || wait/io/file/innodb/innodb_data_file | 1088581278 | 1842175247375114168 | 1692271328 | 6365399988684 || wait/io/file/innodb/innodb_log_file | 5854916 | 5020821707657712 | 857539122 | 3847054242900 || wait/io/file/sql/binlog | 32327316 | 4349218352498492 | 134536644 | 2164527273216 || wait/io/socket/sql/client_connection | 90526125 | 1518288976010884 | 16771832 | 328431026880 || wait/synch/sxlock/innodb/index_tree_rw_lock | 312878257 | 1019600508298130 | 3258728 | 3287452194642 || wait/io/file/innodb/innodb_temp_file | 11492 | 439096054593504 | 38208845378 | 1986035621856 || wait/lock/table/sql/handler | 11321841 | 22348126302238 | 1973796 | 4859263794 || wait/synch/mutex/sql/THD::LOCK_query_plan | 151886514 | 19710505985302 | 129580 | 4591687782 || wait/synch/mutex/sql/THD::LOCK_thd_data | 60756333 | 14994231372560 | 246620 | 7748871042 |+---------------------------------------------+--------------+---------------------+-------------+------------------+
• Handler ?? On what?
Dig inside the Events wait (handler)select ewh.EVENT_NAME,ewh.SOURCE,sum(ewh.TIMER_WAIT)/1000000000 as TWait_ms,ewh.OBJECT_NAME,ewh.OBJECT_TYPE,ewh.OPERATION from events_waits_history ewh Join threads th on ewh.THREAD_ID = th.THREAD_ID where EVENT_NAME like '%handler%' group by EVENT_NAME,ewh.SOURCE,ewh.OBJECT_NAME,ewh.OBJECT_TYPE,ewh.OPERATION order by TWait_ms desc limit 10;| EVENT_NAME | SOURCE | TWait_ms | OBJECT_NAME | OBJECT_TYPE | OPERATION || wait/io/table/sql/handler | handler.cc:2837 | 6534232.2868 | tbtest1 | TABLE | fetch || wait/io/table/sql/handler | handler.cc:2684 | 4321099.7060 | tbtest1 | TABLE | fetch || wait/io/table/sql/handler | handler.cc:7442 | 2266974.4749 | tbtest_child1 | TABLE | insert || wait/io/table/sql/handler | handler.cc:7442 | 1848697.1140 | tbtest_child2 | TABLE | insert || wait/io/table/sql/handler | handler.cc:7442 | 1612219.8075 | tbtest_child4 | TABLE | insert || wait/io/table/sql/handler | handler.cc:7442 | 1516154.9357 | tbtest_child5 | TABLE | insert || wait/io/table/sql/handler | handler.cc:7442 | 1006817.2949 | tbtest_child3 | TABLE | insert || wait/io/table/sql/handler | handler.cc:2753 | 184560.4405 | tbtest1 | TABLE | fetch || wait/io/table/sql/handler | handler.cc:7442 | 205.4325 | tbtest4 | TABLE | insert || wait/io/table/sql/handler | handler.cc:7442 | 175.4129 | tbtest1 | TABLE | insert |
• handler::ha_index_last• handler::ha_index_read_map• handler::ha_write_row (no surprise given Text field in the tables)
Dig inside the Events wait (handler) 2Example in Read only scenario| EVENT_NAME | SOURCE | TWait_ms | OBJECT_NAME | OBJECT_TYPE | OPERATION |+-----------------------------+-----------------+----------+---------------+-------------+---------------+| wait/io/table/sql/handler | handler.cc:2612 | 54.9236 | tbtest4 | TABLE | fetch || wait/io/table/sql/handler | handler.cc:2612 | 30.8319 | tbtest2 | TABLE | fetch || wait/io/table/sql/handler | handler.cc:2612 | 27.5169 | tbtest1 | TABLE | fetch || wait/io/table/sql/handler | handler.cc:2612 | 12.4204 | tbtest3 | TABLE | fetch || wait/lock/table/sql/handler | handler.cc:7359 | 0.0022 | tbtest2 | TABLE | read external || wait/lock/table/sql/handler | handler.cc:7359 | 0.0020 | tbtest1 | TABLE | read external || wait/lock/table/sql/handler | handler.cc:7359 | 0.0012 | tbtest_child1 | TABLE | read external |+-----------------------------+-----------------+----------+---------------+-------------+---------------+
• handler::ha_rnd_next• handler::ha_external_lock
Dig inside the Events wait (handler) 2Checking index_tree_rw_lock | EVENT_NAME | SOURCE | TWait_ms | | OPERATION |+---------------------------------------------+--------------------+----------+..+-----------------------+| wait/synch/sxlock/innodb/index_tree_rw_lock | dict0stats.cc:1920 | 0.0191 |..| shared_exclusive_lock || wait/synch/sxlock/innodb/index_tree_rw_lock | dict0stats.cc:2009 | 0.0025 |..| shared_exclusive_lock || wait/synch/sxlock/innodb/index_tree_rw_lock | btr0cur.cc:997 | 0.0017 |..| shared_lock || wait/synch/sxlock/innodb/index_tree_rw_lock | dict0stats.cc:1895 | 0.0003 |..| shared_lock |+---------------------------------------------+--------------------+----------+..+-----------------------+
• dict_stats_analyze_index (1920 & 2009) /** Lock an rw-lock in sx-mode. */• dict_stats_analyze_index (1895) /** Lock an rw-lock in s-mode. */
• handler::ha_external_lock (997) /** Lock an rw-lock in s-mode. */
Dig inside the Events wait (data file)select ewh.EVENT_NAME,ewh.SOURCE,sum(ewh.TIMER_WAIT)/1000000000 as TWait_ms,ewh.OBJECT_NAME,ewh.OBJECT_TYPE,ewh.OPERATION from events_waits_history ewh Join threads th on ewh.THREAD_ID = th.THREAD_ID where EVENT_NAME like '%innodb_data_file%' group by EVENT_NAME,ewh.SOURCE,ewh.OBJECT_NAME,ewh.OBJECT_TYPE,ewh.OPERATION order by TWait_ms desc limit 10;
| EVENT_NAME | SOURCE | TWait_ms | OBJECT_NAME | OBJECT_TYPE | OPERATION || innodb_data_file | fil0fil.cc:5128 | 1507.3954 | data/test/tbtest2.ibd | FILE | read || innodb_data_file | fil0fil.cc:5128 | 4228.5256 | data/test/tbtest4.ibd | FILE | read || innodb_data_file | fil0fil.cc:5128 | 906.8597 | data/test/tbtest1.ibd | FILE | read || innodb_data_file | fil0fil.cc:5128 | 875.7241 | data/test/tbtest3.ibd | FILE | read || innodb_data_file | fil0fil.cc:5128 | 800.1938 | data/test/tbtest5.ibd | FILE | read || innodb_data_file | fil0fil.cc:5128 | 471.1378 | data/ibdata1 | FILE | read || innodb_data_file | fil0fil.cc:5128 | 223.8774 | data/test/tbtest_child5.ibd | FILE | read || innodb_data_file | fil0fil.cc:5128 | 125.6467 | data/test/tbtest_child3.ibd | FILE | read || innodb_data_file | fil0fil.cc:5128 | 88.9138 | data/test/tbtest_child4.ibd | FILE | read || innodb_data_file | fil0fil.cc:5128 | 45.0886 | data/test/tbtest_child2.ibd | FILE | read |
All referring to Queue Async IO request
Using Digestcall sys.ps_trace_statement_digest('ea28940bf4bb5fd9aa1268e0e9dd6484',10, 0.9, 0, 0);
SUMMARY STATISTICS| executions | exec_time | lock_time | rows_sent | rows_affected | rows_examined | tmp_tables | full_scans | 234 | 13.23 h | 17.47 ms | 0 | 5 | 13 | 0 | 0
Stages| event_name | count | latency || stage/sql/updating | 14 | 42.40 m || stage/sql/starting | 10 | 1.02 ms || stage/sql/freeing items | 17 | 624.15 us || stage/sql/System lock | 7 | 528.10 us || stage/sql/end | 15 | 351.38 us || stage/sql/closing tables | 17 | 155.02 us || stage/sql/init | 8 | 139.60 us || stage/sql/Opening tables | 8 | 126.69 us || stage/sql/query end | 17 | 94.66 us || stage/sql/cleaning up | 16 | 34.22 us || stage/sql/checking permissions | 8 | 28.23 us || stage/sql/executing | 1 | 11.13 us || stage/sql/optimizing | 1 | 6.30 us |+--------------------------------+-------+-----------+
LONGEST RUNNING STATEMENTthread_id :5424 exec_time :28.11 mlock_time :81.00 usrows_sent :0rows_affected :0rows_examined :0tmp_tables :0full_scan :0
Wait by table and operationselect table_name,count_read,sum_timer_read,count_write,sum_timer_write,sum_timer_misc from x$ps_schema_table_statistics_io where count_read > 0 order by sum_timer_misc desc limit 10;+---------------+------------+--------------------+-------------+------------------+------------------+| table_name | count_read | sum_timer_read | count_write | sum_timer_write | sum_timer_misc || binlog | 11323892 | 163139996976308 | 11841548 | 307459297894408 | 3788322881789798 || ibdata1 | 128772 | 4258158556762616 | 2278000 | 2785324205349796 | 1259544814299640 || tbtest1 | 234589510 | 315279966332950080 | 10403104 | 406966920291206 | 246765147229150 || tbtest4 | 258521061 | 493310414097526278 | 10437042 | 410673354346948 | 239124000613652 || tbtest2 | 271610618 | 518366238483893778 | 10514402 | 400663975741590 | 236586775434724 || tbtest3 | 266652598 | 507970328316288904 | 10445230 | 393134473196278 | 235346859204446 || tbtest5 | 2753335 | 3946292748170630 | 10408304 | 384969226511474 | 224098676055694 || tbtest_child6 | 35022 | 845392798229298 | 172133 | 7241543257388 | 69054777297836 || tbtest_child3 | 35055 | 852721852233658 | 172336 | 9229856202182 | 66488959863458 || tbtest_child5 | 35203 | 834911893464088 | 172795 | 7701415791256 | 64662418280350 |
• Binlog impact• Ibdata (internal undo ..??)• As expected table space
Memory From 5.7 memory utilization is available• Account• Host• User• Global
Memory (account) Main consumer by Account
select thread_id,user,current_count_used,current_allocated,current_avg_alloc,total_allocated from x$memory_by_thread_by_current_bytes order by current_allocated desc limit 10;
| thread_id | user | current_count_used | current_allocated | current_avg_alloc | total_allocated | 26 | innodb/srv_purge_thread | 4572 | 4411780800 | 964956.4304 | 5731809118 | 29 | innodb/dict_stats_thread | 41388 | 24213528 | 585.0374 | 223637019 | 5362 | [email protected] | 56 | 10787522 | 192634.3214 | 193705857 | 5440 | [email protected] | 55 | 10783594 | 196065.3455 | 217683673 | 5337 | [email protected] | 52 | 10783450 | 207374.0385 | 236334335 | 5416 | [email protected] | 54 | 10783354 | 199691.7407 | 174439938 | 5370 | [email protected] | 58 | 10782576 | 185906.4828 | 214784845 | 5371 | [email protected] | 57 | 10782408 | 189165.0526 | 238437935 | 5351 | [email protected] | 57 | 10782280 | 189162.8070 | 232599540 | 5345 | [email protected] | 58 | 10782023 | 185896.9483 | 199472328
Memory (global) Main consumer by event
select event_name,current_count,current_alloc,high_count,high_alloc from x$memory_global_by_current_allocated where event_name not like '%performance_schema%' order by current_alloc desc limit 10;
+-------------------------------+---------------+---------------+------------+------------+| event_name | current_count | current_alloc | high_count | high_alloc |+-------------------------------+---------------+---------------+------------+------------+| memory/mysys/IO_CACHE | 876 | 1525287730 | 1162 | 1977776080 || memory/sql/thd::main_mem_root | 1210 | 16810704 | 4141 | 57437376 || memory/innodb/mem0mem | 10110 | 15927009 | 51239 | 351157290 || memory/innodb/lock0lock | 9166 | 14812256 | 9166 | 14812256 || memory/sql/TABLE | 3826 | 4444548 | 6768 | 13680166 || memory/sql/String::value | 683 | 3684040 | 3981 | 54023544 || memory/sql/NET::buff | 180 | 3294444 | 1174 | 19443738 || memory/innodb/trx0trx | 9166 | 2016520 | 9166 | 2016520 || memory/mysys/array_buffer | 923 | 1502688 | 5017 | 10117520 || memory/innodb/os0event | 9334 | 1344096 | 9354 | 1346976 |+-------------------------------+---------------+---------------+------------+------------+
Memory (PS utilization) select event_name,current_count,current_alloc,high_count,high_alloc from x$memory_global_by_current_allocated where event_name like '%performance_schema%' order by current_alloc desc limit 10;
+---------------------------------------------------------------------+---------------+---------------+------------+------------+| event_name | current_count | current_alloc | high_count | high_alloc |+---------------------------------------------------------------------+---------------+---------------+------------+------------+|performance_schema/events_statements_summary_by_thread_by_event_name | 2 | 17993728 | 138 | 1241567232 ||performance_schema/events_statements_history_long | 1 | 14160000 | 1 | 14160000 ||performance_schema/memory_summary_by_thread_by_event_name | 2 | 11796480 | 128 | 754974720 ||performance_schema/events_statements_history_long.tokens | 1 | 10240000 | 1 | 10240000 ||performance_schema/events_statements_history_long.sqltext | 1 | 10240000 | 1 | 10240000 ||performance_schema/events_statements_summary_by_digest.tokens | 1 | 10240000 | 1 | 10240000 ||performance_schema/table_handles | 1 | 9437184 | 1 | 9437184 ||performance_schema/events_statements_history | 2 | 7249920 | 108 | 391495680 ||performance_schema/events_statements_current | 2 | 7249920 | 96 | 347996160 ||performance_schema/events_waits_summary_by_thread_by_event_name | 2 | 6291456 | 146 | 459276288 |+---------------------------------------------------------------------+---------------+---------------+------------+------------+
Lock information• Meta locks
– From Performance schema• InnoDb lock waits
– From Information schema
Identify Meta-lockYou can get the meta-lock by current or history select THREAD_ID,EVENT_ID,EVENT_NAME,TIMER_WAIT, LOCK_DURATION,LOCK_TYPE,ml.SOURCE,OBJECT_SCHEMA,OBJECT_NAME from events_stages_history esh join metadata_locks ml on esh.EVENT_ID=ml.OWNER_EVENT_ID order by TIMER_WAIT desc limit 10;+-----------+--------------------+------------+---------------+--------------+-------------------+---------------+| THREAD_ID | EVENT_NAME | TIMER_WAIT | LOCK_DURATION | LOCK_TYPE | SOURCE | OBJECT_NAME |+-----------+--------------------+------------+---------------+--------------+-------------------+---------------+| 5332 | stage/sql/starting | 1423172000 | TRANSACTION | SHARED_WRITE | sql_parse.cc:5585 | tbtest_child3 || 5470 | stage/sql/starting | 167592000 | TRANSACTION | SHARED_READ | sql_parse.cc:5585 | tbtest2 || 5470 | stage/sql/starting | 167592000 | TRANSACTION | SHARED_READ | sql_parse.cc:5585 | tbtest4 || 5470 | stage/sql/starting | 167592000 | TRANSACTION | SHARED_READ | sql_parse.cc:5585 | tbtest4 || 5525 | stage/sql/starting | 121304000 | TRANSACTION | SHARED_READ | sql_parse.cc:5585 | tbtest_child1 || 5525 | stage/sql/starting | 121304000 | TRANSACTION | SHARED_READ | sql_parse.cc:5585 | tbtest1 || 5510 | stage/sql/starting | 114792000 | TRANSACTION | SHARED_READ | sql_parse.cc:5585 | tbtest_child1 || 5522 | stage/sql/starting | 107460000 | TRANSACTION | SHARED_READ | sql_parse.cc:5585 | tbtest_child1 || 5522 | stage/sql/starting | 107460000 | TRANSACTION | SHARED_READ | sql_parse.cc:5585 | tbtest_child1 || 5526 | stage/sql/starting | 104756000 | TRANSACTION | SHARED_READ | sql_parse.cc:5585 | tbtest4 |+-----------+--------------------+------------+---------------+--------------+-------------------+---------------+
Other Lock information from SYS• Meta locksOBJECT_TYPE: TABLE
OBJECT_SCHEMA: performance_schema
OBJECT_NAME: metadata_locks
OBJECT_INSTANCE_BEGIN: 140045498780240
LOCK_TYPE: SHARED_READ
LOCK_DURATION: TRANSACTION
LOCK_STATUS: GRANTED
SOURCE: sql_parse.cc:5585
OWNER_THREAD_ID: 6141
OWNER_EVENT_ID: 9
select * from metadata_locks\G
• InnoDb lock waitswait_started: 2015-04-06 10:26:21
wait_age: 00:00:47
locked_table: `test`.`tbtest1`
locked_index: PRIMARY
locked_type: RECORD
waiting_trx_id: 111008059
waiting_trx_started: 2015-04-06 10:26:21
waiting_trx_age: 00:00:47
waiting_trx_rows_locked: 1
waiting_trx_rows_modified: 0
waiting_pid: 6104
waiting_query: update test.tbtest1
set b ='aaaaaddaaaasa' where a <> 1582347553
select * from x$innodb_lock_waits\G
waiting_lock_id: 111008059:284:6:2
waiting_lock_mode: X
blocking_trx_id: 111008056
blocking_pid: 6078
blocking_query: NULL
blocking_lock_id: 111008056:284:6:2
blocking_lock_mode: X
blocking_trx_started: 2015-04-06 09:27:08
blocking_trx_age: 01:00:00
blocking_trx_rows_locked: 18048041
blocking_trx_rows_modified: 16450211
InnoDB Lock (example)select * from INNODB_LOCK_WAITS;| requesting_trx_id | requested_lock_id | blocking_trx_id | blocking_lock_id || 91459149 | 91459149:183:54275:439 | 91323715 | 91323715:183:54275:439 |
select * from INNODB_LOCKS;| lock_id | lock_trx_id | lock_mode | lock_type | lock_table | lock_index | 91465549:183:48232:264 | 91465549 | X,GAP | RECORD | `test`.`tbtest1` | IDX_a
select * from information_schema.INNODB_TRX where trx_id=91323715\Gtrx_id: 91323715trx_mysql_thread_id: 269
select * from processlist where id=269;| ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | 269 | root | localhost | test | Sleep | 397 | | NULL
PS Replication• Useful when multi-threaded slave operation• Group replication• Reports by applier / coordinator• Not really useful when using single replication• Just for fun run all of them:
– Show slave status\G– select * from replication_applier_configuration \G– select * from replication_applier_status \G– select * from replication_applier_status_by_coordinator \G– select * from replication_applier_status_by_worker \G– select * from replication_connection_configuration \G– select * from replication_connection_status \G– select * from replication_group_member_stats \G– select * from replication_group_members \G
PS Replication• Diagram from Oracle presentation
PS Replication (where my delay goes?)
• The show slave status reportMaster_Log_File: binlog.000538Read_Master_Log_Pos: 264094003Relay_Log_File: relay.001602Relay_Log_Pos: 145859792Relay_Master_Log_File: binlog.000538Slave_IO_Running: YesSlave_SQL_Running: YesSkip_Counter: 0Exec_Master_Log_Pos: 145859586Relay_Log_Space: 264094449Seconds_Behind_Master: 172Master_UUID: 706af0a0-bdf9-11e4-9efb-d4ae52e5d40cMaster_Info_File:
/home/mysql/mysql_instances/server57/data/master.info
SQL_Delay: 0SQL_Remaining_Delay: NULLSlave_SQL_Running_State: invalidating query cache
entries (table)
• The PS ??select * from replication_applier_status_by_coordinator CHANNEL_NAME: THREAD_ID: 32 SQL ThreadSERVICE_STATE: ONLAST_ERROR_NUMBER: 0LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00---------------------------------------------------select * from replication_connection_status CHANNEL_NAME: GROUP_NAME: SOURCE_UUID: 706af0a0-bdf9-11e4-9efb-d4ae52e5d40cTHREAD_ID: 31 IO ThreadSERVICE_STATE: ONCOUNT_RECEIVED_HEARTBEATS: 669LAST_HEARTBEAT_TIMESTAMP: 2015-04-06 11:12:42RECEIVED_TRANSACTION_SET: LAST_ERROR_NUMBER: 0LAST_ERROR_MESSAGE: LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00
What you can do with PS
Source: LeFred https://github.com/lefred/pfs2elastic
Commands reference slide 1/3Initial reviewselect * from sys.x$host_summary;call sys.ps_statement_avg_latency_histogram()\Gselect * from sys.host_summary_by_file_io; <-- summary IO by connections (ip sum not single thread)select * from sys.host_summary_by_file_io_type; <-- summary by IO with max latency and main consumer (by ip)select * from sys.x$host_summary_by_stages order by 4 desc; <-- summary latency per stage per ipselect * from sys.x$host_summary_by_statement_latency; <-- summary by statement latency by IP with row examined affected and full scans select * from sys.x$host_summary_by_statement_type order by lock_latency desc; <-- summary locking latency by statement and IP
User reviewselect * from sys.user_summary; <-- summary to know what a user is doing including memory utilizationselect * from sys.user_summary_by_file_io; <--- user io and latencyselect * from sys.x$user_summary_by_file_io_type; <--- summary by user about io consumer and latencyselect * from sys.x$user_summary_by_stages where user like 'stress%' order by avg_latency desc; <--- avg latency by stage event and userselect * from sys.x$user_summary_by_statement_latency ; <--- total statement latency by user select * from sys.x$user_summary_by_statement_type where user like 'stress%' order by lock_latency desc; <--- summary per user of statement with latencyStatementselect * from sys.x$statement_analysis where db='test' order by avg_latency desc limit 2 \G <--- slow query select * from sys.x$statements_with_errors_or_warnings order by error_pct desc limit 4\G <--- statements generating errorsselect * from sys.x$statements_with_full_table_scans order by total_latency desc limit 2 \G <--- full table scan (and query not using index) select * from sys.x$statements_with_runtimes_in_95th_percentile order by max_latency desc\G <--- slow queryselect * from sys.x$statements_with_temp_tables where disk_tmp_tables > 0 order by exec_count,tmp_tables_to_disk_pct desc limit 5\G <--- Query with temp table
Commands reference slide 2/3InnoDB Buffer Pool (from Information Schema) <--- heavy select * from sys.innodb_buffer_stats_by_schema; select * from sys.innodb_buffer_stats_by_table;select * from sys.innodb_lock_waits\G
I/Oselect * from sys.x$io_by_thread_by_latency order by max_latency desc limit 10; <----- io latency by thread
DIG MORE??? select * from sys.processlist where conn_id=1659\G <---- which thread from processlist
select * from sys.x$io_global_by_file_by_bytes limit 50; <---- I/O latency/bytes by fileselect * from sys.x$io_global_by_file_by_latency limit 50; <---- I/O count of operation /latency per fileselect * from sys.io_global_by_wait_by_bytes; <--- I/O global main consumers by wait and bytesselect * from sys.io_global_by_wait_by_latency; <--- I/O global main consumers by latency per operation read/writeselect * from sys.latest_file_io;
More:select * from sys.x$latest_file_io where thread like '%thread:21'; <-- list specific activity for the threadselect file , count(file), thread, operation from sys.x$latest_file_io group by thread; <-- specific count of the threads
Commands reference slide 3/3Waitselect * from `sys`.`x$waits_global_by_latency`; <-- Lists the top wait events by their total latency, ignoring idleselect * from `sys`.x$wait_classes_global_by_avg_latency; <-- Lists the top wait classes by average latency, ignoring idleselect * from `sys`.x$wait_classes_global_by_latency; <-- Same above but for totals instead AVG).select * from `sys`.x$waits_by_host_by_latency order by avg_latency desc limit 40; <-- Lists the top wait events per host by their total latency, ignoring idleselect * from `sys`.x$waits_by_host_by_latency where host='10.0.0.151' order by avg_latency desc limit 40;select * from events_waits_summary_by_host_by_event_name where host = '10.0.0.151'and count_star >0; <-- similar to the one above select * from `sys`.x$waits_by_user_by_latency order by avg_latency desc limit 40; <-- Lists the top wait events per user by their total latency, ignoring idleselect * from `sys`.x$waits_by_user_by_latency where user='stress1' order by avg_latency desc limit 40;
Memory checkselect * from `sys`.memory_global_total;select * from `sys`.x$memory_by_host_by_current_bytes order by current_allocated desc; <-- Summarizes memory use by host.select * from memory_summary_by_thread_by_event_name where COUNT_ALLOC > 0 and THREAD_ID IN (select THREAD_ID from threads where PROCESSLIST_HOST='10.0.0.151') order by thread_id, SUM_NUMBER_OF_BYTES_ALLOC desc; <-- Detail memory by hostselect * from `sys`.x$memory_by_thread_by_current_bytes order by current_allocated desc limit 50; <-- Summarizes memory use by thread select * from memory_summary_by_thread_by_event_name where thread_id in (select THREAD_ID from performance_schema.threads where PROCESSLIST_HOST='10.0.0.151') and COUNT_ALLOC > 0 order by SUM_NUMBER_OF_BYTES_ALLOC desc; <--- Details for a specific hostselect * from `sys`.x$memory_by_user_by_current_bytes order by current_allocated desc limit 50; <---- Summarizes memory use by userselect * from `sys`.x$memory_global_by_current_allocated order by current_alloc desc limit 50; <---- memory allocated by consumerselect * from `sys`.x$memory_global_by_current_bytes order by current_alloc desc limit 50; <---- Shows the current memory usage within the server globally broken down by allocation type.To know memeory used by Performance SchemaSELECT distinct (sum(CURRENT_NUMBER_OF_BYTES_USED)/1024)/1024 as MB FROM memory_summary_global_by_event_name WHERE EVENT_NAME LIKE 'memory/performance_schema/%';
Steps & Commands 1/3 Initial review by SQLselect ss.*,(ss.full_scans/ss.total) * 100 as `FScan_%` from sys.x$host_summary_by_statement_latency as ss where max_latency > 0;
Slower tablesselect object_schema, object_name, count_star, sum_timer_wait from performance_schema.table_io_waits_summary_by_table order by 4 desc limit 10;
Find the most expensive stagesselect *, total_latency/total as latency_by_operation from sys.x$host_summary_by_stages where host like '10%' order by 6 desc limit 10;
Identify the files waitselect *, (total_latency/total) as latency_by_operation from sys.x$host_summary_by_file_io_type where host like '10%' order by latency_by_operation desc;
Identify the most expensive by type and host with detailsSelect host,event,exec_count,total_latency,lock_latency,changed_rows,sent_rows,examined_rows,tmp_table_on_disk,tmp_table,join_scan,join_range,join_select_check,join_full_scan,sort_passes,no_index_used,no_good_index from sys.x$statement_analysis_by_host where host like '10.%' order by total_latency desc limit 50;
Steps & Commands 2/3Identify which wait event are the expensive onesSELECT PROCESSLIST_ID,ewh.THREAD_ID,ewh.EVENT_NAME,ewh.SOURCE, sum(ewh.TIMER_WAIT)/1000000000 asWait_ms, ewh.OBJECT_SCHEMA, ewh.OBJECT_NAME, ewh.OBJECT_TYPE, ewh.OPERATION from events_waits_history ewh Join events_stages_history_long esth ON ewh.NESTING_EVENT_ID = esth.EVENT_ID Join events_statements_history_long esh ON esth.NESTING_EVENT_ID =esh.EVENT_ID Join threads th ON ewh.THREAD_ID = th.THREAD_ID where PROCESSLIST_HOST like '10.%' group by EVENT_NAME,PROCESSLIST_ID,ewh.THREAD_ID,ewh.EVENT_NAME,ewh.SOURCE, ewh.OBJECT_SCHEMA, ewh.OBJECT_NAME, ewh.OBJECT_TYPE, ewh.OPERATION order by ewh.TIMER_WAIT desc limit 50;
Compare with what id GLOBALLY impactingselect * from sys.x$waits_global_by_latency limit 50;
For each Event dig what is happeningselect ewh.EVENT_NAME,ewh.SOURCE,sum(ewh.TIMER_WAIT)/1000000000 as TWait_ms,ewh.OBJECT_NAME,ewh.OBJECT_TYPE,ewh.OPERATION from events_waits_history ewh Join threads th on ewh.THREAD_ID = th.THREAD_ID where EVENT_NAME like '%handler%' group by EVENT_NAME,ewh.SOURCE,ewh.OBJECT_NAME,ewh.OBJECT_TYPE,ewh.OPERATION order by TWait_ms desc limit 10;
Steps & Commands 3/3Time to see data files as wellselect ewh.EVENT_NAME,ewh.SOURCE,sum(ewh.TIMER_WAIT)/1000000000 as TWait_ms,ewh.OBJECT_NAME,ewh.OBJECT_TYPE,ewh.OPERATION from events_waits_history ewh Join threads th on ewh.THREAD_ID = th.THREAD_ID where EVENT_NAME like '%innodb_data_file%' group by EVENT_NAME,ewh.SOURCE,ewh.OBJECT_NAME,ewh.OBJECT_TYPE,ewh.OPERATION order by TWait_ms desc limit 10;
And compare with GLOBAL wait for tableselect table_name,count_read,sum_timer_read,count_write,sum_timer_write,sum_timer_misc from sys.x$ps_schema_table_statistics_io where count_read > 0 order by sum_timer_misc desc limit 10;
Check Memory• Account: select thread_id,user,current_count_used,current_allocated,current_avg_alloc,total_allocated from x$memory_by_thread_by_current_bytes order by current_allocated desc limit 10;• Event: select event_name,current_count,current_alloc,high_count,high_alloc from x$memory_global_by_current_allocated where event_name not like '%performance_schema%' order by current_alloc desc limit 10;• PS: select event_name,current_count,current_alloc,high_count,high_alloc from x$memory_global_by_current_allocated where event_name like '%performance_schema%' order by current_alloc desc limit 10;
Information schema - what is it?
• Focus on MySQL metadata information
• It is an abstraction, no real tables or directory
• Can be query with SQL statements (SELECT ..)
• Most information can be retrieve using SHOW
• Queries may impact on server performance
Information schema – Access Mode When writing a SQL statement to access IS take in to account the modes:•SKIP_OPEN_TABLE: Table files do not need to be opened. The information has already become available within the query by scanning the database directory.
•OPEN_FRM_ONLY: Only the table's .frm file need be opened.
•OPEN_TRIGGER_ONLY: Only the table's .TRG file need be opened.
•OPEN_FULL_TABLE: The unoptimized information lookup. The .frm, table files must be opened.
Information schema – Use Explain
A simple query:SELECT TABLE_SCHEMA, ENGINE, COUNT(1) as 'TABLES', sum(TABLE_ROWS) as 'ROWS',
TRUNCATE(sum(DATA_LENGTH)/pow(1024,2),2) as 'DATA (M)',
TRUNCATE(sum(INDEX_LENGTH)/pow(1024,2),2) as 'INDEX (M)',
TRUNCATE((sum(DATA_LENGTH)+sum(INDEX_LENGTH))/pow(1024,2),2) AS 'TOTAL(M)'
FROM information_schema.tables
WHERE TABLE_SCHEMA <> 'information_schema'
AND TABLE_SCHEMA <> 'mysql'
AND TABLE_SCHEMA <> 'performance_schema'
AND TABLE_TYPE = 'BASE TABLE'
GROUP BY TABLE_SCHEMA, ENGINE WITH ROLLUP;
Extra
Using where; Open_full_table; Scanned all databases; Using filesort
Information schema - the main tables for the catalog
• Privileges (General/Schema/Table/Column)
• Structure information (Table/Column/Views/Routines/Triggers/Files/Tablespaces)
• Server Information (Character_sets/Collations/Plugins/Engines)
• Server behaviour (Processlist/Status)
• InnoDB– Catalog– Behaviour
Information schema – ??• PROCESSLIST • PARTITIONS• STATISTICS• TABLES• FILES <- bug http://bugs.mysql.com/bug.php?id=76182• TABLESPACES <- Bug• OPTIMIZER_TRACE
Processlist – recipe • Count user by origin and if activeselect count(USER) N,USER,SUBSTRING_INDEX(HOST,':',1) HH ,STATE from
processlist WHERE COMMAND !='Sleep' GROUP BY USER,HH;
• List long running queriesselect USER,SUBSTRING_INDEX(HOST,':',1) HH ,STATE,COMMAND,STATE,INFO,TIME
from PROCESSLIST where TIME > 4 Order by Time DESC\G
• List Threads by Stateselect COUNT(USER) N, USER,SUBSTRING_INDEX(HOST,':',1) HH
,STATE,COMMAND,STATE from PROCESSLIST Group By STATE Order by STATE\G
Partitions – recipe • Crazy query, reporting Partitions, information, and data
distributionSELECT TB.TABLE_SCHEMA,TB.TABLE_NAME, TB.TABLE_TYPE,TB.ENGINE,TB.ROW_FORMAT,IBS.SPACE,
IBS.FILE_FORMAT,PARTITION_NAME,PARTITION_ORDINAL_POSITION,TB.TABLE_ROWS,
TB.DATA_LENGTH,TB.INDEX_LENGTH,(TP.TABLE_ROWS/TB.TABLE_ROWS)*100 as PCT_PARTITION_ROWS,(TP.DATA_LENGTH/TB.DATA_LENGTH)*100 PCT_PARTITION_DATA
from information_schema.TABLES as TB JOIN information_schema.PARTITIONS as TP on TB.TABLE_SCHEMA = TP.TABLE_SCHEMA AND TB.TABLE_NAME = TP.TABLE_NAME LEFT OUTER JOIN information_schema.INNODB_SYS_TABLES AS IBS on CONCAT(TB.TABLE_SCHEMA,'/',CONCAT(TB.TABLE_NAME,CONCAT('#P#',PARTITION_NAME)))=IBS.NAME where TP.PARTITION_NAME IS NOT NULL;Extra Using where; Open_full_table; Scanned all databases Using where; Open_full_table; Scanned all databases; Using join buffer (Block Nested Loop)Using where; Using join buffer (Block Nested Loop)
Partitions – recipe 2 • Query, reporting Partitions, information, and data
distributionSELECT TB.TABLE_SCHEMA,TB.TABLE_NAME, count(TB.TABLE_NAME), TB.TABLE_TYPE,TB.ENGINE,TB.ROW_FORMAT, TB.TABLE_ROWS,TB.DATA_LENGTH,TB.INDEX_LENGTH from TABLES as TB JOIN PARTITIONS as TP on TB.TABLE_SCHEMA = TP.TABLE_SCHEMA AND TB.TABLE_NAME = TP.TABLE_NAME GROUP BY TB.TABLE_SCHEMA,TB.TABLE_NAME ORDER By 1,2,3,5;
Extra Open_full_table; Scanned all databases; Using temporary; Using filesort Using where; Open_full_table; Scanned all databases; Using join buffer (Block Nested Loop)
Statistics – recipe 1 • Query, reporting Partitions, information, and data
distributionSELECT TB.TABLE_SCHEMA,TB.TABLE_NAME, count(TB.TABLE_NAME) AS NPARTS, TB.TABLE_TYPE,TB.ENGINE,TB.ROW_FORMAT, TB.TABLE_ROWS,TB.DATA_LENGTH,TB.INDEX_LENGTH from TABLES as TB JOIN PARTITIONS as TP on TB.TABLE_SCHEMA = TP.TABLE_SCHEMA AND TB.TABLE_NAME = TP.TABLE_NAME GROUP BY TB.TABLE_SCHEMA,TB.TABLE_NAME ORDER By 1,2,3,5;
Extra Open_full_table; Scanned all databases; Using temporary; Using filesort Using where; Open_full_table; Scanned all databases; Using join buffer (Block Nested Loop)
Statistics – resultTABLE_NAME |NParts | TABLE_TYPE | ENGINE | ROW_FORMAT | TABLE_ROWS | DATA_LENGTH | INDEX_LENGTH
tbtest1 | 18 | BASE TABLE | InnoDB | Compact | 7618351 | 3297886208 | 1165770752 tbtest1A | 1 | BASE TABLE | InnoDB | Compact | 97470 | 42565632 | 12648448 tbtest2 | 1 | BASE TABLE | InnoDB | Compact | 6115350 | 3320840192 | 914817024 tbtest2A | 1 | BASE TABLE | InnoDB | Compact | 9766 | 4734976 | 1867776 tbtest3 | 1 | BASE TABLE | InnoDB | Compact | 6582955 | 3303014400 | 897171456tbtest4 | 1 | BASE TABLE | InnoDB | Compact | 6226597 | 3290431488 | 905461760 tbtest5 | 1 | BASE TABLE | InnoDB | Compact | 6265127 | 3293560832 | 904364032
Statistics – recipe 2 • Query, reporting possible tables to be ANALYZE
select ST.TABLE_NAME,INDEX_NAME, SEQ_IN_INDEX, COLUMN_NAME, CARDINALITY,TB.TABLE_ROWS, (CARDINALITY/TB.TABLE_ROWS)*100 AS 'Card_%' from STATISTICS ST JOIN TABLES TB on ST.TABLE_SCHEMA=TB.TABLE_SCHEMA AND ST.TABLE_NAME=TB.TABLE_NAME where ST.TABLE_SCHEMA='test' ORDER BY ST.TABLE_NAME,INDEX_NAME,SEQ_IN_INDEX;
Extra Using where; Open_full_table; Scanned 1 database; Using temporary; Using filesort
Using where; Open_full_table; Scanned all databases; Using join buffer (Block Nested Loop)
Statistics – result 2TABLE_NAME | INDEX_NAME | SEQ_IN_INDEX | COLUMN_NAME | CARDINALITY | TABLE_ROWS | Card_%
tbtest_child3 | bb | 1 | bb | 5511 | 5884 | 93.6608 tbtest_child3 | PRIMARY | 1 | a | 4958 | 5884 | 84.2624 tbtest_child3 | PRIMARY | 2 | bb | 5882 | 5884 | 99.9660
+--------------+--------------+------+-----+-------------------+-----------------------------+
| Field | Type | Null | Key | Default | Extra |
+--------------+--------------+------+-----+-------------------+-----------------------------+
| a | int(11) | NO | PRI | NULL | |
| bb | int(11) | NO | PRI | NULL | auto_increment |
| date | date | NO | | NULL | |
| partitionid | int(11) | NO | | 0 | |
| stroperation | varchar(254) | YES | | NULL | |
| time | timestamp | NO | | CURRENT_TIMESTAMP | on update CURRENT_TIMESTAMP |
+--------------+--------------+------+-----+-------------------+-----------------------------+
FILES - TABLESPACES• The FILES table provides information about the files in
which MySQL tablespace data is stored.• The TABLESPACES table provides information about
active tablespaces.• Quite useful to identify multiple files for tablespace
Unfortunately Bug in 5.7.6 M16 and none of the is working (Bug #76182)
OPTIMIZER_TRACE• Present from 5.6.3• Activate on need (SET optimizer_trace="enabled=on";)• Terrific tool when debugging queries• Given memory utilization it can be disable (for all)
--maximum-optimizer-trace-max-mem-size=0
--optimizer-trace-max-mem-size=0
OPTIMIZER_TRACE exampleSET optimizer_trace_offset=-2, optimizer_trace_limit=2;
SET optimizer_trace="enabled=on";
select tbtest2.a from tbtest2 join tbtest_child2 on tbtest2.a=tbtest_child2.a;
select tbtest1.a from tbtest1 join tbtest_child1 on tbtest1.a=tbtest_child1.a;
SELECT * FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE;SET optimizer_trace="enabled=off";
OPTIMIZER_TRACE example cont."rows_estimation": [
{"table": "`tbtest2`",
"table_scan":
{
"rows": 11241377,
"cost": 352832
}},
{"table": "`tbtest_child2`",
"table_scan": {
"rows": 10545,
"cost": 344}
}]
"rows_estimation": [
{"table": "`tbtest1`", "table_scan":
{
"rows": 7618351, "cost": 201287
}},
{"table": "`tbtest_c/hild1`", "table_scan": {
"rows": 10816,
"cost": 343}
}]
Name: tbtest1Engine: InnoDB Version: 10 Row_format: CompactRows: 7618351 Avg_row_length: 432 Data_length:3297886208Max_data_length: 0 Index_length: 1165770752 Data_free: 11534336 Auto_increment: 16418768
InnoDB - Catalog • INNODB_SYS_TABLES• INNODB_SYS_INDEXES• INNODB_SYS_COLUMNS• INNODB_SYS_FIELDS• INNODB_SYS_FOREIGN
• INNODB_SYS_FOREIGN_COLS• INNODB_SYS_TABLESTATS• INNODB_SYS_DATAFILES• INNODB_SYS_TABLESPACES
InnoDB – New in SYS_INDEXES• MERGE_THRESHOLD
– When the “page-full” percentage for an index page falls below 50%, which is the default MERGE_THRESHOLD setting, InnoDB attempts to merge the index page with a neighboring page.CREATE TABLE t1 (
id INT,
KEY id_index (id)
) COMMENT='MERGE_THRESHOLD=45';
InnoDB TRX & Lock• Detailed information about TRX• Unique source of information to identify loking threads
– INNODB_TRX Table– INNODB_LOCKS Table– INNODB_LOCK_WAITS Tabl
InnoDB TRX• INNODB_TRX
– select * from information_schema.INNODB_TRX where trx_concurrency_tickets < 100 and trx_concurrency_tickets > 0\G
trx_id: 91121661
trx_state: RUNNING
trx_started: 2015-03-12 16:35:18
trx_requested_lock_id: NULL
trx_wait_started: NULL
trx_weight: 5
trx_mysql_thread_id: 126
trx_query: UPDATE sbtest1 SET ….trx_operation_state: NULL
trx_tables_in_use: 1 trx_tables_locked: 1trx_lock_structs: 3trx_lock_memory_bytes: 1136 trx_rows_locked: 2 trx_rows_modified: 2trx_concurrency_tickets: 499trx_isolation_level: REPEATABLE READ trx_unique_checks: 1trx_foreign_key_checks: 1trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0trx_adaptive_hash_timeout: 10000 trx_is_read_only: 0trx_autocommit_non_locking: 0
InnoDB Lock (example)select * from INNODB_LOCK_WAITS;| requesting_trx_id | requested_lock_id | blocking_trx_id | blocking_lock_id || 91459149 | 91459149:183:54275:439 | 91323715 | 91323715:183:54275:439 |
select * from INNODB_LOCKS;| lock_id | lock_trx_id | lock_mode | lock_type | lock_table | lock_index | 91465549:183:48232:264 | 91465549 | X,GAP | RECORD | `test`.`tbtest1` | IDX_a
select * from information_schema.INNODB_TRX where trx_id=91323715\Gtrx_id: 91323715trx_mysql_thread_id: 269
select * from processlist where id=269;| ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO | 269 | root | localhost | test | Sleep | 397 | | NULL
InnoDB Buffer Pool info• The INNODB_BUFFER_PAGE table holds information about each
page in the InnoDB buffer pool.• The INNODB_BUFFER_PAGE_LRU table holds information about
how they are ordered in the LRU list that determines which pages to evict from the buffer pool when it becomes full
(NOTE DO NOT USE IN PROD)
• The INNODB_BUFFER_POOL_STATS table provides much of the same buffer pool information provided in SHOW ENGINE INNODB STATUS
InnoDB Buffer Pool Metrics| subsystem |+---------------------+| metadata || lock || server || buffer || buffer_page_io || os || transaction || purge || recovery |
| subsystem |+---------------------+| compression || index || adaptive_hash_index || file_system || change_buffer || dml || ddl || icp |
InnoDB Buffer Pool Metrics
• By default only 65 enabled over 234
• Enable ONLY what you need & Disable them after• Enable/reset/disable is simple:
– set global innodb_monitor_enable='index_%';– set global innodb_monitor_disable='index_%';– set global innodb_monitor_reset='index_%';
InnoDB Buffer Pool Metrics NAME | COUNT | AVG | COMMENT |adaptive_hash_searches | 470 | 2.3 |successful searches using Adaptive Hash Index|adaptive_hash_searches_btree | 626974 | 311 |searches using B-tree on an index search|adaptive_hash_pages_added | 71 | 0.3 |index pages on which the Adaptive Hash Index is
built |adaptive_hash_pages_removed | 2 | 0.0 |index pages whose corresponding Adaptive Hash
Index entries were removed |adaptive_hash_rows_added | 95028 | 472 |Adaptive Hash Index rows added |adaptive_hash_rows_removed | 389 | 1.9 |Adaptive Hash Index rows removed |adaptive_hash_rows_deleted_no_hash_entry | 0 | 0 |rows deleted that did not have corresponding Adaptive Hash Index entries |adaptive_hash_rows_updated | 0 | 0 |Adaptive Hash Index rows updated
Good insight on Adaptive Hash usage!
Thanks to…• Mark Leith (for SYS schema)• Sveta Smirnova • Vaerii Kravchuk• Todd Farmer• Dimitri Kravtchuk • Fred Descamps (LeFred)
What Next?• Improve SYS schema
• Develop scripts for data analysis
• Create/improve graphic interface
In short make Performance schema usable
(take a look to VividCortex)
Others presentation coming from me• Group replication VS Galera• Galera new feature old problems?• Sharding with MySQL, once more.• MariaDb and Oracle MySQL where are they going?• MySQL/Galera pushed beyond the limits• PS how to get even more but easier
http://www.tusacentral.net
Q & A
Thank youTo contact us
1-877-PYTHIAN
To follow us
http://www.pythian.com/blog
http://www.facebook.com/pages/The-Pythian-Group/163902527671
@pythian
http://www.linkedin.com/company/pythian
To contact Me
To follow me
http://www.tusacentral.net/
https://www.facebook.com/marco.tusa.94
@marcotusa
http://it.linkedin.com/in/marcotusa/