how to measure calc time from logs
I all,I'm investigating on calculation time looking into user logs file.
For example:
<I 2012Oct09 15:40:44.443> Calculating WPMLEuBy = WPVndPrpNtEuBy - WPVndCstEuEs
<D 2012Oct09 15:40:44.443> EvalLoopHelper::initIter (wpmleuby%1)
<D 2012Oct09 15:40:44.445> EvalLoopHelper::initIter (wpvndprpnteuby%1)
<D 2012Oct09 15:40:44.445> Initializing expression iterator "wpvndprpnteuby%1": priority 0
<D 2012Oct09 15:40:44.445> 55.% populated (941297 / 1709568 cells); navalue = [0.]; dimension space: DimSpace(sku:11872, negz:144, info:1)
<D 2012Oct09 15:40:44.446> EvalLoopHelper::initIter (wpvndcsteues%1)
<D 2012Oct09 15:40:44.446> Initializing expression iterator "wpvndcsteues%1": priority 0
<D 2012Oct09 15:40:44.448> 55.% populated (941101 / 1709568 cells); navalue = [0.]; dimension space: DimSpace(sku:11872, negz:144, info:1)
<D 2012Oct09 15:40:44.448> .
<D 2012Oct09 15:40:44.513> 15 cells evaluated.
<P 2012Oct09 15:40:44.522>
<P 2012Oct09 15:40:44.522> =========================================================
<P 2012Oct09 15:40:44.522> TSI:2 0.080364 seconds for Expression::evalIncremental
<P 2012Oct09 15:40:44.522> =========================================================
from 15:40:44.443 to 15:40:44.513 (where log writes 15 cells evaluated.) are 0.070 seconds
For example:
<I 2012Oct09 15:40:44.443> Calculating WPMLEuBy = WPVndPrpNtEuBy - WPVndCstEuEs
<D 2012Oct09 15:40:44.443> EvalLoopHelper::initIter (wpmleuby%1)
<D 2012Oct09 15:40:44.445> EvalLoopHelper::initIter (wpvndprpnteuby%1)
<D 2012Oct09 15:40:44.445> Initializing expression iterator "wpvndprpnteuby%1": priority 0
<D 2012Oct09 15:40:44.445> 55.% populated (941297 / 1709568 cells); navalue = [0.]; dimension space: DimSpace(sku:11872, negz:144, info:1)
<D 2012Oct09 15:40:44.446> EvalLoopHelper::initIter (wpvndcsteues%1)
<D 2012Oct09 15:40:44.446> Initializing expression iterator "wpvndcsteues%1": priority 0
<D 2012Oct09 15:40:44.448> 55.% populated (941101 / 1709568 cells); navalue = [0.]; dimension space: DimSpace(sku:11872, negz:144, info:1)
<D 2012Oct09 15:40:44.448> .
<D 2012Oct09 15:40:44.513> 15 cells evaluated.
<P 2012Oct09 15:40:44.522>
<P 2012Oct09 15:40:44.522> =========================================================
<P 2012Oct09 15:40:44.522> TSI:2 0.080364 seconds for Expression::evalIncremental
<P 2012Oct09 15:40:44.522> =========================================================
from 15:40:44.443 to 15:40:44.513 (where log writes 15 cells evaluated.) are 0.070 seconds
0