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

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

[Reyna, David]

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@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@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@intel.com]
> >> Sent: Thursday, April 10, 2014 9:06 AM
> >> To: Reyna, David; Lerner, Dave
> >> Cc: toaster@yoctoproject.org
> >> Subject: Re: [review-request] 6137 excessive load time for All Recipes
> >>page
> >>
> >> On 09/04/2014 06:31, "Reyna, David" <david.reyna@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
> >> >
> >> >
> >>
> >
> 

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

[Barros Pena, Belen]

On 11/04/2014 01:44, "Reyna, David" <david.reyna@windriver.com> wrote:

>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

This is obviously a huge improvement. What bothers me is that the Recipes
page still seems to be performing much worse than all other pages. Should
we be trying to fix the root cause of the problem, ie. the "100*(2+2)
foreign key lookups and filters/count"?

Thanks!

Belén

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

[Lerner, Dave]

If we split recipes into 1 html page per tab, then the apparent delays will be split into a few seconds per tab switch, and probably less since the tab-specific queries can be optimized further using either the forward or reverse joins on package and package_dependency (for example for the package tab).

However, the greatest side effect of that change, 1 html page per tab, is simplicity in using other 'included' pages that define sorting and search bars without adding a lot of logic that tries to send the active #anchor from the client to the server in some encoded form, and then re-encode it back through our view functions to the client.

Also I feel strongly that the simplest solution is to switch to a default of 25 rows for this view.  Here's why: we have column sorting, and rows-per-page widgets, so I don't feel that the primary workflow will be perusing long lists, but rather filtering to find what you want, either by entering strings, sorting alphabetically, or sorting on size.  

For that matter (an aside) if long list browsing must be supported, then there isn't a reason  to constrain that list to 100 rows - it should be a pull-down or input field with a max value on the order of 10^3 rows.

Dave
> -----Original Message-----
> From: Barros Pena, Belen [mailto:belen.barros.pena@intel.com]
> Sent: Friday, April 11, 2014 7:41 AM
> To: Reyna, David; Lerner, Dave
> Cc: toaster@yoctoproject.org
> Subject: Re: [review-request] V2: 6137 excessive load time for All Recipes page
> 
> On 11/04/2014 01:44, "Reyna, David" <david.reyna@windriver.com> wrote:
> 
> >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
> 
> This is obviously a huge improvement. What bothers me is that the Recipes
> page still seems to be performing much worse than all other pages. Should
> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
> foreign key lookups and filters/count"?
> 
> Thanks!
> 
> Belén
> 

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

[Reyna, David]

Hi Dave,

> If we split recipes into 1 html page per tab, ...

I think that you are referring to the Recipe Detail page (recipe.html). That page does have four tabs (implemented as "wells"), but it is very small and localized to a single recipe, so I do not see load delays.

The page I am referring to is the "All Recipes" page (recipes.html). It has no tabs. It does have a column for forward dependencies and a column for reverse dependencies per package, and that is where the load time comes from.

We can certainly consider reducing the default count from 100 to 25, but I think that my proposed speed up is applicable in all cases, especially if the user decides they really want to 100 line view for their own purposes.

- David


> -----Original Message-----
> From: Lerner, Dave
> Sent: Friday, April 11, 2014 7:20 AM
> To: BARROS PENA, BELEN; Reyna, David
> Cc: toaster@yoctoproject.org
> Subject: RE: [review-request] V2: 6137 excessive load time for All Recipes
> page
> 
> If we split recipes into 1 html page per tab, then the apparent delays will
> be split into a few seconds per tab switch, and probably less since the tab-
> specific queries can be optimized further using either the forward or reverse
> joins on package and package_dependency (for example for the package tab).
> 
> However, the greatest side effect of that change, 1 html page per tab, is
> simplicity in using other 'included' pages that define sorting and search
> bars without adding a lot of logic that tries to send the active #anchor from
> the client to the server in some encoded form, and then re-encode it back
> through our view functions to the client.
> 
> Also I feel strongly that the simplest solution is to switch to a default of
> 25 rows for this view.  Here's why: we have column sorting, and rows-per-page
> widgets, so I don't feel that the primary workflow will be perusing long
> lists, but rather filtering to find what you want, either by entering
> strings, sorting alphabetically, or sorting on size.
> 
> For that matter (an aside) if long list browsing must be supported, then
> there isn't a reason  to constrain that list to 100 rows - it should be a
> pull-down or input field with a max value on the order of 10^3 rows.
> 
> Dave
> > -----Original Message-----
> > From: Barros Pena, Belen [mailto:belen.barros.pena@intel.com]
> > Sent: Friday, April 11, 2014 7:41 AM
> > To: Reyna, David; Lerner, Dave
> > Cc: toaster@yoctoproject.org
> > Subject: Re: [review-request] V2: 6137 excessive load time for All Recipes
> page
> >
> > On 11/04/2014 01:44, "Reyna, David" <david.reyna@windriver.com> wrote:
> >
> > >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
> >
> > This is obviously a huge improvement. What bothers me is that the Recipes
> > page still seems to be performing much worse than all other pages. Should
> > we be trying to fix the root cause of the problem, ie. the "100*(2+2)
> > foreign key lookups and filters/count"?
> >
> > Thanks!
> >
> > Belén
> >

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

[Reyna, David]

Hi Belén,

> page still seems to be performing much worse than all other pages. Should
> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
> foreign key lookups and filters/count"?

If we stay with the current design of the page, then I think the solution is along the lines:

  1. Add two fields to the Recipe class to hold the respective forward and reverse counts to support instant lookup. These values are fixed when the build completes so they can be consider constant for our purposes, plus they would add very little overhead to the database (if you can get this proposal past Alex). An alternate implementation to keep the database pristine is to add the ability to cache information like this in some runtime table, so that the calculation time is only spent once.

  2. Add a dynamic lookup of a given forward or reverse dependency list when one of those buttons are clicked. In this manner we only spend the list computation time when explicitly asked, not for every recipe whether they want it or not.

- David

> -----Original Message-----
> From: Barros Pena, Belen [mailto:belen.barros.pena@intel.com]
> Sent: Friday, April 11, 2014 5:41 AM
> To: Reyna, David; Lerner, Dave
> Cc: toaster@yoctoproject.org
> Subject: Re: [review-request] V2: 6137 excessive load time for All Recipes
> page
> 
> On 11/04/2014 01:44, "Reyna, David" <david.reyna@windriver.com> wrote:
> 
> >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
> 
> This is obviously a huge improvement. What bothers me is that the Recipes
> page still seems to be performing much worse than all other pages. Should
> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
> foreign key lookups and filters/count"?
> 
> Thanks!
> 
> Belén
> 

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

[Damian, Alexandru]

[-- Attachment #1.1: Type: text/plain, Size: 2929 bytes --]

Hello,

I have a small modification to David's patch that improves the loading time
about 5-fold compared to his latest version, from 5 seconds to less than 1
second on my laptop.

The trick used is to bring the whole list of dependencies for the entire
recipe list in a single call, and do the match manually, instead of getting
a call per recipe.

This approach allows the code to perform constant lookup times independent
of number of rows.

Since I can't push to contrib on my laptop (something funky about keys),
I'm attaching the patch for review.

Please let me know how it goes.

Cheers,
Alex


On Fri, Apr 11, 2014 at 5:26 PM, Reyna, David <david.reyna@windriver.com>wrote:

> Hi Belén,
>
> > page still seems to be performing much worse than all other pages. Should
> > we be trying to fix the root cause of the problem, ie. the "100*(2+2)
> > foreign key lookups and filters/count"?
>
> If we stay with the current design of the page, then I think the solution
> is along the lines:
>
>   1. Add two fields to the Recipe class to hold the respective forward and
> reverse counts to support instant lookup. These values are fixed when the
> build completes so they can be consider constant for our purposes, plus
> they would add very little overhead to the database (if you can get this
> proposal past Alex). An alternate implementation to keep the database
> pristine is to add the ability to cache information like this in some
> runtime table, so that the calculation time is only spent once.
>
>   2. Add a dynamic lookup of a given forward or reverse dependency list
> when one of those buttons are clicked. In this manner we only spend the
> list computation time when explicitly asked, not for every recipe whether
> they want it or not.
>
> - David
>
> > -----Original Message-----
> > From: Barros Pena, Belen [mailto:belen.barros.pena@intel.com]
> > Sent: Friday, April 11, 2014 5:41 AM
> > To: Reyna, David; Lerner, Dave
> > Cc: toaster@yoctoproject.org
> > Subject: Re: [review-request] V2: 6137 excessive load time for All
> Recipes
> > page
> >
> > On 11/04/2014 01:44, "Reyna, David" <david.reyna@windriver.com> wrote:
> >
> > >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
> >
> > This is obviously a huge improvement. What bothers me is that the Recipes
> > page still seems to be performing much worse than all other pages. Should
> > we be trying to fix the root cause of the problem, ie. the "100*(2+2)
> > foreign key lookups and filters/count"?
> >
> > Thanks!
> >
> > Belén
> >
>
> --
> _______________________________________________
> toaster mailing list
> toaster@yoctoproject.org
> https://lists.yoctoproject.org/listinfo/toaster
>



-- 
Alex Damian
Yocto Project
SSG / OTC

[-- Attachment #1.2: Type: text/html, Size: 4970 bytes --]

[-- Attachment #2: 0001-bitbake-toaster-reduce-redundant-foreign-key-lookups.patch --]
[-- Type: text/x-patch, Size: 4552 bytes --]

From 520ebcc860ce11cbb3751cb8cdc4e7a0c22a7bb5 Mon Sep 17 00:00:00 2001
From: David Reyna <David.Reyna@windriver.com>
Date: Tue, 8 Apr 2014 22:25:13 -0700
Subject: [PATCH 1/1] bitbake: toaster: reduce redundant foreign key lookups

Replace redundant foreign key lookups with "with" to
improve all recipes page load time.

Modified by Alex to improve loading time.

[YOCTO #6137]

Signed-off-by: David Reyna <David.Reyna@windriver.com>
Signed-off-by: Alex D <ddalex@gmail.com>
---
 .../lib/toaster/toastergui/templates/recipes.html    | 20 ++++++++++++++------
 bitbake/lib/toaster/toastergui/views.py              | 18 ++++++++++++++++++
 2 files changed, 32 insertions(+), 6 deletions(-)

diff --git a/bitbake/lib/toaster/toastergui/templates/recipes.html b/bitbake/lib/toaster/toastergui/templates/recipes.html
index 907b83d..791a487 100755
--- a/bitbake/lib/toaster/toastergui/templates/recipes.html
+++ b/bitbake/lib/toaster/toastergui/templates/recipes.html
@@ -45,31 +45,39 @@
         <td><a href="{% url "recipe" build.pk recipe.pk %}">{{recipe.version}}</a></td>
         <!-- Depends -->
         <td class="depends_on">
-            {% if recipe.r_dependencies_recipe.all.count %}
+            {% with deps=recipe_deps|get_dict_value:recipe.pk %}
+            {% with count=deps|length %}
+            {% if count %}
             <a class="btn"
                 title="<a href='{% url "recipe" build.pk recipe.pk %}#dependencies'>{{recipe.name}}</a> dependencies"
                 data-content="<ul class='unstyled'>
-                  {% for i in recipe.r_dependencies_recipe.all|dictsort:"depends_on.name"%}
+                  {% for i in deps|dictsort:"depends_on.name"%}
                     <li><a href='{% url "recipe" build.pk i.depends_on.pk %}'>{{i.depends_on.name}}</a></li>
                   {% endfor %}
                 </ul>">
-                {{recipe.r_dependencies_recipe.all.count}}
+                {{count}}
             </a>
             {% endif %}
+            {% endwith %}
+            {% endwith %}
         </td>
         <!--  Brought in by -->
         <td class="depends_by">
-            {% if recipe.r_dependencies_depends.all.count %}
+            {% with revs=recipe_revs|get_dict_value:recipe.pk %}
+            {% with count=revs|length %}
+            {% if count %}
             <a class="btn"
                 title="<a href='{% url "recipe" build.pk recipe.pk %}#brought-in-by'>{{recipe.name}}</a> reverse dependencies"
                 data-content="<ul class='unstyled'>
-                  {% for i in recipe.r_dependencies_depends.all|dictsort:"recipe.name"%}
+                  {% for i in revs|dictsort:"recipe.name" %}
                     <li><a href='{% url "recipe" build.pk i.recipe.pk %}'>{{i.recipe.name}}</a></li>
                   {% endfor %}
                 </ul>">
-                {{recipe.r_dependencies_depends.all.count}}
+                {{count}}
             </a>
             {% endif %}
+            {% endwith %}
+            {% endwith %}
         </td>
         <!-- Recipe file -->
         <td class="recipe_file">{{recipe.file_path}}</td>
diff --git a/bitbake/lib/toaster/toastergui/views.py b/bitbake/lib/toaster/toastergui/views.py
index e4ada14..e22e87c 100644
--- a/bitbake/lib/toaster/toastergui/views.py
+++ b/bitbake/lib/toaster/toastergui/views.py
@@ -1037,10 +1037,28 @@ def recipes(request, build_id):
 
     recipes = _build_page_range(Paginator(queryset, request.GET.get('count', 100)),request.GET.get('page', 1))
 
+    # prefetch the forward and reverse recipe dependencies
+    deps = { }; revs = { }
+    queryset_dependency=Recipe_Dependency.objects.filter(recipe__in=map(lambda x: x.id, recipes.object_list));
+    for recipe in recipes:
+        deplist = [ ]
+        for recipe_dep in [x for x in queryset_dependency if x.recipe_id == recipe.id]:
+            deplist.append(recipe_dep) 
+        deps[recipe.id] = deplist
+
+    queryset_dependency=Recipe_Dependency.objects.filter(depends_on__in=map(lambda x: x.id, recipes.object_list));
+    for recipe in recipes:
+        revlist = [ ]
+        for recipe_dep in [x for x in queryset_dependency if x.depends_on_id == recipe.id]:
+            revlist.append(recipe_dep) 
+        revs[recipe.id] = revlist
+
     context = {
         'objectname': 'recipes',
         'build': Build.objects.filter(pk=build_id)[0],
         'objects': recipes,
+        'recipe_deps' : deps,
+        'recipe_revs' : revs,
         'tablecols':[
             {
                 'name':'Recipe',
-- 
1.8.3.2

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

[Reyna, David]

[-- Attachment #1: Type: text/plain, Size: 3458 bytes --]

Yeow! All of 1 second render time on my slow host!

  1397242146.23:RECIPES
  1397242147.32 delta: 1.09702301025: RECIPES

I have updated my commit with your change:  dreyna/recipes_loadtime_6137

- David

From: Damian, Alexandru [mailto:alexandru.damian@intel.com]
Sent: Friday, April 11, 2014 11:05 AM
To: Reyna, David
Cc: BARROS PENA, BELEN; Lerner, Dave; toaster@yoctoproject.org
Subject: Re: [Toaster] [review-request] V2: 6137 excessive load time for All Recipes page

Hello,

I have a small modification to David's patch that improves the loading time about 5-fold compared to his latest version, from 5 seconds to less than 1 second on my laptop.

The trick used is to bring the whole list of dependencies for the entire recipe list in a single call, and do the match manually, instead of getting a call per recipe.

This approach allows the code to perform constant lookup times independent of number of rows.

Since I can't push to contrib on my laptop (something funky about keys), I'm attaching the patch for review.

Please let me know how it goes.

Cheers,
Alex

On Fri, Apr 11, 2014 at 5:26 PM, Reyna, David <david.reyna@windriver.com<mailto:david.reyna@windriver.com>> wrote:
Hi Belén,

> page still seems to be performing much worse than all other pages. Should
> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
> foreign key lookups and filters/count"?
If we stay with the current design of the page, then I think the solution is along the lines:

  1. Add two fields to the Recipe class to hold the respective forward and reverse counts to support instant lookup. These values are fixed when the build completes so they can be consider constant for our purposes, plus they would add very little overhead to the database (if you can get this proposal past Alex). An alternate implementation to keep the database pristine is to add the ability to cache information like this in some runtime table, so that the calculation time is only spent once.

  2. Add a dynamic lookup of a given forward or reverse dependency list when one of those buttons are clicked. In this manner we only spend the list computation time when explicitly asked, not for every recipe whether they want it or not.

- David

> -----Original Message-----
> From: Barros Pena, Belen [mailto:belen.barros.pena@intel.com<mailto:belen.barros.pena@intel.com>]
> Sent: Friday, April 11, 2014 5:41 AM
> To: Reyna, David; Lerner, Dave
> Cc: toaster@yoctoproject.org<mailto:toaster@yoctoproject.org>
> Subject: Re: [review-request] V2: 6137 excessive load time for All Recipes
> page
>
> On 11/04/2014 01:44, "Reyna, David" <david.reyna@windriver.com<mailto:david.reyna@windriver.com>> wrote:
>
> >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
>
> This is obviously a huge improvement. What bothers me is that the Recipes
> page still seems to be performing much worse than all other pages. Should
> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
> foreign key lookups and filters/count"?
>
> Thanks!
>
> Belén
>

--
_______________________________________________
toaster mailing list
toaster@yoctoproject.org<mailto:toaster@yoctoproject.org>
https://lists.yoctoproject.org/listinfo/toaster



--
Alex Damian
Yocto Project
SSG / OTC

[-- Attachment #2: Type: text/html, Size: 10059 bytes --]

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

[Barros Pena, Belen]

On 11/04/2014 19:57, "Reyna, David" <david.reyna@windriver.com> wrote:

>Yeow! All of 1 second render time on my slow host!
> 
>  1397242146.23:RECIPES
>  1397242147.32 delta: 1.09702301025: RECIPES
> 
>I have updated my commit with your change:  dreyna/recipes_loadtime_61

Very impressive :)

> 
>- David
> 
>From: Damian, Alexandru [mailto:alexandru.damian@intel.com]
>
>Sent: Friday, April 11, 2014 11:05 AM
>To: Reyna, David
>Cc: BARROS PENA, BELEN; Lerner, Dave; toaster@yoctoproject.org
>Subject: Re: [Toaster] [review-request] V2: 6137 excessive load time for
>All Recipes page
>
>
> 
>Hello,
>
> 
>
>I have a small modification to David's patch that improves the loading
>time about 5-fold compared to his latest version, from 5 seconds to less
>than 1 second on my laptop.
>
> 
>
>The trick used is to bring the whole list of dependencies for the entire
>recipe list in a single call, and do the match manually, instead of
>getting a call per recipe.
>
> 
>
>This approach allows the code to perform constant lookup times
>independent of number of rows.
>
> 
>
>Since I can't push to contrib on my laptop (something funky about keys),
>I'm attaching the patch for review.
>
> 
>
>Please let me know how it goes.
>
> 
>
>Cheers,
>
>Alex
>
>
> 
>On Fri, Apr 11, 2014 at 5:26 PM, Reyna, David <david.reyna@windriver.com>
>wrote:
>Hi Belén,
>
>> page still seems to be performing much worse than all other pages.
>>Should
>> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
>> foreign key lookups and filters/count"?
>
>If we stay with the current design of the page, then I think the solution
>is along the lines:
>
>  1. Add two fields to the Recipe class to hold the respective forward
>and reverse counts to support instant lookup. These values are fixed when
>the build completes so they can be consider constant for our purposes,
>plus they would add very little overhead
> to the database (if you can get this proposal past Alex). An alternate
>implementation to keep the database pristine is to add the ability to
>cache information like this in some runtime table, so that the
>calculation time is only spent once.
>
>  2. Add a dynamic lookup of a given forward or reverse dependency list
>when one of those buttons are clicked. In this manner we only spend the
>list computation time when explicitly asked, not for every recipe whether
>they want it or not.
>
>- David
>
>> -----Original Message-----
>> From: Barros Pena, Belen [mailto:belen.barros.pena@intel.com]
>
>> Sent: Friday, April 11, 2014 5:41 AM
>> To: Reyna, David; Lerner, Dave
>> Cc: toaster@yoctoproject.org
>
>> Subject: Re: [review-request] V2: 6137 excessive load time for All
>>Recipes
>> page
>>
>
>> On 11/04/2014 01:44, "Reyna, David" <david.reyna@windriver.com> wrote:
>>
>> >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
>>
>> This is obviously a huge improvement. What bothers me is that the
>>Recipes
>> page still seems to be performing much worse than all other pages.
>>Should
>> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
>> foreign key lookups and filters/count"?
>>
>> Thanks!
>>
>> Belén
>>
>
>--
>_______________________________________________
>toaster mailing list
>toaster@yoctoproject.org
>https://lists.yoctoproject.org/listinfo/toaster
>
>
>
>
>
>
> 
>
>-- 
>Alex Damian
>Yocto Project
>
>SSG / OTC 
>
>
>
>
>

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

[Damian, Alexandru]

[-- Attachment #1: Type: text/plain, Size: 4363 bytes --]

I replied to the other 6137 with a refactor request at some points in code -

- filtering Recipe_Dependency so we don't load the whole table in memory;
this is not scalable; we need to load Recipe_dependency only for recipes
currently displayed in page

- whitespace in views.py

Thank you,
Alex



On Mon, Apr 14, 2014 at 12:35 PM, Barros Pena, Belen <
belen.barros.pena@intel.com> wrote:

>
> On 11/04/2014 19:57, "Reyna, David" <david.reyna@windriver.com> wrote:
>
> >Yeow! All of 1 second render time on my slow host!
> >
> >  1397242146.23:RECIPES
> >  1397242147.32 delta: 1.09702301025: RECIPES
> >
> >I have updated my commit with your change:  dreyna/recipes_loadtime_61
>
> Very impressive :)
>
> >
> >- David
> >
> >From: Damian, Alexandru [mailto:alexandru.damian@intel.com]
> >
> >Sent: Friday, April 11, 2014 11:05 AM
> >To: Reyna, David
> >Cc: BARROS PENA, BELEN; Lerner, Dave; toaster@yoctoproject.org
> >Subject: Re: [Toaster] [review-request] V2: 6137 excessive load time for
> >All Recipes page
> >
> >
> >
> >Hello,
> >
> >
> >
> >I have a small modification to David's patch that improves the loading
> >time about 5-fold compared to his latest version, from 5 seconds to less
> >than 1 second on my laptop.
> >
> >
> >
> >The trick used is to bring the whole list of dependencies for the entire
> >recipe list in a single call, and do the match manually, instead of
> >getting a call per recipe.
> >
> >
> >
> >This approach allows the code to perform constant lookup times
> >independent of number of rows.
> >
> >
> >
> >Since I can't push to contrib on my laptop (something funky about keys),
> >I'm attaching the patch for review.
> >
> >
> >
> >Please let me know how it goes.
> >
> >
> >
> >Cheers,
> >
> >Alex
> >
> >
> >
> >On Fri, Apr 11, 2014 at 5:26 PM, Reyna, David <david.reyna@windriver.com>
> >wrote:
> >Hi Belén,
> >
> >> page still seems to be performing much worse than all other pages.
> >>Should
> >> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
> >> foreign key lookups and filters/count"?
> >
> >If we stay with the current design of the page, then I think the solution
> >is along the lines:
> >
> >  1. Add two fields to the Recipe class to hold the respective forward
> >and reverse counts to support instant lookup. These values are fixed when
> >the build completes so they can be consider constant for our purposes,
> >plus they would add very little overhead
> > to the database (if you can get this proposal past Alex). An alternate
> >implementation to keep the database pristine is to add the ability to
> >cache information like this in some runtime table, so that the
> >calculation time is only spent once.
> >
> >  2. Add a dynamic lookup of a given forward or reverse dependency list
> >when one of those buttons are clicked. In this manner we only spend the
> >list computation time when explicitly asked, not for every recipe whether
> >they want it or not.
> >
> >- David
> >
> >> -----Original Message-----
> >> From: Barros Pena, Belen [mailto:belen.barros.pena@intel.com]
> >
> >> Sent: Friday, April 11, 2014 5:41 AM
> >> To: Reyna, David; Lerner, Dave
> >> Cc: toaster@yoctoproject.org
> >
> >> Subject: Re: [review-request] V2: 6137 excessive load time for All
> >>Recipes
> >> page
> >>
> >
> >> On 11/04/2014 01:44, "Reyna, David" <david.reyna@windriver.com> wrote:
> >>
> >> >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
> >>
> >> This is obviously a huge improvement. What bothers me is that the
> >>Recipes
> >> page still seems to be performing much worse than all other pages.
> >>Should
> >> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
> >> foreign key lookups and filters/count"?
> >>
> >> Thanks!
> >>
> >> Belén
> >>
> >
> >--
> >_______________________________________________
> >toaster mailing list
> >toaster@yoctoproject.org
> >https://lists.yoctoproject.org/listinfo/toaster
> >
> >
> >
> >
> >
> >
> >
> >
> >--
> >Alex Damian
> >Yocto Project
> >
> >SSG / OTC
> >
> >
> >
> >
> >
>
>


-- 
Alex Damian
Yocto Project
SSG / OTC

[-- Attachment #2: Type: text/html, Size: 6543 bytes --]

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

[Reyna, David]

[-- Attachment #1: Type: text/plain, Size: 5034 bytes --]

Hi Alex,

I have redone my commit as per your comments: dreyna/recipes_loadtime_6137

Here is the new query command:

   queryset_dependency=Recipe_Dependency.objects.filter(recipe__layer_version__build_id = build_id)

I was able to find a relation to the “build_id“ for any given recipe via its “layer_version” member, and I am using that to filter the queryset.

- David

From: Damian, Alexandru [mailto:alexandru.damian@intel.com]
Sent: Thursday, May 08, 2014 5:54 AM
To: BARROS PENA, BELEN
Cc: Reyna, David; Lerner, Dave; toaster@yoctoproject.org
Subject: Re: [Toaster] [review-request] V2: 6137 excessive load time for All Recipes page

I replied to the other 6137 with a refactor request at some points in code -
- filtering Recipe_Dependency so we don't load the whole table in memory; this is not scalable; we need to load Recipe_dependency only for recipes currently displayed in page
- whitespace in views.py
Thank you,
Alex


On Mon, Apr 14, 2014 at 12:35 PM, Barros Pena, Belen <belen.barros.pena@intel.com<mailto:belen.barros.pena@intel.com>> wrote:

On 11/04/2014 19:57, "Reyna, David" <david.reyna@windriver.com<mailto:david.reyna@windriver.com>> wrote:

>Yeow! All of 1 second render time on my slow host!
>
>  1397242146.23:RECIPES
>  1397242147.32 delta: 1.09702301025: RECIPES
>
>I have updated my commit with your change:  dreyna/recipes_loadtime_61
Very impressive :)

>
>- David
>
>From: Damian, Alexandru [mailto:alexandru.damian@intel.com<mailto:alexandru.damian@intel.com>]
>
>Sent: Friday, April 11, 2014 11:05 AM
>To: Reyna, David
>Cc: BARROS PENA, BELEN; Lerner, Dave; toaster@yoctoproject.org<mailto:toaster@yoctoproject.org>
>Subject: Re: [Toaster] [review-request] V2: 6137 excessive load time for
>All Recipes page
>
>
>
>Hello,
>
>
>
>I have a small modification to David's patch that improves the loading
>time about 5-fold compared to his latest version, from 5 seconds to less
>than 1 second on my laptop.
>
>
>
>The trick used is to bring the whole list of dependencies for the entire
>recipe list in a single call, and do the match manually, instead of
>getting a call per recipe.
>
>
>
>This approach allows the code to perform constant lookup times
>independent of number of rows.
>
>
>
>Since I can't push to contrib on my laptop (something funky about keys),
>I'm attaching the patch for review.
>
>
>
>Please let me know how it goes.
>
>
>
>Cheers,
>
>Alex
>
>
>
>On Fri, Apr 11, 2014 at 5:26 PM, Reyna, David <david.reyna@windriver.com<mailto:david.reyna@windriver.com>>
>wrote:
>Hi Belén,
>
>> page still seems to be performing much worse than all other pages.
>>Should
>> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
>> foreign key lookups and filters/count"?
>
>If we stay with the current design of the page, then I think the solution
>is along the lines:
>
>  1. Add two fields to the Recipe class to hold the respective forward
>and reverse counts to support instant lookup. These values are fixed when
>the build completes so they can be consider constant for our purposes,
>plus they would add very little overhead
> to the database (if you can get this proposal past Alex). An alternate
>implementation to keep the database pristine is to add the ability to
>cache information like this in some runtime table, so that the
>calculation time is only spent once.
>
>  2. Add a dynamic lookup of a given forward or reverse dependency list
>when one of those buttons are clicked. In this manner we only spend the
>list computation time when explicitly asked, not for every recipe whether
>they want it or not.
>
>- David
>
>> -----Original Message-----
>> From: Barros Pena, Belen [mailto:belen.barros.pena@intel.com<mailto:belen.barros.pena@intel.com>]
>
>> Sent: Friday, April 11, 2014 5:41 AM
>> To: Reyna, David; Lerner, Dave
>> Cc: toaster@yoctoproject.org<mailto:toaster@yoctoproject.org>
>
>> Subject: Re: [review-request] V2: 6137 excessive load time for All
>>Recipes
>> page
>>
>
>> On 11/04/2014 01:44, "Reyna, David" <david.reyna@windriver.com<mailto:david.reyna@windriver.com>> wrote:
>>
>> >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
>>
>> This is obviously a huge improvement. What bothers me is that the
>>Recipes
>> page still seems to be performing much worse than all other pages.
>>Should
>> we be trying to fix the root cause of the problem, ie. the "100*(2+2)
>> foreign key lookups and filters/count"?
>>
>> Thanks!
>>
>> Belén
>>
>
>--
>_______________________________________________
>toaster mailing list
>toaster@yoctoproject.org<mailto:toaster@yoctoproject.org>
>https://lists.yoctoproject.org/listinfo/toaster
>
>
>
>
>
>
>
>
>--
>Alex Damian
>Yocto Project
>
>SSG / OTC
>
>
>
>
>



--
Alex Damian
Yocto Project
SSG / OTC

[-- Attachment #2: Type: text/html, Size: 11564 bytes --]

Re: [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@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@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@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@intel.com]
> > >> Sent: Thursday, April 10, 2014 9:06 AM
> > >> To: Reyna, David; Lerner, Dave
> > >> Cc: toaster@yoctoproject.org
> > >> Subject: Re: [review-request] 6137 excessive load time for All Recipes
> > >>page
> > >>
> > >> On 09/04/2014 06:31, "Reyna, David" <david.reyna@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
> > >> >
> > >> >
> > >>
> > >
> >