[Toaster] [review-request] V2: 6137 excessive load time for All Recipes page

[Lerner, Dave]

Django-debug-toolbar may not be counting queries correctly but it still reports over 1K queries with your v1 patch instead of the 200 queries that you report.  Did you estimate the query count or did you use a tool to measure it?
-dave

> -----Original Message-----
> From: Reyna, David
> Sent: Thursday, April 10, 2014 7:45 PM
> To: BARROS PENA, BELEN; Lerner, Dave
> Cc: toaster at yoctoproject.org
> Subject: [review-request] V2: 6137 excessive load time for All Recipes page
> 
> Hi Belen and Dave,
> 
> Here is my V2 version of this fix: dreyna/recipes_loadtime_6137
> 
> The basic slowness of the Recipes page is the 100*(2+2) foreign key lookups and
> filters/count. The V1 removed the redundant references which reduced the overhead to
> 100*(2+0) foreign key lookups. This V2 improves it even more by removing the foreign key
> lookups altogether and replacing it on the view-side with just one forward query plus
> 100*2 simple filters.
> 
>     # prefetch the forward and reverse recipe dependencies
>     deps = { }; revs = { }
>     queryset_dependency=Recipe_Dependency.objects.all()
>     for recipe in recipes:
>         deplist = [ ]
>         for recipe_dep in queryset_dependency.filter(recipe=recipe.id).all():
>             deplist.append(recipe_dep)
>         deps[recipe.id] = deplist
>         revlist = [ ]
>         for recipe_dep in queryset_dependency.filter(depends_on=recipe.id).all():
>             revlist.append(recipe_dep)
>         revs[recipe.id] = revlist
> 
> Here are the timing results on my slow host for the rendering time:
> 
>   (a) Original: 13 seconds
>   (b) V1      :  7 seconds
>   (c) V2      :  4 seconds
> 
> I therefore recommend this patch for 1.6.1.
> 
> ====================================
> 
> I used Dave's log time routine to be able to instrument separate blocks of code within
> the view class. Here were my exact results. Time is in seconds.
> 
> [ Original ]
> 
> 1397163677.7:StartQuery
> 1397163677.71 delta: 0.00934100151062: StopQuery
> 1397163677.71:StartRender
> 1397163690.32 delta: 12.6088190079: StopRender
> 
> [ V1 ]
> 
> 1397163411.71:StartQuery
> 1397163411.72 delta: 0.00832009315491: StopQuery
> 1397163411.72:StartRender
> 1397163418.8 delta: 7.07802510262: StopRender
> 
> [ V2 ]
> 
> 1397174174.31:StartQuery
> 1397174174.32 delta: 0.00747513771057: StopQuery
> 1397174174.32:StartQueryDeps
> 1397174177.21 delta: 2.88377785683: StopQueryDeps
> 1397174177.21:StartRender
> 1397174178.23 delta: 1.01679706573: StopRender
> 
> 
> And here is the logger routine:
> 
> def basetime(now):
>     basetime.time = now
> 
> def logtime(message, setbase=False):
>     import time,logging
>     logger = logging.getLogger('django.request')
>     now = time.time()
>     if setbase:
>         basetime(now)
>         logger.error(str(time.time()) + ":" + message)
>     else:
>         delta = now - basetime.time
>         logger.error(str(time.time()) + " delta: " + str(delta) + ": " + message)
> 
> - David
> 
> > -----Original Message-----
> > From: Barros Pena, Belen [mailto:belen.barros.pena at intel.com]
> > Sent: Thursday, April 10, 2014 10:58 AM
> > To: Reyna, David; Lerner, Dave
> > Cc: DAMIAN, ALEXANDRU
> > Subject: Re: [review-request] 6137 excessive load time for All Recipes page
> >
> >
> > On 10/04/2014 17:23, "Reyna, David" <david.reyna at windriver.com> wrote:
> >
> > >Hi Belén,
> > >
> > >Your host may be much faster than mine, and the difference less obvious.
> > >Hopefully customers also have the faster machines.
> > >
> > >Dave has a nice little execution timing logger that I will set up and
> > >then share with you, which can be used for this and other render time
> > >reviews.
> >
> > Using the Chrome developer tools, the time differences between other
> > tables and the recipes one are still quite big:
> >
> > Packages built: 109ms for 55.5KB of content
> > Variables: 424ms for 234KB of content
> > Tasks: 262ms for 63.5KB of content
> > Recipes: 6.65 seconds for 240KB of content
> >
> > Those Chrome developer tools are quite nifty, I must say. I normally don't
> > use them much, but you guys might want to have a look at them.
> >
> > Cheers
> >
> > Belén
> >
> >
> > >
> > >- David
> > >
> > >> -----Original Message-----
> > >> From: Barros Pena, Belen [mailto:belen.barros.pena at intel.com]
> > >> Sent: Thursday, April 10, 2014 9:06 AM
> > >> To: Reyna, David; Lerner, Dave
> > >> Cc: toaster at yoctoproject.org
> > >> Subject: Re: [review-request] 6137 excessive load time for All Recipes
> > >>page
> > >>
> > >> On 09/04/2014 06:31, "Reyna, David" <david.reyna at windriver.com> wrote:
> > >>
> > >> >Hi Belén,
> > >> >
> > >> >Thanks to some advice from Dave, with this fix I have dramatically
> > >> >improved the load times for the All Recipes page, for example from
> > >>around
> > >> >17 seconds to around 11 seconds. The issue was redundant calls when
> > >> >calculating forward and reverse dependency
> > >> > lists per recipe. Simply using the ³with² clause resolved that.
> > >> >
> > >> >The branch is here: dreyna/recipes_loadtime_6137
> > >>
> > >> Just tested this fairly quickly and without timing anything, but I could
> > >> not see that much of an improvement. I am not sure what I am doing
> > >>wrong :/
> > >>
> > >> >
> > >> >- David
> > >> >
> > >> >
> > >>
> > >
> >