彈簧計劃任務的配置文件性能

Question

我正在嘗試配置計劃的彈簧作業，該計劃是對迭代器進行計算。

爲了剖析我的代碼，我已經在所有的代碼上放置了幾個System.nanoTime()，計算每個重要塊代碼所需的時間。所有的代碼都包含在那個時間計算中，我很確定它。

批次的簡化結構如下：

@Scheduled(cron=CRON_EXPRESSION) 
@Transactional(readOnly=true) 
public void calc() { 
    Session session = (Session) entityManager.unwrap(Session.class); 
    ScrollableResults entities = session.createQuery("select i.id from Entity i") 
     .setCacheMode(CacheMode.IGNORE) 
     .scroll(ScrollMode.FORWARD_ONLY); 

    while (entities.next()){ 
     if (++count % 40 == 0) { 
      entityManager.flush(); 
      entityManager.clear(); 
     }     
     long idEntity = (long)entities.get(0);  
     calcService.calc(idEntity); 
    } 
} 

在這裏，我計算的服務

@Transactional(readOnly=false, propagation=Propagation.REQUIRES_NEW, rollbackFor=Exception.class) 
public void calc(Long id) { 
    // calculation jobs, load/saving entities from repositories 
} 

現在是這裏的日誌結果，我對所有數據集的一個子集打印輸出。

Loaded dataset 
Tot Eval ds elem: 1000 Tot Eval Subentity: 2000 Req Time: 89.16532s 
Tot Eval ds elem: 2000 Tot Eval Subentity: 4000 Req Time: 69.86559s 
Tot Eval ds elem: 3000 Tot Eval Subentity: 6000 Req Time: 66.897255s 
Tot Eval ds elem: 4000 Tot Eval Subentity: 8000 Req Time: 66.97226s 
Tot Eval ds elem: 5000 Tot Eval Subentity: 10000 Req Time: 65.657s 
Tot Eval ds elem: 6000 Tot Eval Subentity: 12000 Req Time: 69.23902s 
Tot Eval ds elem: 7000 Tot Eval Subentity: 14000 Req Time: 75.46887s 
Tot Eval ds elem: 8000 Tot Eval Subentity: 16000 Req Time: 68.46504s 
Tot Eval ds elem: 9000 Tot Eval Subentity: 18000 Req Time: 65.976746s 
Tot Eval ds elem: 10000 Tot Eval Subentity: 20000 Req Time: 67.081604s 
LOAD DATASET SCROLLABLE RESULT: 0.02076124s 
LOAD EACH ENTITY OF DATASET: 0.02628186s 
MARK ALL SUBENTITYes DELETABLE: 16.105577s 
FIND SUBENTITY REPORT: 17.970514s 
FIND SUBENTITY REPORT2: 34.058716s 
MATCH RULE FOR SUBENTITY: 0.15097496s 
CALCULATE MASTER REPORT: 10.864335s 
FIND SUBENTITY DEADLINE: 15.759168s 
FIND SUBENTITY REPORT: 20.173891s 
CALCULATE DEDALINE: 0.003906471s 
SAVE DEADLINE: 22.892395s 
FINISH: CLEAN UNUSED: 0.001640737s 
FLUSHes/CLEANs ENTITY MANAGER: 0.009685958s 
------------------------------------------------------------ 
TOTAL TIME FROM START: 704.79083s 
TOTAL TIME CALCULATED: 138.03619384765625s 
UNKNOWN TIME: 566.7546997070312s 

我還張貼JUnit測試期間VM剖析兩個截圖，如果它可能是有用的..

這裏從iotop一些快照與MySQL守護進程：

Total DISK READ :  0.00 B/s | Total DISK WRITE :  824.04 K/s 
Actual DISK READ:  0.00 B/s | Actual DISK WRITE: 1069.55 K/s 
    TID PRIO USER  DISK READ DISK WRITE SWAPIN  IO> COMMAND                              
    168 be/3 root  0.00 B/s 0.00 B/s 0.00 % 79.97 % [jbd2/sda3-8] 
9043 be/4 mysql  0.00 B/s 82.76 K/s 0.00 % 1.78 % mysqld 
2232 be/4 mysql  0.00 B/s 740.09 K/s 0.00 % 1.05 % mysqld 
4302 be/4 marco  0.00 B/s 1222.34 B/s 0.00 % 0.34 % chromium-browser --ppapi-flash-path=/usr/lib/pepperflashplugin~ppapi-flash-version=13.0.0.206 --enable-pinch [BrowserBlocking] 
2364 be/4 root  0.00 B/s 0.00 B/s 0.00 % 0.04 % [kworker/u8:0] 
1294 be/4 mysql  0.00 B/s 0.00 B/s 0.00 % 0.00 % mysqld 

Total DISK READ :  0.00 B/s | Total DISK WRITE :  810.60 K/s 
Actual DISK READ:  0.00 B/s | Actual DISK WRITE: 1234.21 K/s 
    TID PRIO USER  DISK READ DISK WRITE SWAPIN  IO> COMMAND                              
    168 be/3 root  0.00 B/s 5.18 K/s 0.00 % 79.21 % [jbd2/sda3-8] 
9043 be/4 mysql  0.00 B/s 80.02 K/s 0.00 % 2.52 % mysqld 
4863 be/4 marco  0.00 B/s 815.38 B/s 0.00 % 1.89 % java -Dorg.eclipse.swt.browser.IEVersion=10001 -Djava.library.~//plugins/org.eclipse.equinox.launcher_1.3.0.v20130327-1440.jar 
21320 be/4 marco  0.00 B/s 815.38 B/s 0.00 % 1.56 % java -Djdk.home=/usr/lib/jvm/java-7-openjdk-amd64 -classpath /~-cachedir /home/marco/.cache/visualvm/1.3.5 --branding visualvm 
29194 be/4 marco  0.00 B/s 407.69 B/s 0.00 % 1.53 % java -Dorg.eclipse.swt.browser.IEVersion=10001 -Djava.library.~//plugins/org.eclipse.equinox.launcher_1.3.0.v20130327-1440.jar 
2232 be/4 mysql  0.00 B/s 721.82 K/s 0.00 % 1.29 % mysqld 
18165 be/4 root  0.00 B/s 0.00 B/s 0.00 % 0.03 % [kworker/u8:1] 


Total DISK READ :  407.55 B/s | Total DISK WRITE : 1735.66 K/s 
Actual DISK READ:  407.55 B/s | Actual DISK WRITE: 1266.82 K/s 
    TID PRIO USER  DISK READ DISK WRITE SWAPIN  IO> COMMAND                              
    168 be/3 root  0.00 B/s 10.75 K/s 0.00 % 82.54 % [jbd2/sda3-8] 
9043 be/4 mysql  0.00 B/s 82.39 K/s 0.00 % 4.85 % mysqld 
2232 be/4 mysql  0.00 B/s 733.11 K/s 0.00 % 2.84 % mysqld 
5255 be/4 marco  407.55 B/s 0.00 B/s 0.00 % 0.24 % gedit 

Total DISK READ :  26.26 K/s | Total DISK WRITE :  831.29 K/s 
Actual DISK READ:  26.26 K/s | Actual DISK WRITE: 1807.43 K/s 
    TID PRIO USER  DISK READ DISK WRITE SWAPIN  IO> COMMAND                              
    168 be/3 root  0.00 B/s 6.37 K/s 0.00 % 79.81 % [jbd2/sda3-8] 
2232 be/4 mysql  0.00 B/s 740.56 K/s 0.00 % 2.40 % mysqld 
9043 be/4 mysql  0.00 B/s 81.18 K/s 0.00 % 2.09 % mysqld 
18165 be/4 root  26.26 K/s 0.00 B/s 0.00 % 1.68 % [kworker/u8:1] 
4391 be/4 marco  0.00 B/s 1629.95 B/s 0.00 % 1.29 % chromium-browser --ppapi-flash-path=/usr/lib/pepperflashplugin~ppapi-flash-version=13.0.0.206 --enable-pinch [BrowserBlocking] 
1294 be/4 mysql  0.00 B/s 0.00 B/s 0.00 % 0.00 % mysqld 


Total DISK READ :  0.00 B/s | Total DISK WRITE :  828.89 K/s 
Actual DISK READ:  0.00 B/s | Actual DISK WRITE: 1071.51 K/s 
    TID PRIO USER  DISK READ DISK WRITE SWAPIN  IO> COMMAND                              
    168 be/3 root  0.00 B/s 1221.86 B/s 0.00 % 81.63 % [jbd2/sda3-8] 
9043 be/4 mysql  0.00 B/s 83.53 K/s 0.00 % 2.00 % mysqld 
2232 be/4 mysql  0.00 B/s 742.18 K/s 0.00 % 1.98 % mysqld 

和CPU分析器的屏幕截圖：

的問題是，TOTAL TIME CALCULATED，即SUM關閉我與System.nanoTime()收集所有值都具有從約566秒TOTAL TIME FROM START的差（在總共704 ：| ）。這是相當長的時間。而且我無法知道這個時間浪費在哪裏！

也許這些秒是春季框架要求​​處理交易/其他事情？事實上，我爲每個數據集元素都有一個新的事務。如果是的話我怎樣才能描述它？

任何幫助，將不勝感激。

想過這個之後，有一點我想起來，那時候我弄不明白是在代理calcService.calc()中被僱用的嗎？是真的嗎？

Answer 1

沒有與VisualVM的一個CPU分析器我想給一個去（你可能必須安裝它作爲一個插件） - 或者，如果你需要更深入的CPU性能分析，嘗試JProfiler的