askql icon indicating copy to clipboard operation
askql copied to clipboard

AskScript programs are much slower than Javascript equivalents

Open czerwinskilukasz1 opened this issue 4 years ago • 5 comments

Consider the following two programs:

AskScript (AskVM)

Source code:

let a = 0;
log(date(), a);
while (a < 10000000) {
  if ((a / 1000):equals(floor(a / 1000))) {
    log(date(), a);
  }
  a = a + 1;
}
log(date(), a);

Changes to cli.ts needed, add these lines above const options: Options = {:

const customResources = {
  date: resource({
    type: any,
    async compute(options, code, args) {
      return new Date().toString();
    },
  }),
};

const resources = { ...builtinResources, ...customResources };

and change steps to 10**12 in src/askvm/index.ts.

How to run:

npm run build && npm run cli

then type: .editor and paste the source code.

Output:

Thu Jul 02 2020 16:27:16 GMT+0200 (Central European Summer Time) 0
Thu Jul 02 2020 16:27:16 GMT+0200 (Central European Summer Time) 0
Thu Jul 02 2020 16:27:17 GMT+0200 (Central European Summer Time) 1000
Thu Jul 02 2020 16:27:19 GMT+0200 (Central European Summer Time) 2000
Thu Jul 02 2020 16:27:21 GMT+0200 (Central European Summer Time) 3000
Thu Jul 02 2020 16:27:22 GMT+0200 (Central European Summer Time) 4000
Thu Jul 02 2020 16:27:24 GMT+0200 (Central European Summer Time) 5000
Thu Jul 02 2020 16:27:26 GMT+0200 (Central European Summer Time) 6000
Thu Jul 02 2020 16:27:28 GMT+0200 (Central European Summer Time) 7000
Thu Jul 02 2020 16:27:29 GMT+0200 (Central European Summer Time) 8000
Thu Jul 02 2020 16:27:31 GMT+0200 (Central European Summer Time) 9000
Thu Jul 02 2020 16:27:33 GMT+0200 (Central European Summer Time) 10000
Thu Jul 02 2020 16:27:35 GMT+0200 (Central European Summer Time) 11000
Thu Jul 02 2020 16:27:37 GMT+0200 (Central European Summer Time) 12000
Thu Jul 02 2020 16:27:39 GMT+0200 (Central European Summer Time) 13000
Thu Jul 02 2020 16:27:41 GMT+0200 (Central European Summer Time) 14000
Thu Jul 02 2020 16:27:43 GMT+0200 (Central European Summer Time) 15000
Thu Jul 02 2020 16:27:44 GMT+0200 (Central European Summer Time) 16000
Thu Jul 02 2020 16:27:47 GMT+0200 (Central European Summer Time) 17000
Thu Jul 02 2020 16:27:48 GMT+0200 (Central European Summer Time) 18000
Thu Jul 02 2020 16:27:50 GMT+0200 (Central European Summer Time) 19000
Thu Jul 02 2020 16:27:52 GMT+0200 (Central European Summer Time) 20000
(...)

36 seconds for 20*1000 iterations, printed every 1000. = 1800 seconds per 1000*1000 iterations

JavaScript

while.js

let a = 0;
console.log(new Date().toString(), a);
while (a < 10000000) {
  if (a / 1000 == Math.floor(a / 1000)) {
    console.log(new Date().toString(), a);
  }
  a = a + 1;
}
console.log(new Date().toString(), a);

How to run:

/usr/bin/time -l node src/drafts/while.js

Output:

(...)
Thu Jul 02 2020 16:36:43 GMT+0200 (Central European Summer Time) 9998000
Thu Jul 02 2020 16:36:43 GMT+0200 (Central European Summer Time) 9999000
Thu Jul 02 2020 16:36:43 GMT+0200 (Central European Summer Time) 10000000
        0.63 real         0.33 user         0.03 sys
  28598272  maximum resident set size
         0  average shared memory size
         0  average unshared data size
         (...)

0.63 seconds for 10*1000*1000 iterations, printed every 1000. = 0.063 per 1000*1000 iterations

AskScript is 28 571 times slower than Javascript.

czerwinskilukasz1 avatar Jul 02 '20 14:07 czerwinskilukasz1

@czerwinskilukasz1 @mhagmajer Do we want to allow so many iterations in AskQL?

YonatanKra avatar Oct 09 '20 09:10 YonatanKra

Anyway - I can duplicate this in a much simpler case:

ask { 
  for (let i = 0; i < 100000; i = i + 1) {
    if ((i / 1000):equals(floor(i / 1000))) {
      log(i);
    }
  }
} 

vs.

for (let i = 0; i < 100000; i++) {
  if (i / 1000 === Math.floor(i / 1000)) console.log(i);
}

The time diff is astounding: js run: 7.679ms ask compile: 49074.156ms

YonatanKra avatar Oct 09 '20 09:10 YonatanKra

Ok - I've started profiling this: image Seems like the call fulfilled is the heavy lifter here. Others should be taken care of - but not as much as the call. @mhagmajer - have any idea why would the call fulfilled will take so much time?

YonatanKra avatar Oct 09 '20 09:10 YonatanKra

@YonatanKra suppose that this is the price we're paying for being asynchronous by default - this allows for easier syntax of performing asynchronous tasks (no async/await syntax), but at the same time, the synchronous like operations take much longer.

const asyncPlus = async (a, b) => a + b;

async function asyncCompute(n) {
  console.time('async');
  let sum = 0;
  for (let i = 0; i < n; i += 1) {
    sum += await asyncPlus(sum, i);
  }
  console.timeEnd('async');
  return sum;
}

asyncCompute(10**3)

async: 3.528076171875 ms

const plus = (a, b) => a + b;

function compute(n) {
  console.time('sync');
  let sum = 0;
  for (let i = 0; i < n; i += 1) {
    sum = plus(sum, i);
  }
  console.timeEnd('sync');
  return sum;
}

compute(10**3)

sync: 0.083984375 ms

Arguably, all the heavier operations should be performed by the resources that are safe to run in the host environment and have fast, native implementation. Operations in AskScript are asynchronous (as you can see this already carries a toll on performance), subject to limitations and additional safety checks.

One potential idea to mitigate that would be to introduce a sync {} block that would only allow synchronous operations inside and would perform them synchronously - however that is probably a long stretch feature that would require substantial additions to the codebase and I'm not even sure if it makes sense for us to optimise performance.

mhagmajer avatar Oct 09 '20 10:10 mhagmajer

Regarding call - this is the asynchronous root function being invoked on every resource - for, if, assign etc, so on every AskScript operation - that's why it is being the bottleneck

mhagmajer avatar Oct 09 '20 10:10 mhagmajer