開發與維運

線上故障如何快速排查?來看這套技巧大全

1.jpg

前言

線上定位問題時,主要靠監控和日誌。一旦超出監控的範圍,則排查思路很重要,按照流程化的思路來定位問題,能夠讓我們在定位問題時從容、淡定,快速的定位到線上的問題。

2.jpg

線上問題定位思維導圖

一 服務器層面

1.1 磁盤

1.1.1 問題現象

當磁盤容量不足的時候,應用時常會拋出如下的異常信息:

java.io.IOException: 磁盤空間不足

或是類似如下告警信息:
3.jpg

1.1.2 排查思路
1.1.2.1 利用 df 查詢磁盤狀態

利用以下指令獲取磁盤狀態:

df -h

結果是:
4.jpg

可知 / 路徑下佔用量最大。

1.1.2.2 利用 du 查看文件夾大小

利用以下指令獲取目錄下文件夾大小:

du -sh *

結果是:

5.jpg

可知root文件夾佔用空間最大,然後層層遞推找到對應的最大的一個或數個文件夾。

1.1.2.3 利用 ls 查看文件大小

利用以下指令獲取目錄下文件夾大小:

ls -lh

結果是:
6.jpg

可以找到最大的文件是日誌文件,然後使用rm指令進行移除以釋放磁盤。

1.1.3 相關命令
1.1.3.1 df

主要是用於顯示目前在 Linux 系統上的文件系統磁盤使用情況統計。

(1)常用參數

啟動參數:

7.jpg
(2)結果參數
8.jpg
9.jpg
1.1.3.2 du

主要是為了顯示目錄或文件的大小。

(1)常用參數

啟動參數:
10.jpg
(2)結果參數

1d23413adb892d602c344099bf3fb13.jpg

1.1.3.3 ls

主要是用於顯示指定工作目錄下的內容的信息。

(1)常用參數

啟動參數:
11.jpg
(2)結果參數

12.jpg

1.2 CPU過高

1.2.1 問題現象

當CPU過高的時候,接口性能會快速下降,同時監控也會開始報警。

1.2.2 排查思路
1.2.2.1 利用 top 查詢CPU使用率最高的進程

利用以下指令獲取系統CPU使用率信息:

top

結果是:
13.jpg
從而可以得知pid為14201的進程使用CPU最高。

1.2.3 相關命令
1.2.3.1 top

(1)常用參數

啟動參數:
14.jpg
top進程內指令參數:
15.jpg
(2)結果參數
16.jpg
17.jpg

二 應用層面

2.1 Tomcat假死案例分析

2.1.1 發現問題

監控平臺發現某個Tomcat節點已經無法採集到數據,連上服務器查看服務器進程還在,netstat -anop|grep 8001端口也有監聽,查看日誌打印時斷時續。
18.jpg

2.2.2 查詢日誌

查看NG日誌,發現有數據進入到當前服務器(有8001和8002兩個Tomcat),NG顯示8002節點訪問正常,8001節點有404錯誤打印,說明Tomcat已經處於假死狀態,這個Tomcat已經不能正常工作了。

過濾Tomcat節點的日誌,發現有OOM的異常,但是重啟後,有時候Tomcat掛掉後,又不會打印如下OOM的異常:

TopicNewController.getTopicSoftList() error="Java heap space 
From class java.lang.OutOfMemoryError"appstore_apitomcat
2.2.3 獲取內存快照

在一次OOM發生後立刻抓取內存快照,需要執行命令的用戶與JAVA進程啟動用戶是同一個,否則會有異常:

/data/program/jdk/bin/jmap -dump:live,format=b,file=/home/www/jmaplogs/jmap-8001-2.bin 18760

ps -ef|grep store.cn.xml|grep -v grep|awk '{print $2}'|xargs /data/program/jdk-1.8.0_11/bin/jmap -dump:live,format=b,file=api.bin

內存dump文件比較大,有1.4G,先壓縮,然後拉取到本地用7ZIP解壓。

linux壓縮dump為.tgz。

在windows下用7zip需要經過2步解壓:

.bin.tgz---.bin.tar--.bin
2.2.4 分析內存快照文件

使用Memory Analyzer解析dump文件,發現有很明顯的內存洩漏提示。
19.jpg
點擊查看詳情,發現定位到了代碼的具體某行,一目瞭然:
20.jpg
查看shallow heap與retained heap能發現生成了大量的Object(810325個對象),後面分析代碼發現是上報softItem對象超過300多萬個對象,在循環的時候,所有的數據全部保存在某個方法中無法釋放,導致內存堆積到1.5G,從而超過了JVM分配的最大數,從而出現OOM。
21.jpg

java.lang.Object[810325] @ 0xb0e971e0

22.jpg

2.2.5 相關知識
2.2.5.1 JVM內存

1111.png
2.2.5.2 內存分配的流程
24.jpg
如果通過逃逸分析,則會先在TLAB分配,如果不滿足條件才在Eden上分配。

2.2.4.3 GC

25.jpg
(1)GC觸發的場景
26.jpg
2)GC Roots

GC Roots有4種對象:

  • 虛擬機棧(棧楨中的本地變量表)中的引用的對象,就是平時所指的java對象,存放在堆中。
  • 方法區中的類靜態屬性引用的對象,一般指被static修飾引用的對象,加載類的時候就加載到內存中。
  • 方法區中的常量引用的對象。
  • 本地方法棧中JNI(native方法)引用的對象。

(3)GC算法

27.jpg

  • 串行只使用單條GC線程進行處理,而並行則使用多條。
  • 多核情況下,並行一般更有執行效率,但是單核情況下,並行未必比串行更有效率。

28.jpg

  • STW會暫停所有應用線程的執行,等待GC線程完成後再繼續執行應用線程,從而會導致短時間內應用無響應。
  • Concurrent會導致GC線程和應用線程併發執行,因此應用線程和GC線程互相搶用CPU,從而會導致出現浮動垃圾,同時GC時間不可控。

(4)新生代使用的GC算法
29.jpg

  • 新生代算法都是基於Coping的,速度快。
  • Parallel Scavenge:吞吐量優先。
    • 吞吐量=運行用戶代碼時間 /(運行用戶代碼時間 + 垃圾收集時間)

(5)老年代使用的GC算法
30.jpg
31.jpg

Parallel Compacting

32.jpg

Concurrent Mark-Sweep(CMS)

(6)垃圾收集器總結
33.jpg
(7)實際場景中算法使用的組合
34.jpg
(8)GC日誌格式

(a)監控內存的OOM場景

不要在線上使用jmap手動抓取內存快照,其一系統OOM時手工觸發已經來不及,另外在生成dump文件時會佔用系統內存資源,導致系統崩潰。只需要在JVM啟動參數中提取設置如下參數,一旦OOM觸發會自動生成對應的文件,用MAT分析即可。

# 內存OOM時,自動生成dump文件 
-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/

如果Young GC比較頻繁,5S內有打印一條,或者有Old GC的打印,代表內存設置過小或者有內存洩漏,此時需要抓取內存快照進行分享。

(b)Young Gc日誌

2020-09-23T01:45:05.487+0800: 126221.918: [GC (Allocation Failure) 2020-09-23T01:45:05.487+0800: 126221.918: [ParNew: 1750755K->2896K(1922432K), 0.0409026 secs] 1867906K->120367K(4019584K), 0.0412358 secs] [Times: user=0.13 sys=0.01, real=0.04 secs]

35.jpg
(c)Old GC日誌

2020-10-27T20:27:57.733+0800: 639877.297: [Full GC (Heap Inspection Initiated GC) 2020-10-27T20:27:57.733+0800: 639877.297: [CMS: 165992K->120406K(524288K), 0.7776748 secs] 329034K->120406K(1004928K), [Metaspace: 178787K->178787K(1216512K)], 0.7787158 secs] [Times: user=0.71 sys=0.00, real=0.78 secs]

36.jpg

2.2 應用CPU過高

2.2.1 發現問題

一般情況下會有監控告警進行提示:
37.jpg

2.2.2 查找問題進程

利用top查到佔用cpu最高的進程pid為14,結果圖如下:
38.jpg

2.2.3 查找問題線程

利用 top -H -p 查看進程內佔用cpu最高線程,從下圖可知,問題線程主要是activeCpu Thread,其pid為417。
39.jpg

2.2.4 查詢線程詳細信息
  • 首先利用 printf "%x n" 將tid換為十六進制:xid。
  • 再利用 jstack | grep nid=0x -A 10 查詢線程信息(若進程無響應,則使用 jstack -f ),信息如下:

40.jpg

2.2.5 分析代碼

由上一步可知該問題是由 CpuThread.java 類引發的,故查詢項目代碼,獲得如下信息:
41.jpg

2.2.6 獲得結論

根據代碼和日誌分析,可知是由於限制值max太大,致使線程長時間循環執行,從而導致問題出現。

三 Mysql

3.1 死鎖

3.1.1 問題出現

最近線上隨著流量變大,突然開始報如下異常,即發生了死鎖問題:

Deadlock found when trying to get lock; try restarting transaction ;
3.1.2 問題分析
3.1.2.1 查詢事務隔離級別

利用 select @@tx_isolation 命令獲取到數據庫隔離級別信息:
42.jpg

3.1.2.2 查詢數據庫死鎖日誌

利用 show engine innodb status 命令獲取到如下死鎖信息:
43.jpg
44.jpg
由上可知,是由於兩個事物對這條記錄同時持有S鎖(共享鎖)的情況下,再次嘗試獲取該條記錄的X鎖(排它鎖),從而導致互相等待引發死鎖。

3.1.2.3 分析代碼

根據死鎖日誌的SQL語句,定位獲取到如下偽代碼邏輯:

@Transactional(rollbackFor = Exception.class)
void saveOrUpdate(MeetingInfo info) {
    // insert ignore into table values (...)
    int result = mapper.insertIgnore(info);
    if (result>0) {
       return;
    }
    // update table set xx=xx where id = xx
    mapper.update(info);
}
3.1.2.4 獲得結論

分析獲得產生問題的加鎖時序如下,然後修改代碼實現以解決該問題。
45.jpg

3.2 慢SQL

3.2.1 問題出現

應用TPS下降,並出現SQL執行超時異常或者出現了類似如下的告警信息,則常常意味著出現了慢SQL。
46.jpg

3.2.2 問題分析

分析執行計劃:利用explain指令獲得該SQL語句的執行計劃,根據該執行計劃,可能有兩種場景。

SQL不走索引或掃描行數過多等致使執行時長過長。

SQL沒問題,只是因為事務併發導致等待鎖,致使執行時長過長。

3.2.3 場景一
3.2.3.1 優化SQL

通過增加索引,調整SQL語句的方式優化執行時長, 例如下的執行計劃:
47.jpg

該SQL的執行計劃的type為ALL,同時根據以下type語義,可知無索引的全表查詢,故可為其檢索列增加索引進而解決。
48.jpg

3.2.4 場景二
3.2.4.1 查詢當前事務情況

可以通過查看如下3張表做相應的處理:

-- 當前運行的所有事務
select *  from information_schema.innodb_trx;
-- 當前出現的鎖
SELECT * FROM information_schema.INNODB_LOCKS;
-- 鎖等待的對應關係
select *  from information_schema.INNODB_LOCK_WAITS;

(1)查看當前的事務有哪些:
49.jpg
(2)查看事務鎖類型索引的詳細信息:
50.jpg
lock_table字段能看到被鎖的索引的表名,lock_mode可以看到鎖類型是X鎖,lock_type可以看到是行鎖record。

3.2.4.2 分析

根據事務情況,得到表信息,和相關的事務時序信息:

DROP TABLE IF EXISTS `emp`;
CREATE TABLE `emp` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`salary` int(10) DEFAULT NULL,
`name` varchar(255) DEFAULT NULL,
PRIMARY KEY (`id`),
KEY `idx_name` (`name`(191)) USING BTREE
) ENGINE=InnoDB AUTO_INCREMENT=6 DEFAULT CHARSET=utf8mb4;

A事物鎖住一條記錄,不提交,B事物需要更新此條記錄,此時會阻塞,如下圖是執行順序:
51.jpg

3.2.4.3 解決方案

(1)修改方案

由前一步的結果,分析事務間加鎖時序,例如可以通過tx_query字段得知被阻塞的事務SQL,trx_state得知事務狀態等,找到對應代碼邏輯,進行優化修改。

(2)臨時修改方案

trx_mysql_thread_id是對應的事務sessionId,可以通過以下命令殺死長時間執行的事務,從而避免阻塞其他事務執行。

kill 105853

3.3 連接數過多

3.3.1 問題出現

常出現too many connections異常,數據庫連接到達最大連接數。

3.3.2 解決方案

解決方案:

通過set global max_connections=XXX增大最大連接數。

先利用show processlist獲取連接信息,然後利用kill殺死過多的連。

常用腳本如下:

排序數據庫連接的數目 
mysql -h127.0.0.0.1 -uabc_test -pXXXXX -P3306 -A -e 'show processlist'| awk '{print $4}'|sort|uniq -c|sort -rn|head -10

3.4 相關知識

3.4.1 索引

3.4.1.1 MySql不同的存儲引擎
52.jpg

3.4.1.2 InnoDB B+Tree索引實現

主鍵索引(聚集索引):

  • 葉子節點data域保存了完整的數據的地址。
  • 主鍵與數據全部存儲在一顆樹上。
  • Root節點常駐內存。
  • 每個非葉子節點一個innodb_page_size大小,加速磁盤IO。
  • 磁盤的I/O要比內存慢幾百倍,而磁盤慢的原因在於機械設備尋找磁道慢,因此採用磁盤預讀,每次讀取一個磁盤頁(page:計算機管理存儲器的邏輯塊-通常為4k)的整倍數。
  • 如果沒有主鍵,MySQL默認生成隱含字段作為主鍵,這個字段長度為6個字節,類型為長整形。
  • 輔助索引結構與主索引相同,但葉子節點data域保存的是主鍵指針。
  • InnoDB以表空間Tablespace(idb文件)結構進行組織,每個Tablespace 包含多個Segment段。
  • 每個段(分為2種段:葉子節點Segment&非葉子節點Segment),一個Segment段包含多個Extent。
  • 一個Extent佔用1M空間包含64個Page(每個Page 16k),InnoDB B-Tree 一個邏輯節點就分配一個物理Page,一個節點一次IO操作。
  • 一個Page裡包含很多有序數據Row行數據,Row行數據中包含Filed屬性數據等信息。

InnoDB存儲引擎中頁的大小為16KB,一般表的主鍵類型為INT(佔用4個字節)或BIGINT(佔用8個字節),指針類型也一般為4或8個字節,也就是說一個頁(B+Tree中的一個節點)中大概存儲16KB/(8B+8B)=1K個鍵值(因為是估值,為方便計算,這裡的K取值為[10]^3)。

也就是說一個深度為3的B+Tree索引可以維護 10^3 10^3 10^3 = 10億 條記錄。
53.jpg
每個索引的左指針都是比自己小的索引/節點,右指針是大於等於自己的索引/節點。

3.4.2 B+ Tree索引檢索
3.4.2.1 主鍵索引檢索
select * from table where id = 1

54.jpg

3.4.2.2 輔助索引檢索
select * from table where name = 'a'

55.jpg

3.4.3 事物的隔離級別
3.4.3.1 如何查看數據庫的事務隔離級別

使用如下命令可以查看事務的隔離級別:

show variables like 'tx_isolation';

阿里雲上的rds的隔離級別是read committed ,而不是原生mysql的“可重複讀(repeatable-read)。
56.jpg

  • Repeatable read不存在幻讀的問題,RR隔離級別保證對讀取到的記錄加鎖 (記錄鎖),同時保證對讀取的範圍加鎖,新的滿足查詢條件的記錄不能夠插入 (間隙鎖),不存在幻讀現象。
  • 在MYSQL的事務引擎中,INNODB是使用範圍最廣的。它默認的事務隔離級別是REPEATABLE READ(可重複讀),在標準的事務隔離級別定義下,REPEATABLE READ是不能防止幻讀產生的。INNODB使用了next-key locks實現了防止幻讀的發生。
  • 在默認情況下,mysql的事務隔離級別是可重複讀,並且innodb_locks_unsafe_for_binlog參數為OFF,這時默認採用next-key locks。所謂Next-Key Locks,就是Record lock和gap lock的結合,即除了鎖住記錄本身,還要再鎖住索引之間的間隙。可以設置為ON,則RR隔離級別時會出現幻讀。
3.4.3.2 多版本併發控制MVCC

MySQL InnoDB存儲引擎,實現的是基於多版本的併發控制協議——MVCC (Multi-Version Concurrency Control) (注:與MVCC相對的,是基於鎖的併發控制,Lock-Based Concurrency Control)。

MVCC最大的好處,相信也是耳熟能詳:讀不加鎖,讀寫不衝突。在讀多寫少的OLTP應用中,讀寫不衝突是非常重要的,極大的增加了系統的併發性能。

在MVCC併發控制中,讀操作可以分成兩類:快照讀 (snapshot read)與當前讀 (current read)。

快照讀:簡單的select操作,屬於快照讀,不加鎖。(當然,也有例外,下面會分析)。

select * from table where ?;

當前讀:特殊的讀操作,插入/更新/刪除操作,屬於當前讀,需要加鎖。

select * from table where ? lock in share mode;    加S鎖 (共享鎖)
-- 下面的都是X鎖 (排它鎖)
select * from table where ? for update;

insert into table values (…);

update table set ? where ?;

delete from table where ?;
3.4.4.3 場景模擬

修改事務隔離級別的語句:

SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ;  
-- READ UNCOMMITTED/READ COMMITTED/REPEATABLE READ/SERIALIZABLE

(1)髒讀場景模擬

DROP TABLE IF EXISTS `employee`;
CREATE TABLE `employee` (
  `id` int(11) NOT NULL,
  `name` varchar(50) NOT NULL,
  `salary` int(11) DEFAULT NULL,
  KEY `IDX_ID` (`id`) USING BTREE
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

-- ----------------------------
-- Records of employee
-- ----------------------------
INSERT INTO `employee` VALUES ('10', '1s', '10');
INSERT INTO `employee` VALUES ('20', '2s', '20');
INSERT INTO `employee` VALUES ('30', '3s', '30');

57.jpg

髒讀場景模擬

(2)不可重複讀模擬

DROP TABLE IF EXISTS `employee`;
CREATE TABLE `employee` (
  `id` int(11) NOT NULL,
  `name` varchar(50) NOT NULL,
  `salary` int(11) DEFAULT NULL,
  KEY `IDX_ID` (`id`) USING BTREE
) ENGINE=InnoDB DEFAULT CHARSET=utf8;


-- ----------------------------
-- Records of employee
-- ----------------------------
INSERT INTO `employee` VALUES ('10', '1s', '10');
INSERT INTO `employee` VALUES ('20', '2s', '20');
INSERT INTO `employee` VALUES ('30', '3s', '30');

不可重複讀的重點是修改: 同樣的條件, 你讀取過的數據, 再次讀取出來發現值不一樣了。
58.jpg
(3)幻讀場景模擬

表結構與數據如下:id不是主鍵,也不是唯一索引,只是一個普通索引,事務隔離級別設置的是RR,可以模擬到GAP鎖產生的場景。

DROP TABLE IF EXISTS `emp`;
CREATE TABLE `emp` (
  `id` int(11) NOT NULL,
  `salary` int(11) DEFAULT NULL,
  KEY `IDX_ID` (`id`) USING BTREE
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

-- ----------------------------
-- Records of emp
-- ----------------------------
INSERT INTO `emp` VALUES ('10', '10');
INSERT INTO `emp` VALUES ('20', '20');
INSERT INTO `emp` VALUES ('30', '30');

修改id=20的數據後,會在加多個鎖:20會被加X鎖,[10-20],[20-30]之間會被加GAP鎖。
59.jpg
幻讀的重點在於新增或者刪除 (數據條數變化)。同樣的條件, 第1次和第2次讀出來的記錄數不一樣。

在標準的事務隔離級別定義下,REPEATABLE READ是不能防止幻讀產生的。INNODB使用了2種技術手段(MVCC AND GAP LOCK)實現了防止幻讀的發生。

3.4.4 Innodb的多種鎖
3.4.4.1 鎖類型

60.jpg

  • 表鎖的優勢:開銷小;加鎖快;無死鎖。
  • 表鎖的劣勢:鎖粒度大,發生鎖衝突的概率高,併發處理能力低。
  • 加鎖的方式:自動加鎖。查詢操作(SELECT),會自動給涉及的所有表加讀鎖,更新操作(UPDATE、DELETE、INSERT),會自動給涉及的表加寫鎖。也可以顯示加鎖。
  • 共享讀鎖:lock table tableName read
  • 獨佔寫鎖:lock table tableName write
  • 批量解鎖:unlock tables
3.4.4.2 行鎖

61.jpg
只在Repeatable read和Serializable兩種事務隔離級別下才會取得上面的鎖。

3.4.4.3 意向鎖

(1)場景

在mysql中有表鎖,LOCK TABLE my_tabl_name READ; 用讀鎖鎖表,會阻塞其他事務修改表數據。LOCK TABLE my_table_name WRITe; 用寫鎖鎖表,會阻塞其他事務讀和寫。

Innodb引擎又支持行鎖,行鎖分為共享鎖,一個事務對一行的共享只讀鎖。排它鎖,一個事務對一行的排他讀寫鎖。

這兩中類型的鎖共存的問題考慮這個例子:

事務A鎖住了表中的一行,讓這一行只能讀,不能寫。之後,事務B申請整個表的寫鎖。如果事務B申請成功,那麼理論上它就能修改表中的任意一行,這與A持有的行鎖是衝突的。

數據庫需要避免這種衝突,就是說要讓B的申請被阻塞,直到A釋放了行鎖。

(2)問題

數據庫要怎麼判斷這個衝突呢?

(3)答案

無意向鎖的情況下:

step1:判斷表是否已被其他事務用表鎖鎖表

step2:判斷表中的每一行是否已被行鎖鎖住。

有意向鎖的情況下:

  • step1:不變
  • step2:發現表上有意向共享鎖,說明表中有些行被共享行鎖鎖住了,因此,事務B申請表的寫鎖會被阻塞。

(4)總結

在無意向鎖的情況下,step2需要遍歷整個表,才能確認是否能拿到表鎖。而在意向鎖存在的情況下,事務A必須先申請表的意向共享鎖,成功後再申請一行的行鎖,不需要再遍歷整個表,提升了效率。因此意向鎖主要是為了實現多粒度鎖機制(白話:為了表鎖和行鎖都能用)。

3.4.4.4 X/S鎖

62.jpg

3.4.4.5 一條SQL的加鎖分析
-- select操作均不加鎖,採用的是快照讀,因此在下面的討論中就忽略了
SQL1:select * from t1 where id = 10;
SQL2:delete from t1 where id = 10;

組合分為如下幾種場景:
63.jpg
(1)組合7的GAP鎖詳解讀

Insert操作,如insert [10,aa],首先會定位到[6,c]與[10,b]間,然後在插入前,會檢查這個GAP是否已經被鎖上,如果被鎖上,則Insert不能插入記錄。因此,通過第一遍的當前讀,不僅將滿足條件的記錄鎖上 (X鎖),與組合三類似。同時還是增加3把GAP鎖,將可能插入滿足條件記錄的3個GAP給鎖上,保證後續的Insert不能插入新的id=10的記錄,也就杜絕了同一事務的第二次當前讀,出現幻象的情況。

既然防止幻讀,需要靠GAP鎖的保護,為什麼組合五、組合六,也是RR隔離級別,卻不需要加GAP鎖呢?

GAP鎖的目的,是為了防止同一事務的兩次當前讀,出現幻讀的情況。而組合五,id是主鍵;組合六,id是unique鍵,都能夠保證唯一性。

一個等值查詢,最多隻能返回一條記錄,而且新的相同取值的記錄,一定不會在新插入進來,因此也就避免了GAP鎖的使用。

(2)結論

  • Repeatable Read隔離級別下,id列上有一個非唯一索引,對應SQL:delete from t1 where id = 10; 首先,通過id索引定位到第一條滿足查詢條件的記錄,加記錄上的X鎖,加GAP上的GAP鎖,然後加主鍵聚簇索引上的記錄X鎖,然後返回;然後讀取下一條,重複進行。直至進行到第一條不滿足條件的記錄[11,f],此時,不需要加記錄X鎖,但是仍舊需要加GAP鎖,最後返回結束。
  • 什麼時候會取得gap lock或nextkey lock 這和隔離級別有關,只在REPEATABLE READ或以上的隔離級別下的特定操作才會取得gap lock或nextkey lock。
3.4.5 線上問題處理
3.4.5.1 觀察問題的幾個常見庫表

首先可以通過下屬兩個命令來查看mysql的相應的系統變量和狀態變量。

# status代表當前系統的運行狀態,只能查看,不能修改
show status like '%abc%';
show variables like '%abc%';

MySQL 5.7.6開始後改成了從如下表獲取:

performance_schema.global_variables 
performance_schema.session_variables 
performance_schema.variables_by_thread 
performance_schema.global_status 
performance_schema.session_status 
performance_schema.status_by_thread 
performance_schema.status_by_account 
performance_schema.status_by_host 
performance_schema.status_by_user

之前是從如下表獲取:

INFORMATION_SCHEMA.GLOBAL_VARIABLES 
INFORMATION_SCHEMA.SESSION_VARIABLES 
INFORMATION_SCHEMA.GLOBAL_STATUS 
INFORMATION_SCHEMA.SESSION_STATUS

比較常用的系統變量和狀態變量有:

# 查詢慢SQL查詢是否開啟
show variables like 'slow_query_log';
# 查詢慢SQL的時間
show variables like 'long_query_time';
# 查看慢SQL存放路徑,一般:/home/mysql/data3016/mysql/slow_query.log
show variables like 'slow_query_log_file';

# 查看數據庫的事務隔離級別,RDS:READ-COMMITTED   Mysql:Repeatable read
show variables like 'tx_isolation'; 
 # innodb數據頁大小  16384
show variables like 'innodb_page_size'; 

show status  like 'innodb_row_%';

# 查看慢SQL
SHOW SLOW limit 10;
show full slow limit 10;

# 查看autocommit配置
select @@autocommit; 
 # 同上
show variables like 'autocommit'; 
#設置SQL自動提交模式  1:默認,自動提交   0:需要手動觸發commit,否則不會生效
set autocommit=1;  
# 查看默認的搜索引擎
show variables like '%storage_engine%'; 

# 設置事務隔離級別
SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ;

3.5 一些建議

3.5.1 小表驅動大表
  • nb_soft_nature:小表
  • nb_soft:大表
  • package_name:都是索引

MySQL 表關聯的算法是Nest Loop Join(嵌套循環連接),是通過驅動表的結果集作為循環基礎數據,然後一條一條地通過該結果集中的數據作為過濾條件到下一個表中查詢數據,然後合併結果。

(1)小表驅動大表
64.jpg
nb_soft_nature 中只有24條數據,每條數據的package_name連接到nb_soft表中做查詢,由於package_name在nb_soft表中有索引,因此一共只需要24次掃描即可。

(2)大表驅動小表
65.jpg
同上,需要100多萬次掃描才能返回結果

3.5.2 使用自增長主鍵

結合B+Tree的特點,自增主鍵是連續的,在插入過程中儘量減少頁分裂,即使要進行頁分裂,也只會分裂很少一部分。並且能減少數據的移動,每次插入都是插入到最後。總之就是減少分裂和移動的頻率。

四 Redis

4.1 問題處理思路

66.jpg

4.2 內存告警

時常會出現下述異常提示信息:

OOM command not allowed when used memory
4.2.1 設置合理的內存大小

設置maxmemory和相對應的回收策略算法,設置最好為物理內存的3/4,或者比例更小,因為redis複製數據等其他服務時,也是需要緩存的。以防緩存數據過大致使redis崩潰,造成系統出錯不可用。

(1)通過redis.conf 配置文件指定

maxmemory xxxxxx

(2)通過命令修改

config set  maxmemory xxxxx
4.2.2 設置合理的內存淘汰策略

67.jpg
(1)通過redis.conf 配置文件指定

maxmemory-policy allkeys-lru
4.2.3 查看大key

(1)有工具的情況下:

安裝工具dbatools redisTools,列出最大的前N個key

/data/program/dbatools-master/redisTools/redis-cli-new -h <ip> -p <port> --bigkeys --bigkey-numb 3

得到如下結果:

Sampled 122114 keys in the keyspace!
Total key length in bytes is 3923725 (avg len 32.13)


Biggest string Key Top   1  found 'xx1' has 36316 bytes
Biggest string Key Top   2  found 'xx2' has 1191 bytes
Biggest string Key Top   3  found 'xx3' has 234 bytes
Biggest   list Key Top   1  found 'x4' has 204480 items
Biggest   list Key Top   2  found 'x5' has 119999 items
Biggest   list Key Top   3  found 'x6' has 60000 items
Biggest    set Key Top   1  found 'x7' has 14205 members
Biggest    set Key Top   2  found 'x8' has 292 members
Biggest    set Key Top   3  found 'x,7' has 21 members
Biggest   hash Key Top   1  found 'x' has 302939 fields
Biggest   hash Key Top   2  found 'xc' has 92029 fields
Biggest   hash Key Top   3  found 'xd' has 39634 fields

原生命令為:

/usr/local/redis-3.0.5/src/redis-cli -c -h <ip> -p <port> --bigkeys

分析rdb文件中的全部key/某種類型的佔用量:

rdb -c memory dump.rdb -t list -f dump-formal-list.csv

查看某個key的內存佔用量:

[root@iZbp16umm14vm5kssepfdpZ redisTools]# redis-memory-for-key  -s <ip> -p <port> x
Key             x
Bytes               4274388.0
Type                hash
Encoding            hashtable
Number of Elements      39634
Length of Largest Element   29

(2)無工具的情況下可利用以下指令評估key大小:

debug object key

4.3 Redis的慢命令

4.3.1 設置Redis的慢命令的時間閾值(單位:微妙)

(1)通過redis.conf配置文件方式

# 執行時間大於多少微秒(microsecond,1秒 = 1,000,000 微秒)的查詢進行記錄。
slowlog-log-lower-than 1000

# 最多能保存多少條日誌
slowlog-max-len 200

(2)通過命令方式

# 配置查詢時間超過1毫秒的, 第一個參數單位是微秒
config set slowlog-log-lower-than 1000

# 保存200條慢查記錄
config set slowlog-max-len 200
4.3.2 查看Redis的慢命令
slowlog get

4.4 連接過多

(1)通過redis.conf 配置文件指定最大連接數

maxclients 10000

(2)通過命令修改

config set maxclients xxx

4.5 線上Redis節點掛掉一個之後的處理流程

4.5.1 查看節點狀態

執行 cluster nodes 後發現會有一個節點dead:

[rgp@iZ23rjcqbczZ ~]$ /data/program/redis-3.0.3/bin/redis-cli -c -h <ip> -p <port>
ip:port> cluster nodes
9f194f671cee4a76ce3b7ff14d3bda190e0695d5 m1 master - 0 1550322872543 65 connected 10923-16383
a38c6f957f2706f269cf5d9b628586a9372265e9 s1 slave 9f194f671cee4a76ce3b7ff14d3bda190e0695d5 0 1550322872943 65 connected
77ce43ec23f25f77ec68fe71ae3cb799e7300c6d s2 slave 03d72a3a5050c85e280e0bbeb687056b84f10077 0 1550322873543 63 connected
03d72a3a5050c85e280e0bbeb687056b84f10077 m2 master - 0 1550322873343 63 connected 5461-10922
5799070c6a63314296f3661b315b95c6328779f7 :0 slave,fail,noaddr 6147bf416ef216b6a1ef2f100d15de4f439b7352 1550320811474 1550320808793 49 disconnected
6147bf416ef216b6a1ef2f100d15de4f439b7352 m3 myself,master - 0 0 49 connected 0-5460
4.5.2 移除錯誤節點

(1)一開始執行如下的刪除操作失敗,需要針對於每一個節點都執行 cluster forget:

ip:port> cluster forget 61c70a61ad91bbac231e33352f5bdb9eb0be6289
CLUSTER FORGET <node_id> 從集群中移除 node_id 指定的節點

(2)刪除掛掉的節點:

[rgp@iZ23rjcqbczZ ~]$ /data/program/redis-3.0.3/bin/redis-trib.rb del-node m3 b643d7baa69922b3fdbd1e25ccbe6ed73587b948
>>> Removing node b643d7baa69922b3fdbd1e25ccbe6ed73587b948 from cluster m3
>>> Sending CLUSTER FORGET messages to the cluster...
>>> SHUTDOWN the node.

(3)清理掉節點配置目錄下的rdb aof nodes.conf 等文件,否則節點的啟動會有如下異常:

[ERR] Node s3 is not empty. Either the node already knows other nodes (check with CLUSTER NODES) or contains some key in database 0.
4.5.3 恢復節點

(1)後臺啟動Redis某個節點:

/data/program/redis-3.0.3/bin/redis-server /data/program/redis-3.0.3/etc/7001/redis.conf &

(2)將該節點添加進集群:

[root@iZ23rjcqbczZ rgp]# /data/program/redis-3.0.3/bin/redis-trib.rb add-node  --slave --master-id 6147bf416ef216b6a1ef2f100d15de4f439b7352 s3 m3
>>> Adding node s3 to cluster m3
>>> Performing Cluster Check (using node m3)
M: 6147bf416ef216b6a1ef2f100d15de4f439b7352 m3
   slots:0-5460 (5461 slots) master
   0 additional replica(s)
M: 9f194f671cee4a76ce3b7ff14d3bda190e0695d5 m1
   slots:10923-16383 (5461 slots) master
   1 additional replica(s)
S: a38c6f957f2706f269cf5d9b628586a9372265e9 s1
   slots: (0 slots) slave
   replicates 9f194f671cee4a76ce3b7ff14d3bda190e0695d5
S: 77ce43ec23f25f77ec68fe71ae3cb799e7300c6d s2
   slots: (0 slots) slave
   replicates 03d72a3a5050c85e280e0bbeb687056b84f10077
M: 03d72a3a5050c85e280e0bbeb687056b84f10077 m2
   slots:5461-10922 (5462 slots) master
   1 additional replica(s)
[OK] All nodes agree about slots configuration.
>>> Check for open slots...
>>> Check slots coverage...
[OK] All 16384 slots covered.
>>> Send CLUSTER MEET to node s3 to make it join the cluster.
Waiting for the cluster to join..
>>> Configure node as replica of m3.
[OK] New node added correctly.
  • s3:本次待添加的從節點ip:port
  • m3:主節點的ip:port
  • 6147bf416ef216b6a1ef2f100d15de4f439b7352:主節點編號

五 網絡

5.1 排查流程

5.1.1 現象出現

在非壓測或者高峰期的情況下,突然出現大量的503等錯誤碼,頁面無法打開。

5.1.2 查看是否遭受了DOS攻擊

當Server上有大量半連接狀態且源IP地址是隨機的,則可以斷定遭到SYN攻擊了,使用如下命令可以讓之現行。

netstat -n|grep SYN_RECV
5.1.3 查看TCP連接狀態

首先利用以下查看tcp總連接數,判斷連接數是否正常:

netstat -anoe|grep 8000|wc -l 查看8000

然後利用如下命令判斷各個狀態的連接數是否正常:

netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'

根據上述信息,如果TIME_WAIT 狀態數量過多,可利用如下命令查看連接CLOSE_WAIT最多的IP地址,再結合業務分析問題:

netstat -n|grep TIME_WAIT|awk '{print $5}'|awk -F: '{print $1}'|sort|uniq -c|sort -nr|head -10

5.2 相關知識

5.2.1 TCP連接

TCP三次握手四次揮手
68.jpg
為什麼在第3步中客戶端還要再進行一次確認呢?這主要是為了防止已經失效的連接請求報文段突然又傳回到服務端而產生錯誤的場景:

所謂"已失效的連接請求報文段"是這樣產生的。正常來說,客戶端發出連接請求,但因為連接請求報文丟失而未收到確認。於是客戶端再次發出一次連接請求,後來收到了確認,建立了連接。數據傳輸完畢後,釋放了連接,客戶端一共發送了兩個連接請求報文段,其中第一個丟失,第二個到達了服務端,沒有"已失效的連接請求報文段"。

現在假定一種異常情況,即客戶端發出的第一個連接請求報文段並沒有丟失,只是在某些網絡節點長時間滯留了,以至於延誤到連接釋放以後的某個時間點才到達服務端。本來這個連接請求已經失效了,但是服務端收到此失效的連接請求報文段後,就誤認為這是客戶端又發出了一次新的連接請求。於是服務端又向客戶端發出請求報文段,同意建立連接。假定不採用三次握手,那麼只要服務端發出確認,連接就建立了。

由於現在客戶端並沒有發出連接建立的請求,因此不會理會服務端的確認,也不會向服務端發送數據,但是服務端卻以為新的傳輸連接已經建立了,並一直等待客戶端發來數據,這樣服務端的許多資源就這樣白白浪費了。

採用三次握手的辦法可以防止上述現象的發生。比如在上述的場景下,客戶端不向服務端的發出確認請求,服務端由於收不到確認,就知道客戶端並沒有要求建立連接。

SYN攻擊時一種典型的DDOS攻擊,檢測SYN攻擊的方式非常簡單,即當Server上有大量半連接狀態且源IP地址是隨機的,則可以斷定遭到SYN攻擊了,使用如下命令可以讓之現行:

netstat -nap | grep SYN_RECV

69.jpg

5.2.2 一些常見問題

(1)為什麼TCP連接的建立只需要三次握手而TCP連接的釋放需要四次握手呢?

因為服務端在LISTEN狀態下,收到建立請求的SYN報文後,把ACK和SYN放在一個報文裡發送給客戶端。而連接關閉時,當收到對方的FIN報文時,僅僅表示對方沒有需要發送的數據了,但是還能接收數據,己方未必數據已經全部發送給對方了,所以己方可以立即關閉,也可以將應該發送的數據全部發送完畢後再發送FIN報文給客戶端來表示同意現在關閉連接。

從這個角度而言,服務端的ACK和FIN一般都會分開發送。

(2)如果已經建立了連接,但是客戶端突然出現故障了怎麼辦?

TCP還設有一個保活計時器,顯然,客戶端如果出現故障,服務器不能一直等下去,白白浪費資源。服務器每收到一次客戶端的請求後都會重新復位這個計時器,時間通常是設置為2小時,若兩小時還沒有收到客戶端的任何數據,服務器就會發送一個探測報文段,以後每隔75秒鐘發送一次。若一連發送10個探測報文仍然沒反應,服務器就認為客戶端出了故障,接著就關閉連接。

(3)為什麼TIME_WAIT狀態需要經過2MSL(最大報文段生存時間)才能返回到CLOSE狀態?

雖然按道理,四個報文都發送完畢,我們可以直接進入CLOSE狀態了,但是我們必須假象網絡是不可靠的,有可以最後一個ACK丟失。所以TIME_WAIT狀態就是用來重發可能丟失的ACK報文。

在Client發送出最後的ACK回覆,但該ACK可能丟失。Server如果沒有收到ACK,將不斷重複發送FIN片段。所以Client不能立即關閉,它必須確認Server接收到了該ACK。Client會在發送出ACK之後進入到TIME_WAIT狀態。Client會設置一個計時器,等待2MSL的時間。如果在該時間內再次收到FIN,那麼Client會重發ACK並再次等待2MSL。所謂的2MSL是兩倍的MSL(Maximum Segment Lifetime)。

MSL指一個片段在網絡中最大的存活時間,2MSL就是一個發送和一個回覆所需的最大時間。如果直到2MSL,Client都沒有再次收到FIN,那麼Client推斷ACK已經被成功接收,則結束TCP連接。

六 業務異常日誌

6.1 問題出現

主要是通過業務日誌監控主動報警或者是查看錯誤日誌被動發現:
70.jpg

6.2 日誌分析

6.2.1 確認日誌格式

日誌格式如下:

<property name="METRICS_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS}|${APP_NAME}|%X{className}|%X{methodName}|%X{responseStatus}|%X{timeConsume}|%X{traceId}|%X{errorCode}|%msg%n"/>


 <property name="ERROR_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%X{traceId}|${APP_NAME}|%serverIp|%X{tenantId}|%X{accountId}|%thread|%logger{30}|%msg%n"/>


<!--日誌格式 時間|級別|鏈路id|應用名|服務器ip|租戶id|用戶id|線程名稱|logger名稱|業務消息 -->
<property name="BIZ_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss.SSS}|%-5level|%X{traceId}|${APP_NAME}|%serverIp|%X{tenantId}|%X{accountId}|%thread|%logger{30}|%msg%n"/>
6.2.2 在日誌文件中檢索異常

利用如下命令可獲得異常的詳細信息:

cat error.log|grep -n " java.lang.reflect.InvocationTargetException"

71.jpg
根據日誌格式和日誌信息,可獲得traceId為489d71fe-67db-4f59-a916-33f25d35cab8,然後利用以下指令獲取整個流程的日誌信息:

cat biz.log |grep -n '489d71fe-67db-4f59-a916-33f25d35cab8'

72.jpg

6.2.3 代碼分析

然後根據上述流程日誌找到對應的代碼實現,然後進行具體的業務分析。

Leave a Reply

Your email address will not be published. Required fields are marked *