Mick Moignard's Blog

We've been having some trouble with an application I'm dealing with.  This is a business critical app for the end-users, and one that has a large database - 20+ Gigs in size with upwards of 1.5m documents.   For what are mostly Accessibility reasons, many of the views are set to Refresh  Display, rather than Display Indicator.  What that means is that once or twice a minute, sometimes a little more often, the displayed view flickers as the client refreshes the view.  

But recently we've started to see delays - sometimes 20-30 seconds, and more.  We've looked at the client-debug messages, and we see pairs of messages, Read_entries and Update_Collection,  like the ones shown below.   We have two puzzles over this:

Firstly, why does the Update_collection sometimes take so long - in one case, over 5000ms as shown in the sample below?  Surely this is just the client updating its display with the Read_entries result - there is a tiny exchange of data with the server, all of 152 bytes.   What is that exchange, and what might make the exchange take so long?  

Secondly, why so are there sometimes a huge number of these  many Read_entries calls - sometimes we see tens or even hundreds of these call pairs going on for one view refresh.  Is it that each view row that's updated is passed back in one read_entries call, or what?     We've also tried pressing F9 manually, and as far as we can tell, the same exchange of pairs of Read_Entries and Update_collection calls - and we also noticed, that on a second F9 press immediately after a first, there can often be jsut one message pair.  

Finally, anyone have any ideas that would help us to debug this further, so that we can try to establish if the issue is a server delay, or a networking issue.  Right now, we can't really tell where the delays come from.

Here's the sample of client debug entries:
(15806-85078 [15808]) READ_ENTRIES(REP8025XXXX:XXXXXXXX-NT0000XXXX): 1484 ms. [304+3836=4140]
(15807-85080 [15809]) UPDATE_COLLECTION(REP8025XXXX:XXXXXXXX-NT0000XXXX): 5219 ms. [36+116=152]
(15808-85085 [15810]) READ_ENTRIES(REP8025XXXX:XXXXXXXX-NT0000XXXX): 1578 ms. [304+3836=4140]
(15809-85087 [15811]) UPDATE_COLLECTION(REP8025XXXX:XXXXXXXX-NT0000XXXX): 656 ms. [36+116=152]
(15810-85087 [15812]) READ_ENTRIES(REP8025XXXX:XXXXXXXX-NT0000XXXX): 625 ms. [304+3836=4140]
(15811-85088 [15813]) UPDATE_COLLECTION(REP8025XXXX:XXXXXXXX-NT0000XXXX): 313 ms. [36+116=152]
(15812-85088 [15814]) READ_ENTRIES(REP8025XXXX:XXXXXXXX-NT0000XXXX): 282 ms. [304+3840=4144]
(15813-85088 [15815]) UPDATE_COLLECTION(REP8025XXXX:XXXXXXXX-NT0000XXXX): 421 ms. [36+116=152]
(15814-85089 [15816]) READ_ENTRIES(REP8025XXXX:XXXXXXXX-NT0000XXXX): 329 ms. [304+3836=4140]
(15815-85089 [15817]) UPDATE_COLLECTION(REP8025XXXX:XXXXXXXX-NT0000XXXX): 328 ms. [36+116=152]
(15816-85090 [15818]) READ_ENTRIES(REP8025XXXX:XXXXXXXX-NT0000XXXX): 500 ms. [304+3836=4140]
(15817-85090 [15819]) UPDATE_COLLECTION(REP8025XXXX:XXXXXXXX-NT0000XXXX): 453 ms. [36+116=152]