launchpad-reviewers team mailing list archive

[Stuart Bishop <stuart.bishop@xxxxxxxxxxxxx>]

Stuart Bishop has proposed merging lp:~stub/launchpad/pending-db-changes into lp:launchpad/db-devel.

Requested reviews:
  Launchpad code reviewers (launchpad-reviewers)
Related bugs:
  #368600 Replicated upgrade.py needs to output timestamps
  https://bugs.launchpad.net/bugs/368600


Take II at fixing Bug #368600

Here we take the original work to store and report database patch application times, extending it to work when multiple patches are applied in a single transaction. To do this, we store the time we start to apply patches (which is not the transaction start time - there are preamble steps), and repair the incorrect data in LaunchpadDatabaseRevision after applying the patches (they all have their start_time set to the transaction start time).


-- 
https://code.launchpad.net/~stub/launchpad/pending-db-changes/+merge/42933
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~stub/launchpad/pending-db-changes into lp:launchpad/db-devel.

=== modified file 'database/replication/Makefile'
--- database/replication/Makefile	2010-09-27 11:32:31 +0000
+++ database/replication/Makefile	2010-12-07 12:39:05 +0000
@@ -13,6 +13,7 @@
 #
 # To test the staging rebuild script:
 #
+#  $ mkdir -p /srv/staging.launchpad.net/staging-logs
 #  $ cd database/replication
 #  $ pg_dump --format=c launchpad_dev | bzip2 -c > launchpad.dump.bz2
 #  $ make stagingsetup \

=== 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-12-07 12:39:05 +0000
@@ -0,0 +1,14 @@
+SET client_min_messages=ERROR;
+
+ALTER TABLE LaunchpadDatabaseRevision
+    ADD start_time timestamp without time zone,
+    ADD end_time timestamp without time zone;
+   
+ALTER TABLE LaunchpadDatabaseRevision
+    ALTER COLUMN start_time
+        SET DEFAULT (transaction_timestamp() AT TIME ZONE 'UTC'),
+    ALTER COLUMN end_time
+        SET 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-12-03 12:07:43 +0000
+++ database/schema/upgrade.py	2010-12-07 12:39:05 +0000
@@ -32,38 +32,141 @@
 
 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)
+
+    # Commit changes
+    if options.commit:
+        log.debug("Committing changes")
+        con.commit()
+
     return 0
 
 
+# When we apply a number of patches in a transaction, they all end up
+# with the same start_time (the transaction start time). This SQL fixes
+# that up by setting the patch start time to the previous patches end
+# time when there are patches that share identical start times. The
+# FIX_PATCH_TIMES_PRE_SQL stores the start time of patch application,
+# which is probably not the same as the transaction timestamp because we
+# have to apply trusted.sql before applying patches (in addition to
+# other preamble time such as Slony-I grabbing locks).
+# FIX_PATCH_TIMES_POST_SQL does the repair work.
+FIX_PATCH_TIMES_PRE_SQL = dedent("""\
+    CREATE TEMPORARY TABLE _start_time AS (
+        SELECT statement_timestamp() AT TIME ZONE 'UTC' AS start_time);
+    """)
+FIX_PATCH_TIMES_POST_SQL = dedent("""\
+    UPDATE LaunchpadDatabaseRevision
+    SET start_time = prev_end_time
+    FROM (
+        SELECT
+            LDR1.major, LDR1.minor, LDR1.patch,
+            max(LDR2.end_time) AS prev_end_time
+        FROM
+            LaunchpadDatabaseRevision AS LDR1,
+            LaunchpadDatabaseRevision AS LDR2
+        WHERE
+            (LDR1.major, LDR1.minor, LDR1.patch)
+                > (LDR2.major, LDR2.minor, LDR2.patch)
+            AND LDR1.start_time = LDR2.start_time
+        GROUP BY LDR1.major, LDR1.minor, LDR1.patch
+        ) AS PrevTime
+    WHERE
+        LaunchpadDatabaseRevision.major = PrevTime.major
+        AND LaunchpadDatabaseRevision.minor = PrevTime.minor
+        AND LaunchpadDatabaseRevision.patch = PrevTime.patch
+        AND LaunchpadDatabaseRevision.start_time <> prev_end_time;
+
+    UPDATE LaunchpadDatabaseRevision
+    SET start_time=_start_time.start_time
+    FROM _start_time
+    WHERE
+        LaunchpadDatabaseRevision.start_time
+            = transaction_timestamp() AT TIME ZONE 'UTC';
+    """)
+
+
+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]
+        # Patches before 2208-01-1 don't have timing information.
+        # Ignore this. We can remove this code the next time we
+        # create a new database baseline, as all patches will have
+        # timing information.
+        if db_time is None:
+            log.debug('%d-%d-%d no application time', major, minor, patch)
+            continue
+        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
     # be required for patches to apply correctly so must be run first.
     apply_other(con, 'trusted.sql')
 
+    # Prepare to repair patch timestamps if necessary.
+    con.cursor().execute(FIX_PATCH_TIMES_PRE_SQL)
+
     # Apply the patches
     patches = get_patchlist(con)
     for (major, minor, patch), patch_file in patches:
         apply_patch(con, major, minor, patch, patch_file)
 
+    # Repair patch timestamps if necessary.
+    con.cursor().execute(FIX_PATCH_TIMES_POST_SQL)
+
     # Update comments.
     apply_comments(con)
 
-    # Commit changes
-    if options.commit:
-        log.debug("Committing changes")
-        con.commit()
-
 
 def apply_patches_replicated():
     """Update a Slony-I cluster."""
@@ -97,6 +200,11 @@
                 );
             """ % full_path)
 
+    # We are going to generate some temporary files using
+    # NamedTempoararyFile. Store them here so we can control when
+    # they get closed and cleaned up.
+    temporary_files = []
+
     # Apply trusted.sql
     run_sql('trusted.sql')
 
@@ -105,19 +213,29 @@
     # they get closed and cleaned up.
     temporary_files = []
 
-    # Apply DB patches.
+    # Apply DB patches as one big hunk.
+    combined_script = NamedTemporaryFile(prefix='patch', suffix='.sql')
+    temporary_files.append(combined_script)
+
+    # Prepare to repair the start timestamps in
+    # LaunchpadDatabaseRevision.
+    print >> combined_script, FIX_PATCH_TIMES_PRE_SQL
+
     patches = get_patchlist(con)
     for (major, minor, patch), patch_file in patches:
-        run_sql(patch_file)
-        # Cause a failure if the patch neglected to update
+        print >> combined_script, open(patch_file, 'r').read()
+
+        # Trigger a failure if the patch neglected to update
         # LaunchpadDatabaseRevision.
-        assert_script = NamedTemporaryFile(prefix='assert', suffix='.sql')
-        print >> assert_script, dedent("""
-            SELECT assert_patch_applied(%d, %d, %d);
-            """ % (major, minor, patch))
-        assert_script.flush()
-        run_sql(assert_script.name)
-        temporary_files.append(assert_script)
+        print >> combined_script, (
+            "SELECT assert_patch_applied(%d, %d, %d);"
+            % (major, minor, patch))
+
+    # Fix the start timestamps in LaunchpadDatabaseRevision.
+    print >> combined_script, FIX_PATCH_TIMES_POST_SQL
+
+    combined_script.flush()
+    run_sql(combined_script.name)
 
     # Close transaction block and abort on error.
     print >> outf, dedent("""\