ArrayList插入1000w条数据的时间比较分析

准备:调试程序加入VM Options: -XX:+PrintGCDetails -XX:+PrintGCDateStamps 

1.List未初始化大小时，执行时间差不多，应该跟数组频繁扩容有关。

 1 public class Test {
 2     public static void main(String[] args) {
 3         long start0 = System.currentTimeMillis();
 4         List<Integer> list0 = new ArrayList<>();
 5         for (int i = 0; i < 10000000; i++){
 6             list0.add(i);
 7          }
 8         System.out.println("耗时:"+(System.currentTimeMillis() - start0));
 9         long start1 = System.currentTimeMillis();
10         List<Integer> list1 = new ArrayList<>();
11         for (int i = 0; i < 10000000; i++){
12             list1.add(i);
13         }
14         System.out.println("耗时:"+(System.currentTimeMillis() - start1));
15     }
16 }

GC日志以及程序结果打印

2019-10-11T23:00:10.624+0800: [GC (Allocation Failure) [PSYoungGen: 54881K->10730K(76288K)] 54881K->36330K(251392K), 0.0467742 secs] [Times: user=0.28 sys=0.01, real=0.03 secs] 
2019-10-11T23:00:10.681+0800: [GC (Allocation Failure) [PSYoungGen: 74086K->10744K(141824K)] 99686K->80960K(316928K), 0.0799013 secs] [Times: user=0.83 sys=0.05, real=0.09 secs] 
2019-10-11T23:00:10.831+0800: [GC (Allocation Failure) [PSYoungGen: 141816K->10744K(141824K)] 212032K->188175K(319488K), 0.1750429 secs] [Times: user=1.50 sys=0.06, real=0.18 secs] 
2019-10-11T23:00:11.009+0800: [Full GC (Ergonomics) [PSYoungGen: 10744K->0K(141824K)] [ParOldGen: 177431K->171802K(411136K)] 188175K->171802K(552960K), [Metaspace: 3220K->3220K(1056768K)], 3.6056097 secs] [Times: user=19.06 sys=0.03, real=3.61 secs] 
耗时:4055
2019-10-11T23:00:14.650+0800: [GC (Allocation Failure) [PSYoungGen: 131072K->10738K(200704K)] 302874K->282502K(611840K), 0.1212870 secs] [Times: user=1.22 sys=0.03, real=0.12 secs] 
2019-10-11T23:00:14.832+0800: [GC (Allocation Failure) [PSYoungGen: 200690K->10752K(272896K)] 472454K->414803K(684032K), 0.1926591 secs] [Times: user=1.91 sys=0.09, real=0.19 secs] 
2019-10-11T23:00:15.025+0800: [Full GC (Ergonomics) [PSYoungGen: 10752K->0K(272896K)] [ParOldGen: 404051K->168023K(565248K)] 414803K->168023K(838144K), [Metaspace: 3731K->3731K(1056768K)], 3.9056201 secs] [Times: user=21.02 sys=0.05, real=3.90 secs] 
耗时:4305
Heap
 PSYoungGen      total 272896K, used 82411K [0x000000076b500000, 0x0000000792800000, 0x00000007c0000000)
  eden space 262144K, 31% used [0x000000076b500000,0x000000077057afa8,0x000000077b500000)
  from space 10752K, 0% used [0x000000077b500000,0x000000077b500000,0x000000077bf80000)
  to   space 176128K, 0% used [0x0000000787c00000,0x0000000787c00000,0x0000000792800000)
 ParOldGen       total 565248K, used 168023K [0x00000006c1e00000, 0x00000006e4600000, 0x000000076b500000)
  object space 565248K, 29% used [0x00000006c1e00000,0x00000006cc215df8,0x00000006e4600000)
 Metaspace       used 3737K, capacity 4540K, committed 4864K, reserved 1056768K
  class space    used 410K, capacity 428K, committed 512K, reserved 1048576K

 

2..List初始化大小，第二次执行时间总是比第一次少较多时间。

 1 public class Test {
 2     public static void main(String[] args) {
 3         long start0 = System.currentTimeMillis();
 4         List<Integer> list0 = new ArrayList<>(10000000);
 5         for (int i = 0; i < 10000000; i++){
 6             list0.add(i);
 7          }
 8         System.out.println("耗时:"+(System.currentTimeMillis() - start0));
 9         long start1 = System.currentTimeMillis();
10         List<Integer> list1 = new ArrayList<>(10000000);
11         for (int i = 0; i < 10000000; i++){
12             list1.add(i);
13         }
14         System.out.println("耗时:"+(System.currentTimeMillis() - start1));
15     }
16 }

GC日志以及程序结果打印

2019-10-11T23:02:01.720+0800: [GC (Allocation Failure) [PSYoungGen: 65536K->10728K(76288K)] 65536K->62246K(251392K), 0.1034325 secs] [Times: user=0.88 sys=0.09, real=0.12 secs] 
2019-10-11T23:02:01.852+0800: [GC (Allocation Failure) [PSYoungGen: 76264K->10744K(141824K)] 127782K->127950K(316928K), 0.7058133 secs] [Times: user=5.91 sys=0.11, real=0.70 secs] 
2019-10-11T23:02:02.555+0800: [Full GC (Ergonomics) [PSYoungGen: 10744K->0K(141824K)] [ParOldGen: 117206K->127705K(312320K)] 127950K->127705K(454144K), [Metaspace: 3220K->3220K(1056768K)], 3.0072554 secs] [Times: user=15.83 sys=0.17, real=3.01 secs] 
耗时:3897
2019-10-11T23:02:05.611+0800: [GC (Allocation Failure) [PSYoungGen: 131072K->10752K(141824K)] 258777K->252752K(454144K), 0.5464546 secs] [Times: user=4.14 sys=0.09, real=0.55 secs] 
2019-10-11T23:02:06.165+0800: [Full GC (Ergonomics) [PSYoungGen: 10752K->0K(141824K)] [ParOldGen: 242000K->57244K(365056K)] 252752K->57244K(506880K), [Metaspace: 3732K->3732K(1056768K)], 0.5518679 secs] [Times: user=2.63 sys=0.00, real=0.54 secs] 
2019-10-11T23:02:06.753+0800: [GC (Allocation Failure) [PSYoungGen: 131072K->10752K(209408K)] 188316K->188596K(574464K), 1.2310512 secs] [Times: user=10.47 sys=0.01, real=1.23 secs] 
耗时:2403
Heap
 PSYoungGen      total 209408K, used 24457K [0x000000076b500000, 0x0000000779180000, 0x00000007c0000000)
  eden space 198656K, 6% used [0x000000076b500000,0x000000076c2624c8,0x0000000777700000)
  from space 10752K, 100% used [0x0000000778180000,0x0000000778c00000,0x0000000778c00000)
  to   space 10752K, 0% used [0x0000000777700000,0x0000000777700000,0x0000000778180000)
 ParOldGen       total 365056K, used 177844K [0x00000006c1e00000, 0x00000006d8280000, 0x000000076b500000)
  object space 365056K, 48% used [0x00000006c1e00000,0x00000006ccbad380,0x00000006d8280000)
 Metaspace       used 3738K, capacity 4540K, committed 4864K, reserved 1056768K
  class space    used 410K, capacity 428K, committed 512K, reserved 1048576K

3.当List初始化大小时，第二次循环插入时间总是比第一次少很多。

Java JIT性能调优中介绍了：

JVM自动监控着所有方法的执行，如果某个方法是热点方法，JVM就计划把该方法的字节码代码编译成本地机器代码，同时还会在后续的执行过程中进行可能的更深层次的优化，编译成机器代码的过程是在独立线程中执行的，不会影响程序的执行；除次以外，JVM还对热点方法和很小的方法内联到调用方的方法中，减少方法栈的创建。这些就是JIT（just in time）。

On Stack Replacement (OSR)：如果某个循环执行的次数非常多，那么这个循环体代码也可能会编译为本地代码。

编译阈值

• • 
    
• 是否对代码进行编译受两个计数器的影响：1）方法的调用次数 2）方法内循环的次数 。 当JVM执行一个JAVA方法的时候，它都会检查这两个计数器，以便确定是否需要对方法进行编译。
• 当JVM执行一个JAVA方法的时候，它会检查这两个计数器值的总和，然后确定这个方法是否需要进行编译。如果需要进行编译，这个方法会放入编译队列。这种编译没有官方的名字，一般称之为​标准编译​。
• 如果方法里面是一个循环，虽然方法只调用一次，但是循环在不停执行。此时，JVM会对这个循环的代码进行编译。这种编译称之为​栈上替换OSR​（on-stack replacement)。因为即使循环被编译了，这还不够，JVM还需要能够在循环正在执行的时候，转为执行编译后的代码。JVM采用的方式就是将编译后的代码替换当前正在执行的方法字节码。由于方法在栈上执行，所以这个操作又称之为：​栈上替换​。
• 可以通过配置 -XX:CompileThreshold=N来确定计数器的阈值，从而控制编译的条件。但是如果降低了这个值，会导致JVM没有收集到足够的信息就进行了编译，导致编译的代码优化不够（不过影响会比较小）。
• 如果-XX:CompileThreshold=N配置的两个值（一个大，一个小）在性能测试方面表现差不多，那么会推荐使用小一点的配置，主要有两个原因：
• • • 
      
  • 可以减小应用的warm-up period。
  • 可以防止某个方法永远得不到编译。这是因为JVM会周期（每到安全点的时候）的对计数进行递减。如果阈值比较大，并且方法周期性调用的时间较长，导致计数永远达不到这个阈值，从而不会进行编译。
    • 
      
  • 
    

探寻编译过程

　　选项 -XX:+PrintCompilation可以打开编译日志，当JVM对方法进行编译的时候，都会打印一行信息，什么方法被编译了。具体格式如下：

 　　timestamp compilation_idattributes (tiered_level) method_name size deopt 

• • 
    
• timestamp是编译时相对于JVM启动的时间戳
• compliation_id是内部编译任务的ID，一般都是递增的
• attributes由5个字母组成，用来显示代码被编译的状态：
• • • 
      
  • %：编译是OSR
  • s：方法是synchronized的
  • !：方法有异常处理
  • b：编译线程不是后台运行的，而是同步的（当前版本的JVM应该不会打印这个状态了）
  • n：表示JVM产生了一些辅助代码，以便调用native 方法
    • 
      
• tiered_level：采用tiered compilation编译器时才会打印。
• method_name：被编译的方法名称，格式是：classname::method
• size: 被编译的代码大小（单位：字节），这里的代码是Java字节码。
• deopt：如果发生了去优化，这里说明去优化的类型。
  • 
    

　　VM Options加入 -XX:+PrintCompilation 后再运行Test，得到以下输出打印:

129    2       3       java.lang.AbstractStringBuilder::append (50 bytes)
    130    3       3       java.lang.String::hashCode (55 bytes)
    131    4       3       sun.nio.cs.ext.DoubleByte$Encoder::encodeChar (21 bytes)
    131    5       3       java.lang.Object::<init> (1 bytes)
    131    6       3       java.lang.StringBuilder::append (8 bytes)
    131    8       3       java.lang.CharacterData::of (120 bytes)
    132    9       3       java.lang.CharacterDataLatin1::getProperties (11 bytes)
    132    7       4       java.lang.String::length (6 bytes)
    132    1       4       java.lang.String::charAt (29 bytes)
    133   10     n 0       java.lang.System::arraycopy (native)   (static)
    134   11       1       sun.instrument.TransformerManager::getSnapshotTransformerList (5 bytes)
    134   12       3       java.io.WinNTFileSystem::normalize (143 bytes)
    135   13       3       java.lang.String::equals (81 bytes)
    136   14       4       java.lang.AbstractStringBuilder::append (29 bytes)
    137   15       3       java.lang.String::getChars (62 bytes)
    138   16       3       java.lang.Math::min (11 bytes)
    138   20       3       java.lang.String::indexOf (70 bytes)
    139   19       3       java.lang.String::startsWith (72 bytes)
    139   18       3       java.lang.String::startsWith (7 bytes)
    139   22       4       java.io.WinNTFileSystem::isSlash (18 bytes)
    139   23       4       java.lang.AbstractStringBuilder::ensureCapacityInternal (27 bytes)
    139   24  s    3       java.lang.StringBuffer::append (13 bytes)
    140   21       3       java.lang.String::indexOf (7 bytes)
    140   17       1       java.util.ArrayList::size (5 bytes)
    140   25       3       java.nio.Buffer::position (43 bytes)
    140   28     n 0       sun.misc.Unsafe::getObjectVolatile (native)   
    141   26       3       java.lang.System::getSecurityManager (4 bytes)
    141   27       3       java.util.concurrent.ConcurrentHashMap::tabAt (21 bytes)
    156   29       3       java.util.ArrayList::add (29 bytes)
    157   36       1       java.lang.Object::<init> (1 bytes)
    157    5       3       java.lang.Object::<init> (1 bytes)   made not entrant
    157   35       3       java.lang.Integer::valueOf (32 bytes)
    157   30       3       java.util.ArrayList::ensureCapacityInternal (13 bytes)
    157   37       4       java.util.ArrayList::add (29 bytes)
    157   38       4       java.lang.Integer::valueOf (32 bytes)
    157   32       2       java.util.ArrayList::ensureExplicitCapacity (26 bytes)
    158   31       2       java.util.ArrayList::calculateCapacity (16 bytes)
    158   33       2       java.lang.Number::<init> (5 bytes)
    158   34       2       java.lang.Integer::<init> (10 bytes)
    158   35       3       java.lang.Integer::valueOf (32 bytes)   made not entrant
    158   29       3       java.util.ArrayList::add (29 bytes)   made not entrant
    160   39 %     3       com.lucky.iot.express.base.express2.eunm.Test::main @ 17 (147 bytes)
    161   40       3       com.lucky.iot.express.base.express2.eunm.Test::main (147 bytes)
    162   41 %     4       com.lucky.iot.express.base.express2.eunm.Test::main @ 17 (147 bytes)
    164   39 %     3       com.lucky.iot.express.base.express2.eunm.Test::main @ -2 (147 bytes)   made not entrant
2019-10-12T10:11:26.812+0800: [GC (Allocation Failure) [PSYoungGen: 65536K->10728K(76288K)] 65536K->62098K(251392K), 0.0821551 secs] [Times: user=0.45 sys=0.01, real=0.08 secs] 
2019-10-12T10:11:26.910+0800: [GC (Allocation Failure) [PSYoungGen: 76264K->10728K(141824K)] 127634K->127802K(316928K), 0.4259123 secs] [Times: user=2.38 sys=0.11, real=0.43 secs] 
2019-10-12T10:11:27.336+0800: [Full GC (Ergonomics) [PSYoungGen: 10728K->0K(141824K)] [ParOldGen: 117074K->127504K(314368K)] 127802K->127504K(456192K), [Metaspace: 3220K->3220K(1056768K)], 2.5013968 secs] [Times: user=14.53 sys=0.14, real=2.50 secs] 
   3209   42       3       java.lang.ref.Reference::<init> (25 bytes)
   3210   43       3       java.lang.Character::toLowerCase (9 bytes)
   3210   44       3       java.lang.CharacterDataLatin1::toLowerCase (39 bytes)
   3210   45       3       java.util.Arrays::copyOfRange (63 bytes)
   3211   48       3       java.io.DataInputStream::readUTF (501 bytes)
   3212   53       3       java.io.DataInputStream::readFully (63 bytes)
   3212   47       3       java.io.BufferedInputStream::getBufIfOpen (21 bytes)
   3212   49  s    3       java.io.BufferedInputStream::read (49 bytes)
   3212   55       4       java.io.BufferedInputStream::getBufIfOpen (21 bytes)
   3212   50  s    3       java.io.BufferedInputStream::read (113 bytes)
   3213   47       3       java.io.BufferedInputStream::getBufIfOpen (21 bytes)   made not entrant
   3213   57       4       java.lang.String::hashCode (55 bytes)
   3213   54       3       java.io.DataInputStream::readShort (40 bytes)
   3213   52       3       java.io.BufferedInputStream::read1 (108 bytes)
   3214   46       3       java.lang.String::<init> (82 bytes)
   3214   51       3       java.io.DataInputStream::readUTF (5 bytes)
   3214   56       3       java.util.HashMap::hash (20 bytes)
   3214    3       3       java.lang.String::hashCode (55 bytes)   made not entrant
   3215   37       4       java.util.ArrayList::add (29 bytes)   made not entrant
   3216   59       3       java.util.HashMap::putVal (300 bytes)
   3217   58       3       java.util.HashMap::put (13 bytes)
   3217   60       3       java.lang.String::indexOf (166 bytes)
   3217   61       3       java.util.HashMap$Node::<init> (26 bytes)
   3218   62       3       java.lang.String::toLowerCase (439 bytes)
   3219   63   !   3       java.io.BufferedReader::readLine (304 bytes)
   3220   65       3       java.lang.String::lastIndexOf (52 bytes)
   3220   68       3       java.lang.StringBuilder::append (8 bytes)
   3221   69  s    4       java.lang.StringBuffer::append (13 bytes)
   3221   66       3       java.util.BitSet::wordIndex (5 bytes)
   3221   67       3       java.util.BitSet::checkInvariants (111 bytes)
   3221   64       1       java.io.File::getPath (5 bytes)
   3221   70       1       java.net.URL::getProtocol (5 bytes)
   3221   71       1       java.nio.Buffer::position (5 bytes)
   3222   38       4       java.lang.Integer::valueOf (32 bytes)   made not entrant
   3224   41 %     4       com.lucky.iot.express.base.express2.eunm.Test::main @ -2 (147 bytes)   made not entrant
   3224   72       3       sun.util.locale.LocaleUtils::isUpper (18 bytes)
耗时:3082
   3224   24  s    3       java.lang.StringBuffer::append (13 bytes)   made not entrant
   3224   73       3       sun.instrument.InstrumentationImpl::transform (38 bytes)
   3224   74   !   3       sun.instrument.TransformerManager::transform (98 bytes)
   3226   76       3       java.util.LinkedHashMap::newNode (23 bytes)
   3226   75       1       java.util.LinkedHashMap::removeEldestEntry (2 bytes)
   3226   77       3       java.util.LinkedHashMap::linkNodeLast (33 bytes)
   3226   78       3       java.util.LinkedHashMap::afterNodeInsertion (40 bytes)
   3226   79       3       java.util.LinkedHashMap$Entry::<init> (10 bytes)
   3226   80       1       java.lang.ref.Reference::get (5 bytes)
   3227   81  s    3       java.util.Hashtable::get (69 bytes)
   3227   83       3       java.lang.AbstractStringBuilder::<init> (12 bytes)
   3227   82       3       java.lang.String::<init> (10 bytes)
   3227   84       3       java.lang.AbstractStringBuilder::newCapacity (39 bytes)
   3227   85       3       java.util.Properties::saveConvert (434 bytes)
   3233   86       3       java.lang.StringBuffer::<init> (6 bytes)
   3239   88       3       java.lang.Integer::valueOf (32 bytes)
   3240   90       4       java.lang.Integer::<init> (10 bytes)
   3240   87       3       java.util.ArrayList::add (29 bytes)
   3240   34       2       java.lang.Integer::<init> (10 bytes)   made not entrant
   3240   91       4       java.util.ArrayList::ensureCapacityInternal (13 bytes)
   3240   92       4       java.lang.Integer::valueOf (32 bytes)
   3240   89 %     3       com.lucky.iot.express.base.express2.eunm.Test::main @ 90 (147 bytes)
   3240   93       4       java.util.ArrayList::add (29 bytes)
   3240   30       3       java.util.ArrayList::ensureCapacityInternal (13 bytes)   made not entrant
   3241   88       3       java.lang.Integer::valueOf (32 bytes)   made not entrant
   3241   87       3       java.util.ArrayList::add (29 bytes)   made not entrant
   3241   94 %     4       com.lucky.iot.express.base.express2.eunm.Test::main @ 90 (147 bytes)
   3245   89 %     3       com.lucky.iot.express.base.express2.eunm.Test::main @ -2 (147 bytes)   made not entrant
2019-10-12T10:11:29.883+0800: [GC (Allocation Failure) [PSYoungGen: 131072K->10752K(141824K)] 258576K->252542K(456192K), 0.3817872 secs] [Times: user=2.74 sys=0.06, real=0.38 secs] 
2019-10-12T10:11:30.265+0800: [Full GC (Ergonomics) [PSYoungGen: 10752K->0K(141824K)] [ParOldGen: 241790K->57043K(369664K)] 252542K->57043K(511488K), [Metaspace: 3734K->3734K(1056768K)], 0.3879005 secs] [Times: user=1.58 sys=0.00, real=0.39 secs] 
2019-10-12T10:11:30.683+0800: [GC (Allocation Failure) [PSYoungGen: 131072K->10752K(204288K)] 188115K->188387K(573952K), 0.7772698 secs] [Times: user=6.06 sys=0.00, real=0.78 secs] 
   4833   94 %     4       com.lucky.iot.express.base.express2.eunm.Test::main @ -2 (147 bytes)   made not entrant
耗时:1609
Heap
 PSYoungGen      total 204288K, used 24103K [0x000000076b500000, 0x0000000778c80000, 0x00000007c0000000)
  eden space 193536K, 6% used [0x000000076b500000,0x000000076c209f48,0x0000000777200000)
  from space 10752K, 100% used [0x0000000777c80000,0x0000000778700000,0x0000000778700000)
  to   space 10752K, 0% used [0x0000000777200000,0x0000000777200000,0x0000000777c80000)
 ParOldGen       total 369664K, used 177635K [0x00000006c1e00000, 0x00000006d8700000, 0x000000076b500000)
  object space 369664K, 48% used [0x00000006c1e00000,0x00000006ccb78f98,0x00000006d8700000)
 Metaspace       used 3740K, capacity 4540K, committed 4864K, reserved 1056768K
  class space    used 410K, capacity 428K, committed 512K, reserved 1048576K