We are having issues with the performance of Javascript Remoting calls. We have been analyzing them using Debug logs and have noticed some things which we hoped someone might be able to shed some light on, or even to confirm if anyone else is seeing these kinds of issues.
1 : Regularly the 'Debug Logs' page shows a request starting at a particular time. However the timestamp of the first log line of the log can be 2 or more seconds later than the listed request start time. It would appear as though the request is blocked/queued up for some period of time. We understand that buffered requests are serialized but we see these delays when there is only a single remoting request underway. Is it possible that our request is being queued for another reason ? Is it possibly being queued by the underlying app server infrastructure ?
2 : The second kind of delay we are seeing in the logs is just as we enter our managed package code. Looking at the example below, the first log line shows the request arriving at 04:53:39.039 and then we see a delay of almost 800 milliseconds before it initializes the handling controller. This feels almost like a remoting endpoint synchronization. Is there any such synchronization/serialization in play here ?
04:53:39.039 (39938000)|CODE_UNIT_STARTED|[EXTERNAL]|XXX|VFRemote: DMAPP.OurController invoke(methodName)
04:53:39.815 (815878000)|METHOD_ENTRY|[1]|XXX|OurController.OurController()*
3: The third kind of delay we see is after the handling controller is intialized. The following log lines show an example of this. The initializer for the handling controller OurController returns at 08:32:28.394 and the next log entry shows some initialization on the first line of the implementing method at 08:32:30.247. From that trace it appears as though the platform runtime spends about 1.8 seconds doing something between initializing the controller and hitting the first line of its implementation. We speculate that this delay is caused by the runtime processing the @RemoteAction annotations in OurController. We have a lot of remote actions in this controller. Is this a contributing factor ?
08:32:28.394 (2394347000)|METHOD_EXIT|[1]|OurController
08:32:30.247 (4247073000)|METHOD_ENTRY|[1]|XXX|DelegateController.DelegateController()
Anyone got any insight / ideas ?
cheers
Dave
Best Answer
JavaScript Remoting does not instantiate the controller or load the view state. For this reason, the methods are declared as static, because there is no instance associated with these calls. There is a buffering mechanism that causes calls that are called close together to be buffered together and submitted at once; this is a default behavior that can be modified per the JavaScript Remoting for Apex Controllers page. Disabling buffering may increase performance, although surely not as much as 2000 ms worth of delay that you're observing. My typical response time when using remoting with buffering is around 19 ms in demo classes I've written.
The server may choose to delay these requests until resources are available, just like any other request. They are not given any special priority queue, nor are they processed any differently than a normal request. They are generally faster, though, because they do not carry their view state with them, which tends to make them faster and more responsive. However, like all software systems, there can sometimes be unforeseen contention. Submitting a case with support may be able to help isolate this problem.
Classes are, as in Java, compiled to bytecode when they are successfully deployed. This means that your code should load in linear time for any given execution cycle. The size of the class and all the classes upon which it depends can play a factor. More importantly, the first run after a class changes may be delayed if there are inter-class relationships that haven't been compiled (e.g. a change to a utility class will cause all classes that use that utility class to have to re-compile on next execution). This delay is usually minor, and should only occur once per code change.
The system also depends on a cache, so loading a controller for the first time in a while (however long the cache keeps recently used bytecode) may result in a loading penalty, but again this is usually far less than your observation of 1800 ms. Generally this delay is less than 100 ms on a busy day, and I can't think of any documented reason why it would take as long as you've observed unless there's some other issue going on, usually internal in nature.
It might be worth the effort to submit a case to Developer Support and see if they can help isolate the issue. Occasionally, there are definitely hiccups in the system, but the engineers usually keep tabs on this and submit hotfixes for situations like this. You might try reducing the complexity of your code and/or splitting your remote functions across multiple classes (this is a great use case for extensions).