Skip to content

Commit b7572ed

Browse files
patrickbirchpatrickbirch
authored
Merge pull request #396 from percona/ps-9428
PS-9428 Rewrite the Slow Query log topic in 8.0
2 parents fc65d9b + 87c8aea commit b7572ed

File tree

5 files changed

+204
-207
lines changed

5 files changed

+204
-207
lines changed

‎docs/extended-select-into-outfile.md

Lines changed: 3 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -1,19 +1,10 @@
11
# Extended SELECT INTO OUTFILE/DUMPFILE
22

3-
*Percona Server for MySQL* has extended the `SELECT INTO ... OUTFILE` and `SELECT INTO
4-
DUMPFILE` [commands](https://dev.mysql.com/doc/refman/8.0/en/select-into.html)
5-
to add support for UNIX sockets and named pipes. Before this was implemented
6-
the database would return an error for such files.
3+
Percona Server for MySQL improves the `SELECT INTO ... OUTFILE` and `SELECT ... INTO DUMPFILE` commands by allowing them to work with UNIX sockets and named pipes. In the past, using these types of files would cause an error.
74

8-
This feature allows using `LOAD DATA LOCAL INFILE` in combination with
9-
`SELECT INTO OUTFILE` to quickly load multiple partitions across the network
10-
or in other setups, without having to use an intermediate file that wastes
11-
space and I/O.
5+
This feature lets you quickly combine `LOAD DATA LOCAL INFILE` with `SELECT INTO ... OUTFILE` to transfer data across the network or between different partitions. It avoids creating an intermediate file, saves disk space, and reduces I/O usage. This ability makes data loading more efficient, especially for large datasets or complex configurations.
126

137
## Version specific information
148

15-
* 8.0.12-1: The feature was ported from *Percona Server for MySQL* 5.7.
9+
* 8.0.12-1: The feature was ported from Percona Server for MySQL 5.7.
1610

17-
## Other reading
18-
19-
* *MySQL* bug: [#44835](https://bugs.mysql.com/bug.php?id=44835)

‎docs/improved-slow-query-log.md

Lines changed: 164 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,164 @@
1+
# Improved slow query log
2+
3+
This feature adds microsecond time resolution and additional statistics to the slow query log output. It lets you turn the slow query log on or off at runtime, adds logging for the replica SQL thread, and adds fine-grained control over what and how much to log into the slow query log.
4+
5+
You can use the Percona Toolkit [pt-query-digest](https://docs.percona.com/percona-toolkit/pt-query-digest.html) tool to aggregate similar queries together and report on those that consume the most execution time.
6+
7+
## Version specific information
8+
9+
* 8.0.12-1: The feature was ported from Percona Server for MySQL 5.7.
10+
11+
## Other information
12+
13+
### Changes to the log format
14+
15+
The feature adds more information to the slow log output.
16+
17+
??? example "Expected output"
18+
19+
```{.text .no-copy}
20+
# Time: 130601 8:01:06.058915
21+
# User@Host: root[root] @ localhost [] Id: 42
22+
# Schema: imdb Last_errno: 0 Killed: 0
23+
# Query_time: 7.725616 Lock_time: 0.000328 Rows_sent: 4 Rows_examined: 1543720 Rows_affected: 0
24+
# Bytes_sent: 272 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
25+
# Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
26+
# Filesort: No Filesort_on_disk: No Merge_passes: 0
27+
SET timestamp=1370073666;
28+
SELECT id,title,production_year FROM title WHERE title = 'Bambi';
29+
```
30+
31+
Another example (log_slow_verbosity `=profiling`):
32+
33+
??? example "Expected output"
34+
35+
```{.text .no-copy}
36+
# Time: 130601 8:03:20.700441
37+
# User@Host: root[root] @ localhost [] Id: 43
38+
# Schema: imdb Last_errno: 0 Killed: 0
39+
# Query_time: 7.815071 Lock_time: 0.000261 Rows_sent: 4 Rows_examined: 1543720 Rows_affected: 0
40+
# Bytes_sent: 272
41+
# Profile_starting: 0.000125 Profile_starting_cpu: 0.000120
42+
Profile_checking_permissions: 0.000021 Profile_checking_permissions_cpu: 0.000021
43+
Profile_Opening_tables: 0.000049 Profile_Opening_tables_cpu: 0.000048 Profile_init: 0.000048
44+
Profile_init_cpu: 0.000049 Profile_System_lock: 0.000049 Profile_System_lock_cpu: 0.000048
45+
Profile_optimizing: 0.000024 Profile_optimizing_cpu: 0.000024 Profile_statistics: 0.000036
46+
Profile_statistics_cpu: 0.000037 Profile_preparing: 0.000029 Profile_preparing_cpu: 0.000029
47+
Profile_executing: 0.000012 Profile_executing_cpu: 0.000012 Profile_Sending_data: 7.814583
48+
Profile_Sending_data_cpu: 7.811634 Profile_end: 0.000013 Profile_end_cpu: 0.000012
49+
Profile_query_end: 0.000014 Profile_query_end_cpu: 0.000014 Profile_closing_tables: 0.000023
50+
Profile_closing_tables_cpu: 0.000023 Profile_freeing_items: 0.000051
51+
Profile_freeing_items_cpu: 0.000050 Profile_logging_slow_query: 0.000006
52+
Profile_logging_slow_query_cpu: 0.000006
53+
# Profile_total: 7.815085 Profile_total_cpu: 7.812127
54+
SET timestamp=1370073800;
55+
SELECT id,title,production_year FROM title WHERE title = 'Bambi';
56+
```
57+
58+
Notice that the `Killed:` keyword is followed by zero when the
59+
query successfully completes. This keyword is followed by a number other than zero if the query is unsuccessful:
60+
61+
| Killed Numeric Code | Exception |
62+
|---------------------|------------------------------------------------|
63+
| 0 | NOT_KILLED |
64+
| 1 | KILL_BAD_DATA |
65+
| 1053 | ER_SERVER_SHUTDOWN (see MySQL Documentation) |
66+
| 1317 | ER_QUERY_INTERRUPTED (see MySQL Documentation) |
67+
| 3024 | ER_QUERY_TIMEOUT (see MySQL Documentation) |
68+
| Any other number | KILLED_NO_VALUE (Catches all other cases) |
69+
70+
### Connection and Schema Identifier
71+
72+
Each slow log entry now contains a connection identifier so you can trace all the queries from a single connection. This identifier is the same value shown in the Id column in `SHOW FULL PROCESSLIST` or returned from the `CONNECTION_ID()` function.
73+
74+
Each entry also contains a schema name to trace all the queries for a particular schema.
75+
76+
??? example "Expected output"
77+
78+
```{.text .no-copy}
79+
# Id: 43 Schema: imdb
80+
```
81+
82+
### Microsecond time resolution and extra row information
83+
84+
This microsecond time resolution and extra row information are the 'microflow` feature's original functionality. `Query_time` and `Lock_time` are logged with microsecond resolution.
85+
86+
The feature also adds information about how many rows were examined for `SELECT` queries and how many were analyzed and affected for `UPDATE`, `DELETE`, and `INSERT` queries.
87+
88+
??? example "Expected output"
89+
90+
```{.text .no-copy}
91+
# Query_time: 0.962742 Lock_time: 0.000202 Rows_sent: 4 Rows_examined: 1543719 Rows_affected: 0
92+
```
93+
94+
Values and context:
95+
96+
* `Rows_examined`: Number of rows scanned - `SELECT`
97+
98+
* `Rows_affected`: Number of rows changed - `UPDATE`, `DELETE`, `INSERT`
99+
100+
### Memory footprint
101+
102+
The feature provides information about the amount of bytes sent for the result of the query and the number of temporary tables created for its execution - differentiated by whether they were created on memory or on disk - with the total number of bytes used by them.
103+
104+
??? example "Expected output"
105+
106+
```{.text .no-copy}
107+
# Bytes_sent: 8053 Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 950528
108+
```
109+
110+
Values and context:
111+
112+
* `Bytes_sent`: The amount of bytes sent for the result of the query
113+
114+
* `Tmp_tables`: Number of temporary tables created on memory for the query
115+
116+
* `Tmp_disk_tables`: Number of temporary tables created on disk for the query
117+
118+
* `Tmp_table_sizes`: Total Size in bytes for all temporary tables used in the query
119+
120+
### Query plan information
121+
122+
The database can execute a query using different methods:
123+
124+
* Using indexes
125+
126+
* Scanning the entire table
127+
128+
* Creating temporary tables
129+
130+
Each query can be executed in various ways. For example, it may use indexes or do a full table scan, or a temporary table may be needed. These are the things that you can usually see by running `EXPLAIN` on the query. The feature will now allow you to see the most important facts about the execution in the log file.
131+
132+
??? example "Expected output"
133+
134+
```{.text .no-copy}
135+
# Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
136+
# Filesort: No Filesort_on_disk: No Merge_passes: 0
137+
```
138+
139+
The values and their meanings are documented with the [`log_slow_filter`](slow-extended.md#log_slow_filter) option.
140+
141+
### InnoDB usage information
142+
143+
The final part of the output is the InnoDB usage statistics. MySQL currently shows many per-session statistics for operations with `SHOW SESSION STATUS`, but that does not include those of InnoDB, which are always global and shared by all threads. This feature lets you see those values for a given query.
144+
145+
??? example "Expected output"
146+
147+
```{.text .no-copy}
148+
# InnoDB_IO_r_ops: 6415 InnoDB_IO_r_bytes: 105103360 InnoDB_IO_r_wait: 0.001279
149+
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
150+
# InnoDB_pages_distinct: 6430
151+
```
152+
153+
154+
| Value | Description |
155+
|----------------------|--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
156+
| InnoDB_IO_r_ops | Counts the planned page read operations. The actual number may differ due to asynchronous operations. |
157+
| InnoDB_IO_r_bytes | Similar to InnoDB_IO_r_ops but measures the operations in bytes instead of counts. |
158+
| InnoDB_IO_r_wait | Shows how long (in seconds) InnoDB took to read data from storage. |
159+
| InnoDB_rec_lock_wait | Indicates how long (in seconds) the query waited for row locks. |
160+
| InnoDB_queue_wait | Measures how long (in seconds) the query waited to enter the InnoDB queue or waited inside the queue for execution. |
161+
| InnoDB_pages_distinct | Estimates the number of unique pages the query accessed. It uses a small hash array to represent the entire buffer pool, which may lead to inaccuracy for queries accessing many pages. |
162+
163+
164+
If the query did not use *InnoDB* tables, that information is written into the log instead of the above statistics.

0 commit comments

Comments
 (0)