春季计划任务的性能分析答案

【问题标题】：Profile performances of a spring scheduled task春季计划任务的性能分析
【发布时间】：2014-06-14 07:56:19
【问题描述】：

我正在尝试分析计划的春季作业，该作业在 ScrollableResults 迭代器上进行计算。

为了分析我的代码，我在所有代码上放置了几个System.nanoTime()，计算每个重要块代码所需的时间。该时间计算涵盖了所有代码，我对此非常确定。

batch的简化结构如下：

@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 profiler 的截图：

问题在于TOTAL TIME CALCULATED，即我使用System.nanoTime() 收集的所有值的总和，与TOTAL TIME FROM START 的差异约为 566 秒（总共 704 :| ）。这是一个变化很大的时间。而且我不知道这段时间浪费在哪里！

也许 Spring 框架需要这些秒来处理事务/其他事情？事实上，我对每个数据集元素都有一个新事务。如果是，我该如何分析它？

任何帮助将不胜感激。

想了想有点想不通的时间是用来代理calcService.calc()？可以吗？

【问题讨论】：

标签： java spring performance jpa profiling

【解决方案1】：

有一个带有 visualvm 的 CPU 分析器，我会试一试（您可能必须将它作为插件安装） - 或者如果您需要更深入的 CPU 分析，请尝试 JProfiler

【讨论】：

我应该看看它，但从第一张图可以看出（如果图表足够），cpu永远不会超过10％。仅在启动期间，同时初始化 spring 上下文。
该图显示了您的程序正在使用多少整个 CPU - 因此，如果您的程序没有给系统带来太大压力，那么这个值很低并不异常。如果您期望这更高，那么也许您的程序正在花费时间等待 i/o 等资源 - 看看 iowait 或 top 等......您的问题更像是在我的程序中花费的时间在哪里。 CPU 分析器等会告诉你。
嘿伙计！我已经更新了我的问题......如果你想看看......谢谢你:)
我想我已经解决了。问题是传播=REQUIRES_NEW。改变是为了传播=需要让事情变得更快..但这不是我想要的。无论如何，非常感谢您的宝贵时间