Runmap & performance improvements

de.peeeq.wurstscript/build.gradle

@@ -106,7 +106,7 @@ dependencies {
     implementation 'commons-lang:commons-lang:2.6'
     implementation 'com.github.albfernandez:juniversalchardet:2.4.0'
     implementation 'com.github.inwc3:jmpq3:29b55f2c32'
-    implementation 'com.github.inwc3:wc3libs:bab65b961b'
+    implementation 'com.github.inwc3:wc3libs:cc49c8e63c'
     implementation('com.github.wurstscript:wurstsetup:393cf5ea39') {
         exclude group: 'org.eclipse.jgit', module: 'org.eclipse.jgit'
         exclude group: 'org.eclipse.jgit', module: 'org.eclipse.jgit.ssh.apache'

de.peeeq.wurstscript/src/main/java/de/peeeq/wurstio/CompiletimeFunctionRunner.java

@@ -51,6 +51,8 @@ public class CompiletimeFunctionRunner {
     private final ImTranslator translator;
     private boolean injectObjects;
     private final Deque<Runnable> delayedActions = new ArrayDeque<>();
+    private final Map<String, Long> compiletimeFunctionNanos = new LinkedHashMap<>();
+    private long compiletimeExprNanos = 0L;
 
     public ILInterpreter getInterpreter() {
         return interpreter;
@@ -97,21 +99,29 @@ public CompiletimeFunctionRunner(
 
     public void run() {
         try {
+            long t0 = System.nanoTime();
             List<Either<ImCompiletimeExpr, ImFunction>> toExecute = new ArrayList<>();
             collectCompiletimeExpressions(toExecute);
             collectCompiletimeFunctions(toExecute);
+            long tCollected = System.nanoTime();
 
             toExecute.sort(Comparator.comparing(this::getOrderIndex));
+            long tSorted = System.nanoTime();
 
             execute(toExecute);
+            long tExecuted = System.nanoTime();
 
 
             if (functionFlag == FunctionFlagToRun.CompiletimeFunctions) {
                 interpreter.writebackGlobalState(isInjectObjects());
             }
+            long tWriteback = System.nanoTime();
             runDelayedActions();
+            long tDelayed = System.nanoTime();
 
             partitionCompiletimeStateInitFunction();
+            long tPartitioned = System.nanoTime();
+            logCompiletimeTiming(toExecute, t0, tCollected, tSorted, tExecuted, tWriteback, tDelayed, tPartitioned);
 
         } catch (InterpreterException e) {
             Element origin = e.getTrace();
@@ -136,6 +146,48 @@ public void run() {
 
     }
 
+    private void logCompiletimeTiming(List<Either<ImCompiletimeExpr, ImFunction>> toExecute,
+                                      long t0, long tCollected, long tSorted, long tExecuted,
+                                      long tWriteback, long tDelayed, long tPartitioned) {
+        int exprCount = 0;
+        int funcCount = 0;
+        for (Either<ImCompiletimeExpr, ImFunction> e : toExecute) {
+            if (e.isLeft()) {
+                exprCount++;
+            } else {
+                funcCount++;
+            }
+        }
+        WLogger.info(String.format(
+            "Compiletime breakdown: total=%dms collect=%dms sort=%dms execute=%dms writeback=%dms delayed=%dms partition=%dms funcs=%d exprs=%d exprEval=%dms",
+            ms(tPartitioned - t0),
+            ms(tCollected - t0),
+            ms(tSorted - tCollected),
+            ms(tExecuted - tSorted),
+            ms(tWriteback - tExecuted),
+            ms(tDelayed - tWriteback),
+            ms(tPartitioned - tDelayed),
+            funcCount,
+            exprCount,
+            ms(compiletimeExprNanos)
+        ));
+        if (!compiletimeFunctionNanos.isEmpty()) {
+            List<Map.Entry<String, Long>> top = compiletimeFunctionNanos.entrySet().stream()
+                .sorted((a, b) -> Long.compare(b.getValue(), a.getValue()))
+                .limit(10)
+                .collect(Collectors.toList());
+            StringBuilder sb = new StringBuilder("Top compiletime functions:");
+            for (Map.Entry<String, Long> e : top) {
+                sb.append("\n  ").append(e.getKey()).append(": ").append(ms(e.getValue())).append("ms");
+            }
+            WLogger.info(sb.toString());
+        }
+    }
+
+    private static long ms(long nanos) {
+        return nanos / 1_000_000L;
+    }
+
     private void partitionCompiletimeStateInitFunction() {
         if (compiletimeStateInitFunction == null) {
             return;
@@ -220,6 +272,7 @@ public void visit(ImCompiletimeExpr e) {
 
 
     private void executeCompiletimeExpr(ImCompiletimeExpr cte) {
+        long t0 = System.nanoTime();
         try {
             ProgramState globalState = interpreter.getGlobalState();
             globalState.setLastStatement(cte);
@@ -261,6 +314,8 @@ private void executeCompiletimeExpr(ImCompiletimeExpr cte) {
             e.setStacktrace(msg);
             e.setTrace(cte.attrTrace());
             throw e;
+        } finally {
+            compiletimeExprNanos += System.nanoTime() - t0;
         }
     }
 
@@ -491,11 +546,12 @@ private ImFunction findNative(String funcName, WPos trace) {
 
     private void executeCompiletimeFunction(ImFunction f) {
         if (functionFlag.matches(f)) {
+            long t0 = System.nanoTime();
             try {
                 if (!f.getBody().isEmpty()) {
                     interpreter.getGlobalState().setLastStatement(f.getBody().get(0));
                 }
-                WLogger.debug("running " + functionFlag + " function " + f.getName());
+                WLogger.trace(() -> "running " + functionFlag + " function " + f.getName());
                 interpreter.runVoidFunc(f, null);
                 successTests.add(f);
             } catch (TestSuccessException e) {
@@ -505,6 +561,8 @@ private void executeCompiletimeFunction(ImFunction f) {
             } catch (Throwable e) {
                 failTests.put(f, Pair.create(interpreter.getLastStatement(), e.toString()));
                 throw e;
+            } finally {
+                compiletimeFunctionNanos.merge(f.getName(), System.nanoTime() - t0, Long::sum);
             }
         }
     }

de.peeeq.wurstscript/src/main/java/de/peeeq/wurstio/WurstCompilerJassImpl.java

@@ -535,12 +535,14 @@ public JassProg transformProgToJass() {
         }
 
         beginPhase(13, "flatten");
-        optimizer.removeGarbage();
+        boolean garbageChanged = optimizer.removeGarbage();
         imProg.flatten(imTranslator);
 
         // Re-run to avoid #883
-        optimizer.removeGarbage();
-        imProg.flatten(imTranslator);
+        if (garbageChanged) {
+            optimizer.removeGarbage();
+            imProg.flatten(imTranslator);
+        }
 
         printDebugImProg("./test-output/im " + stage++ + "_afterremoveGarbage1.im");
         timeTaker.endPhase();
@@ -561,7 +563,7 @@ public JassProg transformProgToJass() {
         // translate flattened intermediate lang to jass:
 
         beginPhase(14, "translate to jass");
-        getImTranslator().calculateCallRelationsAndUsedVariables();
+        getImTranslator().calculateCallRelationsAndReadVariables();
         ImToJassTranslator translator =
             new ImToJassTranslator(getImProg(), getImTranslator().getCalledFunctions(), getImTranslator().getMainFunc(), getImTranslator().getConfFunc());
         prog = translator.translate();
@@ -952,12 +954,14 @@ public LuaCompilationUnit transformProgToLua() {
 
         printDebugImProg("./test-output/lua/im " + stage++ + "_afterlocalopts.im");
 
-        optimizer.removeGarbage();
+        boolean garbageChanged = optimizer.removeGarbage();
         imProg.flatten(imTranslator);
 
         // Re-run to avoid #883
-        optimizer.removeGarbage();
-        imProg.flatten(imTranslator);
+        if (garbageChanged) {
+            optimizer.removeGarbage();
+            imProg.flatten(imTranslator);
+        }
 
         printDebugImProg("./test-output/lua/im " + stage++ + "_afterremoveGarbage1.im");
 

de.peeeq.wurstscript/src/main/java/de/peeeq/wurstio/jassinterpreter/JassInterpreter.java

@@ -60,7 +60,7 @@ public static ILconst getDefaultValue(String type) {
 
     public ILconst executeFunction(String name, ILconst... arguments) {
         if (trace) {
-            WLogger.trace(name + "( " + Utils.join(arguments, ", ") + ")");
+            WLogger.trace(() -> name + "( " + Utils.join(arguments, ", ") + ")");
         }
 
         ExecutableJassFunction func = searchFunction(name);
@@ -99,13 +99,13 @@ ILconst executeJassFunction(JassFunction func, ILconst... arguments) {
             this.executeStatements(localVarMap, body);
         } catch (ReturnException e) {
             if (trace) {
-                WLogger.trace("end function " + func.getName() + " returns " + e.getVal());
+                WLogger.trace(() -> "end function " + func.getName() + " returns " + e.getVal());
             }
             return e.getVal();
         }
 
         if (trace) {
-            WLogger.trace("end function " + func.getName());
+            WLogger.trace(() -> "end function " + func.getName());
         }
         return null;
     }

de.peeeq.wurstscript/src/main/java/de/peeeq/wurstio/jassinterpreter/providers/ForceProvider.java

@@ -44,7 +44,6 @@ public void DestroyForce(IlConstHandle force) {
     public void ForForce(IlConstHandle force, ILconstFuncRef funcRef) {
         // TODO take force param into account
         // For now this simply executes the supplied function.
-        WLogger.trace("for force call");
         interpreter.runFuncRef(funcRef, null);
     }
 }

de.peeeq.wurstscript/src/main/java/de/peeeq/wurstio/jassinterpreter/providers/GroupProvider.java

@@ -52,11 +52,9 @@ public ILconst FirstOfGroup(IlConstHandle group) {
     }
 
     public void ForGroup(IlConstHandle group, ILconstFuncRef funcRef) {
-        WLogger.trace("for group call");
         LinkedHashSet<IlConstHandle> groupList = (LinkedHashSet<IlConstHandle>) group.getObj();
         groupList.forEach((IlConstHandle u) -> {
             enumUnitStack.push(u);
-            WLogger.trace("for group call itr: " + funcRef.getFuncName());
             interpreter.runFuncRef(funcRef, null);
             enumUnitStack.pop();
         });

de.peeeq.wurstscript/src/main/java/de/peeeq/wurstio/languageserver/ConfigProvider.java

@@ -143,7 +143,7 @@ private void refreshCacheAsync() {
                 }
             })
             .exceptionally(e -> {
-                WLogger.trace("Background config refresh failed (this is normal if client is busy): " + e.getMessage());
+                WLogger.trace(() -> "Background config refresh failed (this is normal if client is busy): " + e.getMessage());
                 return null;
             });
     }

de.peeeq.wurstscript/src/main/java/de/peeeq/wurstio/languageserver/ModelManagerImpl.java

@@ -87,25 +87,30 @@ private List<CompilationUnit> getJassdocCUs(Path jassdoc, WurstGui gui) {
 
     @Override
     public Changes removeCompilationUnit(WFile resource) {
-        parseErrors.remove(resource);
         WurstModel model2 = model;
-        if (model2 == null) {
-            return Changes.empty();
-        }
-
-        syncCompilationUnitContent(resource, "");
         List<CompilationUnit> toRemove = new ArrayList<>();
-        for (CompilationUnit compilationUnit : model2) {
-            if (wFile(compilationUnit).equals(resource)) {
-                toRemove.add(compilationUnit);
+        if (model2 != null) {
+            for (CompilationUnit compilationUnit : model2) {
+                if (wFile(compilationUnit).equals(resource)) {
+                    toRemove.add(compilationUnit);
+                }
             }
+            model2.removeAll(toRemove);
         }
-        model2.removeAll(toRemove);
-        return new Changes(toRemove.stream()
-            .map(this::wFile),
+
+        // Always clear state and diagnostics for removed files.
+        clearFileState(resource);
+        reportErrors("remove cu ", resource, Collections.emptyList());
+
+        toRemove.forEach(compilationunitFile::remove);
+
+        return new Changes(
+            java.util.Collections.singletonList(resource),
             toRemove.stream()
                 .flatMap(cu -> cu.getPackages().stream())
-                .map(WPackage::getName));
+                .map(WPackage::getName)
+                .collect(Collectors.toList())
+        );
     }
 
     @Override
@@ -165,7 +170,7 @@ private File[] getFiles(File dir) {
     }
 
     private void processWurstFile(WFile f) {
-        WLogger.info("processing file " + f);
+        WLogger.debug("processing file " + f);
         replaceCompilationUnit(f);
     }
 
@@ -366,7 +371,6 @@ private WurstCompilerJassImpl getCompiler(WurstGui gui) {
     }
 
     private void updateModel(CompilationUnit cu, WurstGui gui) {
-        WLogger.trace("update model with " + cu.getCuInfo().getFile());
         parseErrors.put(wFile(cu), new ArrayList<>(gui.getErrorsAndWarnings()));
 
         WurstModel model2 = model;
@@ -526,15 +530,20 @@ private CompilationUnit replaceCompilationUnit(WFile filename, String contents,
         if (fileHashcodes.containsKey(filename)) {
             int oldHash = fileHashcodes.get(filename);
             if (oldHash == contents.hashCode()) {
-                // no change
-                WLogger.trace("CU " + filename + " was unchanged.");
-                return getCompilationUnit(filename);
+                CompilationUnit existing = getCompilationUnit(filename);
+                if (existing != null) {
+                    // no change
+                    WLogger.trace(() -> "CU " + filename + " was unchanged.");
+                    return existing;
+                }
+                // Stale hash cache after remove/move; CU is gone, so reparse.
+                WLogger.info("CU hash unchanged but model entry missing for " + filename + ", reparsing.");
             } else {
                 WLogger.info("CU changed. oldHash = " + oldHash + " == " + contents.hashCode());
             }
         }
 
-        WLogger.trace("replace CU " + filename);
+        WLogger.trace(() -> "replace CU " + filename);
         WurstGui gui = new WurstGuiLogger();
         WurstCompilerJassImpl c = getCompiler(gui);
         CompilationUnit cu = c.parse(filename.toString(), new StringReader(contents));
@@ -557,6 +566,12 @@ private CompilationUnit replaceCompilationUnit(WFile filename, String contents,
         return cu;
     }
 
+    private void clearFileState(WFile file) {
+        parseErrors.remove(file);
+        otherErrors.remove(file);
+        fileHashcodes.remove(file);
+    }
+
     @Override
     public CompilationUnit getCompilationUnit(WFile filename) {
         List<CompilationUnit> matches = getCompilationUnits(Collections.singletonList(filename));

de.peeeq.wurstscript/src/main/java/de/peeeq/wurstio/languageserver/requests/BuildMap.java

@@ -61,17 +61,28 @@ public Object execute(ModelManager modelManager) throws IOException {
             // first we copy in same location to ensure validity
             File buildDir = getBuildDir();
             String fileName = projectConfig.getBuildMapData().getFileName();
-            Optional<File> targetMap = Optional.of(
-                new File(buildDir, fileName.isEmpty() ? projectConfig.getProjectName() + ".w3x" : fileName + ".w3x"));
-            CompilationResult result = compileScript(modelManager, gui, targetMap, projectConfig, buildDir, true);
-
-            injectMapData(gui, targetMap, result);
-
-            Files.copy(getCachedMapFile().toPath(), targetMap.get().toPath(), java.nio.file.StandardCopyOption.REPLACE_EXISTING);
+            File targetMapFile = new File(buildDir, fileName.isEmpty() ? projectConfig.getProjectName() + ".w3x" : fileName + ".w3x");
+            targetMapFile = ensureWritableTargetFile(
+                targetMapFile,
+                "Build Map",
+                "The output map file is in use and cannot be replaced.\nClose Warcraft III and click Retry, choose Rename to use a temporary file name, or Cancel.",
+                "Build canceled because output map target is in use."
+            );
+            CompilationResult result = compileScript(modelManager, gui, Optional.of(targetMapFile), projectConfig, buildDir, true);
+
+            injectMapData(gui, Optional.of(targetMapFile), result);
+
+            targetMapFile = ensureWritableTargetFile(
+                targetMapFile,
+                "Build Map",
+                "The output map file is still in use and cannot be replaced.\nClick Retry, choose Rename to use a temporary file name, or Cancel.",
+                "Build canceled because output map target is in use."
+            );
+            Files.copy(getCachedMapFile().toPath(), targetMapFile.toPath(), java.nio.file.StandardCopyOption.REPLACE_EXISTING);
 
             gui.sendProgress("Finalizing map");
 
-            try (MpqEditor mpq = MpqEditorFactory.getEditor(targetMap)) {
+            try (MpqEditor mpq = MpqEditorFactory.getEditor(Optional.of(targetMapFile))) {
                 if (mpq != null) {
                     mpq.closeWithCompression();
                 }