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