一個慢SQL引發的慘案

每週至少一篇高質量原創技術文章

這是Yasin的第 1 篇原創文章

事故

一個風和日麗的下午，程序員小齊和往常同樣，正在寫bug。。。

寫代碼

忽然接到客服那邊的消息，說接到大量用戶投訴，頁面打不開了。小齊內心一咯噔，最近就本身發佈了新代碼，加了一個新功能，不會是那部分代碼出問題了吧？！！

僞裝看不見
趕忙切流到備庫，回滾代碼。而後查看錯誤日誌，發現數據庫鏈接池報了大量的超時錯誤，這種狀況通常有兩種可能：

• 一種是數據庫或者鏈接數據庫的網絡發生了某種意外，致使數據庫鏈接不上了，達到超時時間了；
• 另外一種多是有大量線程執行慢查詢，老線程還在執行查詢，新線程只能陷入等待，等待過久達到超時時間了。

最終定位到是數據庫慢查詢的問題致使的這個故障。一個高頻查詢「沒有命中索引，致使全表掃描」，單個查詢最少就須要一秒多，因此大量查詢請求堆積，超時。

覆盤

痛定思痛，小齊決定在本地覆盤一下這個故障。

首先，來一個極其簡單的demo表，再建立一個錯誤的索引age, score：

create table demo
(
    id    int auto_increment
        primary key,
    name  varchar(255) null,
    age   int          null,
    score int          null
);

create index idx_age_score
    on demo (age, score);

開啓慢SQL日誌：

SET GLOBAL slow_query_log=1;

而後，用python擼一個500w條隨機數據的SQL文件，出問題的那個線上表也差很少就這個量級：

import random
if __name__ == '__main__':
    SQL_file = open('./batch_jq.SQL', 'w', encoding='utf-8')
    a1 = ['張', '金', '李', '王', '趙']
    a2 = ['玉', '明', '龍', '芳', '軍', '玲']
    a3 = ['', '立', '玲', '', '國', '']
    _len = 5000 # 5k次循環
    while _len >= 1:
        line = 'insert into demo(name, age, score) values '
        arr = []
        # 每次批量插入1k條
        for i in range(1, 1001):
            name=random.choice(a1)+random.choice(a2)+random.choice(a3)
            arr.append((name, random.randint(1, 100), random.randint(1, 10000000)))
        _SQL = line + str(arr).strip('[]')
        SQL_file.write(_SQL + ';\n')
        _len -= 1

PS：這裏用的是批量插入，而不是一條一條插數據，這樣在運行SQL的時候能快一點點。

而後運行SQL插入500w條數據：

...
[2020-04-19 20:05:22] 24000 row(s) affected in 636 ms
...
[2020-04-19 20:05:23] 24000 row(s) affected in 638 ms
.
[2020-04-19 20:05:23] 8000 row(s) affected in 193 ms
[2020-04-19 20:05:23] Summary: 5000 of 5000 statements executed in 3 m 42 s 989 ms (106742400 symbols in file)

而後用SpringBoot + JdbcTemplate擼一個簡單的應用程序：

@RestController
public class DemoController {

    private static final Logger LOGGER = LoggerFactory.getLogger(DemoController.class);

    @Resource
    private JdbcTemplate jdbcTemplate;

    // 引起慢查詢業務的入口
    @GetMapping("trigger")
    public String trigger() {
        long before = System.currentTimeMillis();
        jdbcTemplate.query("select * from demo.demo where score < 20 limit 50", (set) -> {
        });
        long after = System.currentTimeMillis();
        LOGGER.info("調用時間: {} ms", after - before);
        return "success";
    }
}

嘗試調用了一下http://localhost:8080/trigger，發現差很少用了一秒多。雖然慢了點，可是還能接受。

因而上ab壓測一下：

$ ab -n500 -c20 http://localhost:8080/trigger
# 表明共500請求，每次併發數量爲20

這一壓測，發現日誌打印出的時間基本上在15秒左右，雖然已經很慢了，但沒有報錯，業務也還能正經常使用一用，並且數據庫裏也沒有慢查詢：

2020-04-19 20:56:21.665  INFO 18908 --- [nio-8080-exec-3] c.e.s.controller.DemoController          : 調用時間: 15260 ms
2020-04-19 20:56:21.779  INFO 18908 --- [io-8080-exec-10] c.e.s.controller.DemoController          : 調用時間: 15445 ms
......

再加大一點併發數量：

$ ab -n500 -c50 http://localhost:8080/trigger
# 表明共500請求，每次併發數量爲50

這個時候能夠看到控制檯打印出的調用時間激增，而後開始打印出一些異常信息：

2020-04-19 21:02:55.277 ERROR 17100 --- [io-8080-exec-45] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is java.SQL.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.] with root cause

java.SQL.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
 at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:689) ~[HikariCP-3.4.2.jar:na]
 at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:196) ~[HikariCP-3.4.2.jar:na]

示例代碼用的SpringBoot自帶的數據庫鏈接池Hikari，默認超時時間是30秒，若是超過30秒就會拋出異常。不論什麼鏈接池，雖然功能可能有些許不一樣，但基本上都會有超時時間這個配置。

網頁錯誤

這個時候在數據庫裏也多了一些慢SQL記錄：

> SHOW GLOBAL STATUS LIKE '%Slow_queries%';
| Slow_queries | 51 |

接下來是問題定位，執行下列SQL能夠打印出當前的鏈接狀態，能夠看看是什麼SQL語句在佔用時間：

SHOW FULL processlist;

SQL詳情

能夠很輕易地發現咱們的SQL執行時間超過了1秒。咱們拿着這個SQL去explain一下，發現走的是全表掃描。

固然了，實際項目的表並非這麼簡單，SQL語句和索引也更加複雜，這裏只是爲了演示方便建立了一個簡單的示例。

並且如今有不少優秀的數據庫監控工具，可以更方便美觀地展現日誌和排查數據庫問題，好比阿里的Druid等。

調優後，在本地一樣用50併發壓測一次，發現響應時間基本上維持在十幾毫秒左右，徹底無壓力。

調優

使用索引

不少時候，慢SQL均可以經過使用索引來解決。

經過問題定位咱們發現，咱們對於某一個字段有高頻的查詢需求，但沒有爲其建索引。MySQL的索引都是「最左匹配原則」，因此現有的聯合索引age, score並不能命中咱們的這個高頻查詢。

固然了，建太多索引也是有弊端的，這個根據本身的業務來就好。

使用緩存

經過分析咱們發現，這些慢SQL其實執行的查詢條件都是如出一轍的。也就是說，咱們能夠把查詢結果放到緩存裏，這樣後續的查詢就能夠直接去緩存取，能夠大幅提高性能。

其實如今主流的ORM框架都是支持緩存的，甚至能夠多級緩存，Spring也提供了緩存框架「Spring Cache」能夠根據本身的須要去配置和使用。

反思

覆盤與調優完了，接下來就到了面壁思過的時間了。

面壁思過

利用好explain

「咱們的SQL語句，在使用前能夠儘可能先explain一下」，看有沒有命中索引，若是沒有命中，考慮一下是否是高頻語句，是否是須要調優。

進行充分的壓測

線上無小事，切勿盲目自信，認爲本身寫的程序就必定沒有問題，直接部署到生產環境。若是可以在上線以前作一些壓測，就可以儘早發現性能問題，及時止損。

利用好日誌和監控

一般狀況下，咱們是在晚上等用戶使用量低的時候發佈上線的。若是咱們可以配置好錯誤日誌的採集、以及數據庫監控與告警，或許就能趕在大量用戶發現以前注意到這個問題。那就能夠儘早解決，減少用戶和公司的損失。

都看到這裏了，說明你承認個人文章。
若是對你有幫助，不妨支持我一下：
你的關注、點贊、轉發、在看，
都是我寫做路上最大的鼓勵。

每週至少推送一篇高質量原創技術文章，
週一早上8:50，不見不散~