sebastienros / jint

Javascript Interpreter for .NET
BSD 2-Clause "Simplified" License
3.99k stars 553 forks source link

Performance regression between 2.x vs 3.x beta #782

Closed raghur closed 3 years ago

raghur commented 3 years ago

So I just noticed this - and here's two runs of my code that calls a simple script file. Only difference between the two is the switch to 3.x beta. (3.0.0-beta-1828)

3.x

2020-09-19 13:39:50Z [INF]  starting script execution
2020-09-19 13:39:50Z [INF] /home/raghu/.config/fs-home/one.js js args ["[0, { Envelope = Address 209 Voltage 27800mV  Boot 25700ms\nPayload: [|200uy|]\n  Radio = HomeAutomation.NRF24.Radio+NrfRadio }]", "[1, RadioSensorDecl 209uy]"]
2020-09-19 13:39:50Z [INF] /home/raghu/.config/fs-home/one.js Address 209
2020-09-19 13:39:50Z [INF] /home/raghu/.config/fs-home/one.js Voltage 27800
2020-09-19 13:39:50Z [INF] /home/raghu/.config/fs-home/one.js Bootup 25700
2020-09-19 13:39:50Z [INF] /home/raghu/.config/fs-home/one.js function
2020-09-19 13:39:50Z [INF]  published sddf to cmnd/DVES_2E9E86_fb/POWER - null
2020-09-19 13:39:50Z [INF] /home/raghu/.config/fs-home/one.js sleepy time
2020-09-19 13:39:50Z [INF] /home/raghu/.config/fs-home/one.js script is done
2020-09-19 13:39:50Z [INF]  script execution took - 42 millis

2.11.58

2020-09-19 13:48:37Z [INF]  starting script execution
2020-09-19 13:48:37Z [INF] /home/raghu/.config/fs-home/one.js js args ["[0, { Envelope = Address 209 Voltage 27800mV  Boot 25700ms\nPayload: [|200uy|]\n  Radio = HomeAutomation.NRF24.Radio+NrfRadio }]", "[1, RadioSensorDecl 209uy]"]
2020-09-19 13:48:37Z [INF] /home/raghu/.config/fs-home/one.js Address 209
2020-09-19 13:48:37Z [INF] /home/raghu/.config/fs-home/one.js Voltage 27800
2020-09-19 13:48:37Z [INF] /home/raghu/.config/fs-home/one.js Bootup 25700
2020-09-19 13:48:37Z [INF] /home/raghu/.config/fs-home/one.js function
2020-09-19 13:48:37Z [INF]  published sddf to cmnd/DVES_2E9E86_fb/POWER - null
2020-09-19 13:48:37Z [INF] /home/raghu/.config/fs-home/one.js sleepy time
2020-09-19 13:48:37Z [INF] /home/raghu/.config/fs-home/one.js script is done
2020-09-19 13:48:37Z [INF]  script execution took - 22 millis

As you can see, the time has roughly doubled - and this is consistent over repeated runs. Now this doesn't track well with the other issue I saw that had perf benchmarks show 3.x improvements.

Now my script itself is pretty trivial - and commenting individual lines doesnt make much of a difference. What moves the needle though is that it seems function call (Engine.Invoke) seems to have a pretty large (relative) overhead in 3.x. Emptying out the function body altogether

on 2.x - 1 milisecond on 3.x - 17 millis

Are there any dos/dont's when moving to 3.x or something that can alleviate this overhead?

lahma commented 3 years ago

Can you provide a bit more usage sample? Are you parsing the script only once into Program and then feeding it to Jint?

Quite hard to give much pointers yet.

raghur commented 3 years ago

I understand and my apologies

Yes - script is being parsed only once. Script defines a function ("handle"). This function is called at a later time (the engine is passed around)

let jsEngineHandlerWrapper (jsfile:string) (engine:Engine) src ev =
        let args = [|ev:> obj; src|]
        try
            Log.Information("starting script execution - {file}", jsfile)
            let sw = new Stopwatch()
            sw.Start()
            engine.Invoke("handle", args) |> ignore
            sw.Stop()
            Log.Information("script {jsfile} execution took - {time} millis", jsfile, sw.ElapsedMilliseconds)
        with
            | exn ->
                printfn "%A" exn
                Log.Error(exn, "Error invoking script {jsfile}{ex}", jsfile, exn)
lahma commented 3 years ago

Invoke does wrapping of parameters (converts them to JsValues) and such. Without running any code, does it make a difference if you set the value to engine like engine.SetValue("args", args"); and then engine.Execute("handle(args);");? I haven't studied the differences with the old 2.x and the new line, but whatever wrapping you can reduce should help, like if obj and src are somewhat constant values and can be cached as direct JsValues.

42ms is still relatively fast, how fast do you need to go? 🙂

raghur commented 3 years ago

I'll try that later today and see if it improves things.

42ms is still relatively fast, how fast do you need to go? slightly_smiling_face

I agree and most times, this wouldn't matter at all. In this case, I have a nrf radio remaining awake on a tiny battery so the sooner I give it a response the better. My baseline with C++ comes to ~50ms for the entire period from receiving an input from the radio to calculating and sending a response.. I'm trying to not stray too far from that while being able to have a scriptable interface. Right now this is just the invocation time for the script.

raghur commented 3 years ago

@lahma - there is no difference with using SetValue followed by Execute

            engine.SetValue(JsValue.FromObject(engine, "__args"), args)
            sw.Start()
            engine.Execute("handle(...__args)") |> ignore
            sw.Stop()
lahma commented 3 years ago

I created following test app and ran it under .NET Core 3.1:

using System;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using Jint;

namespace ConsoleApp1
{
    class Program
    {
        static void Main(string[] args)
        {
            var testCase = new TestCase();
            testCase.Prepare();
            var sw = Stopwatch.StartNew();
            RunTestCase(testCase);
            sw.Stop();
            Console.WriteLine("Took: " + sw.Elapsed.TotalMilliseconds + "ms");
        }

        [MethodImpl(MethodImplOptions.NoInlining)]
        private static void RunTestCase(TestCase testCase)
        {
            testCase.Execute();
        }
    }

    public class TestCase
    {
        Engine e;
        private object[] args;

        public void Prepare()
        {
            e = new  Engine();
            e.Execute("function foo(arg1, arg2) { if (arg1) {} if (arg2) {} }");
            args = new object[] { new Argument(), new Argument()  };
            e.Invoke("foo", args);
        }

        public class Argument
        {
            public string Property1 { get; set; }
            public string Property2 { get; set; }
        }

        public void Execute()
        {
            for (var i = 0; i < 1000; ++i)
            {
                e.Invoke("foo", args);
            }
        }
    }
}

Jint 2.11.58: Took: 5.7056ms Jint 3.0.0-beta-1828: Took: 2.6032ms

So Jint 3 is faster in this case, so currently I'm unable to reproduce the regression.

raghur commented 3 years ago

@lahma - Thank you for looking into this. I am able to reproduce your results - which of course leaves me wondering :). I'll try to create a minimal example as well.

Feel free to close this. I'll reopen if I get a minimal example to illustrate my case.

lahma commented 3 years ago

Sure. I'd love to see a repro, but generally I think for engine reuse with given script should be faster with v3. Maybe you can run some traces etc, might be runtime dependent too.

lahma commented 3 years ago

Closing for now and we can reopen if more information presents itself.