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)
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 ?
Anyone got any insight / ideas ?
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).