打印GRPC日志 gc日志打印设置

转载

mob64ca140761a4 2024-03-17 00:13:49

文章标签 打印GRPC日志 sed Time JVM 文章分类 云原生云计算

GC日志配置与日志格式

-XX:+PrintGC或者-verbose:gc：开启日志打印功能，即JVM会将运行期间的每次GC事件都以日志方式输出出来。配置之后打印如下：

[GC 118250K->113543K(130112K), 0.0094143 secs]
[Full GC 121376K->10414K(130112K), 0.0650971 secs]

GC表示为Minor GC，Full GC表示为Full GC，即表示收集类型。
其中118250K->113543K(130112K) 0.0094143 secs 表示：118250K为GC回收之前堆空间的大小，113543K为GC回收后堆空间的大小，130112K为堆空间的大小，0.0094143 secs表示以秒为单位的GC执行时间。

-Xloggc:：GC日志文件配置，日志将会输出到GC日志到该指定的文件。
-XX:PrintGCDetails：GC时输出更多详细的信息，如使用的GC回收器类型，新生代或者老年代的回收情况等，不同的垃圾回收器略有不同，如下：

Serial + ParNew

新生代：ParNew（par new generation）
老年代：Tenured
永久代：Perm

ParNew + CMS + Serial Old

新生代：DefNew(def new generation)
老年代：CMS
永久代：CMS Perm

Parallel Scavenge + Parallel Old

新生代：PSYoungGen
老年代：ParOldGen
永久代：PSPermGen

如下为Parallel并发回收器的Minor GC和Full GC的回收日志：

[GC [PSYoungGen: 7307K->480K(9216K)] 7307K->6624K(19456K), 0.0072860 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
[Full GC [PSYoungGen: 480K->0K(9216K)] [ParOldGen: 6144K->6476K(10240K)] 6624K->6476K(19456K) [PSPermGen: 2920K->2919K(21504K)], 0.0178620 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

[PSYoungGen: 7307K->480K(9216K)]表示新生代的垃圾回收前后的大小情况，回收前内存占用为7307K，回收后内存占用为480K，新生代总大小为9216K；
7307K->6624K(19456K)表示此次GC的堆的内存变化情况，堆的总大小为19456K。
0.0072860 secs为此次GC的实际耗时。
[Times: user=0.01 sys=0.01, real=0.00 secs]：user表示用户态CPU耗时，sys为系统态CPU耗时，real为GC实际执行耗时。user + sys 时间为GC执行实际使用的CPU时间。注意这里指所有的 CPU的累加值，因此如果在进程里有多个线程的话，这个时间可能会超过real所表示的时钟时间。
如果user + sys 时间的和比 real 时间要大，是因为real对应的日志时间是从JVM中获得的，而这个JVM 在多核的处理器上被配置了多个GC 线程，由于多个线程并行地执行GC，因此整个GC 工作被这些线程共享，最终导致实际的时钟时间（real）小于总的 CPU 时间（user + sys）。

-XX:PrintGCDateStamps：以日期格式打印此处GC事件发生的时间点，如下：

2019-03-23T01:49:18.778+0800: 7.315: [GC [PSYoungGen: 393216K->60678K(458752K)] 393216K->60686K(720896K), 0.1241514 secs] [Times: user=0.13 sys=0.05, real=0.12 secs]

-XX:PrintGCTimeStamps：以相对于JVM进程启动时间的时间点，即在JVM执行执行了多久时，发生了此处GC事件，如下：

289.556: [GC [PSYoungGen: 314113K->15937K(300928K)] 405513K->107901K(407680K), 0.0178568 secs] [Times: user=0.06 sys=0.00, real=0.01 secs]

-XX:PrintGCApplicationStoppedTime：应用程序在此次GC期间暂停的时间如下：

21.773: Total time for which application threads were stopped: 0.0542506 seconds

-XX:PrintHeapAtGC：打印GC前后堆的详细信息：

{Heap before GC invocations=4 (full 0):
 PSYoungGen      total 17408K, used 17392K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)
  eden space 16384K, 100% used [0x00000000fdf00000,0x00000000fef00000,0x00000000fef00000)
  from space 1024K, 98% used [0x00000000fef00000,0x00000000feffc010,0x00000000ff000000)
  to   space 1024K, 0% used [0x00000000fff00000,0x00000000fff00000,0x0000000100000000)
 ParOldGen       total 68608K, used 34096K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)
  object space 68608K, 49% used [0x00000000f9c00000,0x00000000fbd4c000,0x00000000fdf00000)
 Metaspace       used 2612K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 285K, capacity 386K, committed 512K, reserved 1048576K

[GC (Allocation Failure) [PSYoungGen: 17392K->1024K(32768K)] 51488K->52816K(101376K), 0.0101398 secs] [Times: user=0.00 sys=0.00, real=0.00

Heap after GC invocations=4 (full 0):
 PSYoungGen      total 32768K, used 1024K [0x00000000fdf00000, 0x0000000100000000, 0x0000000100000000)
  eden space 31744K, 0% used [0x00000000fdf00000,0x00000000fdf00000,0x00000000ffe00000)
  from space 1024K, 100% used [0x00000000fff00000,0x0000000100000000,0x0000000100000000)
  to   space 1024K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x00000000fff00000)
 ParOldGen       total 68608K, used 51792K [0x00000000f9c00000, 0x00000000fdf00000, 0x00000000fdf00000)
  object space 68608K, 75% used [0x00000000f9c00000,0x00000000fce94050,0x00000000fdf00000)
 Metaspace       used 2612K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 285K, capacity 386K, committed 512K, reserved 1048576K
}