MAAS

'tags machines' takes 30+ seconds to respond with list of 9 nodes

Bug #1715634 reported by Jason Hobbs
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MAAS
Fix Released
Critical
Blake Rouse
MAAS 2.3.0alpha3
2.2
Fix Released
Critical
Blake Rouse
MAAS 2.2.3

Bug Description

I am issuing 'maas <profile> tag machines <tag>' calls to my maas server; it is taking 30+ seconds to respond, even when mostly idle otherwise.

I turned on slow query logging at 100 ms and I see that there are event log queries happening for each node, which are taking a long time to complete:

http://paste.ubuntu.com/25483865/

This is with 2.3.0~alpha2-6194-g7fb23b0-0ubuntu1~16.04.1

Tags: cdo-qa

Related branches

~blake-rouse/maas:query-count-tags-2.2
Blake Rouse (community): Approve
Diff: 308 lines (+217/-4)
2 files modified
src/maasserver/api/tags.py (+17/-4)
src/maasserver/api/tests/test_tag.py (+200/-0)
~blake-rouse/maas:query-count-tags
Mike Pontillo (community): Approve
Diff: 308 lines (+217/-4)
2 files modified
src/maasserver/api/tags.py (+17/-4)
src/maasserver/api/tests/test_tag.py (+200/-0)
Revision history for this message
Jason Hobbs (jason-hobbs) wrote :

The problem with the event query is that it's sorting by 'created', which there is no index for: http://paste.ubuntu.com/25483923/

It shouldn't need to sort by created time, since sorting by id will give the same results.

Revision history for this message
Jason Hobbs (jason-hobbs) wrote :

The event query is coming from the 'status_action' method on the node model. Changing it to just use -id dropped my API response time from 33 seconds to 27 seconds. So, an improvement, but not great yet.

Revision history for this message
Blake Rouse (blake-rouse) wrote :

Actually it must sort by created time because events can be created out of order, as they are now deferred processing and with multiple region workers and region controllers the order by ID cannot be guaranteed. The time the event comes in is saved in the queue and that is used to for the created time.

So we can only guarantee that the created times will be in the correct order to show the events.

Blake Rouse (blake-rouse)
Changed in maas:
status: New → Triaged
status: Triaged → In Progress
importance: Undecided → Critical
assignee: nobody → Blake Rouse (blake-rouse)
milestone: none → 2.3.0
Revision history for this message
Jason Hobbs (jason-hobbs) wrote :

Ok, then there should be an index on created. But, that's not the biggest problem. Even doing 'machine read' for a single node takes 6 - 7 seconds.

MAAS Lander (maas-lander)
Changed in maas:
status: In Progress → Fix Committed
Andres Rodriguez (andreserl)
Changed in maas:
milestone: 2.3.0 → 2.3.0alpha3
Revision history for this message
Jason Hobbs (jason-hobbs) wrote :

This made a huge difference for our system - this query is down to 3 seconds now.

Revision history for this message
Jason Hobbs (jason-hobbs) wrote :

(after manually applying the patch)

Andres Rodriguez (andreserl)
Changed in maas:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.