ArrayList插入1000w條數據的時間比較分析

時間  2019-11-10
標籤 arraylist 插入 1000w 數據 時間 比較分析 欄目 Java 简体版
原文   原文鏈接

一分鐘系列： 讀懂GC日誌

ArrayList插入1000w條數據以後，我懷疑了jvm...

Java JIT性能調優

Java性能優化指南系列(三）：理解JIT編譯器

準備:調試程序加入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性能調優中介紹了：java

JVM自動監控着全部方法的執行，若是某個方法是熱點方法，JVM就計劃把該方法的字節碼代碼編譯成本地機器代碼，同時還會在後續的執行過程當中進行可能的更深層次的優化，編譯成機器代碼的過程是在獨立線程中執行的，不會影響程序的執行；除次之外，JVM還對熱點方法和很小的方法內聯到調用方的方法中，減小方法棧的建立。這些就是JIT（just in time）。express

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，獲得如下輸出打印:app

    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
相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程