Linux性能优化-狂打日志的问题

最新推荐文章于 2022-08-08 10:55:51 发布

hixiaoxiaoniao

最新推荐文章于 2022-08-08 10:55:51 发布

阅读量803

点赞数

分类专栏：系统 Linux

本文链接：https://blog.csdn.net/hixiaoxiaoniao/article/details/86534555

版权

系统同时被 2 个专栏收录

47 篇文章 9 订阅

订阅专栏

Linux

28 篇文章 0 订阅

订阅专栏

文件系统，是对存储设备上的文件进行组织管理的一种机制。为了支持各类不同的文件系统，Linux 在各种文件系统上，抽象了一层虚拟文件系统 VFS。

它定义了一组所有文件系统都支持的数据结构和标准接口。这样，应用程序和内核中的其他子系统，就只需要跟 VFS 提供的统一接口进行交互。

在文件系统的下层，为了支持各种不同类型的存储设备，Linux 又在各种存储设备的基础上，抽象了一个通用块层。

通用块层，为文件系统和应用程序提供了访问块设备的标准接口；同时，为各种块设备的驱动程序提供了统一的框架。此外，通用块层还会对文件系统和应用程序发送过来的 I/O 请求进行排队，并通过重新排序、请求合并等方式，提高磁盘读写的效率。

通用块层的下一层，自然就是设备层了，包括各种块设备的驱动程序以及物理存储设备。

运行需要测试的python程序

top查看结果

Tasks: 182 total,   2 running, 179 sleeping,   1 stopped,   0 zombie
Cpu0  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu1  : 25.7%us, 47.7%sy,  0.0%ni, 26.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu2  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu3  :  0.3%us,  0.7%sy,  0.0%ni, 98.7%id,  0.3%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  16326548k total,  7038956k used,  9287592k free,   531456k buffers
Swap:  4194300k total,        0k used,  4194300k free,  4789188k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                   
26414 root      20   0  438m 276m 2980 R 73.4  1.7   0:08.38 python                                                                                                    
   15 root      RT   0     0    0    0 S  0.3  0.0   0:03.08 migration/3                                                                                               
  362 root      20   0     0    0    0 S  0.3  0.0   0:33.83 jbd2/vda1-8                                                                                               
 1118 root      20   0 18240  692  472 S  0.3  0.0   3:14.95 irqbalance

vmstat查看结果

vmstat 1
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0 15541456   3344  30476    0    0     0     5    3    2  4  0 96  0  0
 0  0      0 15541456   3344  30496    0    0     0     0  145  189  0  0 100  0  0
 0  0      0 15541300   3344  30580    0    0     0     0  136  194  0  0 100  0  0
。。。
 1  0      0 13886648   7532 1513740    0    0     0     0  822  223  6 11 83  0  0
 1  0      0 13487196   7532 1790220    0    0     0     0  845  211  6 11 82  0  0

iostat查看结果

iostat -x 1
Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
vda               0.00 119176.00    3.00 1010.00    24.00 814488.00   804.06   112.75   88.78   0.98  98.80

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           4.86    0.00   24.04   19.18    0.00   51.92


Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
vda               0.00 156839.00    2.00 1172.00    16.00 1105088.00   941.32    85.80   67.60   0.58  67.80

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           5.96    0.00   21.76   12.95    0.00   59.33

pidstat查看结果

pidstat -d 1

20:32:42 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
20:32:43 PM     25608      0.00 276480.00      0.00  python


20:32:44 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
20:32:45 PM       362      0.00 659460.00      0.00  jbd2/vda1-8
20:32:45 PM       777     12.00    192.00      0.00  flush-252:0
20:32:45 PM     25608      0.00 201436.00      0.00  python


20:32:45 PM       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
20:32:46 PM       362      0.00 620636.00      0.00  jbd2/vda1-8
20:32:46 PM       777     24.00    336.00      0.00  flush-252:0
20:32:46 PM       815      0.00      8.00      0.00  jbd2/vda5-8
20:32:46 PM     25608      0.00 184324.00 489476.00  python

通过top结果看 26414的python进程占用了73%的CPU

磁盘的util也就是使用率很高
每秒的请求队列长度是80+，等待时间是60-80毫秒
通过pidstat看，jbd2/vda1-8和python进程都是不停的写

通过strace查看

。。。
munmap(0x7f173a287000, 4096)            = 0
stat("/tmp/logtest.txt.1", {st_mode=S_IFREG|0644, st_size=1038090735, ...}) = 0
unlink("/tmp/logtest.txt.1")            = 0
rename("/tmp/logtest.txt", "/tmp/logtest.txt.1") = 0
open("/tmp/logtest.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
。。。

通过lsof查看

lsof -p 49547
COMMAND   PID USER   FD   TYPE DEVICE  SIZE/OFF    NODE NAME
python  49547 root  cwd    DIR  252,1      4096     574 /root/test/linux
python  49547 root  rtd    DIR  252,1      4096       2 /
python  49547 root  txt    REG  252,5      9032 1444548 /usr/bin/python
python  49547 root  mem    REG  252,1    157072     140 /lib64/ld-2.12.so
python  49547 root  mem    REG  252,1   1928936    4945 /lib64/libc-2.12.so
python  49547 root  mem    REG  252,1    145936    5707 /lib64/libpthread-2.12.so
python  49547 root  mem    REG  252,1     22536    8270 /lib64/libdl-2.12.so
python  49547 root  mem    REG  252,1    599480    8280 /lib64/libm-2.12.so
python  49547 root  mem    REG  252,1     91096    8279 /lib64/libz.so.1.2.3
python  49547 root  mem    REG  252,1    124624    8281 /lib64/libselinux.so.1
python  49547 root  mem    REG  252,1    113952    5723 /lib64/libresolv-2.12.so
python  49547 root  mem    REG  252,1     17520    5750 /lib64/libutil-2.12.so
python  49547 root  mem    REG  252,1     17256    8297 /lib64/libcom_err.so.2.1
python  49547 root  mem    REG  252,1    944712    8298 /lib64/libkrb5.so.3.3
python  49547 root  mem    REG  252,5   1965824  919245 /usr/lib64/libcrypto.so.1.0.1e
python  49547 root  mem    REG  252,1    280520    8299 /lib64/libgssapi_krb5.so.2.2
python  49547 root  mem    REG  252,1     12592    5312 /lib64/libkeyutils.so.1.3
python  49547 root  mem    REG  252,1     46368    8295 /lib64/libkrb5support.so.0.1
python  49547 root  mem    REG  252,1    177520    8296 /lib64/libk5crypto.so.3.1
python  49547 root  mem    REG  252,5    444168  919251 /usr/lib64/libssl.so.1.0.1e
python  49547 root  mem    REG  252,5   1672544  919178 /usr/lib64/libpython2.6.so.1.0
python  49547 root  mem    REG  252,5     37840  920816 /usr/lib64/python2.6/lib-dynload/_struct.so
python  49547 root  mem    REG  252,5     75664  920821 /usr/lib64/python2.6/lib-dynload/cPickle.so
python  49547 root  mem    REG  252,5     34112  920815 /usr/lib64/python2.6/lib-dynload/_ssl.so
python  49547 root  mem    REG  252,5     60752  920813 /usr/lib64/python2.6/lib-dynload/_socketmodule.so
python  49547 root  mem    REG  252,5     12680  919216 /usr/lib64/python2.6/lib-dynload/_randommodule.so
python  49547 root  mem    REG  252,5     20976  920282 /usr/lib64/python2.6/lib-dynload/binascii.so
python  49547 root  mem    REG  252,5     26408  920307 /usr/lib64/python2.6/lib-dynload/mathmodule.so
python  49547 root  mem    REG  252,5     54896  920303 /usr/lib64/python2.6/lib-dynload/itertoolsmodule.so
python  49547 root  mem    REG  252,5     38608  920312 /usr/lib64/python2.6/lib-dynload/operator.so
python  49547 root  mem    REG  252,5     28112  919186 /usr/lib64/python2.6/lib-dynload/_collectionsmodule.so
python  49547 root  mem    REG  252,5     12256  919198 /usr/lib64/python2.6/lib-dynload/_functoolsmodule.so
python  49547 root  mem    REG  252,5     19248  920822 /usr/lib64/python2.6/lib-dynload/cStringIO.so
python  49547 root  mem    REG  252,5     25288  920341 /usr/lib64/python2.6/lib-dynload/stropmodule.so
python  49547 root  mem    REG  252,5     20328  920836 /usr/lib64/python2.6/lib-dynload/timemodule.so
python  49547 root  mem    REG  252,5  99164480  529975 /usr/lib/locale/locale-archive
python  49547 root    0u   CHR  136,0       0t0       3 /dev/pts/0
python  49547 root    1u   CHR  136,0       0t0       3 /dev/pts/0
python  49547 root    2u   CHR  136,0       0t0       3 /dev/pts/0
python  49547 root    3w   REG  252,1 377487540  131642 /tmp/logtest.txt

查看python代码如下

#!/usr/bin/env python
# -*- coding: UTF-8 -*-

import logging
import random
import string
import signal
import time

from logging.handlers import RotatingFileHandler

logger = logging.getLogger(__name__)
logger.setLevel(level=logging.INFO)
rHandler = RotatingFileHandler(
    "/tmp/logtest.txt", maxBytes=1024 * 1024 * 1024, backupCount=1)
rHandler.setLevel(logging.INFO)
formatter = logging.Formatter(
    '%(asctime)s - %(name)s - %(levelname)s - %(message)s')
rHandler.setFormatter(formatter)
logger.addHandler(rHandler)


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)


def get_message(N):
    '''Get message for logging'''
    return N * ''.join("aaa")
        #random.choices(string.ascii_uppercase + string.digits, k=1))


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


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

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

向这个进程发送信号，改变日志的优先级，再观察服务器清空

kill -SIGUSR2 50506

top
Tasks: 189 total,   1 running, 188 sleeping,   0 stopped,   0 zombie
Cpu0  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu1  :  0.3%us,  0.0%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu2  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Cpu3  :  0.0%us,  0.0%sy,  0.0%ni,100.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  16326548k total,  2208584k used, 14117964k free,    31588k buffers
Swap:  4194300k total,        0k used,  4194300k free,  1285112k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                   
 1623 nginx     20   0 67188  12m  904 S  0.3  0.1   5:56.58 nginx                                                                                                     
23055 tomcat    20   0 4210m 123m  12m S  0.3  0.8  28:37.93 java                                                                                                      
50650 root      20   0  258m  96m 2980 S  0.3  0.6   0:15.76 python  



iostat -x 1
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.50    0.00    1.75    0.00    0.00   97.75

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
vda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

日志，是了解应用程序内部运行情况，最常用、也最有效的工具。无论是操作系统，还是应用程序，都会记录大量的运行日志，以便事后查看历史记录。这些日志一般按照不同级别来开启，比如，开发环境通常打开调试级别的日志，而线上环境则只记录警告和错误日志。

在排查应用程序问题时，我们可能需要，在线上环境临时开启应用程序的调试日志。有时候，事后一不小心就忘了调回去。没把线上的日志调高到警告级别，可能会导致 CPU 使用率、磁盘 I/O 等一系列的性能问题，严重时，甚至会影响到同一台服务器上运行的其他应用程序。

在碰到这种“狂打日志”的场景时，可以用 iostat、strace、lsof 等工具来定位狂打日志的进程，找出相应的日志文件，再通过应用程序的接口，调整日志级别来解决问题。

如果应用程序不能动态调整日志级别，你可能还需要修改应用的配置，并重启应用让配置生效。