Performance when starting a new instance of a script engine

[DoctorGester]

Hi,

We have a game server running multiple instances of a game with code in javascript. The current code takes about 2 seconds to start executing scripts on my M1 Pro. In an actual production container it takes even longer.

The code looks something like this:

        instance.log.Information("Instantiating script engine");

        engine = new V8ScriptEngine(flags);
        instance.log.Information("Loading script...");
        
        engine.DocumentSettings.AccessFlags = DocumentAccessFlags.EnableFileLoading;
        engine.DocumentSettings.LoadCallback = (ref DocumentInfo info) => {
            info.SourceMapUri = new Uri(info.Uri.AbsolutePath + ".map");
        };
        engine.DocumentSettings.Loader = documentLoader;
        instance.log.Information("...Loading extensions");
        V8TextSupport.Extend(engine);
        instance.log.Information("...Adding host types");
        engine.AddHostType(typeof(ScriptGameConfiguration));
        engine.AddHostType(typeof(ScriptPlayer));
        engine.AddHostType(typeof(GlobalScript));
        engine.AddHostObject(nameof(GameScript), this);

        instance.log.Information("...Executing modules");
        engine.ExecuteDocument("scripts/compat/misc.js");
        engine.ExecuteDocument("scripts/compat/entity.js");
        engine.ExecuteDocument("scripts/compat/abilities.js");
        engine.ExecuteDocument("scripts/compat/game_rules.js");
        engine.ExecuteDocument("scripts/compat/modifier.js");
        engine.ExecuteDocument("scripts/compat/particles.js");
        engine.ExecuteDocument("scripts/compat/player.js");
        engine.ExecuteDocument("scripts/index.js", ModuleCategory.Standard);
        
        instance.log.Information("...Script loaded");

and the resulting log looks something like this

[20:54:29.116] [INF] (4) Instantiating script engine
[20:54:29.545] [INF] (4) Script engine loaded with 205 files
[20:54:29.547] [INF] (4) Loading script...
[20:54:29.548] [INF] (4) ...Loading extensions
[20:54:29.550] [INF] (4) ...Adding host types
[20:54:29.597] [INF] (4) ...Executing modules
[20:54:30.982] [INF] (4) Starting match with id 71679477

So new V8ScriptEngine takes about 300ms give or take (there is other minor work happening to set up a custom import resolver), then adding host types is about 50ms, which is fine, but then actual script loading and initial execution takes 1500ms more. That last part is what is bothering me.

sloc reports 36590 lines of code which is not "a lot" by V8 standards, I definitely don't expected it to compile code as slowly as at 25000 LoC/s. I have tried adding a compiled code cache in my custom loader, like this:

   private class ImportMapLoader : DefaultDocumentLoader {
        private readonly V8ScriptEngine engine;
        private readonly Dictionary<string, Dictionary<string, string>> pathToImportToFile;
        private readonly HashSet<string> compiledCode = new();
        private readonly ILogger log;

        public ImportMapLoader(V8ScriptEngine engine, Dictionary<string, Dictionary<string, string>> pathToImportToFile, ILogger log) {
            this.engine = engine;
            this.pathToImportToFile = pathToImportToFile;
            this.log = log;
        }

        public override Task<Document> LoadDocumentAsync(DocumentSettings settings, DocumentInfo? sourceInfo, string specifier, DocumentCategory category,
            DocumentContextCallback contextCallback) {

            if (sourceInfo.HasValue) {
                var sourceFile = Path.GetRelativePath(".", sourceInfo.Value.Uri.AbsolutePath);
                pathToImportToFile.TryGetValue(sourceFile, out var imports);

                if (imports is not null) {
                    specifier = imports[specifier];
                }
            }
            
            var loaded = base.LoadDocumentAsync(settings, sourceInfo, specifier, category, contextCallback);

            if (sourceInfo.HasValue && compiledCode.Add(specifier)) {
                CompileDocument(loaded, specifier, sourceInfo.Value);
            }

            return loaded;
        }

        private void CompileDocument(Task<Document> loaded, string specifier, DocumentInfo sourceInfo) {
            var document = loaded.Result;
            var cachePath = $"{specifier}.cache";
            var cached = Array.Empty<byte>();

            log.Information("Reading {cachePath}", cachePath);

            try {
                cached = File.ReadAllBytes(cachePath);
            } catch {
                log.Information("Failed to read cache file for {script}", specifier);
            }

            log.Information("Compiling {script}", specifier);

            engine.Compile(sourceInfo, GetTextContents(document), V8CacheKind.Code, ref cached,
                out var result);

            if (result == V8CacheResult.Updated) {
                log.Information("Writing cache for script {script}", specifier);

                File.WriteAllBytes(cachePath, cached);
            } else {
                log.Information("Not writing cache for script {script}, result: {result}", specifier,
                    result.ToString());
            }
        }

        private static string GetTextContents(Document document) {
            using var streamReader = new StreamReader(document.Contents, document.Encoding ?? Encoding.UTF8);
            return streamReader.ReadToEnd();
        }
    }

However this has achieved no significant speedup, although I'm not sure I'm doing it correctly. Even when all scripts have a cache and are loaded from that cache (it takes sub 3ms per script to read and validate the cache), there are significant pauses between LoadDocumentAsync calls up to 40ms. We have no significant work in scripts which is happening at the top level, it's mostly function definitions and variables, no computation. Are there any load time optimization tricks I'm missing? Why would document loading be so slow? Is that because of a "ping-pong" between V8 and C# code when resolving imports?

Any help would be appreciated

[ClearScriptLib]

Hi @DoctorGester,

sloc reports 36590 lines of code which is not "a lot" by V8 standards,

Agreed.

However this has achieved no significant speedup, although I'm not sure I'm doing it correctly.

The loader's job is simply to retrieve file content. The default loader caches each loaded file in memory, avoiding subsequent I/O for the same URL. We're unclear on what ImportFileLoader is intended to add, as it discards the compilation result (V8Script) that could accelerate multiple executions of the same document, which ideally shouldn't be necessary in the first place. We'd recommend removing that part of it.

We have no significant work in scripts which is happening at the top level, it's mostly function definitions and variables, no computation.

So, the scripts in the "compat" directory are just normal (non-module) scripts that do nothing but install global functions and data? If you emit a trace after each one, do they all take roughly equal amounts of time to execute?

Is that because of a "ping-pong" between V8 and C# code when resolving imports?

That's unlikely; the cost of import resolution should be dwarfed by the cost of loading the module. But to what imports are you referring? The only JavaScript module you're loading is "index.js". Does it load a bunch of other modules?

Thanks!

[DoctorGester]

If you remove the manual compilation from your loader, does everything still work?

Yes, this is the starting point which I measured in the initial post. The compilation code I added is an attempt to speed it up.

Also, how large is the module tree pulled in by "index.js" – that is, how many files are we talking about?
The tree is ~200 files total.

Please elaborate. Recursive import resolution should happen without any such extra work on the host's part.

So the abstract logical way of doing such caching code is:

1. Check all files you are going to load
2. Check if there is a compiled cache for them, if not, compile
3. Load all of those files

However, in the case of javascript here, since our starting point is just index.js, we don't know which files are going to be loaded at all besides the index.js itself. To know which files are loaded we have to actually execute the file first. So my idea was when the engine asks the loader for the next file, give it the cached compilation artifact.

I have tried doing some profiling to see where the time is spent and what happens during pauses but seems like jetbrains profiling tooling on mac is underdeveloped, I'll try on windows again later.

Can you confirm that the majority of that time is being spent outside the loader?

I'm pretty sure I checked that and all the time was outside, I'll test again just to be sure.

maybe the async machinery itself incurs overhead.

I did think about this, but ~40 ms seems too much

[DoctorGester]

@ClearScriptLib I have debugged and profiled the code a bit and also have written my own custom loader instead of DefaultDocumentLoader.

From what I can see what I'm doing SHOULD theoretically work. Here is my understanding:

1. When calling engine.Compile the passed in DocumentInfo has an uniqueId.
2. That uniqueId serves as a partial key in a cache (https://github.com/microsoft/ClearScript/blob/master/ClearScriptV8/V8ContextImpl.cpp#L3120)
3. The other part of the cache key is the code digest
4. When calling engine.Execute with a Document.Info.uniqueId + code it should retrieve a cached module (https://github.com/microsoft/ClearScript/blob/master/ClearScriptV8/V8ContextImpl.cpp#L490)
5. This should avoid compilation during .Execute.

With this in mind the custom loader looks like this:

    private class CompilingDocumentLoader : DocumentLoader {
        private readonly Dictionary<Uri, Document> cache = new();
        private readonly V8ScriptEngine engine;

        public CompilingDocumentLoader(V8ScriptEngine engine) {
            this.engine = engine;
        }

        public override Task<Document> LoadDocumentAsync(DocumentSettings settings, DocumentInfo? sourceInfo, string specifier, DocumentCategory category, DocumentContextCallback contextCallback) {
            var path = Path.Combine(Directory.GetCurrentDirectory(), specifier);
            var created = Uri.TryCreate(path, UriKind.Absolute, out var uri);
            if (created && cache.TryGetValue(uri, out var cached)) {
                return Task.FromResult(cached);
            }

            var code = File.ReadAllText(specifier, Encoding.UTF8);
            var info = new DocumentInfo(uri) { Category = category };
            var result = new StringDocument(info, code);
            cache[uri] = result;

            settings.LoadCallback?.Invoke(ref info);
            
            CompileDocument(code, specifier, info);

            return Task.FromResult<Document>(result);
        }
        
        private void CompileDocument(string code, string specifier, DocumentInfo documentInfo) {
            var cachePath = $"{specifier}.cache";
            var cached = Array.Empty<byte>();

            try {
                cached = File.ReadAllBytes(cachePath);
            } catch {
            }

            engine.Compile(documentInfo, code, V8CacheKind.Code, ref cached, out var result);

            if (result == V8CacheResult.Updated) {
                File.WriteAllBytes(cachePath, cached);
            }
        }
    }

However, I can't really tell if it's having any effect. The caches are all accepted, but I don't see a significant speedup.

That said, I did notice one definite performance issue in ClearScript: MiscHelpers.GetContent. This assumes Document content is streamed, while the only implementation I can see is StringDocument. So each time it needs to read the code it creates a MemoryStream and then a StreamReader which in turn creates a StringBuilder which copies the whole thing into a buffer and then copies that into the final string. All of that could be avoided I feel, even if it requires adding a separate codepath for in-memory documents. For me MiscHelpers.GetContent takes ~10% of the whole script loading time.

[ClearScriptLib]

From what I can see what I'm doing SHOULD theoretically work.

You're right that script and module caching should eliminate redundant compilation, but that's an implementation detail that could change in the future 😅

As far as we can tell, the one possible benefit to what you're doing in your loader is the reuse of the compilation cache across engine instances and processes. Unfortunately, the V8 team doesn't provide compilation cache speedup details.

That said, I did notice one definite performance issue in ClearScript: MiscHelpers.GetContent.

If you're referring to this, then we understand and agree. Our next release will optimize the StringDocument case.

Please send any additional thoughts or findings.

[DoctorGester]

As far as we can tell, the one possible benefit to what you're doing in your loader is the reuse of the compilation cache across engine instances and processes. Unfortunately, the V8 team doesn't provide compilation cache speedup details.

Right, maybe I forgot to specify but basically this cache is only going to be relevant for the second engine instance starting with the same code, which is our usecase as well (shipping precompiled caches is also a possibility though).

You're right that script and module caching should eliminate redundant compilation, but that's an implementation detail that could change in the future 😅

Is there any possibility the API is updated to accomodate the usecase of explicitly providing cache bytes for compiled code by host? Some additional CacheLoader alongside DocumentLoader? Not sure.

Our next release will optimize the StringDocument case.

Thank you, yes, that's what I was referring to :)

[ClearScriptLib]

Version 7.4.5 added an optimized path for the StringDocument case.