《分布式java应用：基础与实践》读书笔记

　　在大型互联网领域, 分布式是一种常态. 这本书其实很多技术内容并不只是针对分布式应用, 比如java网络, soa, jvm, jdk集合包, 并发包, java调优, 无论是一般的java应用还是大型的应用, 都有可能涉及到这方面的内容. 而这些正是构建"高可用", "高并发", "可伸缩"系统的基础, 当然里面也涵盖了目前市面上大型互联网公司在这方面的理论和做法.
　　单讲java网络, soa, jvm, jdk集合包, 并发包等这些内容市面上专门的书籍已经有很多了, 所以希望全面深入了解的, 可以找专门的书籍来看(如果欠缺这方面的知识背景, 反而会看不懂里面的一些内容), 本人觉得分析并解决分布式系统中出现的各种问题应该算整本书的亮点, 专门讲这方面的书籍市面上很少, 而且需要有大量的实践经验写出来的东西才比较靠谱.

gc日志信息

引用

[GC [PSYoungGen: 537589K->76797K(537600K)] 765575K->339099K(1598464K), 0.2604570 secs] [Times: user=1.75 sys=0.10, real=0.26 secs]

PS表示GC的方式是PS, 即Parallel Scavenge GC; PSYoungGen之后的537589K->76797K(537600K)表示在Minor GC前, 新生代使用空间为537589K, 回收后新生代空间为76797K, 新生代总共可用空间为537600K.

765575K->339099K(1598464K) 表示在Minor GC前, 堆使用空间为765575K, 回收后使用空间为339099K, 总共可用空间为1598464K

0.2604570 secs 表示本次Minor GC消耗时间

Times: user=1.75 sys=0.10, real=0.26 secs 表示Minor GC 占用spu user和sys的百分比, 以及消耗的总时间.

旧生代和持久代可用的GC
JDK提供了串行, 并行和并发三种GC来对旧生代以及持久代对象所占用的对象进行回收
1.串行
串行基于Mark-Sweep-Compact实现, Mark-Sweep-Compact集合Mark-Sweep, Mark-Compact做了一些改进.

串行执行的整个过程需要暂停应用, 且采用的为单线程方式, 通常要消耗较长时间, 可通过增加-XX:+PrintGCApplicationStoppedTime来查看GC造成的应用暂停的时间.

串行是client即被以及32位windows机器上默认采用的GC方式, 也可通过-XX:+UserSerialGC来强制指定.

3.并发GC(CMS:Concurrent Mark-Sweep GC)
Mark-Sweep方式要对整个空间中的对象进行扫描并标记, 这个过程会造成较长时间的应用暂停, 有些应用对响应时间有很好的要求, 因此Sun JDK提供了CMS GC, 好处是GC的大部分动作均与应用并发进行, 因此可以大大缩短GC造成应用暂停时间.

CMS GC在执行时需要分为多个步骤, 其输出的GC日志信息也会非常多(-Xms20M –Xmx20M –Xmn10M -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails):

引用

[GC [1 CMS-initial-mark: 7170K(10240K)] 9536K(19456K), 0.0004819 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

开始执行CMS GC, 进行Initial-mark步骤, 旧生代的空间为10240K, 目前旧生代被占用了7170K后出发CMS GC

引用

[CMS-concurrent-mark: 0.007/0.007 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

完成concurrent-mark耗时7ms

引用

[CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

重新扫描在concurrent mark阶段CMS Heap中被新创建的对象或从新生代晋升到旧生代对象的引用关系, 以减少remark所需消耗的时间.

引用

[CMS-concurrent-abortable-preclean: 0.002/1.128 secs] [Times: user=0.02 sys=0.00, real=1.14 secs]

暂停preclean 1s左右, 等待remark动作

引用

[GC[YG occupancy: 7332 K (9216 K)][Rescan (parallel) , 0.0018355 secs][weak refs processing, 0.0000104 secs] [1 CMS-remark: 9444K(10240K)] 16776K(19456K), 0.0019495 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

执行并完成remark动作

引用

[CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

执行并完成concurrent-sweep

引用

[CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

重新初始化CMS的相关数据, 为下次CMS GC执行做准备

full gc的四种情况
1.旧生代空间不足
旧生代空间只有在新生代对象转入以及创建为大对象, 大数组时才会出现不足的现象, 当执行full gc后空间仍然不足, 则会抛出oom错误.
为避免这两种情况引起full gc, 调优时应尽量做到让大对象在Minor GC阶段被回收, 让对象在新生代多存活一段时间及不要创建过大的对象和数组.
2.持久代空间满
持久代中存放一些class信息, 当系统中要加载的类, 反射的类和调用的方法较多时, 持久代可能会被占满, 在未配置为采用CMS GC的情况下会执行full gc, 如果经过full gc仍然回收不了, 那么jvm会抛出"PermGen space"的错误信息
为避免持久代被占满造成full gc现象, 可采用的方法是增大持久代或转为使用CMS GC.
3.CMS GC时出现promotion failed和concurrent mode failure
对于采用CMS进行旧生代GC的程序而言, 尤其要注意GC日志中是否有promotion failure和concurrent mode failure两种情况, 这两种状况出现时可能会触发full gc.
promotion failure是在进行minor gc时, survivor space放不下, 对象只能放入旧生代, 而此时旧生代也放不下造成的; concurrent mode failure是在执行CMS GC的过程中同时有对象要放入旧生代, 而此时旧生代空间不足造成的.
应对措施是增加survivor space, 旧生代空间或者调低触发并发GC的比率, 如果remark之后很久才触发sweep, 对这种情况可以通过设置-XX:CMSMaxAbortablePrecleanTime=5(单位为ms)来避免.

full gc日志信息(-server):

引用

[Full GC [PSYoungGen: 1273K->0K(8960K)] [PSOldGen: 6148K->7396K(10240K)] 7421K->7396K(19200K) [PSPermGen: 2025K->2025K(16384K)], 0.0077537 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

这个表明新生代采用了并行回收GC方式, 回收前内存使用1273K, 回收后为0K, 可使用内存为8960K, 旧生代采用了并行回收GC方式, 回收前6148K, 回收后为7396K, 可用内存为19200K, 回收前堆内存为7421K, 回收后为7396K, 可用内存为19200K, 持久代也采用PS GC, 回收前2025K, 回收后依然为2025K, 可用内存为16384K. 回收持久代消耗时间为7.7ms左右, 整个full gc耗时20ms左右.

为避免头痛的gc选择, sun jdk还提供了两种简单的方式来帮助选择gc
1.吞吐量优先
吞吐量是指gc所消耗的时间占应用运行总时间的百分比, 例如, 应用运行了100分钟, 其中执行gc占用了1分钟, 那么吞吐量就是99%, jvm默认的指标是99%.
吞吐量优先的策略以吞吐量为指标, 由jvm自行选择相应的gc策略以及控制新生代, 旧生代内存的大小, 可通过jvm参数中指定的-XX:GCTimeRatio=n来使用此策略.
2.暂停时间优先
暂停时间是指每次gc造成的应用的停顿时间, 默认不启用这个策略.
暂停时间优先的策略即以暂停时间为指标, 由jvm执行选择相应的gc策略以及控制新生代, 旧生代大小, 来尽量保证每次gc造成的应用停顿时间都在指定的数值范围内, 可以通过在jvm参数中指定-XX:MaxGCPauseMillis=n来使用此策略.

内存分析工具
jmap
查看jvm中各个代的内存情况
在linux下执行 jmap -heap pid 可以查看各个代的内存情况:

引用

Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 1342177280 (1280.0MB)
   NewSize          = 335544320 (320.0MB)
   MaxNewSize       = 335544320 (320.0MB)
   OldSize          = 4194304 (4.0MB)
   NewRatio         = 8
   SurvivorRatio    = 8
   PermSize         = 100663296 (96.0MB)
   MaxPermSize      = 268435456 (256.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 301989888 (288.0MB)
   used     = 12453552 (11.876632690429688MB)
   free     = 289536336 (276.1233673095703MB)
   4.123830795288086% used
Eden Space:
   capacity = 268435456 (256.0MB)
   used     = 12453552 (11.876632690429688MB)
   free     = 255981904 (244.1233673095703MB)
   4.639309644699097% used
From Space:
   capacity = 33554432 (32.0MB)
   used     = 0 (0.0MB)
   free     = 33554432 (32.0MB)
   0.0% used
To Space:
   capacity = 33554432 (32.0MB)
   used     = 0 (0.0MB)
   free     = 33554432 (32.0MB)
   0.0% used
tenured generation:
   capacity = 1006632960 (960.0MB)
   used     = 218972904 (208.8288345336914MB)
   free     = 787660056 (751.1711654663086MB)
   21.75300359725952% used
Perm Generation:
   capacity = 100663296 (96.0MB)
   used     = 64892040 (61.88587188720703MB)
   free     = 35771256 (34.11412811279297MB)
   64.46444988250732% used

需要注意的是, 在使用CMS GC时, 执行jmap -heap可能会导致java进程挂起.

jvm中对象内存占用情况(jmap -histo pid | head -n8, 因为内容太多, 因此需要head一下)

引用

num     #instances         #bytes  class name
----------------------------------------------
   1:        839993       48077592  [C
   2:         46325       27393272  [I
   3:       1040471       24971304  java.lang.String
   4:        186190       18294296  [Ljava.lang.Object;
   5:        136653       17474480  <constMethodKlass>

导出整个jvm中的内存信息(jmap -dump:format=b, file=filename pid)

jhat
用来分析jvm heap中对象的内存占用状况, 引用关系等.
执行命令为: jhat -J-Xmx1024M filename
执行之后等待console出现start http server on port 7000， 就可以通过浏览器访问http://ip:7000 此页面默认是按package分类显示系统所有的对象实例. 这个工具针对大的heap的dump文件表现不好, 速度慢.

jstat
sun jdk自带的一个统计分析jvm运行状况的工具, 除了可用于分析gc的状况外, 还可以用于分析编译的状况, class加载的状况等.
jstat用于gc分析的参数有: -gc, -gccapacity, -gccause, -gcnew, -gcnewcapacity, -gcold, -gcoldcapacity, -gcpermcapacity, -gcutil. 最常用的-gcutil, 可以用来查看jvm中各个代的空间占用情况, minor gc的次数, 消耗的时间, full gc的次数以及消耗的时间统计. 执行命令一般为: jstat -gcutils pid interval

引用

  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT  
  0.00   0.00  30.84  21.75  64.46     12    2.835    18   18.322   21.157

S0， S1表示survivor空间的使用率, E表示eden空间的使用率, O表示旧生代, P表示持久代, YGC表示mior gc的执行次数, YGCT表示minor gc执行消耗的时间, FGC表示full gc执行次数, FGCT表示full gc执行消耗时间, GCT表示minor gc+full gc执行消耗的时间.

线程状态及分析
为了跟踪运行时jvm中线程的状况, 可以采用一些工具来判断什么操作是耗系统资源的, 哪些操作出现了锁竞争激烈或死锁现象.

jstack (jstack pid)
sun jdk自带的工具, 用来直接查看jvm中线程的运行情况, 包括锁的等待, 线程是否在运行等. jstack dump出的内容的分析参见(http://www.blogjava.net/jzone/articles/303979.html)

top+thead dump
结合linux的top命令, 可以更轻松的分析目前线程消耗cpu的状况, 包括消耗的cpu总时间, 以及实时cpu消耗比率.

引用

top - 15:49:22 up 570 days, 22:53,  1 user,  load average: 1.92, 1.81, 1.64
Tasks: 120 total,   1 running, 119 sleeping,   0 stopped,   0 zombie
Cpu(s): 12.2% us,  1.3% sy,  0.0% ni, 86.5% id,  0.0% wa,  0.0% hi,  0.0% si
Mem:   4147676k total,  3515764k used,   631912k free,   156032k buffers
Swap:  2096472k total,    33764k used,  2062708k free,   825736k cached

在此需要关注的是第三行信息, 其中12.2% us 表示为用户进程处理所占用的百分比;
1.3% sy 表示内核线程所占用的百分比
0.0% wa 表示在执行过程中等待io所占用的百分比
0.0% ni 标识号被nice命令改变优先级的任务说占用的百分比
86.5% id 表示cpu的空闲时间所占用的百分比
0.0% hi 表示为硬件中断所占的百分比
0.0% si 表示为软件中断所占用的百分比

对于多核cpu, 进入视图后按1， 就会按核来显示消耗情况.

引用

Cpu0  : 34.3% us,  4.7% sy,  0.0% ni, 61.0% id,  0.0% wa,  0.0% hi,  0.0% si
Cpu1  : 10.0% us,  1.0% sy,  0.0% ni, 89.0% id,  0.0% wa,  0.0% hi,  0.0% si
Cpu2  : 12.3% us,  1.0% sy,  0.0% ni, 86.7% id,  0.0% wa,  0.0% hi,  0.0% si
Cpu3  :  2.3% us,  0.7% sy,  0.0% ni, 97.0% id,  0.0% wa,  0.0% hi,  0.0% si
Cpu4  :  6.3% us,  1.0% sy,  0.0% ni, 92.7% id,  0.0% wa,  0.0% hi,  0.0% si
Cpu5  :  6.0% us,  0.7% sy,  0.0% ni, 93.4% id,  0.0% wa,  0.0% hi,  0.0% si
Cpu6  : 10.3% us,  1.0% sy,  0.0% ni, 88.7% id,  0.0% wa,  0.0% hi,  0.0% si
Cpu7  :  5.6% us,  1.0% sy,  0.0% ni, 93.4% id,  0.0% wa,  0.0% hi,  0.0% si

默认情况下, top视图显示的为进程的cpu消耗的情况, 在top视图中按sheft+h, 可按线程来查看cpu的消耗状况.

当cpu消耗严重时, 主要体现在us, sy, wa或hi的值变高, wa的值是io等待造成的, hi的值变高主要为硬件中断造成的, 例如网卡接收数据频繁的状况.

对于java应用而言, cpu消耗严重主要体现在us, sy两个值上.

us
当us值过高时, 表示运行的应用消耗了大量cpu, 在这种情况下, 对于java应用而言, 最终的找到具体消耗cpu的值的线程锁执行的代码.

首先通过linux提供的命令找到消耗cpu严重的线程以及id, 将此线程id转换成十六进制的值. 之后通过jstack的方式dump出应用的java线程信息, 通过之前转换出的十六进制的值找到对应的nid值的线程, 该线程极为消耗cpu的线程, 在采样时须多执行几次上述的过程, 以确保找到真实的消耗cpu的线程.

java应用造成us高的原因主要是线程一直处于可运行状态(runnable), 通常是这些线程在执行无阻塞, 循环, 正则或者纯粹的计算等动作造成的; 另外一个可能也会造成us高的原因是频繁的gc, 如果每次请求都要分配较多的内存, 当访问量高的时候就将导致不断进行gc, 系统响应速度下降, 进入造成堆积的请求更多, 消耗的内存更严重, 最严重的时候有可能导致系统不断进行full gc, 对于频繁gc的状况可以通过分析jvm内存的消耗来查找原因.

在程序运行时 使用top命令打开线程(sheft+h)查看情况
找到最消耗线程的pid (26697), 将其转换为十六进制(0x6849), 结合java thread dump(jstack 26697 | grep 'nid=0x6849), 找到对应的线程
由于jstack需要时间, 因此基于jstack并不一定能分析出真正消耗cpu的代码是哪行. 例如一个操作中循环调用了很多次其他的操作, 如其他的操作每次都比较快, 但由于循环太多次, 造成了cpu消耗, 在这种情况下jstack是无法捕捉出来的.

sy
当sy值高时, 表示linux花费了更多的时间在进行线程切换, java应用造成这种线程的主要原因是启动的线程比较多. 且这些线程多数都处于不断的阻塞(例如锁, io等待状态)和执行状态的变化过程中, 这就导致了操作系统要不断地切换执行的线程, 产生大量的上下文切换, 在这种状态下, 对java应用而言, 最要的是找出线程要不断切换的原因, 可采用的方法是通过jstack -l pid的方式dump出java应用程序的线程信息, 查看线程的状态信息以及锁信息, 找出等待状态或者锁竞争过多的线程.

linux中可采用sar来分析网络io的消耗情况.

vmstat
在命令行中输入vmstat, 其中的信息和内存相关的主要是memory下的swpd, free, buff, cache以及swap下的si和so.
其中swapd是指虚拟内存已经使用的部分, 单位为kb, free表示空闲的物理内存, buff表示用于缓存的内存, cache表示用于作为缓存的内容, swap下的si是指每秒从disk读取至内存的数据量, so是指每秒从内存中写入disk的数据量.
swpd值过高通常是由于物理内存不够用了. os将物理内存中的一部分数据转为放入硬盘上进行存储, 以腾出足够的空间给当前运行的程序使用. 在目前运行的程序变化后, 即从硬盘上重新读取数据到内存中, 以便恢复程序的运行, 这个过程会产生swap io, 因此看swap的消耗情况主要要关注的是swap io的状况, 如swap io发生得较为频繁, 那么会严重影响系统的性能.

sar -r
用来查看内存的消耗情况

引用

02:00:01 PM kbmemfree kbmemused  %memused kbbuffers  kbcached kbswpfree kbswpused  %swpused  kbswpcad
02:10:01 PM    770152   3377524     81.43    144100    733408   2062708     33764      1.61       772
02:20:01 PM    728776   3418900     82.43    145252    742916   2062708     33764      1.61       772

其中和swap相关的信息: kbswpfree表示swap空间的大小, kbswpused表示已使用的swap大小, %swpused  表示使用的swap的空间比率.
kbmemfree kbmemused  %memused表示的是物理内存相关的信息, 当物理内存有空闲时, linux会使用一些物理内存用于buffer以及cache, 以提升系统的运行效率, 因此可以认为系统中可用的物理内存为:kbmemfree +kbcached +kbbuffers 

sar相比vmstat的好处是可以查看历史状况, 以便更加准确地分析趋势状况.


如果系统不是cpu密集型, 且从新生代进入旧生代的大部分对象是可回收的, 那么采用CMS GC可以更好的在旧生代满之前完成对象的回收, 更大程度降低full gc的可能.

cpu us高的原因主要是执行程序无任何挂起动作, 且一直执行, 导致cpu没有机会去调用执行其他的线程, 造成线程饿死(线程始终无法获得资源)的现象. 对于这种情况, 常见的一种优化方法是对这种线程的动作增加Thread.sleep, 以释放cpu的执行权, 降低cpu的消耗.

造成cpu sy高的原因除了启动的线程过多以外, 还有一个重要的原因是线程之间锁竞争激烈, 造成线程状态经常要切换, 因此尽可能降低线程间的锁竞争也是常见的优化方法.