我正在尝试分析一个计划的 Spring 作业，该作业在 ScrollableResults 迭代器上进行计算。
为了分析我的代码，我在所有代码上放置了几个 System.nanoTime()，计算每个重要 block 代码所需的时间。所有代码都包含在该时间计算中，我对此非常确定。
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 测试期间虚拟机分析的两张屏幕截图，如果它有用的话..
这里有一些来自 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 分析器的屏幕截图:
问题在于总时间计算，即我使用System.nanoTime()收集的所有值的总和与总时间有差异FROM START 大约 566 秒(总共 704 :| )。这是相当长的时间。而且我不知道这些时间都浪费在哪里了!
也许 Spring 框架需要这些秒来处理事务/其他事情？事实上，我为每个数据集元素都有一个新事务。如果是，我该如何分析它？
如有任何帮助，我们将不胜感激。
思考之后我突然想到，我不知道时间是用于代理 calcService.calc() 吗？可以吗？
最佳答案
有一个带有 VisualVM 的 CPU 分析器，我会尝试一下(您可能需要将其作为插件安装) - 或者如果您需要更深入的 CPU 分析，请尝试 JProfiler
关于java - Spring计划任务的配置文件性能，我们在Stack Overflow上找到一个类似的问题： https://stackoverflow.com/questions/24217855/