MySQL执行计划

MySQL中的 explain命令可以获取一个查询操作的执行计划,描述MySQL如何执行查询操作、执行顺序,使用到的索引,以及成功返回结果集需要执行的行数。可以帮助我们分析SQL语句,知道查询效率低下的原因,改进查询性能。

explain的限制:

  • 不支持存储过程
  • 不会显示MySQL的优化过程
  • 不会显示所有执行信息

开始之前,所需要的建表语句如下:

DROP TABLE IF EXISTS `actor`;
CREATE TABLE `actor` (
  `id` INT(11) NOT NULL,
  `name` VARCHAR(45) DEFAULT NULL,
  `update_time` DATETIME DEFAULT NULL,
  PRIMARY KEY (`id`)   /*主键*/
) ENGINE=INNODB DEFAULT CHARSET=utf8;

INSERT INTO `actor` (`id`, `name`, `update_time`) VALUES (1,'a','2017-12-22 15:27:18'), (2,'b','2017-12-22 15:27:18'), (3,'c','2017-12-22 15:27:18');

DROP TABLE IF EXISTS `film`;
CREATE TABLE `film` (
  `id` INT(11) NOT NULL AUTO_INCREMENT,
  `name` VARCHAR(10) DEFAULT NULL,
  PRIMARY KEY (`id`), /*主键*/
  KEY `idx_name` (`name`) /*普通键*/
) ENGINE=INNODB DEFAULT CHARSET=utf8;

INSERT INTO `film` (`id`, `name`) VALUES (3,'film0'),(1,'film1'),(2,'film2');

DROP TABLE IF EXISTS `film_actor`;
CREATE TABLE `film_actor` (
  `id` INT(11) NOT NULL,
  `film_id` INT(11) NOT NULL,
  `actor_id` INT(11) NOT NULL,
  PRIMARY KEY (`id`),  /*主键*/
  KEY `idx_film_actor_id` (`film_id`,`actor_id`) /*普通联合键*/
) ENGINE=INNODB DEFAULT CHARSET=utf8;

INSERT INTO `film_actor` (`id`, `film_id`, `actor_id`) VALUES (1,1,1),(2,1,2),(3,2,1);

查看索引:

SHOW INDEX FROM actor;
SHOW INDEX FROM film;
SHOW INDEX FROM film_actor;

explain中的列:

mysql> explain select * from actor\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: actor
   partitions: NULL
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 3
     filtered: 100.00
        Extra: NULL

1. id 列

表示select标识符,同时表明执行顺序,查询序号即为sql语句执行的顺序。

(1)当id值相同时,按从上到下的顺序执行;

(2)当id不同时,按id从大到小执行;

2. select_type 列

查询的类型,主要是区别普通查询和联合查询、子查询之类的复杂查询。

常用取值有:

SIMPLE:简单查询。

mysql>  explain select * from film where id = 1;
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------+
| id | select_type | table | partitions | type  | possible_keys | key     | key_len | ref   | rows | filtered | Extra |
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | film  | NULL       | const | PRIMARY       | PRIMARY | 4       | const |    1 |   100.00 | NULL  |
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------+

2)PRIMARY:复杂查询中最外层的 select。

3)SUBQUERY:包含在 select 中的子查询(不在 from 子句中)。

mysql>  explain select (select id from actor where id = 1) from actor;
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------------+
| id | select_type | table | partitions | type  | possible_keys | key     | key_len | ref   | rows | filtered | Extra       |
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------------+
|  1 | PRIMARY     | actor | NULL       | index | NULL          | PRIMARY | 4       | NULL  |    3 |   100.00 | Using index |
|  2 | SUBQUERY    | actor | NULL       | const | PRIMARY       | PRIMARY | 4       | const |    1 |   100.00 | Using index |
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------------+

4)derived:包含在 from 子句中的子查询。MySQL会将结果存放在一个临时表中,也称为派生表。

5)UNION:在 union 中的第二个和随后的 select。

6)UNION RESULT:从 union 临时表检索结果的 select。

mysql> explain select 1 union select 2;
+----+--------------+------------+------------+------+---------------+------+---------+------+------+----------+-----------------+
| id | select_type  | table      | partitions | type | possible_keys | key  | key_len | ref  | rows | filtered | Extra           |
+----+--------------+------------+------------+------+---------------+------+---------+------+------+----------+-----------------+
|  1 | PRIMARY      | NULL       | NULL       | NULL | NULL          | NULL | NULL    | NULL | NULL |     NULL | No tables used  |
|  2 | UNION        | NULL       | NULL       | NULL | NULL          | NULL | NULL    | NULL | NULL |     NULL | No tables used  |
| NULL | UNION RESULT | <union1,2> | NULL       | ALL  | NULL          | NULL | NULL    | NULL | NULL |     NULL | Using temporary |
+----+--------------+------------+------------+------+---------------+------+---------+------+------+----------+-----------------+

3. table 列

输出行所引用的表的名称,有时候并不是真实的表名。

4. partitions 列

其记录与查询匹配的分区,无分区表的值为 NULL。

5. type 列

MySQL决定如何查找表中的行,很重要的一列。

依次从最优到最差分别为:NULL> system > const > eq_ref > ref > ref_or_null > range > index > ALL

NULLmysql能够在优化阶段分解查询语句,在执行阶段用不着再访问表或索引。

mysql> explain select max(id) from actor;
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+------------------------------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows | filtered | Extra                        |
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+------------------------------+
|  1 | SIMPLE      | NULL  | NULL       | NULL | NULL          | NULL | NULL    | NULL | NULL |     NULL | Select tables optimized away |
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+------------------------------+

system: 表仅有一行,是 const 类型的特例。不常见。

const : 在整个查询过程中这个表最多只会有一条匹配的行,用到了 primary key 或者unique 索引。表数据在分解执行计划时读取。

mysql> explain select * from film where id = 1;
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------+
| id | select_type | table | partitions | type  | possible_keys | key     | key_len | ref   | rows | filtered | Extra |
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | film  | NULL       | const | PRIMARY       | PRIMARY | 4       | const |    1 |   100.00 | NULL  |
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------+

eq_ref:多表联合查询时,使用primary keyunique key作为连接条件。最多只会从该表中返回一条符合条件的记录。

mysql> explain select * from film_actor left join film on film_actor.film_id = film.id;
+----+-------------+------------+------------+--------+---------------+-------------------+---------+---------------------------+------+----------+-------------+
| id | select_type | table      | partitions | type   | possible_keys | key               | key_len | ref                       | rows | filtered | Extra       |
+----+-------------+------------+------------+--------+---------------+-------------------+---------+---------------------------+------+----------+-------------+
|  1 | SIMPLE      | film_actor | NULL       | index  | NULL          | idx_film_actor_id | 8       | NULL                      |    3 |   100.00 | Using index |
|  1 | SIMPLE      | film       | NULL       | eq_ref | PRIMARY       | PRIMARY           | 4       | test02.film_actor.film_id |    1 |   100.00 | NULL        |
+----+-------------+------------+------------+--------+---------------+-------------------+---------+---------------------------+------+----------+-------------+

ref:相比 eq_ref,不使用唯一索引,而是使用普通索引或者键的最左边的前缀,索引要和某个值相比较,可能会找到多个符合条件的行。

/* name是普通索引 */
mysql> explain select * from film where name = 'film';
+----+-------------+-------+------------+------+---------------+----------+---------+-------+------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key      | key_len | ref   | rows | filtered | Extra       |
+----+-------------+-------+------------+------+---------------+----------+---------+-------+------+----------+-------------+
|  1 | SIMPLE      | film  | NULL       | ref  | idx_name      | idx_name | 33      | const |    1 |   100.00 | Using index |
+----+-------------+-------+------------+------+---------------+----------+---------+-------+------+----------+-------------+

/* film_id 是联合索引的最左前缀 */
mysql> explain select * from film left join film_actor on film.id = film_actor.film_id;
+----+-------------+------------+------------+-------+-------------------+-------------------+---------+----------------+------+----------+-------------+
| id | select_type | table      | partitions | type  | possible_keys     | key               | key_len | ref            | rows | filtered | Extra       |
+----+-------------+------------+------------+-------+-------------------+-------------------+---------+----------------+------+----------+-------------+
|  1 | SIMPLE      | film       | NULL       | index | NULL              | idx_name          | 33      | NULL           |    3 |   100.00 | Using index |
|  1 | SIMPLE      | film_actor | NULL       | ref   | idx_film_actor_id | idx_film_actor_id | 4       | test02.film.id |    1 |   100.00 | Using index |
+----+-------------+------------+------------+-------+-------------------+-------------------+---------+----------------+------+----------+-------------+

ref_or_null:类似ref,但是可以搜索值为NULL的行。

mysql> explain select * from film where name = "film1" or name is null;
+----+-------------+-------+------------+-------------+---------------+----------+---------+-------+------+----------+--------------------------+
| id | select_type | table | partitions | type        | possible_keys | key      | key_len | ref   | rows | filtered | Extra                    |
+----+-------------+-------+------------+-------------+---------------+----------+---------+-------+------+----------+--------------------------+
|  1 | SIMPLE      | film  | NULL       | ref_or_null | idx_name      | idx_name | 33      | const |    2 |   100.00 | Using where; Using index |
+----+-------------+-------+------------+-------------+---------------+----------+---------+-------+------+----------+--------------------------+

range:范围扫描通常出现在 in(), between ,> ,<, >= 等操作中。使用一个索引来检索给定范围的行。

mysql> explain select * from actor where id > 2;
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+
| id | select_type | table | partitions | type  | possible_keys | key     | key_len | ref  | rows | filtered | Extra       |
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+
|  1 | SIMPLE      | actor | NULL       | range | PRIMARY       | PRIMARY | 4       | NULL |    1 |   100.00 | Using where |
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+

index: 全索引扫描,先读索引,再读实际的行,结果也是全表扫描,主要优点是避免了排序。(索引是排好序的,并且 all 是从硬盘中读的,index 可能不在硬盘上)

mysql> explain select count(*) from film;
+----+-------------+-------+------------+-------+---------------+----------+---------+------+------+----------+-------------+
| id | select_type | table | partitions | type  | possible_keys | key      | key_len | ref  | rows | filtered | Extra       |
+----+-------------+-------+------------+-------+---------------+----------+---------+------+------+----------+-------------+
|  1 | SIMPLE      | film  | NULL       | index | NULL          | idx_name | 33      | NULL |    3 |   100.00 | Using index |
+----+-------------+-------+------------+-------+---------------+----------+---------+------+------+----------+-------------+

ALL:即全表扫描,意味着mysql需要从头到尾去查找所需要的行。通常情况下这需要增加索引来进行优化。

mysql> explain select * from actor;
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+-------+
| id | select_type | table | partitions | type | possible_keys | key  | key_len | ref  | rows | filtered | Extra |
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+-------+
|  1 | SIMPLE      | actor | NULL       | ALL  | NULL          | NULL | NULL    | NULL |    3 |   100.00 | NULL  |
+----+-------------+-------+------------+------+---------------+------+---------+------+------+----------+-------+

6. possible_keys 列

这一列显示查询可能使用哪些索引来查找。

explain 时可能出现 possible_keys 有列,而 key 显示 NULL 的情况,这种情况是因为表中数据不多,mysql认为索引对此查询帮助不大,选择了全表查询。

如果该列是NULL,则没有相关的索引。在这种情况下,可以通过检查 where 子句看是否可以创造一个适当的索引来提高查询性能,然后用 explain 查看效果。

7. key 列

这一列显示mysql实际采用哪个索引来优化对该表的访问。

如果没有使用索引,则该列是 NULL。如果想强制mysql使用或忽视索引,在查询中使用 force index、ignore index。

8. key_len 列

表示查询优化器使用了索引的字节数, 这个字段可以评估组合索引是否完全被使用,或只有最左部分字段被使用到。 key_len 的计算规则如下:

  • 字符串
    • char(n): n 字节长度
    • varchar(n): 如果是 utf8 编码, 则是 3 n + 2字节; 如果是 utf8mb4 编码, 则是 4 n + 2 字节.
  • 数值类型:
    • TINYINT: 1字节
    • SMALLINT: 2字节
    • MEDIUMINT: 3字节
    • INT: 4字节
    • BIGINT: 8字节
  • 时间类型
    • DATE: 3字节
    • TIMESTAMP: 4字节
    • DATETIME: 8字节
  • 字段属性: NULL 属性 占用一个字节. 如果一个字段是 NOT NULL 的, 则没有此属性.
/* film_id 是联合索引的一部分 */
mysql> explain select * from film_actor where film_id = 2;
+----+-------------+------------+------------+------+-------------------+-------------------+---------+-------+------+----------+-------------+
| id | select_type | table      | partitions | type | possible_keys     | key               | key_len | ref   | rows | filtered | Extra       |
+----+-------------+------------+------------+------+-------------------+-------------------+---------+-------+------+----------+-------------+
|  1 | SIMPLE      | film_actor | NULL       | ref  | idx_film_actor_id | idx_film_actor_id | 4       | const |    1 |   100.00 | Using index |
+----+-------------+------------+------------+------+-------------------+-------------------+---------+-------+------+----------+-------------+

9. ref 列

ref:常见的有:constfuncnull,字段名。显示哪个字段或常数与索引 key 一起被使用。

  • 当使用常量等值查询,显示const
  • 当关联查询时,会显示相应关联表的关联字段。
  • 如果查询条件使用了表达式、函数,或者条件列发生内部隐式转换,可能显示为func
  • 其他情况null

10. rows 列

rows:以表的统计信息和索引使用情况,估算要找到我们所需的记录,需要读取的行数。注意,这不是真实的结果集行数,这只是一个估计值。一般来说,值越小越好。

mysql> explain select * from actor\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: actor
   partitions: NULL
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 3
     filtered: 100.00
        Extra: NULL

11. filtered 列

filtered 这个是一个百分比的值,表里符合条件的记录数的百分比。简单点说,这个字段表示存储引擎返回的数据在经过过滤后,剩下满足条件的记录数量的比例。从优化的角度来说,我们希望过滤的越多越好。

12. Extra 列

Extra :不适合在其他列中显示的信息,Explain 中的很多额外的信息会在 Extra 字段显示。

  • Using index

    我们在相应的 select 操作中使用了覆盖索引,通俗一点讲就是查询的列被索引覆盖,使用到覆盖索引查询速度会非常快,SQl优化中理想的状态。

覆盖索引:一条 SQL只需要通过索引就可以返回我们所需要查询的数据。而不必通过二级索引(回表),查到主键之后再通过主键查询整行数据。

/* 下面的查询也会输出Using index的原因是:film表只有两个字段 id 和 name,而id是主键,name是索引,所以通过遍历name的索引树就能得到全部字段 */
mysql> explain select * from film\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: film
   partitions: NULL
         type: index
possible_keys: NULL
          key: idx_name
      key_len: 33
          ref: NULL
         rows: 3
     filtered: 100.00
        Extra: Using index
  • Using where

    表示存储引擎返回的记录并不是所有的都满足查询条件,需要在server层再进行后过滤(Post-filter)。所谓“后过滤”,就是先读取整行数据,再检查此行是否符合 where 句的条件,符合就留下,不符合便丢弃。因为检查是在读取行后才进行的,所以称为后过滤。查询中含有 WHERE 子句时较常见。

mysql> explain  select * from actor where name='b'\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: actor
   partitions: NULL
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 3
     filtered: 33.33
        Extra: Using where
  • Using temporary

    表示查询后结果需要使用临时表(或内存,或磁盘)来存储,一般在排序或者分组查询时用到。出现这种情况一般是要进行优化的,首先是想到用索引来优化。


mysql> explain select distinct name from actor\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: actor
   partitions: NULL
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 3
     filtered: 100.00
        Extra: Using temporary
  • Using filesort:

    如果查询所需的排序与使用的索引排序不一致,MySQL在取得结果后,还需要按查询所需的顺序对结果进行排序,这时就会出现 Using filesort。这个操作可能在磁盘,也有可能在内存,但是explain并不会告诉你,所以这种情况下一般也是要考虑使用索引来优化的。

mysql> explain select * from actor order by name\G
*************************** 1. row ***************************
           id: 1
  select_type: SIMPLE
        table: actor
   partitions: NULL
         type: ALL
possible_keys: NULL
          key: NULL
      key_len: NULL
          ref: NULL
         rows: 3
     filtered: 100.00
        Extra: Using filesort

总结

  1. explain 的四个重要字段:type、key、rows、extra;
  2. 如果 type 的值为 index 或者 ALL,那么说明该 SQL 性能一般,需要优化;
  3. 如果 key 的值为 NULL,说明该 SQL 没有使用索引,可以考虑在关键字段上增加索引;
  4. row 的值代表了进行本次查询时,搜索记录的条数,当这个值特别大的时候,说明该 SQL 语句性能差;
  5. 如果 Extra 字段的值为 Using filesort 或 Using temporary,也是需要优化的,可以通过调整 order by 或者 group by 的字段来实现。

参考资料

不同模式的性能压测

环境:JDK8、win10,4核8线程

单线程的socket程序

public class HttpServer01 {
    public static void main(String[] args) throws IOException{
        ServerSocket serverSocket = new ServerSocket(8801);
        while (true) {
            try {
                Socket socket = serverSocket.accept();
                service(socket);
            } catch (IOException e) {
                e.printStackTrace();
            }
        }
    }
    
    private static void service(Socket socket) {
        try {
            PrintWriter printWriter = new PrintWriter(socket.getOutputStream(), true);
            printWriter.println("HTTP/1.1 200 OK");
            printWriter.println("Content-Type:text/html;charset=utf-8");
            String body = "hello,nio1";
            printWriter.println("Content-Length:" + body.getBytes().length);
            printWriter.println();
            printWriter.write(body);
            printWriter.close();
            socket.close();
        } catch (IOException e) { // | InterruptedException e) {
            e.printStackTrace();
        }
    }
}

压测:使用sb工具,给40个并发,压60秒。

C:\Users>sb -u http://localhost:8801 -c 40 -N 60
Starting at 2021/7/19 13:02:16
[Press C to stop the test]
143395  (RPS: 2247)
---------------Finished!----------------
Finished at 2021/7/19 13:03:20 (took 00:01:03.9043972)
Status 303:    57964
Status 200:    85432

RPS: 2347.6 (requests/second)
Max: 163ms
Min: 0ms
Avg: 5.2ms

  50%   below 2ms
  60%   below 5ms
  70%   below 7ms
  80%   below 10ms
  90%   below 14ms
  95%   below 19ms
  98%   below 26ms
  99%   below 31ms
99.9%   below 47ms

每个请求一个线程

public class HttpServer02 {
    public static void main(String[] args) throws IOException{
        ServerSocket serverSocket = new ServerSocket(8802);
        while (true) {
            try {
                final Socket socket = serverSocket.accept();
                new Thread(() -> {
                    service(socket);
                }).start();
            } catch (IOException e) {
                e.printStackTrace();
            }
        }
    }
    
    private static void service(Socket socket) {
        try {
            PrintWriter printWriter = new PrintWriter(socket.getOutputStream(), true);
            printWriter.println("HTTP/1.1 200 OK");
            printWriter.println("Content-Type:text/html;charset=utf-8");
            String body = "hello,nio2";
            printWriter.println("Content-Length:" + body.getBytes().length);
            printWriter.println();
            printWriter.write(body);
            printWriter.close();
            socket.close();
        } catch (IOException e) { // | InterruptedException e) {
            e.printStackTrace();
        }
    }
}

压测:使用sb工具,给40个并发,压60秒。

C:\Users>sb -u http://localhost:8802 -c 40 -N 60
Starting at 2021/7/19 13:11:59
[Press C to stop the test]
104055  (RPS: 1630.4)
---------------Finished!----------------
Finished at 2021/7/19 13:13:03 (took 00:01:03.8710839)
Status 200:    92093
Status 303:    11975

RPS: 1704.9 (requests/second)
Max: 88ms
Min: 0ms
Avg: 9ms

  50%   below 7ms
  60%   below 9ms
  70%   below 12ms
  80%   below 15ms
  90%   below 21ms
  95%   below 26ms
  98%   below 32ms
  99%   below 36ms
99.9%   below 50ms

创建固定大小的线程池处理请求

public class HttpServer03 {
    public static void main(String[] args) throws IOException{

        ExecutorService executorService = Executors.newFixedThreadPool(
                Runtime.getRuntime().availableProcessors() + 2);
        final ServerSocket serverSocket = new ServerSocket(8803);
        while (true) {
            try {
                final Socket socket = serverSocket.accept();
                executorService.execute(() -> service(socket));
            } catch (IOException e) {
                e.printStackTrace();
            }
        }
    }
    
    private static void service(Socket socket) {
        try {
            PrintWriter printWriter = new PrintWriter(socket.getOutputStream(), true);
            printWriter.println("HTTP/1.1 200 OK");
            printWriter.println("Content-Type:text/html;charset=utf-8");
            String body = "hello,nio";
            printWriter.println("Content-Length:" + body.getBytes().length);
            printWriter.println();
            printWriter.write(body);
            printWriter.close();
            socket.close();
        } catch (IOException e) { // | InterruptedException e) {
            e.printStackTrace();
        }
    }
}

压测:使用sb工具,给40个并发,压60秒。

C:\Users>sb -u http://localhost:8803 -c 40 -N 60
Starting at 2021/7/19 13:15:28
[Press C to stop the test]
137776  (RPS: 2157.7)
---------------Finished!----------------
Finished at 2021/7/19 13:16:32 (took 00:01:04.0038139)
Status 200:    73110
Status 303:    64666

RPS: 2251.8 (requests/second)
Max: 158ms
Min: 0ms
Avg: 5.7ms

  50%   below 3ms
  60%   below 6ms
  70%   below 8ms
  80%   below 11ms
  90%   below 15ms
  95%   below 20ms
  98%   below 27ms
  99%   below 32ms
99.9%   below 49ms

小结,socket处理请求是阻塞模式;使用单独线程处理请求,理论上性能会好一些;使用线程池可以避免因频繁创建线程造成的开销。

分析G1 GC日志

测试环境:

jdk1.8win10,4核8线程,16G内存

演示代码:程序在1秒内生成许多对象,每个对象随机放在数组里。有的位置就会被重置,就会存在未被使用的对象,等待被回收。

import java.util.Random;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.LongAdder;
/*
演示GC日志生成与解读
*/
public class GCLogAnalysis {
    private static Random random = new Random();
    public static void main(String[] args) {
        // 当前毫秒时间戳
        long startMillis = System.currentTimeMillis();
        // 持续运行毫秒数; 可根据需要进行修改
        long timeoutMillis = TimeUnit.SECONDS.toMillis(1);
        // 结束时间戳
        long endMillis = startMillis + timeoutMillis;
        LongAdder counter = new LongAdder();
        System.out.println("正在执行...");
        // 缓存一部分对象; 进入老年代
        int cacheSize = 2000;
        Object[] cachedGarbage = new Object[cacheSize];
        // 在此时间范围内,持续循环
        while (System.currentTimeMillis() < endMillis) {
            // 生成垃圾对象
            Object garbage = generateGarbage(100*1024);
            counter.increment();
            int randomIndex = random.nextInt(2 * cacheSize);
            if (randomIndex < cacheSize) {
                cachedGarbage[randomIndex] = garbage;
            }
        }
        System.out.println("执行结束!共生成对象次数:" + counter.longValue());
    }

    // 生成对象
    private static Object generateGarbage(int max) {
        int randomSize = random.nextInt(max);
        int type = randomSize % 4;
        Object result = null;
        switch (type) {
            case 0:
                result = new int[randomSize];
                break;
            case 1:
                result = new byte[randomSize];
                break;
            case 2:
                result = new double[randomSize];
                break;
            default:
                StringBuilder builder = new StringBuilder();
                String randomString = "randomString-Anything";
                while (builder.length() < randomSize) {
                    builder.append(randomString);
                    builder.append(max);
                    builder.append(randomSize);
                }
                result = builder.toString();
                break;
        }
        return result;
    }
}

编译代码:

javac GCLogAnalysis.java

G1 – Garbage First(垃圾优先算法),G1 GC最主要的设计目标是: 将STW停顿的时间和分布变成可预期以及可配置。

G1适合大内存,需要低延迟的场景。G1 GC的日志信息太多了,这里只给出一种配置进行分析。

案例( -Xms4g -Xmx4g

D:\>java -XX:+UseG1GC -Xms4g -Xmx4g -XX:+PrintGCDetails GCLogAnalysis
正在执行...
[GC pause (G1 Evacuation Pause) (young), 0.0099569 secs]
   [Parallel Time: 7.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 180.0, Avg: 180.1, Max: 180.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 7.3, Avg: 7.4, Max: 7.5, Diff: 0.3, Sum: 59.3]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.4]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
      [GC Worker Total (ms): Min: 7.8, Avg: 7.8, Max: 7.8, Diff: 0.1, Sum: 62.4]
      [GC Worker End (ms): Min: 187.9, Avg: 187.9, Max: 187.9, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 1.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.5 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 204.0M(204.0M)->0.0B(178.0M) Survivors: 0.0B->26.0M Heap: 204.0M(4096.0M)->65.2M(4096.0M)]
 [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0116306 secs]
   [Parallel Time: 9.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 215.6, Avg: 215.7, Max: 215.7, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 1.0, Max: 3, Diff: 3, Sum: 8]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 9.4, Avg: 9.5, Max: 9.6, Diff: 0.2, Sum: 75.8]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 9.7, Avg: 9.7, Max: 9.8, Diff: 0.1, Sum: 77.8]
      [GC Worker End (ms): Min: 225.4, Avg: 225.4, Max: 225.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 1.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.7 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 178.0M(178.0M)->0.0B(178.0M) Survivors: 26.0M->26.0M Heap: 243.2M(4096.0M)->123.6M(4096.0M)]
 [Times: user=0.02 sys=0.00, real=0.03 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0130914 secs]
   [Parallel Time: 11.0 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 268.1, Avg: 268.1, Max: 268.2, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.7, Diff: 0.6, Sum: 1.2]
         [Processed Buffers: Min: 1, Avg: 1.4, Max: 2, Diff: 1, Sum: 11]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 9.9, Avg: 10.4, Max: 10.7, Diff: 0.7, Sum: 83.3]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 1.8]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 10.8, Avg: 10.9, Max: 10.9, Diff: 0.1, Sum: 87.1]
      [GC Worker End (ms): Min: 279.0, Avg: 279.0, Max: 279.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.3 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.8 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 178.0M(178.0M)->0.0B(178.0M) Survivors: 26.0M->26.0M Heap: 301.6M(4096.0M)->183.8M(4096.0M)]
 [Times: user=0.06 sys=0.06, real=0.03 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0114275 secs]
   [Parallel Time: 10.2 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 320.3, Avg: 320.5, Max: 321.0, Diff: 0.7]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
      [Update RS (ms): Min: 0.0, Avg: 0.2, Max: 1.1, Diff: 1.1, Sum: 1.4]
         [Processed Buffers: Min: 0, Avg: 1.3, Max: 2, Diff: 2, Sum: 10]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 8.7, Avg: 9.6, Max: 9.8, Diff: 1.1, Sum: 76.6]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 9.4, Avg: 9.9, Max: 10.1, Diff: 0.7, Sum: 79.5]
      [GC Worker End (ms): Min: 330.4, Avg: 330.4, Max: 330.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.6 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 178.0M(178.0M)->0.0B(178.0M) Survivors: 26.0M->26.0M Heap: 361.8M(4096.0M)->236.2M(4096.0M)]
 [Times: user=0.00 sys=0.00, real=0.02 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0119627 secs]
   [Parallel Time: 9.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 369.7, Avg: 369.8, Max: 369.9, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
         [Processed Buffers: Min: 1, Avg: 1.3, Max: 2, Diff: 1, Sum: 10]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 9.3, Avg: 9.4, Max: 9.6, Diff: 0.4, Sum: 75.3]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.7]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 9.7, Avg: 9.8, Max: 9.9, Diff: 0.1, Sum: 78.3]
      [GC Worker End (ms): Min: 379.6, Avg: 379.6, Max: 379.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.9 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 178.0M(178.0M)->0.0B(178.0M) Survivors: 26.0M->26.0M Heap: 414.2M(4096.0M)->283.9M(4096.0M)]
 [Times: user=0.00 sys=0.00, real=0.03 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0125605 secs]
   [Parallel Time: 11.1 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 420.1, Avg: 420.2, Max: 420.3, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
         [Processed Buffers: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 10.3, Avg: 10.5, Max: 10.7, Diff: 0.4, Sum: 84.1]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 10.8, Avg: 10.8, Max: 10.9, Diff: 0.2, Sum: 86.5]
      [GC Worker End (ms): Min: 431.0, Avg: 431.0, Max: 431.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.7 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 178.0M(178.0M)->0.0B(178.0M) Survivors: 26.0M->26.0M Heap: 461.9M(4096.0M)->343.5M(4096.0M)]
 [Times: user=0.11 sys=0.02, real=0.03 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0114717 secs]
   [Parallel Time: 10.4 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 473.3, Avg: 473.4, Max: 473.8, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.8]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
         [Processed Buffers: Min: 0, Avg: 1.1, Max: 3, Diff: 3, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 9.7, Avg: 9.9, Max: 10.2, Diff: 0.5, Sum: 79.5]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.5]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 9.9, Avg: 10.3, Max: 10.4, Diff: 0.5, Sum: 82.3]
      [GC Worker End (ms): Min: 483.7, Avg: 483.7, Max: 483.7, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 178.0M(178.0M)->0.0B(210.0M) Survivors: 26.0M->26.0M Heap: 521.5M(4096.0M)->398.9M(4096.0M)]
 [Times: user=0.06 sys=0.05, real=0.02 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0128721 secs]
   [Parallel Time: 11.6 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 526.4, Avg: 526.5, Max: 526.6, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.7]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
         [Processed Buffers: Min: 0, Avg: 1.3, Max: 3, Diff: 3, Sum: 10]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 11.0, Avg: 11.1, Max: 11.2, Diff: 0.2, Sum: 89.0]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 11.4, Avg: 11.5, Max: 11.5, Diff: 0.1, Sum: 91.6]
      [GC Worker End (ms): Min: 538.0, Avg: 538.0, Max: 538.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 0.8 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 210.0M(210.0M)->0.0B(622.0M) Survivors: 26.0M->30.0M Heap: 608.9M(4096.0M)->465.1M(4096.0M)]
 [Times: user=0.00 sys=0.00, real=0.02 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0231822 secs]
   [Parallel Time: 21.5 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 698.9, Avg: 699.0, Max: 699.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.7]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
         [Processed Buffers: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 20.9, Avg: 21.0, Max: 21.1, Diff: 0.2, Sum: 167.9]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.8]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.2]
      [GC Worker Total (ms): Min: 21.3, Avg: 21.3, Max: 21.4, Diff: 0.1, Sum: 170.4]
      [GC Worker End (ms): Min: 720.3, Avg: 720.3, Max: 720.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.6 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 622.0M(622.0M)->0.0B(212.0M) Survivors: 30.0M->82.0M Heap: 1087.1M(4096.0M)->628.2M(4096.0M)]
 [Times: user=0.03 sys=0.06, real=0.08 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0155001 secs]
   [Parallel Time: 14.3 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 814.4, Avg: 814.5, Max: 814.6, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.6]
         [Processed Buffers: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 13.6, Avg: 13.8, Max: 13.9, Diff: 0.3, Sum: 110.2]
      [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 1.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 14.1, Avg: 14.1, Max: 14.2, Diff: 0.2, Sum: 112.9]
      [GC Worker End (ms): Min: 828.6, Avg: 828.6, Max: 828.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 1.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.5 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 212.0M(212.0M)->0.0B(390.0M) Survivors: 82.0M->38.0M Heap: 840.2M(4096.0M)->685.6M(4096.0M)]
 [Times: user=0.05 sys=0.08, real=0.04 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0155628 secs]
   [Parallel Time: 14.6 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 905.1, Avg: 905.2, Max: 905.2, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.7]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.8]
         [Processed Buffers: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 13.8, Avg: 14.1, Max: 14.3, Diff: 0.5, Sum: 112.6]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.2]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 14.4, Avg: 14.4, Max: 14.5, Diff: 0.1, Sum: 115.6]
      [GC Worker End (ms): Min: 919.6, Avg: 919.6, Max: 919.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 0.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.2 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 390.0M(390.0M)->0.0B(502.0M) Survivors: 38.0M->54.0M Heap: 1075.6M(4096.0M)->785.2M(4096.0M)]
 [Times: user=0.01 sys=0.11, real=0.03 secs]
[GC pause (G1 Evacuation Pause) (young), 0.0216765 secs]
   [Parallel Time: 19.7 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 997.7, Avg: 997.7, Max: 997.8, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.7]
      [Update RS (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 0.8]
         [Processed Buffers: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 19.1, Avg: 19.2, Max: 19.3, Diff: 0.2, Sum: 153.9]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 19.5, Avg: 19.6, Max: 19.6, Diff: 0.1, Sum: 156.4]
      [GC Worker End (ms): Min: 1017.3, Avg: 1017.3, Max: 1017.3, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 1.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.8 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 502.0M(502.0M)->0.0B(760.0M) Survivors: 54.0M->70.0M Heap: 1287.2M(4096.0M)->920.4M(4096.0M)]
 [Times: user=0.05 sys=0.08, real=0.11 secs]
执行结束!共生成对象次数:11931
Heap
 garbage-first heap   total 4194304K, used 1003944K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 66 young (135168K), 35 survivors (71680K)
 Metaspace       used 2619K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 288K, capacity 386K, committed 512K, reserved 1048576K

G1 GC日志中的字段进行解释:

  • [GC pause (G1 Evacuation Pause) (young), 0.0099569 secs]:G1转移暂停,只清理年轻代空间。持续的系统时间为0.0099569秒 。
  • [Parallel Time: 7.9 ms, GC Workers: 8]:表明后面的活动由8个 Worker 线程并行执行, 消耗时间为7.9毫秒。
  • GC Worker Start (ms):相对于 pause 开始的时间戳,GCworker线程开始启动所用时间。如果 Min Max 差别很大,则表明本机其他进程所使用的线程数量过多, 挤占了GCCPU时间。
  • Ext Root Scanning (ms):用了多长时间来扫描堆外(non-heap)的root, 如classloaders, JNI引用, JVM的系统root等。后面显示了运行时间, “Sum” 指的是CPU时间。
  • Update RS (ms):更新Remembered Sets使用的时间。
  • Processed Buffers:每个 worker 线程处理了多少个本地缓冲区(local buffer)。
  • Scan RS (ms):用了多长时间扫描来自RSet的引用。
  • Code Root Scanning (ms):用了多长时间来扫描实际代码中的 root
  • Object Copy (ms):用了多长时间来拷贝收集区内的存活对象。
  • Termination (ms)GCworker线程用了多长时间来确保自身可以安全地停止, 这段时间什么也不用做, stop 之后该线程就终止运行了。
  • Termination AttemptsGCworker 线程尝试多少次 try teminate。如果worker发现还有一些任务没处理完,则这一次尝试就是失败的, 暂时还不能终止。
  • GC Worker Other (ms):处理一些琐碎的小活动所用的时间,在GC日志中不值得单独列出来。
  • GC Worker Total (ms)GCworker 线程的工作时间总计。
  • GC Worker End (ms):相对于 pause 开始的时间戳,GCworker 线程完成作业的时间。通常来说这部分数字应该大致相等, 否则就说明有太多的线程被挂起, 很可能是因为坏邻居效应(noisy neighbor) 所导致的。
  • Code Root Fixup:释放用于管理并行活动的内部数据。一般都接近于零。这是串行执行的过程。
  • Code Root Purge:清理其他部分数据, 也是非常快的,但如非必要则几乎等于零。这是串行执行的过程。
  • Clear CT:清理 card table cards 的时间。清理工作只是简单地删除“脏”状态, 此状态用来标识一个字段是否被更新的, 供Remembered Sets使用。
  • Other:其他活动消耗的时间, 其中有很多也是并行执行的。
  • Choose CSet:选择CSet使用时间,CSet是指Collection Set,和RSet(Remembered Set)一样,用于辅助GC,用空间换时间。
  • Ref Proc:处理非强引用(non-strong)的时间: 进行清理或者决定是否需要清理。
  • Ref Enq:用来将剩下的 non-strong 引用排列到合适的 ReferenceQueue中。
  • Redirty Cards:重新脏化卡片。排队引用可能会更新RSet,所以需要对关联的Card重新脏化。
  • Humongous RegisterHumongous Reclaim:主要是对巨型对象回收的信息,youngGC阶段会对RSet中有引用的短命的巨型对象进行回收,巨型对象会直接回收而不需要进行转移(转移代价巨大,也没必要)。
  • Free CSet:释放CSet中的regionfree list使用时间。
  • Eden: 204.0M(204.0M)->0.0B(178.0M) Survivors: 0.0B->26.0M Heap: 204.0M(4096.0M)->65.2M(4096.0M):暂停之前和暂停之后, Eden 区的使用量/总容量。 暂停之前和暂停之后, 存活区的使用量。暂停之前和暂停之后, 整个堆内存的使用量与总容量。
  • Times: user=0.00 sys=0.00, real=0.01 secsGC事件的持续时间, 通过三个部分(用户线程,系统调用, 应用程序暂停的时间)来衡量。

小结:

  • G1是一个有整理内存过程的垃圾收集器,不会产生很多内存碎片。
  • 在实现高吞吐量的同时,G1Stop The World(STW)更可控,在停顿时间上添加了预测机制,用户可以指定期望停顿时间。
  • G1能与应用程序线程并发执行。

如何选择GC

参考资料: