# Working with Slow Query Logs

Created by Kolbe Kegel, last modified on Apr 07, 2021

## Problem

--------

What do you do when a customer has dozens or hundreds of GB of slow query logs? You want to find some of the longest-running or most memory-intensive or just literally longest SQL statements.

## Problem verification and troubleshooting

----------------------------------------

A customer published a gist with URLs to download their uncompressed slow query logs across 8 TiDB nodes. There were dozens of files for each node, for a total of about 174 slow query logs, each of which was hundreds of MB. The total size of all the logs was 133GB.

That was just too much log data to practically download to my local machine (Xfinity has a 1.2TB monthly data cap, it's only 120Mbps, and my poor local machine doesn't need that chaos).

## Solution

--------

### Preparing the environment

The customer's log files were stored in GCP, so I started a GCP VM with a 375GB local disk (to make things faster and a little less expensive, and since I don't care about keeping the data). The number of CPU cores is not very important, but give yourself plenty of memory in case you end up needing to open up some multi-GB text files. The default in GCP seems to be Debian, so that's what I used.

I like to install a few miscellaneous packages that are really helpful:

```bash
apt update  
apt install -y vim screen git curl mariadb-client percona-toolkit
```

I formatted and mounted the local SSD, which was exposed to the OS at /dev/nvme0n1.

```bash
mke2fs /dev/nvme0n1  
mkdir /mnt/data1  
mount /dev/nvme0n1 /mnt/data1  
cd /mnt/data1
```

### Downloading the logs

I got a simple text file with a list of URLs to download the log files, with one URL per line.

In this case the log URLs took this form:

[https://storage.googleapis.com/temp.customer.com/tidb\_logs/prod-tidb-0/tidb-2021-03-06T14-36-36.293.log?x-goog-signature=..](https://storage.googleapis.com/temp.customer.com/tidb_logs/prod-tidb-0/tidb-2021-03-06T14-36-36.293.log?x-goog-signature=..).

I used a simple bash loop with some parameter expansion shenanigans to fetch all the logs.

```bash
while read -r url; do  
   path="${url%\\?\*}"  
   comp=(${path//\\// })  
   file="${path##\*/}"  
   mkdir -p "${comp\[-2\]}"  
   curl -sS -L -C - -o "${comp\[-2\]}/${comp\[-1\]}" "$url" &  
done < log\_list
```

That runs a whole bunch of curl instances in parallel, in the shell's background. Hopefully they'll finish eventually. You can execute jobs to see how many of them are still running.

### Processing the logs

There are a variety of tools that can help parse and understand slow query logs, but they may not be able to fully understand or handle all of the fields specific to the TiDB log format.

One such tool is pt-query-digest, which is part of the Percona Toolkit. I won't cover that here, because I'm interested in trying to use some shell tools to tease out specific information across a huge number of log files.

### Highest memory usage?

One task I wanted to do is find the queries that used the most memory (Mem\_max in the slow query log). I was able to do that using this command:

```{.bash .copyable}
find . -name '\*tidb\_slow\_query\*' -exec grep -Hn Mem\_max {} + | sort -k 3 -n | tail -n 20
```

Here's what's happening in the shell commands.

* find . looks through all the files in and below the current directory
* \-name '\*tidb\_slow\_query\*' matches all files that match the pattern
    * You have to use asterisks to match filenames, and you should quote them in case the shell tries to expand the string into a file in the current directory!
* \-exec grep -Hn Mem\_max {} + executes grep across all the matching files.
    * \-Hn tells grep to omit filenames and line numbers for each match
    * {} + is interpreted by find as the location to put all the matching filenames (up to ARG\_MAX)
* sort -k 3 -n sorts the output of grep by the 3rd field (separated by whitespace, counting from 1), sorted numerically
* tail -n 20 outputs only the last 20 matching lines, in this case the ones that were sorted to have the highest Mem\_max value

#### Output

```output
./prod-tidb-1/tidb\_slow\_query-2021-03-09T10-53-22.803.log:1616835:# Mem\_max: 5620029162  
./prod-tidb-0/tidb\_slow\_query-2021-03-10T06-27-31.988.log:2155436:# Mem\_max: 5621178517  
./prod-tidb-2/tidb\_slow\_query-2021-03-09T06-59-53.512.log:2865945:# Mem\_max: 5622267263  
./prod-tidb-5/tidb\_slow\_query-2021-03-09T10-50-25.012.log:2581655:# Mem\_max: 5628521007  
./prod-tidb-5/tidb\_slow\_query-2021-03-09T10-50-25.012.log:1526238:# Mem\_max: 5630250419  
./prod-tidb-6/tidb\_slow\_query-2021-03-10T08-59-06.065.log:1720455:# Mem\_max: 5631576697  
./prod-tidb-6/tidb\_slow\_query-2021-03-10T08-59-06.065.log:1078276:# Mem\_max: 5652032391  
./prod-tidb-6/tidb\_slow\_query-2021-03-10T08-59-06.065.log:1602614:# Mem\_max: 5657970262  
./prod-tidb-7/tidb\_slow\_query-2021-03-10T11-06-19.439.log:1253469:# Mem\_max: 5660531452  
./prod-tidb-1/tidb\_slow\_query-2021-03-02T13-40-01.189.log:1564777:# Mem\_max: 5870657630  
./prod-tidb-3/tidb\_slow\_query-2021-03-10T10-40-42.326.log:1288007:# Mem\_max: 5909083738  
./prod-tidb-1/tidb\_slow\_query-2021-03-02T13-40-01.189.log:1563497:# Mem\_max: 6108924529  
./prod-tidb-2/tidb\_slow\_query-2021-03-01T19-24-28.820.log:679098:# Mem\_max: 6112772283  
./prod-tidb-6/tidb\_slow\_query-2021-03-26T03-27-54.587.log:16992:# Mem\_max: 7846160911  
./prod-tidb-7/tidb\_slow\_query-2021-03-25T23-30-11.416.log:19813:# Mem\_max: 9296093928  
./prod-tidb-6/tidb\_slow\_query-2021-03-03T04-55-08.492.log:526647:# Mem\_max: 10253964458  
./prod-tidb-3/tidb\_slow\_query-2021-03-02T12-05-31.918.log:375238:# Mem\_max: 10257277082  
./prod-tidb-3/tidb\_slow\_query-2021-03-02T12-05-31.918.log:544192:# Mem\_max: 10258828706  
./prod-tidb-5/tidb\_slow\_query-2021-03-03T04-55-04.674.log:1281382:# Mem\_max: 10260601914  
./prod-tidb-7/tidb\_slow\_query-2021-03-02T16-55-14.373.log:156471:# Mem\_max: 28993567792
```

The highest memory usage query in these logs is using 28993567792 bytes, which is 27GB!

```bah
echo $((28993567792>>30))  
27
```

We want to inspect this query in a little more detail, and we can do that using vim:

* vim -c 'set nowrap' ./prod-tidb-7/tidb\_slow\_query-2021-03-02T16-55-14.373.log +156471  
    \-c 'set nowrap' tells vim not to wrap lines

This is really important when you're working with files like slow query logs that have extremely long lines. Otherwise, vim will have to wrap a single line maybe dozens or hundreds of times, which is basically impossible to work with in a display.

* +156471 tells vim to jump straight to line number 156471

After vim opens, you can view the various attributes of the query:

```
\# Time: 2021-02-25T02:16:51.755416395Z  
\# Txn\_start\_ts: 423149070292615693  
\# User@Host: streak\[streak\] @ 10.36.78.33 \[10.36.78.33\]  
\# Conn\_ID: 2631  
\# Query\_time: 33809.587790309  
\# Parse\_time: 0.00025051  
\# Compile\_time: 0.00332516  
\# Rewrite\_time: 0.00069308  
\# Optimize\_time: 0.0023137  
\# Wait\_TS: 0.00001096  
\# Cop\_time: 42656.119510017 Process\_time: 5658.06 Wait\_time: 119.996 Backoff\_time: 0.66 Request\_count: 347657 Process\_keys: 333967364 Total\_keys: 439830879 Rocksdb\_delete\_skipped\_count: 23339879 Rock  
\# DB: streak  
\# Is\_internal: false  
\# Digest: 3f90d0b40f7b6bcef57ef4c6f42bc13865c077002e352891b902c00a807438e5  
\# Stats: boxes:423149060763681356,boxes\_assigned\_to\_keys:423149060829217076,boxes\_overdue\_task\_assignee\_keys:423149060842849086  
\# Num\_cop\_tasks: 347657  
\# Cop\_proc\_avg: 0.016274834 Cop\_proc\_p90: 0.044 Cop\_proc\_max: 3.408 Cop\_proc\_addr: prod-tikv-15:20160  
\# Cop\_wait\_avg: 0.000345156 Cop\_wait\_p90: 0 Cop\_wait\_max: 0.568 Cop\_wait\_addr: prod-tikv-3:20160  
\# Cop\_backoff\_regionMiss\_total\_times: 330 Cop\_backoff\_regionMiss\_total\_time: 0.66 Cop\_backoff\_regionMiss\_max\_time: 0.002 Cop\_backoff\_regionMiss\_max\_addr: prod-tikv-13:20160 Cop\_backoff\_regionMiss\_avg  
\# Mem\_max: 28993567792  
\# Disk\_max: 134950130  
\# Prepared: false  
\# Plan\_from\_cache: false  
\# Plan\_from\_binding: false  
\# Has\_more\_results: false  
\# KV\_total: 6477.921070636  
\# PD\_total: 0.253207355  
\# Backoff\_total: 0.662  
\# Write\_sql\_response\_total: 0.00000956  
\# Succ: true  
\# Plan: tidb\_decode\_plan('jm7IMAkzXzIxCTAJODYyLjk3CXN0cmVhay5ib3hlcy5zdGFnZV9rZXksIENvbHVtbiMxNTIsGQxsMQkxOAl0aW1lOjloMjNtMjkuNnMsIGxvb3BzOgUofG5jdXJyZW5jeTpPRkYJMS4zNCBLQglOL0EKMQk2XzIyGXgkZ3JvdXAgY  
\# Plan\_digest: aefbad8031694f91f99829cc9078984fffa911e6c809720774dfc264a0d9ad7c  
Looking through these queries actually helped this customer identify a really problematic bug in their application that was causing it to generate bad queries that used tons of memory. Win!
```

### Decode execution plan?

Following on the previous example, once you open the log file in vim and it jumps to the line that matches the search term (Mem\_max in this case), you'll notice the query text itself several lines below, and a few lines above that you'll see # Plan: tidb\_decode\_plan(

The tidb\_decode\_plan() function takes a base64-encoded query execution plan and turns it into the output you'd expect to see from EXPLAIN.

For an extremely complicated query, the tidb\_decode\_plan() line in the slow query log can be really long. For example, ./prod-tidb-6/tidb\_slow\_query-2021-03-26T03-27-54.587.log:16992:# Mem\_max: 7846160911 in the output has a Plan line that's 17MB long, just by itself!

Trying to deal with a 17MB SQL query is not very convenient, so let's put that line into a file by itself so we can execute it without having to somehow paste it or otherwise enter it into a mysql command-line client.

In vim, you can split the window to edit a new, empty file by executing :new . Use ctrl-w-w to switch between panes in vim. Copy the line with "Plan" from the log file (yy copies a line), hit ctrl-w-w to switch to the new, empty pane, and paste (p) it. You'll need to remove the comment character and other stuff before tidb\_decode\_plan( , and you need to add SELECT before it. Save the file (:w decode\_query.sql).

If we want to actually look at the execution plan, we need to install tidb-server. The easiest way to do that is using TiUP, of course!

```bash
curl --proto '=https' --tlsv1.2 -sSf <https://tiup-mirrors.pingcap.com/install.sh> | sh  
source ~/.bashrc  
tiup install tidb:nightly  
~/.tiup/components/tidb/nightly/tidb-server
```

We don't actually need to run a real cluster, just a standalone unistore/mocktikv instance, so we can run tidb-server directly without having TiUP set up a whole cluster or playground.

We can use the mysql command-line client to execute the query that we saved to the file.

```bash
mysql -h 127.0.0.1 -P4000 -u root -BN --raw --max-allowed-packet=1G < decode\_query.sql > explain.out
```

* \-B tells the client to run in batch mode (the default when reading from stdin)
* \-N tells the client to omit column headers (because the headers that for the decoded EXPLAIN in this case are part of the output of the tidb\_decode\_plan() function
* \--raw tells the client to skip escaping special characters, so that we can read the output easily
* \--table tells the client to write the output in the typical table instead of the batch output normally used when the client program reads from stdin
* \--max-allowed-packet=1G is necessary (a smaller value would also work) because the query text itself is so large, and the result also ends up being enormous

```bash
$ ls -sh explain.out  
457M explain.out

$ wc -L explain.out  
68387604 explain.out
```

The file itself is 475M and the longest line is 65M by itself! This is pretty difficult to work with.

The header labels in the file are aligned with the column borders of data rows in the file. If we can identify the byte offsets of the headers, we may be able to cut out the middle sections of the row data in order to see the more interesting sections at the margins.

```{.bash .copyable}
head -n1 explain.out | grep -boE '(\[^\[:space:\]\]+ ?)+'  
```

```output
1:id  
24:task  
34:estRows  
42:operator info  
68387250:actRows  
68387259:execution info  
68387558:memory  
68387567:disk
```

* \-b tells grep to give the byte offset of any matches
* \-o tells grep to show only the matching part
* \-E activates extended regex interpretation so the syntax is a little easier  
    '(\[^\[:space:\]\]+ ?)+' is a regular expression that matches any sequence of...
    * one-or-more non-space characters
    * followed by an optional single space
    * repeated any number of times
    * this is to account for identifiers like "operator info"

Clearly the most substantial part of the column data is contained in "operator info". We can try to completely remove a huge middle part of that, because it's just a bunch of lists of ranges to select. But let's see which operators have data out there in the middle of the file:

### Longest query SQL length?

```{.bash .copyable}
find . -name '\*tidb\_slow\_query\*' -exec grep -HnEo 'len:\[0-9\]+' {} + | sort -t: -k 4 -n | tail -n 20
```

Adding on to the previous section, there are a couple new options at play here

* The addition of -E to grep enables "extended regular expression (ERE)" parsing, which is just a little easier to use and read than basic RE
* The addition of -o to grep makes it output only the matching part of each line
* The regex 'len:\[0-9\]+' matches the literal string "len:" followed by 1 or more characters in the range "0-9".
* The addition of -t: to sort has it split fields on the colon character instead of on whitespace

```output
./prod-tidb-5/tidb\_slow\_query-2021-03-26T14-02-31.616.log:33:len:50590267  
./prod-tidb-3/tidb\_slow\_query-2021-03-26T11-44-10.088.log:21945:len:51587278  
./prod-tidb-0/tidb\_slow\_query-2021-03-25T22-10-29.871.log:133693:len:55277138  
./prod-tidb-5/tidb\_slow\_query-2021-03-26T02-23-23.029.log:21387:len:55278031  
./prod-tidb-0/tidb\_slow\_query-2021-03-25T23-36-47.293.log:33:len:56087183  
./prod-tidb-4/tidb\_slow\_query-2021-03-25T22-13-59.842.log:110290:len:56138648  
./prod-tidb-2/tidb\_slow\_query-2021-03-26T05-04-55.975.log:831:len:56138977  
./prod-tidb-3/tidb\_slow\_query-2021-03-26T00-22-50.341.log:33:len:56139212  
./prod-tidb-5/tidb\_slow\_query-2021-03-26T02-23-23.029.log:16337:len:56139823  
./prod-tidb-2/tidb\_slow\_query-2021-03-25T23-11-28.351.log:30058:len:56139917  
./prod-tidb-6/tidb\_slow\_query-2021-03-25T22-42-32.402.log:15698:len:58409939  
./prod-tidb-2/tidb\_slow\_query-2021-03-26T05-04-55.975.log:14058:len:58410169  
./prod-tidb-3/tidb\_slow\_query-2021-03-26T08-04-08.711.log:481:len:58410997  
./prod-tidb-4/tidb\_slow\_query-2021-03-25T22-13-59.842.log:118088:len:59676620  
./prod-tidb-2/tidb\_slow\_query-2021-03-26T05-04-55.975.log:2079:len:59676855  
./prod-tidb-3/tidb\_slow\_query-2021-03-26T00-22-50.341.log:2645:len:59677184  
./prod-tidb-3/tidb\_slow\_query-2021-03-26T08-04-08.711.log:33:len:59677701  
./prod-tidb-6/tidb\_slow\_query-2021-03-25T22-42-32.402.log:38398:len:59677889  
./prod-tidb-4/tidb\_slow\_query-2021-03-26T13-51-46.989.log:5357:len:66522797  
./prod-tidb-3/tidb\_slow\_query-2021-03-26T14-18-48.126.log:34:len:66940815
```

The longest query is 66940815 bytes ... 63MB!

We can extend this a little further, to find the query patterns of the queries with the longest SQL text:

```{.bash .copyable}
find . -name '\*tidb\_slow\_query\*' -exec grep -HnEo 'len:\[0-9\]+' {} + |

sort -t: -k 4 -n |

tail -n 2000 |

while IFS=: read -r file ln \_; do

tail +"$ln" "$file" |

head -n1

done |

cut -b 1-100 | sort | uniq
```

* We're getting the 2000 queries with longest query text, and they're piped to a while loop
* The while loop uses read to iterate over all the input lines
    * IFS=: splits each input line on the colon character (instead of the default split on whitespace)
    * \-r tells read to ignore certain control characters that can cause problems
    * file ln \_ assigns the fields of each line, in order, to the file variable, ln variable, and the underscore discards the rest of them
* tail +"$ln" "$file" gets all the lines from the file starting with the matched line
* head -n1 gets only the first line of tail output, so only the matching line from the file
* cut -b 1-100 outputs only the first 100 bytes of each input line
* sort | uniq displays only unique input lines

Output:

```output
"SELECT /\*+ INL\_HASH\_JOIN(m2) \*/ m2.gid, m2.thread\_id FROM messages m1 JOIN messages m2 USING (rfc\_m  
"SELECT gid, thread\_id, message\_id, attachment\_id, mime\_type, name, size, content\_id FROM message\_fi  
"SELECT gid, thread\_id, message\_id, email, name, domain, is\_bcc, is\_cc, is\_delivered\_to, is\_from, is  
"SELECT gid, thread\_id, message\_id, history\_id, internal\_date, list\_id, rfc\_message\_id, seen\_on\_inde  
```

These 4 query patterns account for all 2000 of the queries with the longest query text.

**The customer was able to use this information to confirm that a recent fix to reduce the size of the IN() lists for problematic queries addressed all of these query patterns!**

## Related articles

[Working with slow query logs](https://internal.pingcap.net/confluence/display/CS/Working+with+slow+query+logs)

### Meta

\#performance \#tuning \#slow \#kb-troubleshooting-article