Skip to content
Permalink
Branch: master
Find file Copy path
Find file Copy path
Fetching contributors…
Cannot retrieve contributors at this time
114 lines (77 sloc) 7.68 KB
layout title date categories
post
线上问题排查
2019-09-22 21:00:05 +0800
总结

打日志

线上服务老出问题,或许整理、删除日志就能够解决。

如果线上服务没有日志、metrics、tracing追踪,其和裸奔没什么区别,开发者对关键路径打印日志、metrics等,借助监控工具能帮助开发者更好地发现线上问题。在基础组件完善的公司,能够通过request_id来追踪整个请求的路径,以及其打印的日志,在足够的日志下,得到完善的上下文,请求过程中发生了什么一目了然。

但是对于不良的日志,仅仅会增加系统的IO负担、内存申请以及GC压力。没对监控服务、定位问题提供帮助,反倒降低了信噪比。线上服务日志先经过page cache,然后操作系统或程序触发某些条件(内存不足、长度达到阈值),将page cache强制fsync同步到磁盘文件,如果生产日志的速度大于日志落盘的速度,将会导致系统卡顿。

在Go、Java、Python等带运行时GC的编程语言,通过逃逸分析到传递到打印日志的字符串可能会逃逸,则将字符串创建在堆上,如果字符串过大(将对象序列化为JSON输出),运行时内存管理没有这么大的可用内存,则需要系统调用申请更多的内存,在GC时同样需要将大内存归还到操作系统,同样也是系统调用。

定位过好几个线上服务问题,内存占用过高,dirty page居高不下,大多是因为日志打太多了。注:page cache高是一个正常现象。

线上排查问题checklist

如果是业务逻辑问题,看metrics,抓几个log_id查询调用链中的日志是否合理。

监控Linux操作系统的几个常用命令:

  1. top:监控内存、CPU
  2. iostat:监控磁盘IO
  3. ss:监控网络

对于定位发生在过去的问题,可使用atop,其原理是每隔一段时间记录系统的top状态,然后写到日志中,方便开发者随时查看历史监控。

通过top能看到load average指标,这个指标是描述CPU等待队列中task的长度。linux操作系统调度任务的基本单元是线程,所以这里描述的是线程。load average除了包括可运行的任务,还包括uninteruptible状态(等待磁盘、网络IO)的任务,这一点非常迷惑人,网上查询了相关文章,其描述为Linux认为load average是用来描述系统的整体负载的,而不是单纯是CPU负载,所以需要包含磁盘、网络IO。load average中有三个值,第一个代表1分钟内的平均值,第二个代表5分钟内的平均值,第三个代表15分钟内的平均值。若三个数值呈现递增,证明系统负载在降低;若三个数值呈递减,证明系统负载在增高。

top CPU%中us(er)是用户占用CPU的百分比,sy(stem)是系统内核占用系统的百分比,ni(ce)改变过优先级的进程数占比,id(le)空闲CPU的占比,wa(it) IO等待进程数占比,hi硬中断占CPU百分比,si软中断占CPU百分比。

top Mem中的单位是KB,total为系统内存总KB,free为系统真正没使用的内存KB,used为系统正在使用的内存,buff/cache用作缓冲区的内存大小(包含paper cache、网络IObuff等)。total=free+ used+"buff/cache"

top swp中的单位为KB,是交换分区(安装操作系统时,需要挂载特殊的交换分区,其作用做当内存不足时,将内存的部分导入到交换分区磁盘中,腾出空间给其他进程使用),total交换分区的总量,free交换分区空闲量,used交换分区正在使用的量,avail Mem可供使用的内存的量。

Linux中nice优先级是process维度的,而不是thread维度的。设置了一个进程的nice,其下的所有线程共享一个nice值。

Linux内存不足的情况是,swap使用总是在变化,证明系统内存经常和swap分区交换,降低系统的性能。

top进程表中的列说明:

  1. PID:进程ID
  2. USER:用户
  3. PR:优先级
  4. NI:nice值
  5. VIRT进程使用的虚内存总量
  6. SHR:共享内存大小
  7. S:进程状态,D=不可中断的睡眠状态,R=运行,S=睡眠,T=跟踪/停止,Z=僵尸进程
  8. CPU:占用CPU的百分比
  9. MEM:进程使用物理内存百分比
  10. TIME:进程使用CPU时间总计,单位1/100秒
  11. CMD:进程执行的命令

ps:扫描进程表。

nice:进程被调度的优先级,[-20, 20),值越小调度优先级越高,在top或nice命令可以查询和修改进程的nice值。

iowait:又名File I/O wait(当使用NFS时,会包括网络IO),异步IO没有iowait(在内存足够的情况下)。

dirty mem:比如mmap等内存和磁盘是映射,用户修改了内存,但是尚未flush到磁盘,所以此时内存页是脏页;用户写一个文件,但是内容还没flush到磁盘(日志);swap内存修改了,但是还没swap到交换分区。

page cache == buffer cache,In linux these are the same thing. 磁盘、网络等读写会存在page cache

RSS VSZ区别

  1. RSS(Resident Set Size):进程占用物理内存的大小,不包括swap到交换分区的大小,其中包括堆、栈、代码段、动态链接
  2. VSZ(Virtual Set Size):进程占用虚拟内存的大小,包括swap到交换分区的大小和虚拟内存已经分配(物理内存尚未分配)的内存大小

zombie process is actually dead.

ss is a new network command instead of netstat. ss可以监听网络的连接数,队列等。

iostat 可以查看磁盘的负载,读写消耗,磁盘占用率等,提供开发者视角查看磁盘当前状态。

' man iostat -x
Linux 4.14.81.bm.7-amd64 (n18-069-098)  09/22/2019      _x86_64_        (48 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           1.21    0.09    0.18    0.01    0.00   98.51

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.04     8.86    1.88    7.14    78.10   537.14   136.44     0.01    1.56    3.95    0.93   0.07   0.06
sdb               0.00     0.42    1.84    0.43   250.62   564.44   718.67     0.00    1.95    0.77    7.06   0.44   0.10

解析一下每个字段的含义:

  1. Device:物理盘
  2. rrqm/s:每秒合并到设备的读请求数
  3. wrqm/s:每秒合并到设备的写请求数
  4. r/s:每秒向磁盘发起的读操作数
  5. w/s:每秒向磁盘发起的写请求
  6. rKB/s:每秒读KB
  7. wKB/s:每秒写KB
  8. avgrq-sz:平均每次设备IO操作的数据大小
  9. avgqu-sz:平均IO队列长度
  10. await:平均每次设备IO设备的等待时间(ms),从请求开始到请求结束所耗时
  11. r_await:平均每次读所需时间,不仅包括设备操作时间,还包括等待时间
  12. w_await:平均每次写所需时间,不仅包括设备操作时间,还包括等待时间
  13. svctm:从请求开始到请求结束耗时(只计算在设备中的耗时)
  14. %util:磁盘的利用率,最高1

昨天遇到一个docker像是没被调度一样的情况,整个实例在一段时间内突然不消费了,由于tcp栈的链接堆积,一旦实例分配到计算资源后,又会导致实例内存飙升,因为网络框架为每个请求创建了一个goroutine。对于这种计算调度的问题非常难以理解,需要花点时间学习openstack/yarn/k8s的机制。暂且记录一个TODO吧。

说一句与本文无关的话,业务逻辑服务到最后拼的是资源利用率,容灾等做到极致。

当然ROI不一定高,大多数操作都是为了极限(极少数)情况准备,但是当灾难来临时,就是体现其价值,这种情形也是很难模拟测试的。

You can’t perform that action at this time.