SpringCloud服务治理(三十一)线上故障排查

853 阅读35分钟

线上问题不同于开发期间的 bug,与运行时环境、压力、并发情况、具体的业务相关。对于线上的问题利用线上环境可用的工具,收集必要信息 对定位问题十分重要。

1

服务上常见问题

所有 Java 服务的线上问题从系统表象来看归结起来总共有四方面:CPU、内存、磁盘、网络。例如 CPU 使用率峰值突然飚高、内存溢出(泄露)、磁盘满了、网络流量异常、FullGC 等等问题。基于这些现象我们可以将线上问题分成两大类: 系统异常、业务服务异常。

  • 系统异常

常见的系统异常现象包括: CPU 占用率过高、CPU上下文切换频率次数较高、磁盘满了、磁盘 I/O 过于频繁、系统可用内存长期处于较低值(导致 oom killer)、网络流量异常(连接数过多)等等。这些问题可以通过 top(cpu)、free(内存)、df(磁盘)、dstat(网络流量)、strace(底层系统调用)、pstack、vmstat、等工具获取系统异常现象数据。 常见的业务服务异常现象包括: PV 量过高、服务调用耗时异常、线程死锁、多线程并发问题、频繁进行 Full GC、异常安全攻击扫描等

2

问题定位

我们一般会采用排除法,从外部排查到内部排查的方式来定位线上服务问题。

  • 首先我们要排除其他进程(除主进程之外)可能引起的故障问题
  • 其次排除业务应用可能引起的故障问题
  • 最后可以考虑是否为运营商或者云服务提供商所引起的故障

定位流程

  • 系统异常排查流程

  • 业务应用排查流程

Linux常见的性能分析工具

Linux 常用的性能分析工具使用包括 : top(cpu)、df(磁盘)、free(内存)、、dstat(网络流量)、vmstat、pstack、strace(底层系统调用)等。

  • CPU

CPU 是系统重要的监控指标,能够分析系统的整体运行状况。监控指标一般包括运行队列、

CPU

使用率和上下文切换等。

top命令是Linux下常用的 CPU 性能分析工具,能够实时显示系统中各个进程的资源占用状况,常用于服务端性能分析

top 命令显示了各个进程 CPU 使用情况,一般 CPU 使用率从高到低排序展示输出。其中 Load Average 显示最近1分钟、5分钟和15分钟的系统平均负载,上图各值为2.46,1.96,1.99。 我们一般会关注 CPU 使用率最高的进程,正常情况下就是我们的应用主进程。第七行以下:各进程的状态监控。

PID : 进程id
USER : 进程所有者
PR : 进程优先级
NI : nice值。负值表示高优先级,正值表示低优先级
VIRT : 进程使用的虚拟内存总量,单位kb。VIRT=SWAP+RES
RES : 进程使用的、未被换出的物理内存大小,单位kb。RES=CODE+DATA
SHR : 共享内存大小,单位kb
S : 进程状态。D=不可中断的睡眠状态 R=运行 S=睡眠 T=跟踪/停止 Z=僵尸进程
%CPU : 上次更新到现在的CPU时间占用百分比
%MEM : 进程使用的物理内存百分比
TIME+ : 进程使用的CPU时间总计,单位1/100秒
COMMAND : 进程名称
  • 内存

内存是排查线上问题的重要参考依据,内存问题很多时候是引起 CPU 使用率较高的见解因素。

系统内存:free 是显示的当前内存的使用,-m 的意思是M字节来显示内容。

free -m

部分参数说明: total 内存总数: 3790M used 已经使用的内存数: 1880M free 空闲的内存数: 118M shared 当前已经废弃不用,总是0 buffers Buffer 缓存内存数: 1792M

  • 磁盘

磁盘满了很多时候会连带引起系统服务不可用等问题

df -h

du -m /path

  • 网络

dstat 命令可以集成了 vmstat、iostat、netstat 等等工具能完成的任务。

dstat -c  cpu情况
    -d 磁盘读写
    -n 网络状况
    -l 显示系统负载
    -m 显示形同内存状况
    -p 显示系统进程信息
    -r 显示系统IO情况

  • 其它

vmstat:

vmstat 2 10 -t

vmstat 是 Virtual Meomory Statistics(虚拟内存统计)的缩写, 是实时系统监控工具。该命令通过使用 knlist 子程序和 /dev/kmen 伪设备驱动器访问这些数据,输出信息直接打印在屏幕。

使用 vmstat 2 10 -t命令,查看 io 的情况 (第一个参数是采样的时间间隔数单位是秒,第二个参数是采样的次数)。

r 表示运行队列(就是说多少个进程真的分配到CPU),b 表示阻塞的进程。    
swpd 虚拟内存已使用的大小,如果大于0,表示你的机器物理内存不足了,如果不是程序内存泄露的原因,那么你该升级内存了或者把耗内存的任务迁移到其他机器。
free   空闲的物理内存的大小,我的机器内存总共4G,剩余120M左右。
buff   Linux/Unix系统是用来存储,目录里面有什么内容,权限等的缓存,我本机大概占用40多Mcache 文件缓存
si列表示由磁盘调入内存,也就是内存进入内存交换区的数量;
so列表示由内存调入磁盘,也就是内存交换区进入内存的数量
一般情况下,si、so的值都为0,如果si、so的值长期不为0,则表示系统内存不足,需要考虑是否增加系统内存。    
bi 从块设备读入数据的总量(读磁盘)(每秒kb)
bo 块设备写入数据的总量(写磁盘)(每秒kb)
随机磁盘读写的时候,这两个值越大((超出1024k),能看到cpu在IO等待的值也会越大
这里设置的bi+bo参考值为1000,如果超过1000,而且wa值比较大,则表示系统磁盘IO性能瓶颈。in 每秒CPU的中断次数,包括时间中断
cs(上下文切换Context Switch)

strace:strace常用来跟踪进程执行时的系统调用和所接收的信号。

strace -cp tid
strace -T -p tid  
    -T 显示每一调用所耗的时间.
    -p pid  跟踪指定的进程pid. 
    -v 输出所有的系统调用.一些调用关于环境变量,状态,输入输出等调用由于使用频繁,默认不输出. 
    -V 输出strace的版本信息.

JVM 定位问题工具

在 JDK 安装目录的 bin 目录下默认提供了很多有价值的命令行工具。每个小工具体积基本都比较小,因为这些工具只是 jdk\lib\tools.jar 的简单封装。

其中,定位排查问题时最为常用命令包括:jps(进程)、jmap(内存)、jstack(线程)、jinfo(参数)等。

  • jps:查询当前机器所有JAVA进程信息
  • jmap:输出某个 Java 进程内存情况(如产生那些对象及数量等)
  • jstack:打印某个 Java 线程的线程栈信息
  • jinfo:用于查看 jvm 的配置参数
  • jps 命令

jps 用于输出当前用户启动的所有进程 ID,当线上发现故障或者问题时,能够利用 jps 快速定位对应的 Java 进程 ID。

jps -l -m-m -l -l参数用于输出主启动类的完整路径

当然,我们也可以使用 Linux 提供的查询进程状态命令,例如:

ps -ef | grep tomcat

我们也能快速获取 Tomcat 服务的进程 id。

  • jmap 命令

    jmap -heap pid 输出当前进程JVM堆新生代、老年代、持久代等请情况,GC使用的算法等信息 jmap -histo:live {pid} | head -n 10 输出当前进程内存中所有对象包含的大小 jmap -dump:format=b,file=/usr/local/logs/gc/dump.hprof {pid} 以二进制输出档当前内存的堆情况,然后可以导入MAT等工具进行

JMap(Java Memory Map)可以输出所有内存中对象的工具,甚至可以将 VM 中的 heap,以二进制输出成文本。

jmap -heap pid:

jmap -heap pid   输出当前进程JVM堆新生代、老年代、持久代等请情况,GC使用的算法等信息

jmap 可以查看 JVM 进程的内存分配与使用情况,使用 的 GC 算法等信息。

jmap -histo:live {pid} | head -n 10:

jmap -histo:live {pid} | head -n 10  输出当前进程内存中所有对象包含的大小

输出当前进程内存中所有对象实例数(instances)和大小(bytes),如果某个业务对象实例数和大小存在异常情况,可能存在内存泄露或者业务设计方面存在不合理之处。

jmap -dump:

jmap -dump:format=b,file=/usr/local/logs/gc/dump.hprof {pid}

-dump:formate=b,file= 以二进制输出当前内存的堆情况至相应的文件,然后可以结合 MAT 等内存分析工具深入分析当前内存情况。

一般我们要求给 JVM 添加参数 -XX:+Heap Dump On Out Of Memory Error OOM 确保应用发生 OOM 时 JVM 能够保存并 dump 出当前的内存镜像。当然如果你决定手动 dump 内存时,dump 操作占据一定 CPU 时间片、内存资源、磁盘资源等,因此会带来一定的负面影响。

此外,dump 的文件可能比较大,一般我们可以考虑使用zip命令对文件进行压缩处理,这样在下载文件时能减少带宽的开销。在下载 dump 文件完成之后,由于 dump 文件较大可将 dump 文件备份至制定位置或者直接删除,以释放磁盘在这块的空间占用。

  • jstack 命令

    printf '%x\n' tid --> 10进制至16进制线程ID(navtive线程) %d 10进制 jstack pid | grep tid -C 30 --color
    ps -mp 8278 -o THREAD,tid,time | head -n 40

某 Java 进程 CPU 占用率高,我们想要定位到其中 CPU 占用率最高的线程。

(1) 利用 top 命令可以查出占 CPU 最高的线程 pid

top -Hp {pid}

(2) 占用率最高的线程 ID 为 6900,将其转换为16进制形式(因为 java native 线程以16进制形式输出)

printf '%x\n' 6900

(3) 利用 jstack 打印出 Java 线程调用栈信息

jstack 6418 | grep '0x1af4' -A 50 --color

  • jinfo 命令

    查看某个JVM参数值 jinfo -flag ReservedCodeCacheSize 28461 jinfo -flag MaxPermSize 28461

  • jstat 命令

    jstat -gc pid jstat -gcutil pgrep -u admin java

3

日志分析

GC日志分析

  • GC 日志详细分析

Java 虚拟机 GC 日志是用于定位问题重要的日志信息,频繁的 GC 将导致应用吞吐量下降、响应时间增加,甚至导致服务不可用。

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/usr/local/gc/gc.log -XX:+UseConcMarkSweepGC

我们可以在 Java 应用的启动参数中增加**-XX:+PrintGCDetails **可以输出 GC 的详细日志,例外还可以增加其他的辅助参数,如 -Xloggc 制定 GC 日志文件地址。如果你的应用还没有开启该参数,下次重启时请加入该参数。

上图为线上某应用在平稳运行状态下的GC日志截图。

2017-12-29T18:25:22.753+0800: 73143.256: [GC2017-12-29T18:25:22.753+0800: 73143.257: [ParNew: 559782K->1000K(629120K), 0.0135760 secs] 825452K->266673K(2027264K), 0.0140300 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

[2017-12-29T18:25:22.753+0800: 73143.256] : 自JVM启动73143.256秒时发生本次GC.[ParNew: 559782K->1000K(629120K), 0.0135760 secs] : 对新生代进行的GC,使用ParNew收集器,559782K是新生代回收前的大小,1000K是新生代回收后大小,629120K是当前新生代分配的内存总大小, 0.0135760 secs表示本次新生代回收耗时 0.0135760秒[825452K->266673K(2027264K), 0.0140300 secs]:825452K是回收堆内存大小,266673K是回收堆之后内存大小,2027264K是当前堆内存总大小,0.0140300 secs表示本次回收共耗时0.0140300秒[Times: user=0.02 sys=0.00, real=0.02 secs] : 用户态耗时0.02秒,系统态耗时0.00,实际耗时0.02秒

无论是 minor GC 或者是 Full GC,我们主要关注 GC 回收实时耗时, 如 real=0.02secs,即 stop the world 时间,如果该时间过长,则严重影响应用性能。

  • CMS GC 日志分析

Concurrent Mark Sweep(CMS)是老年代垃圾收集器,从名字(Mark Sweep)可以看出,CMS 收集器就是“标记-清除”算法实现的,分为六个步骤:

  • 初始标记(STW initial mark)
  • 并发标记(Concurrent marking)
  • 并发预清理(Concurrent precleaning)
  • 重新标记(STW remark)
  • 并发清理(Concurrent sweeping)
  • 并发重置(Concurrent reset)

其中初始标记(STW initial mark) 和 重新标记(STW remark)需要“Stop the World”。

初始标记 :在这个阶段,需要虚拟机停顿正在执行的任务,官方的叫法 STW(Stop The Word)。这个过程从垃圾回收的"根对象"开始,只扫描到能够和"根对象"直接关联的对象,并作标记。所以这个过程虽然暂停了整个 JVM,但是很快就完成了。

并发标记 :这个阶段紧随初始标记阶段,在初始标记的基础上继续向下追溯标记。并发标记阶段,应用程序的线程和并发标记的线程并发执行,所以用户不会感受到停顿。

并发预清理 :并发预清理阶段仍然是并发的。在这个阶段,虚拟机查找在执行并发标记阶段新进入老年代的对象(可能会有一些对象从新生代晋升到老年代, 或者有一些对象被分配到老年代)。通过重新扫描,减少下一个阶段"重新标记"的工作,因为下一个阶段会 Stop The World。

重新标记 :这个阶段会暂停虚拟机,收集器线程扫描在 CMS 堆中剩余的对象。扫描从"跟对象"开始向下追溯,并处理对象关联。

并发清理 :清理垃圾对象,这个阶段收集器线程和应用程序线程并发执行。

并发重置 :这个阶段,重置 CMS 收集器的数据结构,等待下一次垃圾回收。

CMS 使得在整个收集的过程中只是很短的暂停应用的执行,可通过在 JVM 参数中设置 -XX:UseConcMarkSweepGC 来使用此收集器,不过此收集器仅用于 old 和 Perm(永生)的对象收集。CMS 减少了 stop the world 的次数,不可避免地让整体 GC 的时间拉长了。

Full GC 的次数说的是 stop the world 的次数,所以一次 CMS 至少会让 Full GC 的次数+2,因为 CMS Initial mark 和 remark 都会 stop the world,记做2次。而 CMS 可能失败再引发一次 Full GC。

上图为线上某应用在进行 CMS GC 状态下的 GC 日志截图。

2017-11-02T09:27:03.989+0800: 558115.552: [GC [1 CMS-initial-mark: 1774783K(1926784K)] 1799438K(2068800K), 0.0123430 secs] [Times: user=0.01 sys=0.01, real=0.02 secs] 2017-11-02T09:27:04.001+0800: 558115.565: [CMS-concurrent-mark-start]2017-11-02T09:27:04.714+0800: 558116.277: [CMS-concurrent-mark: 0.713/0.713 secs] [Times: user=1.02 sys=0.03, real=0.71 secs] 2017-11-02T09:27:04.714+0800: 558116.277: [CMS-concurrent-preclean-start]2017-11-02T09:27:04.722+0800: 558116.285: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 2017-11-02T09:27:04.722+0800: 558116.286: [CMS-concurrent-abortable-preclean-start]2017-11-02T09:27:04.836+0800: 558116.399: [GC2017-11-02T09:27:04.836+0800: 558116.400: [ParNew: 138301K->6543K(142016K), 0.0155540 secs] 1913085K->1781327K(2068800K), 0.0160610 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 2017-11-02T09:27:05.005+0800: 558116.569: [CMS-concurrent-abortable-preclean: 0.164/0.283 secs] [Times: user=0.46 sys=0.02, real=0.28 secs] 2017-11-02T09:27:05.006+0800: 558116.570: [GC[YG occupancy: 72266 K (142016 K)]2017-11-02T09:27:05.006+0800: 558116.570: [Rescan (parallel) , 0.2523940 secs]2017-11-02T09:27:05.259+0800: 558116.822: [weak refs processing, 0.0011240 secs]2017-11-02T09:27:05.260+0800: 558116.823: [scrub string table, 0.0028570 secs] [1 CMS-remark: 1774783K(1926784K)] 1847049K(2068800K), 0.2566410 secs] [Times: user=0.14 sys=0.00, real=0.26 secs] 2017-11-02T09:27:05.265+0800: 558116.829: [CMS-concurrent-sweep-start]2017-11-02T09:27:05.422+0800: 558116.986: [GC2017-11-02T09:27:05.423+0800: 558116.986: [ParNew: 120207K->2740K(142016K), 0.0179330 secs] 1885446K->1767979K(2068800K), 0.0183340 secs] [Times: user=0.03 sys=0.01, real=0.02 secs] 2017-11-02T09:27:06.240+0800: 558117.804: [GC2017-11-02T09:27:06.240+0800: 558117.804: [ParNew: 116404K->3657K(142016K), 0.0134680 secs] 1286444K->1173697K(2068800K), 0.0138460 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 2017-11-02T09:27:06.966+0800: 558118.530: [GC2017-11-02T09:27:06.966+0800: 558118.530: [ParNew: 117321K->2242K(142016K), 0.0135210 secs] 738838K->623759K(2068800K), 0.0140130 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 2017-11-02T09:27:07.144+0800: 558118.708: [CMS-concurrent-sweep: 1.820/1.879 secs] [Times: user=2.88 sys=0.14, real=1.88 secs] 2017-11-02T09:27:07.144+0800: 558118.708: [CMS-concurrent-reset-start]2017-11-02T09:27:07.149+0800: 558118.713: [CMS-concurrent-reset: 0.005/0.005 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

如果你已掌握 CMS 的垃圾收集过程,那么上面的 GC 日志你应该很容易就能看的懂,这里我就不详细展开解释说明了。

此外 CMS 进行垃圾回收时也有可能会发生失败的情况。

异常情况有:

伴随 prommotion failed,然后 Full GC:

[prommotion failed:存活区内存不足,对象进入老年代,而此时老年代也仍然没有内存容纳对象,将导致一次Full GC]

伴随 concurrent mode failed,然后 Full GC:

[concurrent mode failed:CMS回收速度慢,CMS完成前,老年代已被占满,将导致一次Full GC]

频繁 CMS GC:

[内存吃紧,老年代长时间处于较满的状态]

业务日志

业务日志除了关注系统异常与业务异常之外,还要关注服务执行耗时情况,耗时过长的服务调用如果没有熔断等机制,很容易导致应用性能下降或服务不可用,服务不可用很容易导致雪崩。

上面是某一接口的调用情况,虽然大部分调用没有发生异常,但是执行耗时相对比较长。

grep '[0-9]{3,}ms' *.log 找出调用耗时大于3位数的dao方法,把3改成4就是大于4位数

互联网应用目前几乎采用分布式架构,但不限于服务框架、消息中间件、分布式缓存、分布式存储等等。那么这些应用日志如何聚合起来进行分析呢? 首先,你需要一套分布式链路调用跟踪系统,通过在系统线程上线文间透传 traceId 和 rpcId,将所有日志进行聚合,例如淘宝的鹰眼,spring cloud zipkin等等

线上定位问题时,主要靠监控和日志。一旦超出监控的范围,则排查思路很重要,按照流程化的思路来定位问题,能够让我们在定位问题时从容、淡定,快速的定位到线上的问题。

线上问题定位思维导图

一 服务器层面

1.1 磁盘

1.1.1 问题现象

当磁盘容量不足的时候,应用时常会抛出如下的异常信息:

java.io.IOException: 磁盘空间不足

或是类似如下告警信息:

1.1.2 排查思路

1.1.2.1 利用 df 查询磁盘状态

利用以下指令获取磁盘状态:

df -h

结果是:

可知 / 路径下占用量最大。

1.1.2.2 利用 du 查看文件夹大小

利用以下指令获取目录下文件夹大小:

du -sh *

结果是:

可知root文件夹占用空间最大,然后层层递推找到对应的最大的一个或数个文件夹。

1.1.2.3 利用 ls 查看文件大小

利用以下指令获取目录下文件夹大小:

ls -lh

结果是:

可以找到最大的文件是日志文件,然后使用rm指令进行移除以释放磁盘。

1.1.3 相关命令

1.1.3.1 df

主要是用于显示目前在 Linux 系统上的文件系统磁盘使用情况统计。

(1)常用参数

启动参数:

(2)结果参数

1.1.3.2 du

主要是为了显示目录或文件的大小。

(1)常用参数

启动参数:

(2)结果参数

1.1.3.3 ls

主要是用于显示指定工作目录下的内容的信息。

(1)常用参数

启动参数:

(2)结果参数

1.2 CPU过高

1.2.1 问题现象

当CPU过高的时候,接口性能会快速下降,同时监控也会开始报警。

1.2.2 排查思路

1.2.2.1 利用 top 查询CPU使用率最高的进程

利用以下指令获取系统CPU使用率信息:

top 

结果是:

从而可以得知pid为14201的进程使用CPU最高。

1.2.3 相关命令

1.2.3.1 top

(1)常用参数

启动参数:

top进程内指令参数:

(2)结果参数

二 应用层面

2.1 Tomcat假死案例分析

2.1.1 发现问题

监控平台发现某个Tomcat节点已经无法采集到数据,连上服务器查看服务器进程还在,netstat -anop|grep 8001端口也有监听,查看日志打印时断时续。

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文件,发现有很明显的内存泄漏提示。

点击查看详情,发现定位到了代码的具体某行,一目了然:

查看shallow heap与retained heap能发现生成了大量的Object(810325个对象),后面分析代码发现是上报softItem对象超过300多万个对象,在循环的时候,所有的数据全部保存在某个方法中无法释放,导致内存堆积到1.5G,从而超过了JVM分配的最大数,从而出现OOM。

java.lang.Object[810325] @ 0xb0e971e0

2.2.5 相关知识

2.2.5.1 JVM内存

2.2.5.2 内存分配的流程

如果通过逃逸分析,则会先在TLAB分配,如果不满足条件才在Eden上分配。

2.2.4.3 GC

(1)GC触发的场景

(2)GC Roots

GC Roots有4种对象:

  • 虚拟机栈(栈桢中的本地变量表)中的引用的对象,就是平时所指的java对象,存放在堆中。

  • 方法区中的类静态属性引用的对象,一般指被static修饰引用的对象,加载类的时候就加载到内存中。

  • 方法区中的常量引用的对象。

  • 本地方法栈中JNI(native方法)引用的对象。

(3)GC算法

  • 串行只使用单条GC线程进行处理,而并行则使用多条。

  • 多核情况下,并行一般更有执行效率,但是单核情况下,并行未必比串行更有效率。

  • STW会暂停所有应用线程的执行,等待GC线程完成后再继续执行应用线程,从而会导致短时间内应用无响应。

  • Concurrent会导致GC线程和应用线程并发执行,因此应用线程和GC线程互相抢用CPU,从而会导致出现浮动垃圾,同时GC时间不可控。

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

  • 新生代算法都是基于Coping的,速度快。

  • Parallel Scavenge:吞吐量优先。

  • 吞吐量=运行用户代码时间 /(运行用户代码时间 + 垃圾收集时间)

(5)老年代使用的GC算法

Parallel Compacting

Concurrent Mark-Sweep(CMS)

(6)垃圾收集器总结

(7)实际场景中算法使用的组合

(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]

(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] 

2.2 应用CPU过高

2.2.1 发现问题

一般情况下会有监控告警进行提示:

2.2.2 查找问题进程

利用top查到占用cpu最高的进程pid为14,结果图如下:

2.2.3 查找问题线程

利用 top -H -p 查看进程内占用cpu最高线程,从下图可知,问题线程主要是activeCpu Thread,其pid为417。

2.2.4 查询线程详细信息

  • 首先利用 printf "%x \n" 将tid换为十六进制:xid。

  • 再利用 jstack | grep nid=0x -A 10 查询线程信息(若进程无响应,则使用 jstack -f ),信息如下:

2.2.5 分析代码

由上一步可知该问题是由 CpuThread.java 类引发的,故查询项目代码,获得如下信息:

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 命令获取到数据库隔离级别信息:

3.1.2.2 查询数据库死锁日志

利用 show engine innodb status 命令获取到如下死锁信息:

由上可知,是由于两个事物对这条记录同时持有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 获得结论

分析获得产生问题的加锁时序如下,然后修改代码实现以解决该问题。

3.2 慢SQL

3.1.1 问题出现

应用TPS下降,并出现SQL执行超时异常或者出现了类似如下的告警信息,则常常意味着出现了慢SQL。

3.1.2 问题分析

分析执行计划:利用explain指令获得该SQL语句的执行计划,根据该执行计划,可能有两种场景。

  • SQL不走索引或扫描行数过多等致使执行时长过长。

  • SQL没问题,只是因为事务并发导致等待锁,致使执行时长过长。

3.1.3 场景一

3.1.3.1 优化SQL

通过增加索引,调整SQL语句的方式优化执行时长, 例如下的执行计划:

该SQL的执行计划的type为ALL,同时根据以下type语义,可知无索引的全表查询,故可为其检索列增加索引进而解决。

3.1.4 场景二

3.1.4.1 查询当前事务情况

可以通过查看如下3张表做相应的处理:

-- 当前运行的所有事务select *  from information_schema.innodb_trx;-- 当前出现的锁SELECT * FROM information_schema.INNODB_LOCKS;-- 锁等待的对应关系select *  from information_schema.INNODB_LOCK_WAITS;

(1)查看当前的事务有哪些:

(2)查看事务锁类型索引的详细信息:

lock_table字段能看到被锁的索引的表名,lock_mode可以看到锁类型是X锁,lock_type可以看到是行锁record。

3.1.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事物需要更新此条记录,此时会阻塞,如下图是执行顺序:

3.1.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不同的存储引擎

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亿 条记录。

每个索引的左指针都是比自己小的索引/节点,右指针是大于等于自己的索引/节点。

3.4.2 B+ Tree索引检索

3.4.2.1 主键索引检索

select * from table where id = 1

3.4.2.2 辅助索引检索

select * from table where name = 'a'

3.4.3 事物的隔离级别

3.4.3.1 如何查看数据库的事务隔离级别

使用如下命令可以查看事务的隔离级别:

show variables like 'tx_isolation';

阿里云上的rds的隔离级别是read committed ,而不是原生mysql的“可重复读(repeatable-read)。

  • 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');

脏读场景模拟

(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');

不可重复读的重点是修改: 同样的条件, 你读取过的数据, 再次读取出来发现值不一样了。

(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锁。

幻读的重点在于新增或者删除 (数据条数变化)。同样的条件, 第1次和第2次读出来的记录数不一样。

在标准的事务隔离级别定义下,REPEATABLE READ是不能防止幻读产生的。INNODB使用了2种技术手段(MVCC AND GAP LOCK)实现了防止幻读的发生。

3.4.4 Innodb的多种锁

3.4.4.1 锁类型

  • 表锁的优势:开销小;加锁快;无死锁。

  • 表锁的劣势:锁粒度大,发生锁冲突的概率高,并发处理能力低。

  • 加锁的方式:自动加锁。查询操作(SELECT),会自动给涉及的所有表加读锁,更新操作(UPDATE、DELETE、INSERT),会自动给涉及的表加写锁。也可以显示加锁。

  • 共享读锁:lock table tableName read

  • 独占写锁:lock table tableName write

  • 批量解锁:unlock tables

3.4.4.2 行锁

只在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锁

3.4.4.5 一条SQL的加锁分析

-- select操作均不加锁,采用的是快照读,因此在下面的讨论中就忽略了SQL1:select * from t1 where id = 10;SQL2:delete from t1 where id = 10;

组合分为如下几种场景:

(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.logshow variables like 'slow_query_log_file';  # 查看数据库的事务隔离级别,RDS:READ-COMMITTED   Mysql:Repeatable readshow variables like 'tx_isolation';  # innodb数据页大小  16384show variables like 'innodb_page_size';   show status  like 'innodb_row_%';  # 查看慢SQLSHOW 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)小表驱动大表

nb_soft_nature 中只有24条数据,每条数据的package_name连接到nb_soft表中做查询,由于package_name在nb_soft表中有索引,因此一共只需要24次扫描即可。

(2)大表驱动小表

同上,需要100多万次扫描才能返回结果

3.5.2 使用自增长主键

结合B+Tree的特点,自增主键是连续的,在插入过程中尽量减少页分裂,即使要进行页分裂,也只会分裂很少一部分。并且能减少数据的移动,每次插入都是插入到最后。总之就是减少分裂和移动的频率。

四 Redis

4.1 问题处理思路

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 设置合理的内存淘汰策略

(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 bytesBiggest string Key Top   2  found 'xx2' has 1191 bytesBiggest string Key Top   3  found 'xx3' has 234 bytesBiggest   list Key Top   1  found 'x4' has 204480 itemsBiggest   list Key Top   2  found 'x5' has 119999 itemsBiggest   list Key Top   3  found 'x6' has 60000 itemsBiggest    set Key Top   1  found 'x7' has 14205 membersBiggest    set Key Top   2  found 'x8' has 292 membersBiggest    set Key Top   3  found 'x,7' has 21 membersBiggest   hash Key Top   1  found 'x' has 302939 fieldsBiggest   hash Key Top   2  found 'xc' has 92029 fieldsBiggest   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> xKey             xBytes               4274388.0Type                hashEncoding            hashtableNumber of Elements      39634Length 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 nodes9f194f671cee4a76ce3b7ff14d3bda190e0695d5 m1 master - 0 1550322872543 65 connected 10923-16383a38c6f957f2706f269cf5d9b628586a9372265e9 s1 slave 9f194f671cee4a76ce3b7ff14d3bda190e0695d5 0 1550322872943 65 connected77ce43ec23f25f77ec68fe71ae3cb799e7300c6d s2 slave 03d72a3a5050c85e280e0bbeb687056b84f10077 0 1550322873543 63 connected03d72a3a5050c85e280e0bbeb687056b84f10077 m2 master - 0 1550322873343 63 connected 5461-109225799070c6a63314296f3661b315b95c6328779f7 :0 slave,fail,noaddr 6147bf416ef216b6a1ef2f100d15de4f439b7352 1550320811474 1550320808793 49 disconnected6147bf416ef216b6a1ef2f100d15de4f439b7352 m3 myself,master - 0 0 49 connected 0-5460

4.5.2 移除错误节点

(1)一开始执行如下的删除操作失败,需要针对于每一个节点都执行 cluster forget:

ip:port> cluster forget 61c70a61ad91bbac231e33352f5bdb9eb0be6289CLUSTER 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 9f194f671cee4a76ce3b7ff14d3bda190e0695d5S: 77ce43ec23f25f77ec68fe71ae3cb799e7300c6d s2   slots: (0 slots) slave   replicates 03d72a3a5050c85e280e0bbeb687056b84f10077M: 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三次握手四次挥手

为什么在第3步中客户端还要再进行一次确认呢?这主要是为了防止已经失效的连接请求报文段突然又传回到服务端而产生错误的场景:

所谓"已失效的连接请求报文段"是这样产生的。正常来说,客户端发出连接请求,但因为连接请求报文丢失而未收到确认。于是客户端再次发出一次连接请求,后来收到了确认,建立了连接。数据传输完毕后,释放了连接,客户端一共发送了两个连接请求报文段,其中第一个丢失,第二个到达了服务端,没有"已失效的连接请求报文段"。

现在假定一种异常情况,即客户端发出的第一个连接请求报文段并没有丢失,只是在某些网络节点长时间滞留了,以至于延误到连接释放以后的某个时间点才到达服务端。本来这个连接请求已经失效了,但是服务端收到此失效的连接请求报文段后,就误认为这是客户端又发出了一次新的连接请求。于是服务端又向客户端发出请求报文段,同意建立连接。假定不采用三次握手,那么只要服务端发出确认,连接就建立了。

由于现在客户端并没有发出连接建立的请求,因此不会理会服务端的确认,也不会向服务端发送数据,但是服务端却以为新的传输连接已经建立了,并一直等待客户端发来数据,这样服务端的许多资源就这样白白浪费了。

采用三次握手的办法可以防止上述现象的发生。比如在上述的场景下,客户端不向服务端的发出确认请求,服务端由于收不到确认,就知道客户端并没有要求建立连接。

SYN攻击时一种典型的DDOS攻击,检测SYN攻击的方式非常简单,即当Server上有大量半连接状态且源IP地址是随机的,则可以断定遭到SYN攻击了,使用如下命令可以让之现行:

netstat -nap | grep SYN_RECV

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 问题出现

主要是通过业务日志监控主动报警或者是查看错误日志被动发现:

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"

根据日志格式和日志信息,可获得traceId为489d71fe-67db-4f59-a916-33f25d35cab8,然后利用以下指令获取整个流程的日志信息:

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

6.2.3 代码分析

然后根据上述流程日志找到对应的代码实现,然后进行具体的业务分析。