java查看日志的命令有哪些 jdk日志怎么查看

转载

mob64ca140a8e67 2023-08-12 21:10:03

文章标签 java查看日志的命令有哪些 java sed Time ci 文章分类 Java 后端开发

前言：

从事java开发的小伙伴，对JVM都不会陌生。这块的知识点笔者不再多述，网络上有很多教程。

基本了解了JVM的内存结构后，那么平时我们怎么排查jvm相关的问题呢？

那就要从jvm参数和GC日志来分析具体问题了，通过jvm参数了解其基本设置；通过GC日志了解GC具体情况。

下面我们来实战一把。

1.准备工作

笔者使用的JDK版本为1.8.0_131版本，通过命令java -version可以看出

PS D:\Program Files\Java\jdk1.8.0_131\bin> java -version
java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)

再准备一个简单的程序，模拟full gc情况

1.1 JVM参数设置

笔者需要将具体的gc情况打印出来，一般需要使用到以下参数

-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式）
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

笔者自己准备的测试代码jvm参数如下

-Xmx1G -Xms1G -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:E:/gclogs

最大堆内存设置为1G，打印gc日志到E:/gclogs文件里

1.2 代码准备

public class User implements Serializable {
    private static final long serialVersionUID = -1754313838977971228L;

    private String password;
    private String username;

    private byte[] bytes = null;
    public User(String password, String username) {
        this.password = password;
        this.username = username;

        bytes = new byte[1 * 1024 * 1024];
    }
}

User对象，每次新建都会占用1MB的空间(bytes对象)

测试类如下：

// -Xmx1G -Xms1G -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:E:/gclogs
public class JvmTest {
	@Test
    public void test() {
        List<User> stuList = new ArrayList<>();
        for (int j = 0; j < 1000; j++) {
            stuList.add(new User("jack" + j, "pass" +j));
            if (stuList.size() == 500) {
                stuList = null;
                stuList = new ArrayList<>();
            }

            try {
                Thread.sleep(50);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }
}

代码很简单，我们设置最大堆内存为1G，这里创建1000个User对象，50ms休息一次，500次将stuList设置为null

2.jvm日志

整个测试过程结束后，生成的gclog文件内容如下：

# 1.JDK及jvm参数信息
Java HotSpot(TM) 64-Bit Server VM (25.131-b11) for windows-amd64 JRE (1.8.0_131-b11), built on Mar 15 2017 01:23:53 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 8271080k(1594440k free), swap 14562536k(5074312k free)
CommandLine flags: -XX:InitialHeapSize=1073741824 -XX:MaxHeapSize=1073741824 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 

# 2.GC情况
2022-03-26T12:22:15.599+0800: 14.553: [GC (Allocation Failure) [PSYoungGen: 262107K->43512K(305664K)] 262107K->225621K(1005056K), 0.0765077 secs] [Times: user=0.08 sys=0.09, real=0.06 secs] 
2022-03-26T12:22:31.416+0800: 30.371: [GC (Allocation Failure) [PSYoungGen: 305123K->43496K(305664K)] 487232K->483665K(1005056K), 0.1101805 secs] [Times: user=0.08 sys=0.31, real=0.11 secs] 
2022-03-26T12:22:31.525+0800: 30.481: [Full GC (Ergonomics) [PSYoungGen: 43496K->0K(305664K)] [ParOldGen: 440169K->481727K(699392K)] 483665K->481727K(1005056K), [Metaspace: 9390K->9390K(1058816K)], 0.0721537 secs] [Times: user=0.20 sys=0.02, real=0.06 secs] 
2022-03-26T12:22:47.551+0800: 46.505: [Full GC (Ergonomics) [PSYoungGen: 262111K->0K(305664K)] [ParOldGen: 481727K->230802K(699392K)] 743839K->230802K(1005056K), [Metaspace: 9390K->9390K(1058816K)], 0.0846851 secs] [Times: user=0.26 sys=0.00, real=0.08 secs] 
2022-03-26T12:23:03.537+0800: 62.490: [GC (Allocation Failure) [PSYoungGen: 262131K->43136K(305664K)] 492934K->492054K(1005056K), 0.0493609 secs] [Times: user=0.19 sys=0.00, real=0.05 secs] 
2022-03-26T12:23:03.583+0800: 62.540: [Full GC (Ergonomics) [PSYoungGen: 43136K->0K(305664K)] [ParOldGen: 448918K->491961K(699392K)] 492054K->491961K(1005056K), [Metaspace: 9390K->9390K(1058816K)], 0.0924415 secs] [Times: user=0.17 sys=0.02, real=0.09 secs] 

# 3.堆内存占用信息
Heap
 PSYoungGen      total 305664K, used 31079K [0x00000000eab00000, 0x0000000100000000, 0x0000000100000000)
  eden space 262144K, 11% used [0x00000000eab00000,0x00000000ec959d90,0x00000000fab00000)
  from space 43520K, 0% used [0x00000000fab00000,0x00000000fab00000,0x00000000fd580000)
  to   space 43520K, 0% used [0x00000000fd580000,0x00000000fd580000,0x0000000100000000)
 ParOldGen       total 699392K, used 491961K [0x00000000c0000000, 0x00000000eab00000, 0x00000000eab00000)
  object space 699392K, 70% used [0x00000000c0000000,0x00000000de06e740,0x00000000eab00000)
 Metaspace       used 9647K, capacity 10788K, committed 11008K, reserved 1058816K
  class space    used 1274K, capacity 1507K, committed 1536K, reserved 1048576K

3 当前进程内存分布情况

之前的博客笔者已经有过介绍，我们使用%JAVA_HOME%/bin下的jmap命令可以查看进程的具体内存分布情况

3.1 jps来获取当前测试进程ID

PS D:\Program Files\Java\jdk1.8.0_131\bin> jps
16128 Launcher
16724
10264 JUnitStarter
9960 RemoteMavenServer
19164 Jps

10264就是上述我们的JvmTest.test()方法进程id

3.2 jmap获取进程内存分布情况

PS D:\Program Files\Java\jdk1.8.0_131\bin> .\jmap.exe -heap 10264
Attaching to process ID 10264, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.131-b11

using thread-local object allocation.
Parallel GC with 4 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 1073741824 (1024.0MB)
   NewSize                  = 357564416 (341.0MB)
   MaxNewSize               = 357564416 (341.0MB)
   OldSize                  = 716177408 (683.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 268435456 (256.0MB)
   used     = 37198920 (35.47565460205078MB)
   free     = 231236536 (220.52434539794922MB)
   13.857677578926086% used
From Space:
   capacity = 44564480 (42.5MB)
   used     = 21331976 (20.34375762939453MB)
   free     = 23232504 (22.15624237060547MB)
   47.867665010340076% used
To Space:
   capacity = 44564480 (42.5MB)
   used     = 0 (0.0MB)
   free     = 44564480 (42.5MB)
   0.0% used
PS Old Generation
   capacity = 716177408 (683.0MB)
   used     = 16384 (0.015625MB)
   free     = 716161024 (682.984375MB)
   0.002287701317715959% used

5259 interned Strings occupying 446160 bytes.

MaxHeapSize最大堆内存就是我们设置的1G

NewRatio=2，所以Old Generation（老年代）占用2/3，为683MB，NewSize（新生代）占用1/3，为341M，总共为683+341=1024M

SurvivorRatio=8，则新生代中 Eden区占用8/10，为256MB，From区和To区分别占用1/10，为42.5MB，总共为256+42.5+42.5=341MB

4.GC日志分析

4.1 young gc分析

我们先来分析下young gc的日志，就是如下一行

2022-03-26T12:22:15.599+0800: 14.553: [GC (Allocation Failure) [PSYoungGen: 262107K->43512K(305664K)] 262107K->225621K(1005056K), 0.0765077 secs] [Times: user=0.08 sys=0.09, real=0.06 secs]

具体每个字段的含义如下：

2022-03-26T12:22:15.599+0800: 14.553	# 当前执行时间
GC (Allocation Failure)					# GC类型为young gc，发生在新生代
PSYoungGen: 262107K->43512K(305664K)	# PSYoungGen(新生代) 262107K(young gc前新生代内存内存占用) 43512K(young gc后新生代内存内存占用) 305664K(新生代总内存大小)
262107K->225621K(1005056K)				# 262107K(young gc前堆内存内存占用) 225621K(young gc后堆内存内存占用)  1005056K(JVM堆总内存大小)
0.0765077 secs							# young gc耗时
Times: user=0.08 sys=0.09, real=0.06 secs	# user(用户耗时) sys(系统耗时) real(young gc实际耗时)

4.2 full gc日志分析

full gc日志如下

2022-03-26T12:22:31.525+0800: 30.481: [Full GC (Ergonomics) [PSYoungGen: 43496K->0K(305664K)] [ParOldGen: 440169K->481727K(699392K)] 483665K->481727K(1005056K), [Metaspace: 9390K->9390K(1058816K)], 0.0721537 secs] [Times: user=0.20 sys=0.02, real=0.06 secs]

具体每个字段的含义如下

2022-03-26T12:22:31.525+0800: 30.481	# 当前执行时间
Full GC (Ergonomics)					# GC类型为 full gc，发生在老年代
PSYoungGen: 43496K->0K(305664K)			# PSYoungGen(新生代) 43496K(full gc前新生代内存内存占用) 0K(full gc后新生代内存内存占用) 305664K(新生代总内存大小)
ParOldGen: 440169K->481727K(699392K)	# ParOldGen(老年代) 440169K(full gc前老年代内存内存占用) 481727K(full gc后老年代内存占用) 699392K(老年代总内存大小)
483665K->481727K(1005056K)				# 483665K(full gc前堆内存内存占用) 481727K(full gc后堆内存内存占用)  1005056K(JVM堆总内存大小)
Metaspace: 9390K->9390K(1058816K)		# Metaspace(方法区) 9390K(full gc前方法区内存内存占用) 9390K(full gc后方法区内存占用) 1058816K(方法区总内存大小)

0.0721537 secs							# full gc耗时
[Times: user=0.20 sys=0.02, real=0.06 secs]		# user(用户耗时) sys(系统耗时) real(full gc实际耗时)

4.3 heap信息分析

Heap
# 新生代总共305664K，已经使用31079K
# eden区空间，11%被使用
 PSYoungGen      total 305664K, used 31079K [0x00000000eab00000, 0x0000000100000000, 0x0000000100000000)
  eden space 262144K, 11% used [0x00000000eab00000,0x00000000ec959d90,0x00000000fab00000)
  from space 43520K, 0% used [0x00000000fab00000,0x00000000fab00000,0x00000000fd580000)
  to   space 43520K, 0% used [0x00000000fd580000,0x00000000fd580000,0x0000000100000000)
  
# 老年代总共699392K，已经使用491961K，被占用70%
 ParOldGen       total 699392K, used 491961K [0x00000000c0000000, 0x00000000eab00000, 0x00000000eab00000)
  object space 699392K, 70% used [0x00000000c0000000,0x00000000de06e740,0x00000000eab00000)
  
# 方法区总共11008K，被使用9647K
 Metaspace       used 9647K, capacity 10788K, committed 11008K, reserved 1058816K
  class space    used 1274K, capacity 1507K, committed 1536K, reserved 1048576K

有关于Metaspace的更多知识点可以参考：https://www.jianshu.com/p/a6f19189ec62

总结：

更多的明细信息可以参考Oracle官网信息，地址如下：Java SE 6 HotSpot[tm] Virtual Machine Garbage Collection Tuning

本文章为转载内容，我们尊重原作者对文章享有的著作权。如有内容错误或侵权问题，欢迎原作者联系我们进行内容更正或删除文章。

上一篇：python语言ord Python语言属于

下一篇：arcmap中怎么运行python arcmap操作

提问和评论都可以，用心的回复会被更多人看到评论

发布评论

相关文章

官方博客	全部文章	热门标签	班级博客
了解我们	网站地图	意见反馈

鸿蒙开发者社区	51CTO学堂
51CTO	软考资讯