Merge lp:~stub/launchpad/pending-db-changes into lp:launchpad/db-devel

[Stuart Bishop]

[r=jelmer][ui=none][bug=368600,678289] Report database patch application times.

Store and report database patch application times.

The reported times are the time spent running the actual SQL. There are also overheads involved, but this should be constant. Given a total of these times for a rollout, the actual time will be "num_nodes * db_time + x * num_patches + y", where x and y are as yet unknown constants representing overhead per patch and extra overhead (trusted.sql, comments.sql, merging new table replication set into main replication set etc.)

[Jelmer Vernooij (jelmer)]

review: Approve

[Robert Collins (lifeless)]

When we have 2 slaves, do they apply patches in parallel with each
other, or serially?

[Stuart Bishop (stub)]

On Thu, Nov 25, 2010 at 2:26 AM, Robert Collins
<email address hidden> wrote:
> When we have 2 slaves, do they apply patches in parallel with each
> other, or serially?

Hmm... yeah. That formula is bogus. I think this is what happens: we
apply all the patches in a transaction on the master, so if it fails
on the master things roll back. Then slony sends off DDL as events
which propagate to the slaves and they run the DDL. Because our slaves
all connect directly to the master at the moment, they end up running
the DDL in parallel. So time would be 2 * db_time + x * num_slaves *
num_patches + y. In reality, we can get away with 2 * db_time + 5
minutes.

--
Stuart Bishop <email address hidden>
http://www.stuartbishop.net/

[Robert Collins (lifeless)]

On Thu, Nov 25, 2010 at 3:17 PM, Stuart Bishop
<email address hidden> wrote:
> the DDL in parallel. So time would be 2 * db_time + x * num_slaves *
> num_patches + y. In reality, we can get away with 2 * db_time + 5
> minutes.

Excellent - thanks. Could you perhaps put that in the release manager
notes on the wiki? We need to write up how to get these things and
have a place to record the total time for devs doing qa on db-devel
too, but thats a slightly separate problem :)

-Rob

=== added file 'database/schema/patch-2208-01-1.sql'
--- database/schema/patch-2208-01-1.sql	1970-01-01 00:00:00 +0000
+++ database/schema/patch-2208-01-1.sql	2010-11-24 10:19:33 +0000
@@ -0,0 +1,10 @@
+SET client_min_messages=ERROR;
+
+ALTER TABLE LaunchpadDatabaseRevision
+    ADD start_time timestamp without time zone DEFAULT (
+        transaction_timestamp() AT TIME ZONE 'UTC'),
+    ADD end_time timestamp without time zone DEFAULT (
+        statement_timestamp() AT TIME ZONE 'UTC');
+
+INSERT INTO LaunchpadDatabaseRevision VALUES (2208, 01, 1);
+

=== modified file 'database/schema/upgrade.py'
--- database/schema/upgrade.py	2010-05-19 18:07:56 +0000
+++ database/schema/upgrade.py	2010-11-24 10:19:33 +0000
@@ -32,19 +32,65 @@
 
 def main():
     con = connect(options.dbuser)
+    patches = get_patchlist(con)
+
     if replication.helpers.slony_installed(con):
         con.close()
         if options.commit is False:
             parser.error("--dry-run does not make sense with replicated db")
         log.info("Applying patches to Slony-I environment.")
         apply_patches_replicated()
+        con = connect(options.dbuser)
     else:
         log.info("Applying patches to unreplicated environment.")
         apply_patches_normal(con)
 
+    report_patch_times(con, patches)
+
     return 0
 
 
+def to_seconds(td):
+    """Convert a timedelta to seconds."""
+    return td.days * (24*60*60) + td.seconds + td.microseconds/1000000.0
+
+
+def report_patch_times(con, todays_patches):
+    """Report how long it took to apply the given patches."""
+    cur = con.cursor()
+
+    todays_patches = [patch_tuple for patch_tuple, patch_file
+        in todays_patches]
+
+    cur.execute("""
+        SELECT
+            major, minor, patch, start_time, end_time - start_time AS db_time
+        FROM LaunchpadDatabaseRevision
+        WHERE start_time > CURRENT_TIMESTAMP AT TIME ZONE 'UTC'
+            - CAST('1 month' AS interval)
+        ORDER BY major, minor, patch
+        """)
+    for major, minor, patch, start_time, db_time in cur.fetchall():
+        if (major, minor, patch) in todays_patches:
+            continue
+        db_time = to_seconds(db_time)
+        start_time = start_time.strftime('%Y-%m-%d')
+        log.info(
+            "%d-%02d-%d applied %s in %0.1f seconds"
+            % (major, minor, patch, start_time, db_time))
+
+    for major, minor, patch in todays_patches:
+        cur.execute("""
+            SELECT end_time - start_time AS db_time
+            FROM LaunchpadDatabaseRevision
+            WHERE major = %s AND minor = %s AND patch = %s
+            """, (major, minor, patch))
+        db_time = cur.fetchone()[0]
+        log.info(
+            "%d-%02d-%d applied just now in %0.1f seconds",
+            major, minor, patch, to_seconds(db_time))
+
+
 def apply_patches_normal(con):
     """Update a non replicated database."""
     # trusted.sql contains all our stored procedures, which may