Java Flight Recordings (JFR) — Java 飞行记录器 – part 1

一、JFR 飞行记录器

Java Flight Recorder(JFR)是一个商业特性,用在生产服务器上是需要商业许可的。

JFR 记录了关于 Java 运行时及运行在其内的 Java 应用程序的详细信息,记录用少量的开销完成。数据是作为时间上的数据点(称为事件)记录的。典型的事件可以是线程等待锁、GC、CPU 周期使用数据等。

在创建飞行记录时,你可以选择哪些事件应当保存,这叫做记录模板。有些模板只保存基本事件,对性能几乎没有影响。其他模板可能有轻微的性能开销,还可能触发 GC 来收集更多信息。通常,超过百分之几的开销是很罕见。

飞行记录可用于调试很大范围的问题,从性能问题到内存泄漏或严重的锁竞争。

1、记录类型

1.1、连续录制

一个连续记录是指记录总是开着并保存,例如,过去六小时的数据。如果应用程序陷入问题,你可以转储(dump)这些数据,例如,从过去一小时的,看看出生问题时发生了什么。

连续记录的默认设置是使用记录 profile,开销极低。这个 profile 不收集堆统计信息或(内存)分配性能分析,但仍然收集了很多有用数据。

保持持续录制一直允许是很好的,对于调试非常罕见的问题时非常有用。记录可以用 jcmdJMC 手工转储。你也可以在 JMC 里设置触发器在一些特定的条件被满足后转储飞行记录。

1.2、性能分析录制

性能分析录制是指记录开着,运行一定时间,然后停止。通常, 性能分析录制允许更多的时间,有可能对性能有较大的冲击。被开启的时间可以被修改,取决于你的 性能分析录制。

使用 性能分析录制 的典型场景如下:

  • 剖析运行最频繁的方法和创建对象最多的地方。
  • 查找使用了越来越多内存的类,暗示着内存泄漏。
  • 查找因为同步而导致的瓶颈,更多类型的情景。

性能分析录制 将给出很多信息,即使你不是在定位特定的问题。 性能分析录制 将给你关于应用程序的很好的视图,可以帮助你找出瓶颈或需要提高的地方。

继续阅读

JVM CPU 使用率高 问题两则

最近有两个系统先后被恶意扫描,出现 CPU 使用率高的现象。很好,把问题暴露出来解决掉。

CPU 使用率很高,首先是要找出 CPU 在执行什么样的代码,然后在分析这些代码有什么问题。

一、问题定位

1、 用命令 “ps aux | grep APP” 找出应用的进程 id:

801       84703  5.6 28.8 4627436 1132100 pts/2 Sl   11:08  11:19 /usr/jdk1.6.0_38/bin/java APP

2、 找出耗CPU的线程,在Linux系统下用命令:“ top –H –p pid ”, pid 就是前面找出来的应用进程 ID 。这个命令会显示出当前占用CPU高的线程。

Tasks: 426 total,   0 running, 426 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.5%us,  0.6%sy,  0.0%ni, 72.3%id, 26.6%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   3924912k total,  3308088k used,   616824k free,      768k buffers
Swap:  8388600k total,  3236720k used,  5151880k free,    12304k cached

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
84784 appdeplo  20   0 4518m 1.1g 3816 S  0.4 29.0   0:00.85 java
84903 appdeplo  20   0 4518m 1.1g 3816 S  0.4 29.0   0:34.66 java
84983 appdeplo  20   0 4518m 1.1g 3816 S  0.4 29.0   0:00.99 java
85091 appdeplo  20   0 4518m 1.1g 3816 S  0.4 29.0   0:02.69 java
85164 appdeplo  20   0 4518m 1.1g 3816 S  0.4 29.0   0:04.92 java
84703 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:00.00 java
84704 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:00.42 java
84705 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:02.52 java
84706 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:02.64 java
84707 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:02.46 java
84708 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:02.39 java
84709 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:33.99 java

这里的 PID 比如 84784 是十进制的,需要转换为十六进制,用windows的计算器就可以转换了,转换为十六进制是:14B30

继续阅读

Java SE 6 故障排除指南 – 4、系统崩溃故障排除

崩溃或致命错误导致进程异常终止。有各种可能的理由导致崩溃。例如,崩溃可能是由于HotSpot VM、系统库、Java SE 库或API、程序本地代码、甚至操作系统里的 bug。极端因素如操作系统资源耗尽也可以导致崩溃。

因 HotSpot VM 或 Java SE库代码导致的崩溃是罕见的。本章提供如何检查崩溃的建议。有时候可以变通崩溃直到导致崩溃的源被诊断和修复(也就是可以避开崩溃)。

通常,崩溃的第一步是定位致命错误日志。这是HotSpot VM生成的文本文件。附录C-致命错误日志 解释了如何定位文件和文件的详细描述。

4.1 崩溃样本

本节展示一些样本来说明错误日志是如何用于启发崩溃原因的。

4.1 测定哪里发生崩溃

错误日志头显示了有问题的帧。见 C.3 格式头。

如果顶层帧是本地帧且不是操作系统本地帧,这表明问题可能发生在本地库,而不是在JVM里。解决崩溃的第一步是研究本地库发生崩溃的源。有三个选择,取决于本地库的源。

如果本地库是由你的程序提供,研究你的本地库的源代码。选项 -Xcheck:jni 可以帮助查找本地 bug。见 B.2.1 -Xcheck:jni 选项。

如果你的程序使用的本地库是由其他供应商提供,报告bug,提供致命错误日志信息。

继续阅读

Java SE 6 故障排除指南 – 5、挂起或循环进程故障排除

本章为挂起或循环进程的故障排除在特定程序上提供了信息和指导。

问题在涉及挂起或循环进程时发生。挂起可能因为多种原因发生,但经常是源于程序代码、API代码或库代码里的死锁。挂起甚至是因为 HotSpot VM的bug。

有时候,一个表面上是挂起的可能是个循环。例如,VM进程里的bug导致一个或多个线程进入死循环,会消耗掉所有可得CPU周期。

诊断挂起的最初步骤是找出VM进程是空闲还是消耗了所有可得CPU周期,为做这个要求使用操作系统工具。如果进程表现为繁忙且消耗了所有可得CPU周期,那么问题很可能是循环线程而不是死锁。

继续阅读

Java SE 6 故障排除指南 – 3、内存泄露

内存泄露故障排除

如果你的应用程序执行的时间越来越长,或如果操作系统执行越来越慢,这可能是内存泄露的指示。换句话说,虚拟内存被分配但在不需要时没有归还。最终应用程序或系统没有可用内存,应用程序非正常终止。

这篇文章提供了一些涉及内存泄露的问题诊断的建议。

3.1 OutOfMemoryError 的含义

一个最常见的内存泄露的指示是 java.lang.OutOfMemoryError 错误。这个错误在Java堆或堆的特定区域没有足够空间用于分配对象时抛出。垃圾收集器不能创造更多可用空间来容纳一个新的对象,堆也不能扩展。

当 java.lang.OutOfMemoryError 错误抛出时,栈轨迹也会被打印。

java.lang.OutOfMemoryError 也可以被本地库代码抛出,当本地分配不能满足时,例如,交换空间很低。

诊断 java.lang.OutOfMemoryError 的一个早期步骤是确定错误的含义。它是否意味着Java堆满了,或意味着本地堆满了?为帮助你回答这个问题,下面的子章节解释了一些可能的错误信息,还有连接到更详细信息的链接:

继续阅读

Java SE 6 故障排除指南 – 1、诊断工具和选项

英文完整文档:http://www.oracle.com/technetwork/java/javase/tsg-vm-149989.pdf

诊断工具和选项

这章介绍了JDK 6 和 Java SE6 里不同的诊断和监视工具。这些工具在第二章详细介绍。

附录 D 列出了这个发布里的可用工具,还有上次发布以来的改变。

注意:本章描述的一些命令行工具是实验性的。例如 jstack, jinfo, jmap 就是实验性的。这些工具可能在将来的JDK发布里改变,或者不包括在将来的发布里。

继续阅读

Java SE 6 故障排除指南 – 附录C、JVM 致命错误日志格式

本文翻译自:http://www.oracle.com/technetwork/java/javase/felog-138657.html
本文内容基于 Java SE 6,HotSpot JVM。

当一个致命错误发生时,一个错误日志将被创建,存储了在致命错误发生时获取到的信息和状态。

注意:这个文件的格式可能随着版本的更新而改变。

C.1 致命错误日志位置

产品标志 -XX:ErrorFile=file 可以指定文件在哪里创建,file 表示了文件位置的完整路径。file 里的子字符串 %% 将被转换为 %%p 将被转换为进程ID。

在下面的例子里,错误日志文件将被写到 /var/log/java 目录、被命名为 java_errorPid.log :java -XX:ErrorFile=/var/log/java/java_error%p.log

如果 -XX:ErrorFile=file 标志没有指定,默认的文件名是 hs_err_pid.log,pid是进程ID。

另外,如果没有指定 -XX:ErrorFile=file 标志,系统尝试在进程的工作目录创建文件。万一不能在工作目录创建文件(空间不足、权限问题或其他问题),文件将在操作系统的临时目录里创建。在Solaris和Linux上临时目录是 /tmp。在Windows上临时目录由环境变量 TMP 指定;如果那个环境变量没有指定,将使用 TEMP 环境变量。

C.2 致命错误日志描述

错误日志包含在致命错误发生时获取到的信息,如果可能,包括下面的信息:

  • 操作异常或激起致命错误的信号
  • 版本信息和配置信息
  • 激起致命错误的线程细节和线程的栈痕迹trace
  • 正在运行的线程列表和它们的状态
  • 堆的概要信息
  • 已加载的本地类库(native libraries)列表
  • 命令行参数
  • 环境变量
  • 操作系统和CPU的细节

注意:在某些情况下,只有这些信息的子集会被输出到错误日志。这在致命错误非常严重以至于错误处理器没法回复并报告所有细节。

错误日志是一个文本文件保护下面的章节:

  • 一个头提供了崩溃的简要描述。
  • 一个章节描述了线程信息。
  • 一个章节描述了进程信息。
  • 一个章节描述了系统信息。

注意:这个致命错误日志描述的格式是基于Java SE 6。格式在不同的发布版之间可能不同。

继续阅读

GC 日志分析

不同的JVM及其选项会输出不同的日志。

GC 日志

生成下面日志使用的选项:-XX:+PrintGCTimeStamps -XX:+PrintGCDetails -Xloggc:d:/GClogs/tomcat6-gc.log

4.231: [GC 4.231: [DefNew: 4928K->512K(4928K), 0.0044047 secs] 6835K->3468K(15872K), 0.0045291 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
 
4.445: [Full GC (System) 4.445: [Tenured: 2956K->3043K(10944K), 0.1869806 secs] 4034K->3043K(15872K), [Perm : 3400K->3400K(12288K)], 0.1870847 secs] [Times: user=0.05 sys=0.00, real=0.19 secs] 

最前面的数字 4.2314.445 代表虚拟机启动以来的秒数。

[GC[Full GC 是垃圾回收的停顿类型,而不是区分是新生代还是年老代,如果有 Full 说明发生了 Stop-The-World 。如果是调用 System.gc() 触发的,那么将显示的是 [Full GC (System)

接下来的 [DefNew, [Tenured, [Perm 表示 GC 发生的区域,区域的名称与使用的 GC 收集器相关。
Serial 收集器中新生代名为 “Default New Generation”,显示的名字为 “[DefNew”。对于ParNew收集器,显示的是 “[ParNew”,表示 “Parallel New Generation”。 对于 Parallel Scavenge 收集器,新生代名为 “PSYoungGen”。年老代和永久代也相同,名称都由收集器决定。

方括号内部显示的 “4928K->512K(4928K)” 表示 “GC 前该区域已使用容量 -> GC 后该区域已使用容量 (该区域内存总容量) ”。

再往后的 “0.0044047 secs” 表示该区域GC所用时间,单位是秒。

再往后的 “6835K->3468K(15872K)” 表示 “GC 前Java堆已使用容量 -> GC后Java堆已使用容量 (Java堆总容量)”。

再往后的 “0.0045291 secs” 是Java堆GC所用的总时间。

最后的 “[Times: user=0.00 sys=0.00, real=0.00 secs]” 分别代表 用户态消耗的CPU时间、内核态消耗的CPU时间 和 操作从开始到结束所经过的墙钟时间。墙钟时间包括各种非运算的等待耗时,如IO等待、线程阻塞。CPU时间不包括等待时间,当系统有多核时,多线程操作会叠加这些CPU时间,所以user或sys时间会超过real时间。

堆的分代

JVM-heap-generations

在上图中:

  • young区域就是新生代,存放新创建对象;
  • tenured是年老代,存放在新生代经历多次垃圾回收后仍存活的对象;
  • perm是永生代,存放类定义信息、元数据等信息。

当GC发生在新生代时,称为Minor GC,次收集;当GC发生在年老代时,称为Major GC,主收集。 一般的,Minor GC的发生频率要比Major GC高很多。

JVM GC 相关的选项

-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳(以基准时间的形式)
-XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800)
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-Xloggc:../logs/gc.log 日志文件的输出路径

欢迎关注我的微信公众号: coderbee笔记,可以更及时回复你的讨论。

JVM 类加载机制

虚拟机类加载机制:把描述类的数据从class文件加载到内存,并对数据进行校验、转换解析和初始化,最终形成可以被虚拟机直接使用的 Java 类型。

在Java语言里面,类型的加载、连接和初始化都是在程序运行期间完成的。

类加载的时机

类的整个生命周期包括:加载(loading)、验证(verification)、准备(preparation)、解析(resolution)、初始化(initialization)、使用(using)和卸载(unloading) 7个阶段。其中 验证、准备、解析 3个部分统称连接(linking)。

class life cycle

5种必须立即初始化的情况:

  1. 遇到new, getstatic, putstatic 或 invokestatic 这4挑字节码指令;
  2. 使用 java.lang.reflect 包的方法对类进行反射调用;
  3. 初始化一个类的时候,其父类还没有初始化,必须先触发其父类的初始化;(对于接口,只有在真正用到其父接口的时候才会初始化)
  4. 虚拟机启动时,用户指定要执行的主类;
  5. 当使用 JDK 1.7 的动态语言支持时,如果一个 java.lang.invoke.MethodHandle 实例最后的解析结果 REF_getStatic, REF_putStatic, REF_invokeStatic 的方法句柄,并且这个方法句柄锁对应的类没有进行出事,则需要先触发其初始化。

对于静态字段,只有直接定义这个字段的类才会被初始化。
继续阅读

HotSpot 垃圾回收算法实现

《深入理解Java虚拟机:JVM高级特性与最佳实践》-笔记

垃圾回收算法

枚举根结点

一致性

在可达性分析期间整个系统看起来就像被冻结在某个时间点上,不可以出现分析过程中对象引用关系还在不断变化的情况。

一致性要求导致GC进行时必须停顿所有Java执行线程。(Stop The World)
即使在号称不会发生停顿的CMS收集器中,枚举根节点时也是必须停顿的。

HotSpot使用的是准确式GC,当执行系统停顿下来后,并不需要一个不漏地检查完所有执行上下文和全局的引用位置,这是通过一组称为OopMap的数据结构来达到的。

在类加载完成后,HotSpot就把对象内什么偏移量上是什么类型的数据计算出来;在JIT编译过程中,也会在特定的位置记录下栈和寄存器中哪些位置是引用。
继续阅读