痛定思痛，一個慢SQL引起的慘案，我悟出了許多！

事故

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

寫代碼

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

假裝看不見

趕緊切流到備庫，回滾代碼。然後查看錯誤日誌，發現數據庫連接池報了大量的超時錯誤，這種情況一般有兩種可能：

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

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

覆盤

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

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

<code>
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);/<code>

開啟慢SQL日誌：

<code>
SET
 
GLOBAL
 slow_query_log=
1
;/<code>

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

<code>import 
random
if 
 __name__ == 
'__main__'
:
    SQL_file = 
open
(
'./batch_jq.SQL'
, 
'w'
, encoding=
'utf-8'
)
    a1 = [
'張'
, 
'金'
, 
'李'
, 
'王'
, 
'趙'
]
    a2 = [
'玉'
, 
'明'
, 
'龍'
, 
'芳'
, 
'軍'
, 
'玲'
]
    a3 = [
''
, 
'立'
, 
'玲'
, 
''
, 
'國'
, 
''
]
    _len = 
5000
 # 
5
k次循環
     
while
 _len >= 
1
:
        line = 
'insert into demo(name, age, score) values '
        arr = []
        # 每次批量插入
1
k條
        
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
/<code>

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

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

<code>
...
[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)
/<code>

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

<code> 
public
 
class
 
DemoController
 
{

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

     
    
private
 JdbcTemplate jdbcTemplate;

     
     (
"trigger"
)
    
public
 String 
trigger
()
 
{
        
long
 before = System.currentTimeMillis();
        jdbcTemplate.query(
"select * from demo.demo where score , (set) -> {
        });
        
long
 after = System.currentTimeMillis();
        LOGGER.info(
"調用時間: {} ms"
, after - before);
        
return
 
"success"
;
    }
}
/<code>

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

於是上ab壓測一下：

<code>$ ab -n500 -c20 http: 
/<code>

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

<code>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
....../<code>

再加大一點併發數量：

<code>$ ab -n500 -c50 http: 
/<code>

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

<code>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
 30000
ms
.
 
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]
/<code>

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

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

<code>> SHOW 
GLOBAL
 STATUS LIKE 
'%Slow_queries%'
;
| Slow_queries | 
51
 |/<code>

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

<code>
SHOW
 
FULL
 
processlist
;/<code>

SQL詳情

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

當然了，實際項目的表並不是這麼簡單，SQL語句和索引也更加複雜，這裡只是為了演示方便創建了一個簡單的實例。

而且現在有很多優秀的數據庫監控工具，能夠更方便美觀地展示日誌和排查數據庫問題，比如阿里的Druid等。

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

調優

使用索引

很多時候，慢SQL都可以通過使用索引來解決。

通過問題定位我們發現，我們對於某一個字段有高頻的查詢需求，但沒有為其建索引。MySQL的索引都是“最左匹配原則”，所以現有的聯合索引age, score並不能命中我們的這個高頻查詢。

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

使用緩存

通過分析我們發現，這些慢SQL其實執行的查詢條件都是一模一樣的。也就是說，我們可以把查詢結果放到緩存裡，這樣後續的查詢就可以直接去緩存取，可以大幅提升性能。

其實現在主流的ORM框架都是支持緩存的，甚至可以多級緩存，Spring也提供了緩存框架「Spring Cache」可以根據自己的需要去配置和使用。

反思

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

利用好explain

「我們的SQL語句，在使用前可以儘量先explain一下」，看有沒有命中索引，如果沒有命中，考慮一下是不是高頻語句，是不是需要調優。

進行充分的壓測

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

利用好日誌和監控

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

作者：編了個程

鏈接：

https://juejin.im/post/5e9dafd06fb9a03c585c1050

來源：掘金