UpsertVisualizationJob slowed down by findModuleByExpressionId

[JaroslavTulach]

While investigating DetachVisualisationHandler request timeout I collected collapse.zip profiling data. Looks like org.enso.interpreter.instrument.job.UpsertVisualisationJob$.invalidateCaches() is slowed down quite significantly by many calls to org.enso.interpreter.runtime.EnsoContext.findModuleByExpressionId().

More efficient implementation is needed. Probably we shall not traverse the the same IR again and again to find the different IDs.

[JaroslavTulach]

Using the Colorado COVID example and instructions as provided by @farmaazon and by modifying the findModuleByExpressionId function to measure its time:

enso$ git diff
diff --git engine/runtime/src/main/java/org/enso/interpreter/runtime/EnsoContext.java engine/runtime/src/main/java/org/enso/interpreter/runtime/EnsoContext.java
index 357b5eb1b..561e3dab4 100644
--- engine/runtime/src/main/java/org/enso/interpreter/runtime/EnsoContext.java
+++ engine/runtime/src/main/java/org/enso/interpreter/runtime/EnsoContext.java
@@ -336,7 +336,8 @@ public class EnsoContext {
    * @return the relevant module, if exists.
    */
   public Optional<Module> findModuleByExpressionId(UUID expressionId) {
-    return getTopScope().getModules().stream()
+    var then = System.currentTimeMillis();
+    var r = getTopScope().getModules().stream()
         .filter(
             module ->
                 module.getIr() != null
@@ -345,6 +346,9 @@ public class EnsoContext {
                         .preorder()
                         .exists(ir -> ir.getExternalId().contains(expressionId)))
         .findFirst();
+    var took = System.currentTimeMillis() - then;
+    System.err.printf("findModuleByExpressionId %s yields %s took %d ms\n", expressionId, r, took);
+    return r;
   }
 
   /**

and see following results:

findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 67 ms
findModuleByExpressionId 66f6cdfe-5ed0-4ca8-b969-22969bcb2919 yields Optional[Module[local.Colorado_COVID.Main]] took 139 ms
findModuleByExpressionId a9e5f782-a384-406b-964a-e2a3663864c6 yields Optional[Module[local.Colorado_COVID.Main]] took 47 ms
findModuleByExpressionId afa84f37-3527-472e-b397-61341fd140e9 yields Optional[Module[local.Colorado_COVID.Main]] took 65 ms
findModuleByExpressionId 75c48d81-3d23-4776-9fe9-dcbd90d7afcf yields Optional[Module[local.Colorado_COVID.Main]] took 52 ms
findModuleByExpressionId 2c3abd7d-b737-4eac-8273-b6b5344ce2d1 yields Optional[Module[local.Colorado_COVID.Main]] took 71 ms
findModuleByExpressionId ee92bdac-a0b7-4835-abac-2ede39f4c4e1 yields Optional[Module[local.Colorado_COVID.Main]] took 61 ms
findModuleByExpressionId a30b2105-5002-47d1-a647-9bbbcedcecfb yields Optional[Module[local.Colorado_COVID.Main]] took 70 ms
[warn] [2023-03-06T14:22:23.818Z] [enso] Execution of function main interrupted.
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 41 ms
findModuleByExpressionId 029ed6ec-bdd6-4e9c-8e65-73a1d811dad3 yields Optional[Module[local.Colorado_COVID.Main]] took 46 ms
findModuleByExpressionId b616460a-546f-4070-9478-918db43818c5 yields Optional[Module[local.Colorado_COVID.Main]] took 45 ms
findModuleByExpressionId 16d6ebe2-3e44-4457-8151-11f79fe97e76 yields Optional[Module[local.Colorado_COVID.Main]] took 54 ms
findModuleByExpressionId 62aef953-af1a-45a7-890c-c56114a70084 yields Optional[Module[local.Colorado_COVID.Main]] took 41 ms
findModuleByExpressionId f6a88311-d994-40de-a72f-894b83398d67 yields Optional[Module[local.Colorado_COVID.Main]] took 40 ms
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 46 ms
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 36 ms
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 43 ms
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 32 ms
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 31 ms
findModuleByExpressionId cbb4d51f-8499-4b37-82ef-9920558b0b03 yields Optional[Module[local.Colorado_COVID.Main]] took 50 ms
findModuleByExpressionId cf2f837b-8273-4e1d-b9f3-69ff41de713f yields Optional[Module[local.Colorado_COVID.Main]] took 52 ms
findModuleByExpressionId 5af97e7c-2779-46e2-acd1-6576d1bfb8bc yields Optional[Module[local.Colorado_COVID.Main]] took 45 ms
findModuleByExpressionId 42fcc17d-d678-494f-a2b0-490fbc2a06d8 yields Optional[Module[local.Colorado_COVID.Main]] took 31 ms
findModuleByExpressionId 0e2be309-48d3-4f5f-a64b-c4ab7675077b yields Optional[Module[local.Colorado_COVID.Main]] took 31 ms
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 28 ms
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 41 ms
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 27 ms
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 28 ms
findModuleByExpressionId 2616180b-1526-4fd0-9761-b0491944c201 yields Optional[Module[local.Colorado_COVID.Main]] took 35 ms

I'd say *even single invocation of the function is slow. The function is invoked many times for the same value.

[enso-bot]

Jaroslav Tulach reports a new STANDUP for yesterday (2023-03-15):

Progress: - UpsertVisualizationJob slowed down by findModuleByExpressionId fixed by #5945
- More work on avoiding UUIDs: 165ce1d
- standup, talk with James
- talk with Marcin: move more info into BingingsMap
- talking with Pavel - sort & co.
- Started work on Meta.Type.constructors: #5956 It should be finished by 2023-03-16.

Next Day: Continue investigating 48MB .ir format. Finalize Meta.Type.constructors.