apply() and call() cause a huge slowdown.

Hi all,

I'm extending our inhouse agent platform to espruino and it seems that using apply() or call() is causing a very big slowdown. In my testcase it is between 0.5 seconds without and 15 seconds with call or apply. I'm not sure why this should be such a difference.. Can anyone shed some light on this?

My code is on here:
https://github.com/AlexDM0/espruinoEVE
The example file is espruinoCall.js
You can alter line 150 to see the difference.

agent[message.content.method].call(agent,message.content.params,callback);

to

agent[message.content.method] (message.content.params,callback);

I tried putting it in a small example to show the problem but I think its due to the size of the objects that it's slowing down. I couldn't succesfully reproduce it in a tiny example.

I'm guessing that 0.5 seconds isn't just for one call? Is that total runtime (including everything else), or just the timings for the call on its own?

It's hard to know exactly where the problem lies. You're sure that the agent function is being executed in both cases?

The only thing I could think that could make the first line 30 times slower is if the function (or its prototype) had a huge amount of fields inside it. You could try:

agent[message.content.method].foo;agent[message.content.method](message.content.params,callback);

And see if that slows it down at all...

The timings are for around 10 calls. I'm sure its the same function. I rewrote the code so that apply or call are not required, though when I place them in there it slows down a lot. I'm not sure what you mean with the .foo? I have printed both "this"-es and they are the same with and without. The reason I needed the apply in the first place was that the methods were in a seperate object:

agent.RPCfunctions[message.content.method].call(agent,message.content.params,callback);

Agent has a number of functions and properties.. not necessarily huge, though shouldnt apply mearly change a pointer to the this object? The callback function contains a reference to the agent as well:

var callback = function (data) {agent._send(message.origin, data, agentId, message.content.id);};

If I empty the callback

var callback = function (data) {};

the difference in execution speed drops dramatically. Does apply or call copy the arguments including their references somehow?

apply/call shouldn't copy any arguments.

The usage of .foo was just to see if trying to access a field in the agent array was slow - but if you're saying that each call takes 15/10=1.5 seconds to complete then that won't be the problem. We'd be talking about a maximum of a few milliseconds.

So you're saying that removing the call to agent._send from callback speeds execution up a lot. Surely that implies that agent._send is the thing that's slowing it all down?

I mean, if agent[message.content.method] was just function(){} I guess this would run pretty quick regardless of the way it was called? Why not try changing the function to function() { print(arguments); } and see if anything is obviously different between calls?

This all looks too complicated for me to be able to help out. If you can get a simple test case that exhibits the behaviour I'll be able to look into it properly - but until then I'm not sure what I can do.

Hi Gordon,
If the callback is unchanged, there the difference in performance between .call/.apply and directly calling (). In this case the callback is still being sent in both versions and it is also being executed succesfully.

I will try to create a small example that reproduces the problem. Thank you for your patience, I guess I was hoping you had some sort of hardware profiling/debugging tool that could explain why the method of calling a function makes such a difference.

I'm afraid I don't really have any special tools - I'd just use getTime to track how long certain things take... You could compile on Linux and use gprof to track down the issue though...

Running espruinoCall.js and swapping line 150 doesn't seem to cause any slowdowns for me. Was that the intention - that it only fails when it's part of a much bigger project?

Just to add, there really shouldn't be a big speed difference - there's a little more work when 'call' is used - but not much.

Have you tried sending the code to Espruino with Throttle on (in Web IDE settings). It's possible that characters get lost when it's sent to Espruino (it's a relatively large function) and that somehow changes what it's doing.

If I upload the code of espruinoCall.js to the espruino, it takes about 15 seconds for all the console.log messages to show up on the webIDE. If I remove the call, it takes less than a second. I also tried to remove the apply's on other places (like 288, apply) and also seems to fix the problem.. Since I'm doing apply on apply on apply, could that run into a recursion problem? I'll try to put this in a small example to see if that could be it.

Also, thank you for the answer on the minify topic ;)

EDIT: throttle did not make a difference. I also don't use minification here.

Hmm... I just got it to happen - not sure why it didn't before.

I added the following code:

      console.log("Before",getTime());
      agent[message.content.method].call(agent,message.content.params,callback);
      //agent[message.content.method] (message.content.params,callback);
      console.log("After",getTime());

and I get results like this:

Before 742.24305057525634765625
fireing callback
I have the answer ( 0 ) 83 0 6fo1civxub28
After 0

But only with .call - not with the normal function call.

It sounds like it's a bug in Espruino somewhere then - possibly caused by nested .apply/call as you say - as I just tried a test case with a single call and couldn't reproduce it. If you could try and come up with an example that would be a huge help...

This is a really strange one.. It may not be related to call or apply at all. I have added a new file on my git, named espruinoMinimized:
https://github.com/AlexDM0/espruinoEVE/blob/master/espruinoMinimized.js

This is the espruinoCall file but stripped function by function untill the problem is gone. In the espruinoMinimized file, the problem is still present and it can be solved by:

removing:

Eve.prototype.sendOverTransports = function(message) {
  this.receiveMessage(message);
};

and changing 57: this.sendOverTransports(JSON.stringify(message)); to this.receiveMessage(JSON.stringify(message)); effectively cutting out the sendOverTransports function.

OR:
you can clear lines 124,130,133,134,135:

Eve.prototype.alreadyHandledMessage = function(UID) {
  return this.receivedMessages.indexOf(UID) != -1;
};

and the single call to this function on 124.

The functions that are removed HAVE to be used. Functions that are not used do not affect this.

It is funny to note that this only happens when used with the setTimeout().

It looks like after a certain execution time threshold, the setTimeout schedules the next time further away. I tried allocating 250 ms for each function call in the set timeout, ie:

setTimeout(function() { me.sendMessage.apply(me); }, 250);
  setTimeout(function() { me.sendMessage.apply(me); }, 500);
  setTimeout(function() { me.sendMessage.apply(me); }, 750);
  setTimeout(function() { me.sendMessage.apply(me); }, 1000);
  setTimeout(function() { me.sendMessage.apply(me); }, 1250);

but that doesn't fix the problem... Does that shed any light on the issue?

EDIT: naturally, removing the call I mentioned in the OP and the apply mentioned after that also fix the problem. They are on lines 28 and 153.

Strange - after fixing that bug you reported, your code doesn't work at all. myEve ends up containing:

{
      "agents":{
        "0":{
          "RPCfunctions":{},
          "init":function () { ... },
          "add":function (params,callback) { ... },
          "sendMessage":function () { ... },
          "sendMessages":function () { ... },
          "agentName":"0",
          "options":{},
          "send":function (destination,message,callback,messageId) { ... },
          "publish":function (topic,message) { ... },
          "subscribe":function (topic,callback) { ... },
          "unsubscribe":function (topic,callback) { ... },
          "schedule":function (callback,time) { ... },
          "repeat":function (callback,time) { ... }
        }
      },
      "topics":{},
      "callbacks":{
        "0":{
          "6qyhirtqklq8":function (answer) { ... },
          "4ec0vmqv6pa8":function (answer) { ... },
          "5k462y63k7pc":function (answer) { ... },
          "58ich9zfwlo":function (answer) { ... },
          "1a8nici2pqxs":function (answer) { ... },
          "5vrmbdrmbh4w":function (answer) { ... },
          "5hu6aackwwow":function (answer) { ... },
          "4u7kbc25iydc":function (answer) { ... },
          "2zzm7mn6g8sg":function (answer) { ... },
          "6jg883hgcscg":function (answer) { ... },
          "3gmwt7ql81hc":function (answer) { ... },
          "5r67qpludmv4":function (answer) { ... },
          "lvvbuu47tio":function (answer) { ... }
        }
      },
      "transport":{
        "ANT":{}
      },
      "receivedMessages":[
        "7rzs33b908s",
        "6tbna54x2lq8",
        "2zj7n5cd77cw",
        "24hfsn1bgj9c",
        "6130s6ugog00",
        "6tjbyw7a38xs",
        "34ydibjauu9s",
        "5pdp63lci680",
        "7242cassfuk",
        "1aj6hevntsgw"
      ],
      "messageHistoryLength":10}

By the way, I noticed a callbacks.lenght on line 120 - but that's not the problem.

that callbacks length is part of the

this.topics[topic] = {agents: { agentId : { callbacks:[]}}, subscriberCount:0};

So that's just an array. I realize codestructure is a bit sloppy, I'm still prototyping ;). I'll try to download the fix you mentioned in the other thread and see if I can get it to run again.

EDIT: ahh you mean the typo.. I tend to mix those up.. let me kick my IDE (not webIDE) :)

Sorry - didn't see your last post. Trying 'espruinoMinimized', I get:

ERROR: Function not found! Skipping. at line 7 col 12
      this.relayMessage(messageObj);
            ^
at line 7 col 24
      this.relayMessage(messageObj);
                        ^
in function "receiveMessage" called from line 2 col 30
in function "sendOverTransports" called from line 13 col 50
in function called from line 6 col 100
in function "send" called from line 5 col 6
in function called from line 1 col 26
in function called from system
> 

with the new version of the code...

To check, it was running on 1.61. I assume you're running off the 1.62? I'll download it now.

EDIT: it works in nodeJS as well as chrome, I'll get the firmware you mentioned.

I have the same problem, I see that I deleted a function but not the call (which doenst really do anything). Maybe my 1.61 kept it in namespace when I loaded the version with that function removed? I updated the file on my git. It seems now that my code isnt doing anything.... hmm..

Since you fixed the bug, the hasOwnProperty does not work correctly.

agents =

"0":{
    "RPCfunctions":{},
    "init":function () {
  console.log(this.agentName + " added");
},
    "add":..............................
}

message =

{
  "address":"0",
  "origin":"0",
  "UID":"4n22krpnok2",
  "content":{
    "method":"add",
    "params":{"a":71,"b":12},
    "id":"2180qsewake8"
  }
}

agent.hasOwnProperty(message.address) == false

Ok, thanks - I was just about to post this too.

I'll fix it - it's because of this difference between a string representing 0 and 0 itself.

Interestingly, using 1.62 and espruinoCall (the one I started with), the execution time problem seems to be fixed.

Strange... There was something odd happening with getTime returning 0 though. I'm still not sure what that was about.

Just fixed, commit df71b0c049f7ca1b334a3b75ef4cea7ef8afeb91.

Again, if you wait an hour you should be able to try that build out. It appears to work with both bits of your code now.

Thanks for helping to track this all down! I managed to find/fix another issue too - with 0.0 in {0:1}

Great, I'm glad it all works now :). Its awesome that you're so quick to respond to these, somewhat vaguely phrased issues! 1.62 is going to be awesome!

Thank you very much!