关于效率测试的一个疑问，欢迎讨论
这个问题从上班的地方带回家，一个晚上还是不能解决。有一些细节部分不清楚，上来问问，请指教。我尽量把问题最小化，代码能够描述清楚状况就可以了。
public static void main(String[] args) throws Exception {
PoolSupper.initPool();
long starttime = System.currentTimeMillis();
ConnectionManage cm = new ConnectionManage();
cm.activity("com.cea.boat.dao.DefMultilangmsg a
,com.cea.boat.dao.DefMultilangmsg a
,com.cea.boat.dao.DefMultilangmsg a
,com.cea.boat.dao.DefMultilangmsg a
,com.cea.boat.dao.DefMultilangmsg a
,com.cea.boat.dao.DefMultilangmsg a
,com.cea.boat.dao.DefMultilangmsg a");
long midtime = System.currentTimeMillis();
System.out.println("midtime:" + (midtime - starttime));
}
public void activity(String actives) throws Exception {
try {
//解析激活参数
long s = System.currentTimeMillis();
execAnalyse(actives);
long e = System.currentTimeMillis();
Repository repository = RepositoryFactory.newInstance();
TableDesc[] tableDesc = new TableDesc[execids.length];
tables = new String[execids.length];
fields = new ArrayList[execids.length];
log.info("execAnalyse:" + (e - s));
for (int i = 0; i < tableDesc.length; i++) {
s = e;
//请各位看官们看这个函数的执行时间，问题重点在这
tableDesc[i] = repository.findTableDesc(execids[i]);
e = System.currentTimeMillis();
log.info("1:" + (e - s));
s = e;
tables[i] = tableDesc[i].getTable();
fields[i] = tableDesc[i].getFieldDescs();
e = System.currentTimeMillis();
log.info("2:" + (e - s));
}
e = System.currentTimeMillis();
log.info("3:" + (e - s));
if (tableDesc[0].getPageCount() != null) {
PAGECOUNT = tableDesc[0].getPageCount().longValue();
}
}
catch (Exception ex) {
log.error(ex.getMessage(), ex);
}
}
public TableDesc findTableDesc(String execid) {
long s = System.currentTimeMillis();
Iterator iter = tableDesc.iterator();
execid = ConvertUtil.patternTablename(execid);
long e = System.currentTimeMillis();
log.info("patternTablename:" + (e - s));
s = e;
while (iter.hasNext()) {
TableDesc ds = (TableDesc) iter.next();
if (ds.getExecid().equalsIgnoreCase(execid)) {
e = System.currentTimeMillis();
log.info("Execid:" + (e - s));
return ds;
}
}
return null;
}
问题点数：101、回复次数：18Top
1 楼cyicecream（为了升仙（星）到处UP）回复于 2005-05-24 09:09:14 得分 0
这是一个激活代码，至于细节可以不必追究，我花了点时间做了些效率测试，发现在整个时间花费，几乎都
在这个函数repository.findTableDesc(execids[i])返回时占用了。我指的是第一次，请看数据
execAnalyse:15
patternTablename:0
Execid:0
1:282
2:0
patternTablename:0
Execid:0
1:93
2:0
patternTablename:0
Execid:32
1:32
2:0
patternTablename:0
Execid:0
1:31
2:0 patternTablename:0
Execid:0
1:0
2:31
patternTablename:0
Execid:0
1:0
2:0
patternTablename:0
Execid:0
1:31
2:0
3:0
时间已经是最深度截取，就在第一次函数返回花费了282豪秒，余下还算正常。到这步我怀疑是第一次调用一个实例的函数
花费的时间会比较多。为此我又做了下面的测试：
public static void main(String[] args) throws Exception {
Untitled1 Untitled1 = new Untitled1();
long starttime = System.currentTimeMillis();
Untitled1.test();
long midtime = System.currentTimeMillis();
System.out.println("time:" + (midtime - starttime));
}
String test() {
return "sdfdsf";
}
输出结果 time:0
怀疑错误，又做了一种测试，把findTableDesc(String execid)函数放在同一个类中调用，希望是不同类之间调用函数的问题。
结果时间还是如第一次的测试结果，花费时间也有300-400豪秒不等。
时间 1 = patternTablename + Execid + 函数返回时间
就算再怎么中断调用，也不至于第一次282，后面还有为0的，JVM在第一次做了些什么？？找不到合适的说法，超出我目前所知道的知识范围，
请知道的人解释一下，谢谢。
看贴请留下脚印:)Top
2 楼jFresH_MaN（十一月的萧邦－夜曲）回复于 2005-05-24 09:21:54 得分 0
看贴留下脚印:)
实在是太长了，有些看不明白。。Top
3 楼cyicecream（为了升仙（星）到处UP）回复于 2005-05-24 09:41:03 得分 0
不用看代码呀，跟着时间输出走，不需要看代码。
哎，两星的。。。。。Top
4 楼nimifeng（学海无涯.......苦作舟....理解是美!!!Mars.Neil）回复于 2005-05-24 09:43:55 得分 0
一会再看...脚印踩不上来..Top
5 楼jFresH_MaN（十一月的萧邦－夜曲）回复于 2005-05-24 10:00:59 得分 0
哎。我就是那个两星的菜鸟，让楼主失望了。Top
6 楼cyicecream（为了升仙（星）到处UP）回复于 2005-05-24 10:10:59 得分 0
既然题目是效率测试，直接看问题所在啊，重点在函数里，为什么第一次返回的时间如此长，我想弄清楚。希望再进来的人别花什么时间看代码了。Top
7 楼jFresH_MaN（十一月的萧邦－夜曲）回复于 2005-05-24 10:26:49 得分 25
你的问题其实就是为什么一个方法第一次执行的时候会耗时多一点。
其实这有两方面因素：
1。一个方法第一次被调用的时候会首先申请一些必要空间，注册一些堆栈信息，这个必然需要一些时间。
2。你紧接着一直调用它，那么在内存中的很多数据就得到了复用，那么速度自然会快。
因为jvm是采用垃圾回收的，那么方法执行完了之后有写没用的对象就已经符合垃圾回收的条件了，但是垃圾回收不是立即就能执行的，所以那些对象就还驻留在内存中。第二次调用方法这些对象就不需要再次创建就可以直接使用内存的原来的数据了。
这是我的理解，可能有些地方不太对，欢迎大家讨论。Top
8 楼cyicecream（为了升仙（星）到处UP）回复于 2005-05-24 14:13:40 得分 0
我也觉得楼上说的有道理，所以我又做了一次测试，这次在函数里放了比多的执行程序，整个内存的开销也占据一定的空间。但是当我执行完后还是找不到正确的解释：（
public static void main(String[] args) throws Exception {
PoolSupper.initPool();
Repository r = RepositoryFactory.newInstance();
Untitled1 x = new Untitled1();
long starttime = System.currentTimeMillis();
x.test();
// System.out.println(x.test());
long midtime = System.currentTimeMillis();
System.out.println("time:" + (midtime - starttime));
}
String test() throws Exception{
StringBuffer sb = new StringBuffer();
Repository r = RepositoryFactory.newInstance();
List tablelist = r.getTableDescs();
int k = 0;
for (int i = 0; i < tablelist.size(); i++) {
TableDesc t = (TableDesc)tablelist.get(i);
List fieldlist = t.getFieldDescs();
for (int j = 0; j < fieldlist.size(); j++) {
k++;
FieldDesc fd = (FieldDesc)fieldlist.get(j);
sb.append(fd.getFieldName() + " ");
}
}
System.out.println("execute times:" + k);
return sb.toString();
}
执行结果为：
execute times:191
time:0
执行了191次，时间还为0。怎么CPU的执行那么快？用不到几毫秒时间吗？
这个测试环境我已经尽量的模仿了原题的效果。
1。一个方法第一次被调用的时候会首先申请一些必要空间，注册一些堆栈信息，这个必然需要一些时间。
-----------------------------------------------------------------------
JVM分配空间需要时间，这里体现不出来，而且执行了很多遍也是这个结果。
只有继续等待下面的回复了Top
9 楼gtlang78（）回复于 2005-05-24 16:10:37 得分 60
楼主，你仔细看看这一段
///////////////////////////////////////////////////////////////
long s = System.currentTimeMillis();
execAnalyse(actives);
long e = System.currentTimeMillis();
Repository repository = RepositoryFactory.newInstance();
TableDesc[] tableDesc = new TableDesc[execids.length];
tables = new String[execids.length];
fields = new ArrayList[execids.length];
log.info("execAnalyse:" + (e - s));
for (int i = 0; i < tableDesc.length; i++) {
s = e;
// 请各位看官们看这个函数的执行时间，问题重点在这
tableDesc[i] = repository.findTableDesc(execids[i]);
e = System.currentTimeMillis();
log.info("1:" + (e - s));
///////////////////////////////////////////////////////////////
第一次循环里的s值实际上是从第三行的 long e = System.currentTimeMillis(); 里来的，所以第一次输出的 log.info("1:" + (e - s)); 时间里包含了前面
这一段的时间
Repository repository = RepositoryFactory.newInstance();
TableDesc[] tableDesc = new TableDesc[execids.length];
tables = new String[execids.length];
fields = new ArrayList[execids.length];
log.info("execAnalyse:" + (e - s));
是不是 RepositoryFactory.newInstance()这个方法比较耗时呢?
Top
10 楼lei8766（lei8766）回复于 2005-05-24 16:34:04 得分 0
看高手讨论......Top
11 楼lei8766（lei8766）回复于 2005-05-24 17:19:02 得分 11
我认为 jFresH_MaN(听说距离产生美，所以我将离开你！) 说的有道理
是JVM的问题
你可以看看我写的一个测试代码:
package test;
public class ClassForLoad {
public static String getString() {
return "看看我的时间多少";
}
public String getString2() {
return "我的时间呢";
}
}
package test;
public class EfficiencyTest {
public static void main(String[] args) {
long s, e;
s = System.currentTimeMillis();
for(int i = 0; i< 5; i++) {
System.out.println(ClassForLoad.getString());
e = System.currentTimeMillis();
System.out.println("1: " + (e - s));
s = e;
System.out.println(new ClassForLoad().getString2());
e = System.currentTimeMillis();
System.out.println("2: " + (e - s));
System.out.println("===============");
s = e;
}
}
}
我的输出为:
看看我的时间多少
1: 0
我的时间呢
2: 15
===============
看看我的时间多少
1: 16
我的时间呢
2: 0
===============
看看我的时间多少
1: 0
我的时间呢
2: 0
===============
看看我的时间多少
1: 15
我的时间呢
2: 0
===============
看看我的时间多少
1: 16
我的时间呢
2: 0
===============Top
12 楼lei8766（lei8766）回复于 2005-05-24 17:23:22 得分 0
上面是执行一次的执行结果,每次的执行结果都不一样,这个要看当时的JVM是如果管理的了.Top
13 楼DanielYWoo（绿色毒汁）回复于 2005-05-24 17:59:31 得分 5
to lei8766(lei8766)
我的打印出来的全是0，呵呵
另外，WindowsNT内核下Timer的分辨率为10毫秒，这个测试不能说明问题，找个CPU负载大点例子看看
to 楼主
你用过JProbe或者OptimizeIt没有？你用这些工具试一下，可以找出你的性能瓶颈Top
14 楼gtlang78（）回复于 2005-05-24 18:10:36 得分 0
楼主的程序里计算时间的代码有问题, 测出的时长是错的Top
15 楼gtlang78（）回复于 2005-05-24 18:16:40 得分 0
导致得出了方法第一次调用耗时很长的错误结论Top
16 楼cyicecream（为了升仙（星）到处UP）回复于 2005-05-25 09:20:10 得分 0
----------------------------------------------------------------------------------------
1。一个方法第一次被调用的时候会首先申请一些必要空间，注册一些堆栈信息，这个必然需要一些时间。
2。你紧接着一直调用它，那么在内存中的很多数据就得到了复用，那么速度自然会快。
因为jvm是采用垃圾回收的，那么方法执行完了之后有写没用的对象就已经符合垃圾回收的条件了，但是垃圾回收不是立即就能执行的，所以那些对象就还驻留在内存中。第二次调用方法这些对象就不需要再次创建就可以直接使用内存的原来的数据了
-----------------------------------------------------------------------------------------
gtlang78() ( ) 的结论是对的，是我的想当然导致的结果，不过这个想当然让我知道对于1。所花的时间不需要太多，在大多数情况下。JVM使用的是执行期动态分配空间；
Repository repository = RepositoryFactory.newInstance();
Repository 是个单实例，第一次初始化时确实需要花费200-300毫秒的时间，以后就不需要花费时间了。直接返回实例，因此就出现了第一次时间差为什么那么大。这个错误的出现是我认为非第一次初始化，所以可以忽略这个时间，导致的错误。不过这次讨论收获不小，谢谢gtlang78() ( ) ，jFresH_MaN(听说距离产生美，所以我将离开你！) ( ) 。
虽然jFresH_MaN 说的看起来有道理，不过还是得动手测试得出结论，我得出的结论是jFresH_MaN所说的不太正确，从测试结果看基本没什么影响。这是个人所见，有错误希望指出。Top
17 楼jFresH_MaN（十一月的萧邦－夜曲）回复于 2005-05-25 09:28:25 得分 0
哎，真是郁闷哦。
这个问题我都感到委屈。
一开始我说楼主的代码太长了。
不用看代码呀，跟着时间输出走，不需要看代码。
既然题目是效率测试，直接看问题所在啊，重点在函数里，为什么第一次返回的时间如此长，我想弄清楚。希望再进来的人别花什么时间看代码了。
---------
楼主既然这么说了，我就说了说对于方法第一次执行的时候会快一点的问题。
原来最后的结论是楼主的测试代码有问题，我也不说什么了。
不过这个问题也让大家知道了，代码一定要分析清楚了，可能问题并不是我们所想象得那么复杂，可能就是由于我们的不细心。
以后有问题再一起讨论吧。
Top
18 楼cyicecream（为了升仙（星）到处UP）回复于 2005-05-25 09:57:58 得分 0
呵呵，对不起，我道歉，是我的错误。不过你的回答也让我知道了这个说法的不正确，你本人也知道不是这个原因，发贴的主旨在于学习知识。：）Top
相关问题
关键词
得分解答快速导航
相关链接
广告也精彩
反馈
