事故

一個風和日麗的下午，程式員小齊和往常一樣，正在寫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一下」，看有沒有命中索引，如果沒有命中，考慮一下是不是高頻陳述句，是不是需要調優，

進行充分的壓測

線上無小事，切勿盲目自信，認為自己寫的程式就一定沒有問題，直接部署到生產環境，如果能夠在上線之前做一些壓測，就能夠盡早發現性能問題，及時止損，

利用好日志和監控

通常情況下，我們是在晚上等用戶使用量低的時候發布上線的，如果我們能夠配置好錯誤日志的采集、以及資料庫監控與告警，或許就能趕在大量用戶發現之前注意到這個問題，那就可以盡早解決，減小用戶和公司的損失，