javascript pausing consistently. How do I find what is causing it to pause?

Question

I've got a fairly ajax heavy site and I'm trying to tune the performance.

I have a function that runs between 20 & 200 times, depending on the user. I'm outputting the time the function takes to execute via console.time in firefox.

The function takes about 4-6ms to complete.

The strange thing is that on my larger test with 200 or runs through that function, it runs through the first 31, then seems to pause for almost a second before completing the last 170 or so.

However, that 'pause' doesn't show up in the console.time logs, and I'm not running any other functions, and the object that gets passed to the function looks the same as all other objects that get passed in.

The function is called like this

for (var s in thisGroup.events){
            showEvent(thisGroup.events[s])
            }

so, I don't see how or why it would suddenly pause near the beginning. but only pause once and then continue through.

The pause ALWAYS happens on the 31st time through the function. I've taken a close look at the 'thisGroup.events[s]' that it is being run through, and it looks like this for #31

 
"eventId":"5106", "sid":"68", "gid":"29", "uid":"70","type":"event", "startDate":"2010-03-22","startTime":"6:00 PM","endDate":"2010-03-22","endTime":"11:00 PM","durationLength":"5", "durationTime":"5:00", "note":"", "desc":"event"

The event immediately after the pause, #32 looks like this

"eventId":"5111", "sid":"68", "gid":"29", "uid":"71","type":"event", "startDate":"2010-03-22","startTime":"6:00 PM","endDate":"2010-03-22","endTime":"11:00 PM","durationLength":"5", "durationTime":"5:00", "note":"", "desc":"event"

another event that runs through no problem looks like this

"eventId":"5113", "sid":"68", "gid":"29", "uid":"72","type":"event", "startDate":"2010-03-22","startTime":"4:30 PM","endDate":"2010-03-22","endTime":"11:00 PM","durationLength":"6.5", "durationTime":"6:30", "note":"", "desc":"event"

From the console outputs, it doesn't appear as there is anything hanging or taking up time in the function itself, as the console.time for each event including #31,32 is 4ms.

Another strange thing here is that the total time running the for loop across the entire object is coming out as 1014ms which is right for 200 events at 4-6ms each.

Any suggestions on how to find this 'pause'? I find it very interesting that it is consistently happening between #31 & #32 only!

------------------- a bit of a hint on the problem, but no solution -------------------

if looks like this is a lag from the where I put the html into the dom. I've stripped out all sorts of code, but when I remove

jQuery('div#holdGroups').append(putHtml);

That is when the lag stops.

Is there any way to do a clean-up or something on the append? I've tried .html, but that isn't any better, and append is really what I want. I can do a solid 3 count during the pause, which really isn't good, and I can't get the pause to show up anywhere in the console or profile. It shows the actual append only taking 117ms but it is a fairly large chunk of html with 6 tables, so I don't think that is too bad.

-------------- further update - maybe garbage collection?? ----------------------- As per a few of the answers below, this may be an issue with garbage collection, though I can't be positive.

I have attempted to delete variables which are being used, such as the variable which holds the html which is added to the dom via

 delete putHtml; 

as well as other variables, but this has not had any affect.

if the problem is with garbage collection, maybe I'm going about cleaning it up wrong? Is there a better way to do this? Is there a way to determine if garbage collection is in fact the issue?

Answer 1

Try using console.profile() rather than console.time(). This allows you to wrap the whole block and get a more detailed breakdown of what's going on.

console.profile('my profile');
for (var s in thisGroup.events){
    showEvent(thisGroup.events[s]);
}
console.profileEnd('my profile');

Answer 2

Does it consistently happen between #31 and #32 across different browsers? My guess is that it has something to do with the garbage collector. Also, timing in browsers is notoriously bad. I would try different browsers. If it consistently happens there, then it might be worth looking deeper into that iteration of the code. Otherwise, if it is the GC, your best bet would be to reduce the number of objects you generate.

Answer 3

Try collecting logs in a variable [array?] and outputing them at the end. I once did a ajax heavy "thingy" and the logs kept popping up in the console long after everything was done. The console might be the source of the lag.

Answer 4

Would it be possible to change the order of the data to see if that changes when the pause is? If it does, then it surely must be caused by the data. If not, then I would try narrowing down the functionality called by commenting out blocks of code until you notice the lag disappear. Experiment with that and I think you could probably find what the trouble is.