@@ -53,6 +53,8 @@ public class CompiletimeFunctionRunner {
5353 private boolean injectObjects ;
5454 private final Deque <Runnable > delayedActions = new ArrayDeque <>();
5555 private final Map <ClassManagementVars , List <CompiletimeObjectInit >> compiletimeObjects = new LinkedHashMap <>();
56+ private final Map <String , Long > compiletimeFunctionNanos = new LinkedHashMap <>();
57+ private long compiletimeExprNanos = 0L ;
5658
5759 public ILInterpreter getInterpreter () {
5860 return interpreter ;
@@ -99,22 +101,30 @@ public CompiletimeFunctionRunner(
99101
100102 public void run () {
101103 try {
104+ long t0 = System .nanoTime ();
102105 List <Either <ImCompiletimeExpr , ImFunction >> toExecute = new ArrayList <>();
103106 collectCompiletimeExpressions (toExecute );
104107 collectCompiletimeFunctions (toExecute );
108+ long tCollected = System .nanoTime ();
105109
106110 toExecute .sort (Comparator .comparing (this ::getOrderIndex ));
111+ long tSorted = System .nanoTime ();
107112
108113 execute (toExecute );
114+ long tExecuted = System .nanoTime ();
109115
110116
111117 if (functionFlag == FunctionFlagToRun .CompiletimeFunctions ) {
112118 interpreter .writebackGlobalState (isInjectObjects ());
113119 }
120+ long tWriteback = System .nanoTime ();
114121 runDelayedActions ();
115122 emitCompiletimeObjectAllocs ();
123+ long tDelayed = System .nanoTime ();
116124
117125 partitionCompiletimeStateInitFunction ();
126+ long tPartitioned = System .nanoTime ();
127+ logCompiletimeTiming (toExecute , t0 , tCollected , tSorted , tExecuted , tWriteback , tDelayed , tPartitioned );
118128
119129 } catch (InterpreterException e ) {
120130 Element origin = e .getTrace ();
@@ -139,6 +149,48 @@ public void run() {
139149
140150 }
141151
152+ private void logCompiletimeTiming (List <Either <ImCompiletimeExpr , ImFunction >> toExecute ,
153+ long t0 , long tCollected , long tSorted , long tExecuted ,
154+ long tWriteback , long tDelayed , long tPartitioned ) {
155+ int exprCount = 0 ;
156+ int funcCount = 0 ;
157+ for (Either <ImCompiletimeExpr , ImFunction > e : toExecute ) {
158+ if (e .isLeft ()) {
159+ exprCount ++;
160+ } else {
161+ funcCount ++;
162+ }
163+ }
164+ WLogger .info (String .format (
165+ "Compiletime breakdown: total=%dms collect=%dms sort=%dms execute=%dms writeback=%dms delayed=%dms partition=%dms funcs=%d exprs=%d exprEval=%dms" ,
166+ ms (tPartitioned - t0 ),
167+ ms (tCollected - t0 ),
168+ ms (tSorted - tCollected ),
169+ ms (tExecuted - tSorted ),
170+ ms (tWriteback - tExecuted ),
171+ ms (tDelayed - tWriteback ),
172+ ms (tPartitioned - tDelayed ),
173+ funcCount ,
174+ exprCount ,
175+ ms (compiletimeExprNanos )
176+ ));
177+ if (!compiletimeFunctionNanos .isEmpty ()) {
178+ List <Map .Entry <String , Long >> top = compiletimeFunctionNanos .entrySet ().stream ()
179+ .sorted ((a , b ) -> Long .compare (b .getValue (), a .getValue ()))
180+ .limit (10 )
181+ .collect (Collectors .toList ());
182+ StringBuilder sb = new StringBuilder ("Top compiletime functions:" );
183+ for (Map .Entry <String , Long > e : top ) {
184+ sb .append ("\n " ).append (e .getKey ()).append (": " ).append (ms (e .getValue ())).append ("ms" );
185+ }
186+ WLogger .info (sb .toString ());
187+ }
188+ }
189+
190+ private static long ms (long nanos ) {
191+ return nanos / 1_000_000L ;
192+ }
193+
142194 private void partitionCompiletimeStateInitFunction () {
143195 if (compiletimeStateInitFunction == null ) {
144196 return ;
@@ -223,6 +275,7 @@ public void visit(ImCompiletimeExpr e) {
223275
224276
225277 private void executeCompiletimeExpr (ImCompiletimeExpr cte ) {
278+ long t0 = System .nanoTime ();
226279 try {
227280 ProgramState globalState = interpreter .getGlobalState ();
228281 globalState .setLastStatement (cte );
@@ -264,6 +317,8 @@ private void executeCompiletimeExpr(ImCompiletimeExpr cte) {
264317 e .setStacktrace (msg );
265318 e .setTrace (cte .attrTrace ());
266319 throw e ;
320+ } finally {
321+ compiletimeExprNanos += System .nanoTime () - t0 ;
267322 }
268323 }
269324
@@ -555,11 +610,12 @@ private ImFunction findNative(String funcName, WPos trace) {
555610
556611 private void executeCompiletimeFunction (ImFunction f ) {
557612 if (functionFlag .matches (f )) {
613+ long t0 = System .nanoTime ();
558614 try {
559615 if (!f .getBody ().isEmpty ()) {
560616 interpreter .getGlobalState ().setLastStatement (f .getBody ().get (0 ));
561617 }
562- WLogger .debug ( "running " + functionFlag + " function " + f .getName ());
618+ WLogger .trace (() -> "running " + functionFlag + " function " + f .getName ());
563619 interpreter .runVoidFunc (f , null );
564620 successTests .add (f );
565621 } catch (TestSuccessException e ) {
@@ -569,6 +625,8 @@ private void executeCompiletimeFunction(ImFunction f) {
569625 } catch (Throwable e ) {
570626 failTests .put (f , Pair .create (interpreter .getLastStatement (), e .toString ()));
571627 throw e ;
628+ } finally {
629+ compiletimeFunctionNanos .merge (f .getName (), System .nanoTime () - t0 , Long ::sum );
572630 }
573631 }
574632 }
0 commit comments