Logbook speedup (#12566)

* Optimize logbook filtering

* Avoid State construction during Events filtering

* Move tuple creation out of loop

* Add benchmark

homeassistant/components/logbook.py

@@ -170,6 +170,8 @@ def humanify(events):
     - if 2+ sensor updates in GROUP_BY_MINUTES, show last
     - if home assistant stop and start happen in same minute call it restarted
     """
+    domain_prefixes = tuple('{}.'.format(dom) for dom in CONTINUOUS_DOMAINS)
+
     # Group events in batches of GROUP_BY_MINUTES
     for _, g_events in groupby(
             events,
@@ -189,11 +191,7 @@ def humanify(events):
             if event.event_type == EVENT_STATE_CHANGED:
                 entity_id = event.data.get('entity_id')
 
-                if entity_id is None:
+                if entity_id.startswith(domain_prefixes):
-                    continue
-
-                if entity_id.startswith(tuple('{}.'.format(
-                        domain) for domain in CONTINUOUS_DOMAINS)):
                     last_sensor_event[entity_id] = event
 
             elif event.event_type == EVENT_HOMEASSISTANT_STOP:
@@ -214,14 +212,6 @@ def humanify(events):
 
                 to_state = State.from_dict(event.data.get('new_state'))
 
-                # If last_changed != last_updated only attributes have changed
-                # we do not report on that yet. Also filter auto groups.
-                if not to_state or \
-                   to_state.last_changed != to_state.last_updated or \
-                   to_state.domain == 'group' and \
-                   to_state.attributes.get('auto', False):
-                    continue
-
                 domain = to_state.domain
 
                 # Skip all but the last sensor state
@@ -290,7 +280,7 @@ def _get_events(hass, config, start_day, end_day):
 
 
 def _exclude_events(events, config):
-    """Get lists of excluded entities and platforms."""
+    """Get list of filtered events."""
     excluded_entities = []
     excluded_domains = []
     included_entities = []
@@ -309,23 +299,41 @@ def _exclude_events(events, config):
         domain, entity_id = None, None
 
         if event.event_type == EVENT_STATE_CHANGED:
-            to_state = State.from_dict(event.data.get('new_state'))
+            entity_id = event.data.get('entity_id')
+
+            if entity_id is None:
+                continue
+
             # Do not report on new entities
             if event.data.get('old_state') is None:
                 continue
 
+            new_state = event.data.get('new_state')
+
             # Do not report on entity removal
-            if not to_state:
+            if not new_state:
+                continue
+
+            attributes = new_state.get('attributes', {})
+
+            # If last_changed != last_updated only attributes have changed
+            # we do not report on that yet.
+            last_changed = new_state.get('last_changed')
+            last_updated = new_state.get('last_updated')
+            if last_changed != last_updated:
+                continue
+
+            domain = split_entity_id(entity_id)[0]
+
+            # Also filter auto groups.
+            if domain == 'group' and attributes.get('auto', False):
                 continue
 
             # exclude entities which are customized hidden
-            hidden = to_state.attributes.get(ATTR_HIDDEN, False)
+            hidden = attributes.get(ATTR_HIDDEN, False)
             if hidden:
                 continue
 
-            domain = to_state.domain
-            entity_id = to_state.entity_id
-
         elif event.event_type == EVENT_LOGBOOK_ENTRY:
             domain = event.data.get(ATTR_DOMAIN)
             entity_id = event.data.get(ATTR_ENTITY_ID)

homeassistant/scripts/benchmark/__init__.py

@@ -144,3 +144,53 @@ def async_million_state_changed_helper(hass):
     yield from event.wait()
 
     return timer() - start
+
+
+@benchmark
+@asyncio.coroutine
+def logbook_filtering_state(hass):
+    """Filter state changes."""
+    return _logbook_filtering(hass, 1, 1)
+
+
+@benchmark
+@asyncio.coroutine
+def logbook_filtering_attributes(hass):
+    """Filter attribute changes."""
+    return _logbook_filtering(hass, 1, 2)
+
+
+@benchmark
+@asyncio.coroutine
+def _logbook_filtering(hass, last_changed, last_updated):
+    from homeassistant.components import logbook
+
+    entity_id = 'test.entity'
+
+    old_state = {
+        'entity_id': entity_id,
+        'state': 'off'
+    }
+
+    new_state = {
+        'entity_id': entity_id,
+        'state': 'on',
+        'last_updated': last_updated,
+        'last_changed': last_changed
+    }
+
+    event = core.Event(EVENT_STATE_CHANGED, {
+        'entity_id': entity_id,
+        'old_state': old_state,
+        'new_state': new_state
+    })
+
+    events = [event] * 10**5
+
+    start = timer()
+
+    # pylint: disable=protected-access
+    events = logbook._exclude_events(events, {})
+    list(logbook.humanify(events))
+
+    return timer() - start

tests/components/test_logbook.py

@@ -372,7 +372,8 @@ class TestComponentLogbook(unittest.TestCase):
         eventB = self.create_state_changed_event(pointA, entity_id2, 20,
                                                  {'auto': True})
 
-        entries = list(logbook.humanify((eventA, eventB)))
+        events = logbook._exclude_events((eventA, eventB), {})
+        entries = list(logbook.humanify(events))
 
         self.assertEqual(1, len(entries))
         self.assert_entry(entries[0], pointA, 'bla', domain='switch',
@@ -389,7 +390,8 @@ class TestComponentLogbook(unittest.TestCase):
         eventB = self.create_state_changed_event(
             pointA, entity_id2, 20, last_changed=pointA, last_updated=pointB)
 
-        entries = list(logbook.humanify((eventA, eventB)))
+        events = logbook._exclude_events((eventA, eventB), {})
+        entries = list(logbook.humanify(events))
 
         self.assertEqual(1, len(entries))
         self.assert_entry(entries[0], pointA, 'bla', domain='switch',