2024-02-21 21:43:46.0|分类: jvm|浏览量: 293
|
tomcat 内存占用不高，tomcat 分了 8 个 G 内存，系统中有缓存对象，缓存对象大概占用 2 个 G。
通过 skywalking 发现 OLD Gc 次数执行了 8 次。根据这个异常指标怀疑系统有显示调用 gc 动作，tomcat 增加上 gc 打印日志，发现 groupx 执行语句的时候会打印 full gc 信息，明显有显示调用 gc 语法。 tomcat启动脚本配置参数： -Xmx8096M -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseConcMarkSweepGC 日志关键信息如下： 2024-02-20T18:18:46.970+0800: [Full GC (System.gc())2024-02-20T18:18:46.970+0800: [CMS: 2114340K->2231301K(3590980K), 2.2208823 secs] 2469949K->2231301K(4204420K), [Metaspace: 98222K->98222K(1140736K)], 2.2219221 secs] [Times: user=2.17 sys=0.05, real=2.22 secs] 2024-02-20T18:18:49.193+0800: [Full GC (System.gc())2024-02-20T18:18:49.193+0800: [CMS: 2231301K->2155273K(3718840K), 2.1092369 secs] 2234145K->2155273K(4332280K), [Metaspace: 98222K->98222K(1140736K)], 2.1094791 secs] [Times: user=2.11 sys=0.00, real=2.11 secs] 2024-02-20T18:18:51.304+0800: [Full GC (System.gc())2024-02-20T18:18:51.304+0800: [CMS: 2155273K->2155274K(3718840K), 1.5618582 secs] 2159149K->2155274K(4332280K), [Metaspace: 98222K->98222K(1140736K)], 1.5620906 secs] [Times: user=1.56 sys=0.00, real=1.56 secs] 2024-02-20T18:18:52.867+0800: [Full GC (System.gc())2024-02-20T18:18:52.867+0800: [CMS: 2155274K->2155288K(3718840K), 1.7847399 secs] 2167302K->2155288K(4332280K), [Metaspace: 98224K->98224K(1140736K)], 1.7851512 secs] [Times: user=1.80 sys=0.00, real=1.78 secs] .... 日志中发现有显示调用gc方法，Full GC (System.gc()执行了8次,每次 gc 时间是：2.17s,2.11s,1.56s,1.80s,1.69s，1.55s,1.58s,1.22s。8 次共耗时13.68s。13.68s 的时候系统好像死掉一样，整个 tomcat 不执行用户动作，用户感觉系统很卡，无法开展实际业务。 找到响应的代码，发现代码中有 Runtime rt = Runtime.getRuntime(); rt.runFinalization(); rt.gc(); Thread.yield(); System.gc()方法的调用 此方法的调用是建议JVM进行Full GC,虽然只是建议而非一定,但很多情况下它会触发 Full GC,从而增加Full GC的频率 ,也即增加了间歇性停顿的次数。 强烈建议能不使用此方法就别使用，让虚拟机自己去管理它的内存，可通过通过-XX:+ DisableExplicitGC来禁止RMI调用System.gc。 老年代代空间不足 老年代空间只有在新生代对象转入及创建为大对象、大数组时才会出现不足的现象，当执行Full GC后空间仍然不足 ，则抛出如下错误： java.lang.OutOfMemoryError: Java heap space 为避免以上两种状况引起的Full GC，调优时应尽量做到让对象在Minor GC阶段被回收、 让对象在新生代多存活一段时间及不要创建过大的对象及数组。 永生区空间不足 JVM规范中运行时数据区域中的方法区，在HotSpot虚拟机中又被习惯称为永生代或者永生区， Permanet Generation中存放的为一些class的信息、常量、静态变量等数据， 当系统中要加载的类、反射的类和调用的方法较多时，Permanet Generation可能会被占满， 在未配置为采用CMS GC的情况下也会执行Full GC。 如果经过Full GC仍然回收不了，那么JVM会抛出如下错误信息： java.lang.OutOfMemoryError: PermGen space 为避免Perm Gen占满造成Full GC现象，可采用的方法为增大Perm Gen空间或转为使用CMS GC 其他gc日志解释： 2024-02-21T21:11:53.138+0800: [GC (Allocation Failure) 2024-02-21T21:11:53.138+0800: [ParNew: 78016K->8640K(78016K), 0.0106275 secs] 149975K->88420K(251456K), 0.0106709 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 上面解释： GC：表明进行了一次垃圾回收，前面没有Full修饰，表明这是一次Minor GC ,注意它不表示只GC新生代， 并且现有的不管是新生代还是老年代都会STW。 Allocation Failure：表明本次引起GC的原因是因为在年轻代中没有足够的空间能够存储新的数据了。 ParNew：表明本次GC发生在年轻代并且使用的是ParNew垃圾收集器。ParNew是一个Serial收集器的多线程版本， 会使用多个CPU和线程完成垃圾收集工作（默认使用的线程数和CPU数相同， 可以使用-XX：ParallelGCThreads参数限制）。该收集器采用复制算法回收内存，期间会停止其他工作线程， 即Stop The World。 78016K->8640K(78016K)：单位是KB 三个参数分别为：GC前该内存区域(这里是年轻代)使用容量，GC后该内存区域使用容量，该内存区域总容量。 0.0106275 secs：该内存区域GC耗时，单位是秒 149975K->88420K(251456K)： 三个参数分别为：堆区垃圾回收前的大小，堆区垃圾回收后的大小，堆区总大小。 0.0106709 secs：该内存区域GC耗时，单位是秒 [Times: user=0.00 sys=0.00, real=0.01 secs]：分别表示用户态耗时，内核态耗时和总耗时 2024-02-21T21:11:53.544+0800: [GC (Allocation Failure) 2024-02-21T21:11:53.544+0800: [ParNew: 78016K->8639K(78016K), 0.0091349 secs] 157796K->94341K(251456K), 0.0091737 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 2024-02-21T21:11:53.922+0800: [GC (Allocation Failure) 2024-02-21T21:11:53.922+0800: [ParNew: 78015K->8639K(78016K), 0.0103036 secs] 163717K->101348K(251456K), 0.0103445 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] CMS(concurrent mark sweep)在jdk1.5中已经开始使用了,2004年9月30日,JDK1.5发布。 CMS设计的目标就是获取最低停顿时间(stop the world停顿时间),它是基于标记-清除算法实现的。 常用的场景是互联网网站(对服务响应要求较高),它是一个老年代垃圾收集器,可以和Serial收集器, Parallel New收集器配合使用。当并行模式(concurrent mode failure)失败时CMS会退化成Serial Old. CMS全称 Concurrent Mark Sweep，是一款并发的、使用标记-清除算法的垃圾回收器 2024-02-21T21:11:53.933+0800: [GC (CMS Initial Mark) [1 CMS-initial-mark: 92708K(173440K)] 102733K(251456K), 0.0007576 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 阶段1：Initial Mark 这个是 CMS 两次 stop-the-wolrd 事件的其中一次，这个阶段的目标是：标记那些直接被 GC root 引用或者被年轻代存活对象所引用的所有对象 2024-02-21T21:11:53.934+0800: [CMS-concurrent-mark-start] 2024-02-21T21:11:53.954+0800: [CMS-concurrent-mark: 0.020/0.020 secs] [Times: user=0.03 sys=0.02, real=0.02 secs] 阶段2：并发标记 在这个阶段 Garbage Collector 会遍历老年代，然后标记所有存活的对象，它会根据上个阶段找到的 GC Roots 遍历查找。并发标记阶段，它会与用户的应用程序并发运行。并不是老年代所有的存活对象都会被标记，因为在标记期间用户的程序可能会改变一些引用 2024-02-21T21:11:53.954+0800: [CMS-concurrent-preclean-start] 2024-02-21T21:11:53.956+0800: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 阶段3：Concurrent Preclean Concurrent Preclean：这也是一个并发阶段，与应用的线程并发运行，并不会 stop 应用的线程。在并发运行的过程中，一些对象的引用可能会发生变化，但是这种情况发生时，JVM 会将包含这个对象的区域（Card）标记为 Dirty，这也就是 Card Marking。 2024-02-21T21:11:53.956+0800: [CMS-concurrent-abortable-preclean-start] 2024-02-21T21:11:54.213+0800: [CMS-concurrent-abortable-preclean: 0.037/0.256 secs] [Times: user=0.28 sys=0.11, real=0.26 secs] 阶段4：Concurrent Abortable Preclean 这也是一个并发阶段，但是同样不会影响影响用户的应用线程，这个阶段是为了尽量承担 STW（stop-the-world）中最终标记阶段的工作。这个阶段持续时间依赖于很多的因素，由于这个阶段是在重复做很多相同的工作，直接满足一些条件（比如：重复迭代的次数、完成的工作量或者时钟时间等）。 2024-02-21T21:11:54.213+0800: [GC (CMS Final Remark) [YG occupancy: 55830 K (78016 K)]2024-02-21T21:11:54.213+0800: [Rescan (parallel) , 0.0044857 secs]2024-02-21T21:11:54.218+0800: [weak refs processing, 0.0001002 secs]2024-02-21T21:11:54.218+0800: [class unloading, 0.0040286 secs]2024-02-21T21:11:54.222+0800: [scrub symbol table, 0.0017544 secs]2024-02-21T21:11:54.224+0800: [scrub string table, 0.0004308 secs][1 CMS-remark: 92708K(173440K)] 148539K(251456K), 0.0114974 secs] [Times: user=0.08 sys=0.00, real=0.01 secs] 阶段5：Final Remark 这是第二个 STW 阶段，也是 CMS 中的最后一个，这个阶段的目标是标记所有老年代所有的存活对象，由于之前的阶段是并发执行的，gc 线程可能跟不上应用程序的变化，为了完成标记老年代所有存活对象的目标，STW 就非常有必要了。 通常 CMS 的 Final Remark 阶段会在年轻代尽可能干净的时候运行，目的是为了减少连续 STW 发生的可能性（年轻代存活对象过多的话，也会导致老年代涉及的存活对象会很多）。这个阶段会比前面的几个阶段更复杂一些， 2024-02-21T21:11:54.225+0800: [CMS-concurrent-sweep-start] 2024-02-21T21:11:54.241+0800: [CMS-concurrent-sweep: 0.016/0.016 secs] [Times: user=0.03 sys=0.02, real=0.02 secs] 阶段6：Concurrent Sweep 这里不需要 STW，它是与用户的应用程序并发运行，这个阶段是：清除那些不再使用的对象，回收它们的占用空间为将来使用 2024-02-21T21:11:54.241+0800: [CMS-concurrent-reset-start] 2024-02-21T21:11:54.309+0800: [CMS-concurrent-reset: 0.069/0.069 secs] [Times: user=0.13 sys=0.13, real=0.07 secs] 阶段7：Concurrent Reset. 这个阶段也是并发执行的，它会重设 CMS 内部的数据结构，为下次的 GC 做准备 2024-02-21T21:11:54.367+0800: [GC (Allocation Failure) 2024-02-21T21:11:54.367+0800: [ParNew: 78015K->8639K(78016K), 0.0059781 secs] 114123K->50492K(251456K), 0.0060213 secs] [Times: user=0.11 sys=0.00, real=0.01 secs] ... |