Merge lp:~stub/launchpad/replication into lp:launchpad/db-devel

[Stuart Bishop]

Don't let replication lag checks by the appserver block long

[Stuart Bishop (stub)]

Address Bug #504696. This is a cherry pick candidate, after manual tests on staging and edge demonstrate things are working as intended.

When things get busy, it can be slow to query the Slony-I tables to determine how lagged the slave database is. This is something we need to deal with, as we are sort of abusing this facility and I doubt it was intended for the sl_status view to be queried 20-30 times per second.

Rather than just letting the replication lag checks go slow, making users cry and timeouts rise, we put a timeout on the check. If we can't get the information we need in 250 ms, assume lag is bad and proceed.

This change cannot be tested by our test suite. It has been tested locally against a replicated environment and should be tested on staging next.

[Henning Eggers (henninge)]

Hi stub,
this sounds like a smart thing to do and the branch looks good. Only thing that'd confuse me is the ".get_one()[0]" construct which looks like strange semantics in the get_one method. I'd exepct it *not* to return a list. But you did not introduce that, so I'll just let it go.

Cheers,
Henning

review: Approve (code)

=== modified file 'lib/canonical/config/schema-lazr.conf'
--- lib/canonical/config/schema-lazr.conf	2009-12-27 00:54:45 +0000
+++ lib/canonical/config/schema-lazr.conf	2010-01-15 12:01:26 +0000
@@ -873,6 +873,11 @@
 storm_cache: generational
 storm_cache_size: 10000
 
+# Assume the slave database is lagged if it takes more than this many
+# milliseconds to calculate this information from the Slony-I tables.
+# datatype: integer
+lag_check_timeout: 250
+
 # If False, do not launch the appserver.
 # datatype: boolean
 launch: True

=== modified file 'lib/canonical/launchpad/webapp/dbpolicy.py'
--- lib/canonical/launchpad/webapp/dbpolicy.py	2009-12-02 19:33:08 +0000
+++ lib/canonical/launchpad/webapp/dbpolicy.py	2010-01-15 12:01:26 +0000
@@ -12,9 +12,11 @@
     ]
 
 from datetime import datetime, timedelta
+import logging
 from textwrap import dedent
 
 from storm.cache import Cache, GenerationalCache
+from storm.exceptions import TimeoutError
 from storm.zope.interfaces import IZStorm
 from zope.session.interfaces import ISession, IClientIdManager
 from zope.component import getUtility
@@ -291,8 +293,26 @@
 
         # sl_status gives meaningful results only on the origin node.
         master_store = self.getStore(MAIN_STORE, MASTER_FLAVOR)
-        return master_store.execute(
-            "SELECT replication_lag(%d)" % slave_node_id).get_one()[0]
+        # If it takes more than (by default) 0.25 seconds to query the
+        # replication lag, assume we are lagged. Normally the query
+        # takes <20ms. This can happen during heavy updates, as the
+        # Slony-I tables can get slow with lots of events. We use a
+        # SAVEPOINT to conveniently reset the statement timeout.
+        master_store.execute("""
+            SAVEPOINT lag_check; SET LOCAL statement_timeout TO %d
+            """ % config.launchpad.lag_check_timeout)
+        try:
+            try:
+                return master_store.execute(
+                    "SELECT replication_lag(%d)" % slave_node_id).get_one()[0]
+            except TimeoutError:
+                logging.warn(
+                    'Gave up querying slave lag after %d ms',
+                    (config.launchpad.lag_check_timeout))
+                return timedelta(days=999) # A long, long time.
+        finally:
+            master_store.execute("ROLLBACK TO lag_check")
+
 
 
 def WebServiceDatabasePolicyFactory(request):