Slow API requests with 2.8 / master

[t-book]

Hi,

when requesting the layers view (/api/layers/?limit=20&offset=0) with GeoNode 2.8 (+master) postgreSql is hit for every layer the user has permissions for (direct SELECT WHERE ID = N):

SELECT "base_resourcebase"."id", "base_resourcebase"."polymorphic_ctype_id", "base_resourcebase"."uuid", "base_resourcebase"."owner_id", "base_resourcebase"."title", "base_resourcebase"."alternate", "base_resourcebase"."date", "base_resourcebase"."date_type", "base_resourcebase"."edition", "base_resourcebase"."abstract", "base_resourcebase"."purpose", "base_resourcebase"."maintenance_frequency", "base_resourcebase"."restriction_code_type_id", "base_resourcebase"."constraints_other", "base_resourcebase"."license_id", "base_resourcebase"."language", "base_resourcebase"."category_id", "base_resourcebase"."spatial_representation_type_id", "base_resourcebase"."temporal_extent_start", "base_resourcebase"."temporal_extent_end", "base_resourcebase"."supplemental_information", "base_resourcebase"."data_quality_statement", "base_resourcebase"."group_id", "base_resourcebase"."bbox_x0", "base_resourcebase"."bbox_x1", "base_resourcebase"."bbox_y0", "base_resourcebase"."bbox_y1", "base_resourcebase"."srid", "base_resourcebase"."csw_typename", "base_resourcebase"."csw_schema", "base_resourcebase"."csw_mdsource", "base_resourcebase"."csw_insert_date", "base_resourcebase"."csw_type", "base_resourcebase"."csw_anytext", "base_resourcebase"."csw_wkt_geometry", "base_resourcebase"."metadata_uploaded", "base_resourcebase"."metadata_uploaded_preserve", "base_resourcebase"."metadata_xml", "base_resourcebase"."popular_count", "base_resourcebase"."share_count", "base_resourcebase"."featured", "base_resourcebase"."is_published", "base_resourcebase"."is_approved", "base_resourcebase"."thumbnail_url", "base_resourcebase"."detail_url", "base_resourcebase"."rating" FROM "base_resourcebase" WHERE "base_resourcebase"."id" = 3455
...
SELECT .... WHERE "base_resourcebase"."id" = 3456
SELECT ... WHERE "base_resourcebase"."id" = 3457
... and 5000 times more

This is resulting in slow loading (slow TTFB) And shows more clear on content heavy GeoNodes.
Can one shed some light if this is by design of tastypie/oauth2 or why this overhead is needed (wasn´t with 2.4)? – If this is needed I would expect the db queries only for the requested subset (LIMIT 20)?

Thanks,

– Toni

[afabiani]

@t-book this is indeed something that must be better inspected. I guess it is the result of mixing old/new design mechanisms. Putting in on my todo list.

[t-book]

Thanks a lot Alessio!

[afabiani]

@t-book I have digged a bit more on this topic (I'm on master branch right now) and those are my current findings:

1. The additional queries have been done by the following method

https://github.com/GeoNode/geonode/blob/master/geonode/api/resourcebase_api.py#L714

In particular, this is trying to enrich the Layer details in order to populate the JSON output.

By removing some details, e.g. owner name, keywords, links and so on, it should reduce and/or completely bypass additional DB queries.

2. At least on master branch, the length of objects array (len(object)) corresponds to the specified limit number. That said the number of queries is limited to the limit number.

Do you have the chance to debug a bit this behavior on 2.8.x also?

[t-book]

Dear Alessio, thanks a lot providing your findings. I´ll have a look at 2.8 and come back! Thanks!

[giohappy]

I would add that not having a cache for the API requests sharpens this even more...

[t-book]

Dear @afabiani,

it was a busy day. So only a brief update.

I can confirm the length of the obj is 20 as the api GET forces but
removing some fields does not lower the database queries.

            '''
            formatted_obj['owner__username'] = username
            formatted_obj['owner_name'] = full_name
            if obj.category:
               formatted_obj['category__gn_description'] = obj.category.gn_description
            if obj.group:
                formatted_obj['group'] = obj.group
                try:
                    formatted_obj['group_name'] = GroupProfile.objects.get(slug=obj.group.name)
                except GroupProfile.DoesNotExist:
                    formatted_obj['group_name'] = obj.group

            formatted_obj['keywords'] = [k.name for k in obj.keywords.all()] if obj.keywords else []
            formatted_obj['regions'] = [r.name for r in obj.regions.all()] if obj.regions else []

            # add the geogig link
            formatted_obj['geogig_link'] = obj.geogig_link

            # provide style information
            bundle = self.build_bundle(obj=obj)
            formatted_obj['default_style'] = self.default_style.dehydrate(
                bundle, for_list=True)

            if self.links.use_in == 'all' or self.links.use_in == 'list':
               formatted_obj['links'] = self.dehydrate_links(
                   bundle)
            # Add resource uri
            formatted_obj['resource_uri'] = self.get_resource_uri(bundle)
            '''

My guess is by this we just reduce the amount of selected fields?

Just to be sure my testing is correct:
This is what I did:

• /etc/postgresql/9.5/main/postgresql.conf
  log_statement = 'all'
• truncate postgresql.log
• request to api /api/layers/?limit=20&offset=0
• sudo grep -o 'SELECT' /var/log/postgresql/postgresql-9.5-main.log | wc -l

Count: 2596 selects which reflects more or less the total amount of 2286 layers.
Further looking at the IDs I can confirm a select is run agains every layer.

I will have a closer look by tomorrow and will try to just return an empty object. Let´s see if this reduces the queries. Thanks a lot for your help!

[afabiani]

@t-book uhm that's weird. In that case, I don't understand where those additional queries come from if the length of the obj is 20.

On my tests I only looked at the queries printed by "django" logs at DEBUG level.

Could you maybe check if the method "get_visible_resources" adds such overhead?

However, in the last case, it won't be trivial updating the logic, since in that case we will allow everyone fetching private/unpublished layers too.

[t-book]

@afabiani Thanks for your feedback. I´ll test your suggestion and double check with django debug toolbar. I´ll keep you updated!

[t-book]

@afabiani I´ve digged a bit deaper. You´re right we can lower the load a bit by removing fields. But this did not significantly speed up the request.

The easiest test I could think of:

• Geonode with two layers (no matter if 2.8 or master)
• Call layer api with limit 1

• I get json back for one layer but database is hit twice (for both layers which GeonodeApiKeyAuthentication is allowing).

Is it possible that it´s the queryset https://github.com/GeoNode/geonode/blob/master/geonode/api/resourcebase_api.py#L882
which hydrates with all layers? (I´ve already tried to slice it by offset but it´s failing as slice and a following filter does not work but a .filter(string__contains='something') definitely limits the hits).

Anyways before rocking the boat it would be

• good to know if others experience slow loading with lot of layers ( @capooti ? )
• See how tastypie works behind the scenes (should be already limited by paginator class?)
• +1 @giohappy ´s comment regarding caching again

[capooti]

de-hydratation is detrimental for performances! Avoid to use it the more you can.

Currently I am using a custom API, you can check it out here: https://github.com/cga-harvard/worldmap/blob/2.10.x/worldmap_site/api.py

It is very easy to enable it in the template of the geonode project (no need to fork):

https://github.com/cga-harvard/worldmap/blob/2.10.x/worldmap_site/templates/layers/layer_list.html#L33

https://github.com/cga-harvard/worldmap/blob/2.10.x/worldmap_site/templates/maps/map_list.html#L25

This is extremely fast with 20,000+ layers:
http://128.31.22.103/layers/?limit=20&offset=0

[t-book]

@capooti big thumbs up! – thanks!

[giohappy]

and my recent commit 704b8d5 exacerbates this even more :)
The current API code is quite convoluted and does a lot of work to extract relevant related data for layers. Maybe a simplified API could be introced along the full one, but we I think we can't get rid of it because several systems rely on it (for instance QGIS GeoNode provider, for which I reintroduced the OGC links)

[t-book]

Maybe a simplified API could be introced along the full one, but we I think we can't get rid of it because several systems rely on it (for instance QGIS GeoNode provider, for which I reintroduced the OGC links)

@giohappy Can we rely on apps [1] or USE_GEOSERVER = False [2]
to adjust the amount of de-hydrated data (geoserver vs. qgis) ?

@capooti Just testing with > 5000 layers indeed your version is way faster ...

[1] https://github.com/GeoNode/geonode/blob/master/geonode/settings.py#L299
[2] https://github.com/GeoNode/geonode/blob/master/geonode/local_settings.py.qgis.sample#L51

[giohappy]

@t-book some checks to distinguish between the backends are already in place, but most of the dehydrated informations affect both.
I think we should dig more on the number of queries actually done and understand exactly where they are issued.

[capooti]

@t-book glad you like it. Not sure if all filters are enabled, that also explains the speed

@giohappy I think it is the combination de-hydratation/ORM to slow down things when you have many resources. I remember when I wanted to fix our problems, looking at the Django toolbar the queries where run for all the resources and not only for the paginated ones. I tried to figure out the problem but couldn't so I prefered to start API from scratch keeping things simple.

[afabiani]

should be fixed now, let's re-open this if this occurs again.