环境准备
Centos7 2c2g 虚拟机
安装docker
安装sysstat (这个包中包含各种stat)
启动项目
启动python项目
[root@10 yum.repos.d]# docker run -v /tmp:/tmp --name=app -itd feisky/logapp Unable to find image 'feisky/logapp:latest' locally latest: Pulling from feisky/logapp 4fe2ade4980c: Pull complete 7cf6a1d62200: Pull complete d16bb326b4ba: Pull complete ed7df901e9a8: Pull complete d7e55b1728aa: Pull complete e355358dada7: Pull complete Digest: sha256:8dfbc3116680c581d20f58d63a2353b9a7e67a0442dd43803d7dad43c6d4ac0a Status: Downloaded newer image for feisky/logapp:latest 3bd923581b43625deff919c8e5ef8a7df36f17b0f835321d32d5598b207e1225
查看进程
性能指标收集
查看Top
CPU
CPU0 的使用率非常高，它的系统 CPU 使用率（sys%）为6%，而 iowait 超过了 90%。这说明 CPU0 上，可能正在运行 I/O 密集型的进程。不过，究竟是什么原因呢？这个疑问先保留着，我们先继续看完。(实验环境不同结果不同)
python 进程的 CPU 使用率已经达到了 68%，而其余进程的 CPU 使用率都比较低。看起来 python 是个可疑进程。记下 python 进程的 PID 号 2100，我们稍后分析。
内存
机器2G的内存，python占用了900多M。 buffer/cache 600多MB，这说明内存大部分被缓存占用。虽然大部分缓存可回收，我们还是得了解下缓存的去处，确认缓存使用都是合理的
初步结论
CPU 使用率中的 iowait 是一个潜在瓶颈.
IO
查看iostat
-d 表示显示 I/O 性能指标，-x 表示显示扩展统计（即所有 I/O 指标）
观察 iostat 的最后一列，你会看到，磁盘 sda 的 I/O 使用率已经高达 80%，很可能已经接近 I/O 饱和。
每秒写磁盘请求数(w/s)是 2000 ，写大小(wkn/s)是 280多MB，写请求的响应时间（w_await）为41 秒，而平均请求队列长度(avgqu-sz)则快达到100。
具体含义可以man一下. 不同版本表示略有不同。
超慢的响应时间和特长的请求队列长度，进一步验证了 I/O 已经饱和的猜想。此时，sda磁盘已经遇到了严重的性能瓶颈
分析高I/O相关进程
pidstat
pidstat 加上 -d 参数，就可以显示每个进程的 I/O 情况
python 进程的写比较大，而且每秒写的数据超过290多 MB，比上面 iostat 发现的 280MB 的结果还要大。很明显，正是 python 进程导致了I/O 瓶颈
虚拟机上pidstat 竟然不显示内核进程.
这里老师给的案例
strace查看系统调用
[root@10 yum.repos.d]# strace -p 2100 strace: Process 2100 attached lseek(3, 0, SEEK_END) = 629145690 lseek(3, 0, SEEK_CUR) = 629145690 munmap(0x7f34b7ba1000, 314576896) = 0 mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34cf2a2000 mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34bc6a1000 write(3, "2022-01-18 14:50:22,943 - __main"..., 314572844) = 314572844 munmap(0x7f34bc6a1000, 314576896) = 0 write(3, "\n", 1) = 1 munmap(0x7f34cf2a2000, 314576896) = 0 select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=100000}) = 0 (Timeout) getpid() = 1 mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34cf2a2000 mmap(NULL, 393220096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34b7ba1000 mremap(0x7f34b7ba1000, 393220096, 314576896, MREMAP_MAYMOVE) = 0x7f34b7ba1000 munmap(0x7f34cf2a2000, 314576896) = 0 lseek(3, 0, SEEK_END) = 943718535 lseek(3, 0, SEEK_CUR) = 943718535 munmap(0x7f34b7ba1000, 314576896) = 0 close(3) = 0 stat("/tmp/logtest.txt.1", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0 unlink("/tmp/logtest.txt.1") = 0 stat("/tmp/logtest.txt", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0 rename("/tmp/logtest.txt", "/tmp/logtest.txt.1") = 0 open("/tmp/logtest.txt", O_WRONLY|O_CREAT|O_APPEND|O_CLOEXEC, 0666) = 3 fcntl(3, F_SETFD, FD_CLOEXEC) = 0 fstat(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0 lseek(3, 0, SEEK_END) = 0 ioctl(3, TIOCGWINSZ, 0x7fff115cff60) = -1 ENOTTY (Inappropriate ioctl for device) lseek(3, 0, SEEK_CUR) = 0 ioctl(3, TIOCGWINSZ, 0x7fff115cfe80) = -1 ENOTTY (Inappropriate ioctl for device) lseek(3, 0, SEEK_CUR) = 0 mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34cf2a2000 mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34bc6a1000 write(3, "2022-01-18 14:50:24,785 - __main"..., 314572844) = 314572844 munmap(0x7f34bc6a1000, 314576896) = 0 write(3, "\n", 1) = 1 munmap(0x7f34cf2a2000, 314576896) = 0 select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=100000}) = 0 (Timeout) getpid() = 1 mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34cf2a2000 mmap(NULL, 393220096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34b7ba1000 mremap(0x7f34b7ba1000, 393220096, 314576896, MREMAP_MAYMOVE) = 0x7f34b7ba1000 munmap(0x7f34cf2a2000, 314576896) = 0 lseek(3, 0, SEEK_END) = 314572845 lseek(3, 0, SEEK_CUR) = 314572845 munmap(0x7f34b7ba1000, 314576896) = 0 mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34cf2a2000 mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f34bc6a1000 write(3, "2022-01-18 14:50:26,527 - __main"..., 314572844) = 314572844 munmap(0x7f34bc6a1000, 314576896) = 0 write(3, "\n", 1) = 1 munmap(0x7f34cf2a2000, 314576896) = 0 select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=100000}) = 0 (Timeout) getpid() = 1
从 write() 系统调用上，我们可以看到，进程向文件描述符编号为 3 的文件中，写入了300MB 的数据。看来，它应该是我们要找的文件。不过，write() 调用中只能看到文件的描述符编号，文件名和路径还是未知的。
再观察后面的 stat() 调用，你可以看到，它正在获取 /tmp/logtest.txt.1 的状态。 这种“点 + 数字格式”的文件，在日志回滚中非常常见。我们可以猜测，这是第一个日志回滚文件，而正在写的日志文件路径，则是 /tmp/logtest.txt。
lsof确定进程和文件的关系
lsof专门用来查看进程打开文件列表，不过，这里的“文件”不只有普通文件，还包括了目录、块设备、动态库、网络套接字等
这个进程打开了文件 /tmp/logtest.txt，并且它的文件描述符是 3号，而 3 后面的 w ，表示以写的方式打开。
和strace的结果吻合。
查看源代码分析问题
# 拷贝案例应用源代码到当前目录
docker cp app:/app.py .
#!/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( 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 = 300 * 1024 * 1024 write_log(msg_size)
它的日志路径是 /tmp/logtest.txt，默认记录 INFO 级别以上的所有日志，而且每次写日志的大小是 300MB。这跟我们上面的分析结果是一致的.
利用SIGUSR动态调整日志
利用SIGUSR动态调整日志
一般来说，生产系统的应用程序，应该有动态调整日志级别的功能。继续查看源码，你会发现，这个程序也可以调整日志级别。如果你给它发送 SIGUSR1 信号，就可以把日志调整为INFO 级；发送 SIGUSR2 信号，则会调整为 WARNING 级。
这一点值得学习.
给python应用发送SIGUSR2
kill -SIGUSR2 2100
查看top 和 iostat恢复正常.
停止案例
停止并删除container
docker rm -f app
