VisualVM - 奇怪的自我時間

今天我對我得到的Visual VM分析結果感到困惑。VisualVM - 奇怪的自我時間

我有以下簡單的Java方法：

public class Encoder { 
    ... 
    private BitString encode(InputStream in, Map<Character, BitString> table) 
     throws IOException { 

    BufferedReader reader = new BufferedReader(new InputStreamReader(in)); 

    BitString result = new BitString(); 
    int i; 
    while ((i = reader.read()) != -1) { 
     char ch = (char) i; 
     BitString string = table.get(ch); 
     result = result.append(string); 
    } 

    return result; 
    } 
}

這種方法從流中讀取字符，一次一個。對於每個字符，它都會查找它的位串表示形式，並且它會連接這些位串來表示整個流。

BitString是一種自定義數據結構，它使用底層字節數組表示一系列位。

該方法表現很差。問題在於BitString#append - 該方法創建一個新的字節數組，從兩個輸入的BitStrings中複製位並將其作爲新的BitString實例返回。

public BitString append(BitString other) { 

    BitString result = new BitString(size + other.size); 
    int pos = 0; 

    for (byte b : this) { 
    result.set(pos, b); 
    pos++; 
    } 
    for (byte b : other) { 
    result.set(pos, b); 
    pos++; 
    } 

    return result; 
}

然而，當我試圖用VisualVM的驗證發生了什麼，這是我的了：

我一般用Visual VM很少的經驗和分析。據我的理解，這看起來好像問題在encode方法本身的某處，而不是在append。

可以肯定，我包圍了整個編碼方法，並用自定義時間測量的附加呼叫，像這樣：

public class Encoder { 
    private BitString encode(InputStream in, Map<Character, BitString> table) 
     throws IOException { 

>> long startTime = System.currentTimeMillis(); 
>> long appendDuration = 0; 

    BufferedReader reader = new BufferedReader(new InputStreamReader(in)); 

    BitString result = new BitString(); 
    int i; 
>> long count = 0; 
    while ((i = reader.read()) != -1) { 
     char ch = (char) i; 
     BitString string = table.get(ch); 

>> long appendStartTime = System.currentTimeMillis(); 
     result = result.append(string); 
>> long appendEndTime = System.currentTimeMillis(); 
>> appendDuration += appendEndTime - appendStartTime; 

>> count++; 
>> if (count % 1000 == 0) { 
>>  log.info(">>> CHARACTERS PROCESSED: " + count); 
>>  long endTime = System.currentTimeMillis(); 
>>  log.info(">>> TOTAL ENCODE DURATION: " + (endTime - startTime) + " ms"); 
>>  log.info(">>> TOTAL APPEND DURATION: " + appendDuration + " ms"); 
>> } 
    } 

    return result; 
    } 
}

而且我得到以下結果：

CHARACTERS PROCESSED: 102000 
TOTAL ENCODE DURATION: 188276 ms 
APPEND CALL DURATION: 188179 ms

這似乎與Visual VM的結果相矛盾。

我錯過了什麼？

來源

2016-09-24 Dušan Rychnovský

你是如何評價時間的，你是否可以添加該代碼？ – hunter

我補充說明了如何測量時間以及'append'的代碼。我不認爲有任何IO或網絡在那裏等待。也許GC暫停？ –

您是否嘗試過[*此方法*]（http://stackoverflow.com/a/378024/23771）？它可以很好地與Java一起工作，並且會準確地告訴你時間在哪裏。請注意，它*不測量*。相反，它利用了活動需要大量時間來查明它的事實。您可以使用它來獲得非常粗略的測量結果，但它確切地發現了問題。 –

[此答案無效。但我保留，直到OP得到一些成員的幫助，因爲這篇文章包含兩個評論，這有助於他人理解這個問題]。

在這種情況下，VisualVM已經測量了實際的CPU時間，但是您測量的時間值是「經過時間」。

如果執行線程必須等待IO或網絡，那麼該時間將不會被測量爲CPU時間。

來源

2016-09-24 19:38:25 hunter

請看我的擴展答案 - 我包含了'append'的實現。我不認爲那裏有任何IO。也許寧可GC停頓？但是，正如您在屏幕截圖中看到的，Visual VM顯示了兩個值 - 「時間」和「時間（CPU）」。 '時間'不是'經過時間'和'時間（CPU）''實際CPU時間'？ –

是的，你說得對，這裏有些奇怪，我的回答對你的情況無效。對於2個編碼調用，追加僅被調用了4次。一目瞭然，所有的調用都沒有被記錄下來。熟悉VisuvalVM的人可能會幫助你。我試圖根據我在JProfiler上的經驗來幫助你。謝謝 – hunter

VisualVM - 奇怪的自我時間

回答

相關問題