关于效率测试的一个疑问，欢迎讨论

Question

这个问题从上班的地方带回家，一个晚上还是不能解决。有一些细节部分不清楚，上来问问，请指教。我尽量把问题最小化，代码能够描述清楚状况就可以了。
    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;
    }

Answer 1

这是一个激活代码，至于细节可以不必追究，我花了点时间做了些效率测试，发现在整个时间花费，几乎都
在这个函数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在第一次做了些什么？？找不到合适的说法，超出我目前所知道的知识范围，
请知道的人解释一下，谢谢。看贴请留下脚印:)

Answer 2

你的问题其实就是为什么一个方法第一次执行的时候会耗时多一点。
其实这有两方面因素：
1。一个方法第一次被调用的时候会首先申请一些必要空间，注册一些堆栈信息，这个必然需要一些时间。
2。你紧接着一直调用它，那么在内存中的很多数据就得到了复用，那么速度自然会快。
因为jvm是采用垃圾回收的，那么方法执行完了之后有写没用的对象就已经符合垃圾回收的条件了，但是垃圾回收不是立即就能执行的，所以那些对象就还驻留在内存中。第二次调用方法这些对象就不需要再次创建就可以直接使用内存的原来的数据了。这是我的理解，可能有些地方不太对，欢迎大家讨论。

Answer 3

我也觉得楼上说的有道理，所以我又做了一次测试，这次在函数里放了比多的执行程序，整个内存的开销也占据一定的空间。但是当我执行完后还是找不到正确的解释：（
    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:191time:0
执行了191次，时间还为0。怎么CPU的执行那么快？用不到几毫秒时间吗？
这个测试环境我已经尽量的模仿了原题的效果。
1。一个方法第一次被调用的时候会首先申请一些必要空间，注册一些堆栈信息，这个必然需要一些时间。
-----------------------------------------------------------------------
JVM分配空间需要时间，这里体现不出来，而且执行了很多遍也是这个结果。
只有继续等待下面的回复了

Answer 4

楼主，你仔细看看这一段///////////////////////////////////////////////////////////////
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()这个方法比较耗时呢?

Answer 5

我认为  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
===============

Answer 6

上面是执行一次的执行结果,每次的执行结果都不一样,这个要看当时的JVM是如果管理的了.

Answer 7

to  lei8766(lei8766) 
我的打印出来的全是0，呵呵另外，WindowsNT内核下Timer的分辨率为10毫秒，这个测试不能说明问题，找个CPU负载大点例子看看to 楼主
你用过JProbe或者OptimizeIt没有？你用这些工具试一下，可以找出你的性能瓶颈

Answer 8

----------------------------------------------------------------------------------------
1。一个方法第一次被调用的时候会首先申请一些必要空间，注册一些堆栈信息，这个必然需要一些时间。
2。你紧接着一直调用它，那么在内存中的很多数据就得到了复用，那么速度自然会快。
因为jvm是采用垃圾回收的，那么方法执行完了之后有写没用的对象就已经符合垃圾回收的条件了，但是垃圾回收不是立即就能执行的，所以那些对象就还驻留在内存中。第二次调用方法这些对象就不需要再次创建就可以直接使用内存的原来的数据了
-----------------------------------------------------------------------------------------
gtlang78() ( ) 的结论是对的，是我的想当然导致的结果，不过这个想当然让我知道对于1。所花的时间不需要太多，在大多数情况下。JVM使用的是执行期动态分配空间；
Repository repository = RepositoryFactory.newInstance();
Repository 是个单实例，第一次初始化时确实需要花费200-300毫秒的时间，以后就不需要花费时间了。直接返回实例，因此就出现了第一次时间差为什么那么大。这个错误的出现是我认为非第一次初始化，所以可以忽略这个时间，导致的错误。不过这次讨论收获不小，谢谢gtlang78() ( ) ，jFresH_MaN(听说距离产生美，所以我将离开你！) ( ) 。
虽然jFresH_MaN 说的看起来有道理，不过还是得动手测试得出结论，我得出的结论是jFresH_MaN所说的不太正确，从测试结果看基本没什么影响。这是个人所见，有错误希望指出。