Datatable delays ajax requests, does more requests then it should

survalent

I am using the control on 2 pages in my application - almost the same except one page has an interval function running that calls fnDraw on the datatable to get it to refresh frequently.
On this refreshing table, there are 2 strange behaviours. First one is a 3 second delay between when the page is loaded and when the first ajax request is received by the server. The second problem is that function that refreshes the table calls fndraw at an interval of 1 second, but the Server gets more frequent requests.

I am stumped on what is going on with this datatable, particularly as my second one works without the strange delay, with only small fractions of a second between when the page request comes in and when the first ajax request come in from the datatable in that page.


Here is the script for the table. Below are diagnostic messages logged by the server application:
Datatable debug code: ayasez

[code]
function RefreshCallDisplay() {
iCountRehresh++;
oTable.fnDraw();
};

$(document).ready(
function () {
oTable = $('#calldisplaytable').dataTable(
{

"bServerSide": true,
"sAjaxSource": "AjaxHandler",
"bProcessing": false,
"bPaginate": false,
"bLengthChange": false,
"bFilter": false,
"bSort": false,
"bInfo": false,
"bAutoWidth": false,
"aoColumns":
[
{ "sName": "Pkey" },
{ "sName": "OffHook" },
{ "sName": "CallPhone" },
{ "sName": "Name" },
{ "sName": "Priority" },
{ "sName": "MeterNum" },
{ "sName": "CaseSeq" },
{ "sName": "NumCalls" }
]
});

//Assign click handler to table rows for selection highlights
$('#calldisplaytable tbody').on("click", "tr", TableSelectionClick);
setInterval(RefreshCallDisplay, 1000);
});
[/code]

I have included snippets from 2 logs written by server application which tracks when requests are coming in, both showing the time when the page is first loaded by the client. The numbers in square brackets besides the timestamps are the fraction of a second.

The request for the page itself is shown as Origin: CallDisplayController.CallDisplayHome
Requests for data by the datatable are marked as Origin: CallDisplayController.AjaxHandler
The ajax request happens over 3 seconds after the request for the table itself. Also note how often the ajax requests are happening once they start. Not shown in the log, but this behavior continues - a break of silence for about 3 seconds, and then a hammering of too-frequent requests, like they are being queued up or something.

On the client there is a very visible delay between when the page gets rendered with the empty datatable and when data shows up - I include this observation to say that the delay does not seem to be due the page being received and rendered by the browser before sending out the Ajax request. In fact my second data table that functions without such delays is on a larger page with other controls.

First log, with refresh enabled (setInterval not commented out)

2012-05-25 11:50:40 [5166]: Origin: MapBingController.UpdateCallMapPins Additional Information: Request for Call Map Pins serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:50:40 [5166]. Previous request was 5001.01 ms ago. Processing time 0 ms.
2012-05-25 11:50:45 [5166]: Origin: MapBingController.UpdateCallMapPins Additional Information: Request for Call Map Pins serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:50:45 [5166]. Previous request was 5000.0358 ms ago. Processing time 0 ms.
2012-05-25 11:50:47 [8879]: Origin: CallDisplayController.CallDisplayHome Additional Information: Rendering Call Display via GET
2012-05-25 11:50:48 [2220]: Origin: MapBingController.MapBingMain Additional Information: Rendering Bing Map
2012-05-25 11:50:48 [3410]: Origin: MapBingController.UpdateOutageMapPins Additional Information: Request for Outage Map Pins serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:50:48 [3410]. Previous request was 17827.3853 ms ago. Processing time 0 ms.
2012-05-25 11:50:51 [4617]: Origin: CallDisplayController.AjaxHandler(Call Display table) Additional Information: Request for CallDisplay data serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:50:48 [3470]. Previous request was 255760.2524 ms ago. Processing time 3114.747 ms.
2012-05-25 11:50:51 [8601]: Origin: CallDisplayController.AjaxHandler(Call Display table) Additional Information: Request for CallDisplay data serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:50:51 [8601]. Previous request was 3513.1534 ms ago. Processing time 0 ms.
2012-05-25 11:50:51 [8757]: Origin: CallDisplayController.AjaxHandler(Call Display table) Additional Information: Request for CallDisplay data serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:50:51 [8757]. Previous request was 15.6 ms ago. Processing time 0 ms.
2012-05-25 11:50:52 [3457]: Origin: CallDisplayController.AjaxHandler(Call Display table) Additional Information: Request for CallDisplay data serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:50:52 [3457]. Previous request was 470.0225 ms ago. Processing time 0 ms.
2012-05-25 11:50:52 [3777]: Origin: CallDisplayController.AjaxHandler(Call Display table) Additional Information: Request for CallDisplay data serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:50:52 [3767]. Previous request was 31.0018 ms ago. Processing time 1.0001 ms.
2012-05-25 11:50:53 [3428]: Origin: MapBingController.UpdateCallMapPins Additional Information: Request for Call Map Pins serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:50:53 [3428]. Previous request was 7826.1802 ms ago. Processing time 0 ms.

The second log is of same page loading, this time with refresh function being commented out. Not that delay between page being loaded and ajaxrequest is still at 3 seconds, but this time only a single Ajax request is done.


2012-05-25 11:46:27 [2815]: Origin: MapBingController.UpdateCallMapPins Additional Information: Request for Call Map Pins serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:46:27 [2815]. Previous request was 5008.8078 ms ago. Processing time 0 ms.
2012-05-25 11:46:32 [1767]: Origin: CallDisplayController.CallDisplayHome Additional Information: Rendering Call Display via GET
2012-05-25 11:46:32 [4917]: Origin: MapBingController.MapBingMain Additional Information: Rendering Bing Map
2012-05-25 11:46:35 [7205]: Origin: CallDisplayController.AjaxHandler(Call Display table) Additional Information: Request for CallDisplay data serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:46:32 [5867]. Previous request was 19087.8669 ms ago. Processing time 3133.7481 ms.
2012-05-25 11:46:36 [1465]: Origin: MapBingController.UpdateOutageMapPins Additional Information: Request for Outage Map Pins serviced for sessions ID [isogcl44igxenhbkxoro4lpk]. Request recieved at 2012-05-25 11:46:36 [1465]. Previous request was 18874.2382 ms ago. Processing time 0 ms.

allan

What does Firebug show when the XHR's are being made - or better yet, the Webkit 'Network' view, since that will show the frequency of the XHR requests nicely.

Certainly your code looks okay to me, although I would say that 1 second updates are very fast - if you get a delay in the network, you might get overlapping requests for example (although DataTables will cope with that :-) ).

Allan