Trafodion 查看详细编译时间

数据库的SQL语句的执行主要分为编译+执行两个动作，编译包括binder、parser、Transformer、Normalizer等具体步骤。

一个SQL语句的执行时间是编译时间+执行时间一体的。对于大数据量的表扫描或者是大表关联的场景，一般执行时间是比较长的，编译时间相对就短的很多了，但对OLTP类的语句，因为大部分属于按主键按索引的精确查询，执行时间是非常短暂的，可能大多是毫秒级别，这种场景下编译的时间则会放大。可能在有些场景下，编译时间比执行时间更长。此时SQL的调优不仅涉及到执行时间的调优，更涉及到编译时间的调优。

既然编译包括binder、parser、Transformer、Normalizer等具体步骤，那么整体的编译时间也由这几部分的编译时间组成，这就让我们不禁想到能否有一种机制可以看到编译每个阶段的执行耗时呢？

幸运的是, Trafodion正好有这样的方法，我们通过以下方法查看SQL的详细编译时间，

sqlci ->
cqd COMPILE_TIME_MONITOR 'ON';
cqd COMPILE_TIME_MONITOR_OUTPUT_FILE 'cmptime1.log';
prepare s from <sql-text>;

上述执行完后会在当前目录下面生成comtime1.log文件，里面有编译每个步骤的执行耗时，下面是一个样例文件的输出，

。。。
--------------------------------------------
Query :
----------------
        Optimization Passes: Time = 0.03 us (microsecond)       ET = 0.00604415 s       Counts = 2      GoodCnts = 2
        Optimize Group Task: Time = 0 us (microsecond)  ET = 9.05991e-06 s      Counts = 102    GoodCnts = 0
        Optimize Expr Task : Time = 0 us (microsecond)  ET = 7.86781e-06 s      Counts = 98     GoodCnts = 0
        Apply Rule Task    : Time = 0.02 us (microsecond)       ET = 1.09673e-05 s      Counts = 99     GoodCnts = 2
        Create Plan Task   : Time = 0.01 us (microsecond)       ET = 1.5974e-05 s       Counts = 292    GoodCnts = 1
        Explore Group Task : Time = 0 us (microsecond)  ET = 6.91414e-06 s      Counts = 1      GoodCnts = 0
        Explore Expr Task  : Time = 0 us (microsecond)  ET = 2.5034e-05 s       Counts = 1      GoodCnts = 0
        Gbg Collection Task: Time = 0 us (microsecond)  ET = 0 s        Counts = 0      GoodCnts = 0

        FileScanOptimizer  : Time = 0 us (microsecond)  ET = 0 s        Counts = 0      GoodCnts = 0
        Compiler all: Time = 6.12 us (microsecond)      ET = 4.06522 s  Counts = 1      GoodCnts = 1
        Sqlcomp time: Time = 6.12 us (microsecond)      ET = 4.06277 s  Counts = 1      GoodCnts = 1
        Parser      : Time = 0 us (microsecond) ET = 0.00229001 s       Counts = 1      GoodCnts = 0
        Binder      : Time = 5.32 us (microsecond)      ET = 3.60115 s  Counts = 1      GoodCnts = 1
        Transformer : Time = 0.01 us (microsecond)      ET = 0.013952 s         Counts = 1      GoodCnts = 1
        Normalizer  : Time = 0.53 us (microsecond)      ET = 0.31823 s  Counts = 1      GoodCnts = 1
        SemanticQOpt: Time = 0 us (microsecond) ET = 3.00407e-05 s      Counts = 1      GoodCnts = 0
        Analyzer    : Time = 0.05 us (microsecond)      ET = 0.016124 s         Counts = 1      GoodCnts = 1
        Pilot Phase : Time = 0 us (microsecond) ET = 0.000398159 s      Counts = 1      GoodCnts = 0
        JBB Setup   : Time = 0 us (microsecond) ET = 3.91006e-05 s      Counts = 1      GoodCnts = 0
        SynthLogProp: Time = 0 us (microsecond) ET = 0 s        Counts = 0      GoodCnts = 0
        ASM Precomp : Time = 0 us (microsecond) ET = 0 s        Counts = 0      GoodCnts = 0
        Query Graph : Time = 0 us (microsecond) ET = 0 s        Counts = 0      GoodCnts = 0
        Optimizer   : Time = 0.04 us (microsecond)      ET = 0.0225661 s        Counts = 1      GoodCnts = 1
        PreCodeGen  : Time = 0.02 us (microsecond)      ET = 0.00574398 s       Counts = 1      GoodCnts = 1
        Generator   : Time = 0.15 us (microsecond)      ET = 0.0825791 s        Counts = 1      GoodCnts = 1
        Comp Cleanup: Time = 0 us (microsecond) ET = 9.05991e-06 s      Counts = 1      GoodCnts = 0
        NodeMap     : Time = 0 us (microsecond) ET = 0 s        Counts = 0      GoodCnts = 0
--------------------------------------------
。。。