Linux性能優化實戰學習筆記：第二十六講

1、案例環境描述

一、環境準備

2CPU,4GB內存

預先安裝docker sysstat工具

二、舒適提示

案例中 Python 應用的核心邏輯比較簡單，你可能一眼就能看出問題，但實際生產環境中的源碼就複雜多了。因此，
我依舊建議，操做以前別看源碼，避免先入爲主，要把它當成一個黑盒來分析。這樣 你能夠更好把握住，怎麼從系統的資源使用問題出發，分析出瓶頸
所在的應用，以及瓶頸在應用中大概的位置

三、應用環境

一、運行目標應用

docker run -v /tmp:/tmp --name=app -itd feisky/logapp 

二、確認應用正常啓動

ps -ef | grep /app.py 
root     18940 18921 73 14:41 pts/0    00:00:02 python /app.py 

2、故障現象

一、發現故障

# 按 1 切換到每一個 CPU 的使用狀況 
$ top 
top - 14:43:43 up 1 day,  1:39,  2 users,  load average: 2.48, 1.09, 0.63 
Tasks: 130 total,   2 running,  74 sleeping,   0 stopped,   0 zombie 
%Cpu0  :  0.7 us,  6.0 sy,  0.0 ni,  0.7 id, 92.7 wa,  0.0 hi,  0.0 si,  0.0 st 
%Cpu1  :  0.0 us,  0.3 sy,  0.0 ni, 92.3 id,  7.3 wa,  0.0 hi,  0.0 si,  0.0 st 
KiB Mem :  8169308 total,   747684 free,   741336 used,  6680288 buff/cache 
KiB Swap:        0 total,        0 free,        0 used.  7113124 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND 
18940 root      20   0  656108 355740   5236 R   6.3  4.4   0:12.56 python 
1312 root      20   0  236532  24116   9648 S   0.3  0.3   9:29.80 python3 

千萬記得必定要用機械硬盤

二、性能現象

3、分析過程

一、iowait超過了90%分析

查看I/O使用狀況

# -d 表示顯示 I/O 性能指標，-x 表示顯示擴展統計（即全部 I/O 指標） 
$ iostat -x -d 1 
Device            r/s     w/s     rkB/s     wkB/s   rrqm/s   wrqm/s  %rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz  svctm  %util 
loop0            0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0.00     0.00     0.00   0.00   0.00 
sdb              0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0.00     0.00     0.00   0.00   0.00 
sda              0.00   64.00      0.00  32768.00     0.00     0.00   0.00   0.00    0.00 7270.44 1102.18     0.00   512.00  15.50  99.20

實際測試截圖

觀測結果分析

二、pidstat分析python進程

一、觀察進程I/O使用狀況

pidstat -d 1 

15:08:35      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command 
15:08:36        0     18940      0.00  45816.00      0.00      96  python 

15:08:36      UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command 
15:08:37        0       354      0.00      0.00      0.00     350  jbd2/sda1-8 
15:08:37        0     18940      0.00  46000.00      0.00      96  python 
15:08:37        0     20065      0.00      0.00      0.00    1503  kworker/u4:2 

二、實際測試截圖

 三、pidstat結果觀測分析

實際測試說明

一、io使用沒有達到90%，而實際測試是14.9(最高)

二、每秒的寫請求是64，而實際測試是85

三、寫大小32MB，而實際測試是107MB

四、請求隊列是1100而實際測試是23.93

三、strace分析python進程調用

一、strace查看指定PID調用狀況

strace -p 18940 
strace: Process 18940 attached 
...
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0f7aee9000 
mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0f682e8000 
write(3, "2018-12-05 15:23:01,709 - __main"..., 314572844 
) = 314572844 
munmap(0x7f0f682e8000, 314576896)       = 0 
write(3, "\n", 1)                       = 1 
munmap(0x7f0f7aee9000, 314576896)       = 0 
close(3)                                = 0 
stat("/tmp/logtest.txt.1", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0 

二、實際測試截圖：機械硬盤 centos

三、strace結果觀測分析

四、lsof查看python進程打開了那些文件

一、查看進程打開了那些文件

lsof -p 18940 
COMMAND   PID USER   FD   TYPE DEVICE  SIZE/OFF    NODE NAME 
python  18940 root  cwd    DIR   0,50      4096 1549389 / 
python  18940 root  rtd    DIR   0,50      4096 1549389 / 
… 
python  18940 root    2u   CHR  136,0       0t0       3 /dev/pts/0 
python  18940 root    3w   REG    8,1 117944320     303 /tmp/logtest.txt 

二、實際測試截圖

三、lsof輸出觀測分析

三、查看源代碼

# 拷貝案例應用源代碼到當前目錄
$ docker cp app:/app.py . 

# 查看案例應用的源代碼
$ cat app.py 

logger = logging.getLogger(__name__) 
logger.setLevel(level=logging.INFO) 
rHandler = RotatingFileHandler("/tmp/logtest.txt", maxBytes=1024 * 1024 * 1024, backupCount=1) 
rHandler.setLevel(logging.INFO) 

def write_log(size): 
  '''Write logs to file''' 
  message = get_message(size) 
  while True: 
    logger.info(message) 
    time.sleep(0.1) 

if __name__ == '__main__': 
  msg_size = 300 * 1024 * 1024 
  write_log(msg_size) 

　　繼續查看源碼

def set_logging_info(signal_num, frame): 
  '''Set loging level to INFO when receives SIGUSR1''' 
  logger.setLevel(logging.INFO) 

def set_logging_warning(signal_num, frame): 
  '''Set loging level to WARNING when receives SIGUSR2''' 
  logger.setLevel(logging.WARNING) 

signal.signal(signal.SIGUSR1, set_logging_info) 
signal.signal(signal.SIGUSR2, set_logging_warning) 

分析這個源碼，咱們發現，它的日誌路徑是/tmp/logtest.txt、默認記錄 INFO 級別以上的全部日誌，並且每次寫日誌的大小是 300MB。這跟咱們上面的分析結果是一致的

4、解決方案

一、運行kill命令給進程發SIGUSR2 信號

kill -SIGUSR2 18940 

二、再執行top和iostat觀察

top

top 
... 
%Cpu(s):  0.3 us,  0.2 sy,  0.0 ni, 99.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st 

iowat

iostat -d -x 1
Device            r/s     w/s     rkB/s     wkB/s   rrqm/s   wrqm/s  %rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz  svctm  %util 
loop0            0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0.00     0.00     0.00   0.00   0.00 
sdb              0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0.00     0.00     0.00   0.00   0.00 
sda              0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0.00     0.00     0.00   0.00   0.00

到這裏，咱們不只定位了狂打日誌的應用程序，並經過調用高日誌級別的方法，完美解決了I/O的性能瓶頸

5、小結

日誌，是瞭解應用程序內部運行狀況、最經常使用、也最高效的工具、不管是操做系統、仍是應用程序、都會記錄大量的運行日誌，以便時候查看歷史記錄，

這些日誌通常按照不一樣的級別來開啓，好比，開發環境一般打開調式級別的日誌，而線上環境則只記錄警告和錯誤日誌

 

在排查應用程序問題時，咱們能夠能須要，在線上環境臨時開啓應用程序的調試日誌，有時候，過後一不當心忘了調回去，沒把線上的日誌調高到警告級別，

可能會致使cpu使用率、磁盤I/O等一系列的性能問題，嚴重時，甚至會影響同一臺服務器上運行的其餘應用程序

 

從此，在碰到這種「狂打日誌」的場景時，你能夠用iostat、strace、losf等工具來定位狂打日誌的進程，找出相應的日誌文件，再經過應用程序接口

調整日誌界別來解決問題