[Zope-CMF] cmf zpt_generic/search - sequence_length is very slow for large collections, len () is much faster.

[Florent Guillaume]

Henryk Paluch  <hpaluch at gitus.cz> wrote:
> Florent Guillaume wrote:
> 
> >The search kw are different, {'portal_type': ['Document'],
> >'SearchableText': ''} vs {'SearchableText': ''}, you can't deduct
> >anything from this.
> >  
> >
> Hi!
>   Good catch, but it does not matter in this case. Here are results for 
> same kw (query returning 108 067 documents):
> 
> --- len(items):
> 2005-01-05T08:47:15 ERROR(200) log_me initating search for 
> {'portal_type': ['Document'], 'SearchableText': ''} 1104911235.226000
> ------
> 2005-01-05T08:47:18 ERROR(200) log_me search took 3.075000
> ------
> 2005-01-05T08:47:18 ERROR(200) log_me batch1 3.141000
> ------
> 2005-01-05T08:47:18 ERROR(200) log_me batch2 3.143000
> ------
> 2005-01-05T08:47:18 ERROR(200) log_me batch3 3.146000
> ------
> 2005-01-05T08:47:18 ERROR(200) log_me batch4 3.177000
> ------
> batch_obj.sequence_length:
> 2005-01-05T08:47:43 ERROR(200) log_me initating search for 
> {'portal_type': ['Document'], 'SearchableText': ''} 1104911263.408000
> ------
> 2005-01-05T08:47:43 ERROR(200) log_me search took 0.478000
> ------
> 2005-01-05T08:47:43 ERROR(200) log_me batch1 0.483000
> ------
> 2005-01-05T08:49:49 ERROR(200) log_me batch2 126.443000
> ------
> 2005-01-05T08:49:49 ERROR(200) log_me batch3 126.446000
> ------
> 2005-01-05T08:49:49 ERROR(200) log_me batch4 126.451000
> 
> Summary:
> len(items) takes 0.002s for lazy set of  108 067 Document objects
> batch_obj.sequence_length takes 125.96s for lazy set of  108 067 
> Document objects
> 
> It is still quite noticable difference. All tests seems to prove 
> hypothesis that the speed of len vs. sequence_length depends on lazy set 
> size only, but not on query expression (not counting obvious case when 
> different queries returns different number of objects).

If I understand your previous code, the difference between the two runs
is what line you comment out. How then do you explain the different
times for "log_me search took" when the code executed is the same (the
changed line is *after* that log) ? Have you restarted Zope before each
run to make sure a ZODB cache does is not involved ?

Florent

-- 
Florent Guillaume, Nuxeo (Paris, France)   CTO, Director of R&D
+33 1 40 33 71 59   http://nuxeo.com   fg at nuxeo.com