prints the migrate/rollback execution time

README.md

@@ -191,6 +191,7 @@ Dropping: myapp_test
 $ dbmate -e TEST_DATABASE_URL --no-dump-schema up
 Creating: myapp_test
 Applying: 20151127184807_create_users_table.sql
+Applied: 20151127184807_create_users_table.sql in 123us
 ```
 
 Alternatively, you can specify the url directly on the command line:
@@ -343,6 +344,7 @@ Run `dbmate up` to run any pending migrations.
 $ dbmate up
 Creating: myapp_development
 Applying: 20151127184807_create_users_table.sql
+Applied: 20151127184807_create_users_table.sql in 123us
 Writing: ./db/schema.sql
 ```
 
@@ -371,6 +373,7 @@ Run `dbmate rollback` to roll back the most recent migration:
 ```sh
 $ dbmate rollback
 Rolling back: 20151127184807_create_users_table.sql
+Rolled back: 20151127184807_create_users_table.sql in 123us
 Writing: ./db/schema.sql
 ```
 

pkg/dbmate/db.go

@@ -377,6 +377,8 @@ func (db *DB) Migrate() error {
 	for _, migration := range pendingMigrations {
 		fmt.Fprintf(db.Log, "Applying: %s\n", migration.FileName)
 
+		start := time.Now()
+
 		parsed, err := migration.Parse()
 		if err != nil {
 			return err
@@ -403,6 +405,9 @@ func (db *DB) Migrate() error {
 			err = execMigration(sqlDB)
 		}
 
+		elapsed := time.Since(start)
+		fmt.Fprintf(db.Log, "Applied: %s in %s\n", migration.FileName, elapsed)
+
 		if err != nil {
 			return err
 		}
@@ -541,6 +546,8 @@ func (db *DB) Rollback() error {
 
 	fmt.Fprintf(db.Log, "Rolling back: %s\n", latest.FileName)
 
+	start := time.Now()
+
 	parsed, err := latest.Parse()
 	if err != nil {
 		return err
@@ -567,6 +574,9 @@ func (db *DB) Rollback() error {
 		err = execMigration(sqlDB)
 	}
 
+	elapsed := time.Since(start)
+	fmt.Fprintf(db.Log, "Rolled back: %s in %s\n", latest.FileName, elapsed)
+
 	if err != nil {
 		return err
 	}

pkg/dbmate/db_test.go

@@ -4,6 +4,7 @@ import (
 	"net/url"
 	"os"
 	"path/filepath"
+	"regexp"
 	"strings"
 	"testing"
 	"testing/fstest"
@@ -315,17 +316,13 @@ func TestWaitBeforeVerbose(t *testing.T) {
 	output := capturer.CaptureOutput(func() {
 		testWaitBefore(t, true)
 	})
-	require.Contains(t, output,
-		`Applying: 20151129054053_test_migration.sql
-Last insert ID: 1
-Rows affected: 1
-Applying: 20200227231541_test_posts.sql
-Last insert ID: 1
-Rows affected: 1`)
-	require.Contains(t, output,
-		`Rolling back: 20200227231541_test_posts.sql
-Last insert ID: 0
-Rows affected: 0`)
+	matched, err := regexp.MatchString(`Applying: 20151129054053_test_migration\.sql\nLast insert ID: 1\nRows affected: 1\nApplied: 20151129054053_test_migration\.sql in ([\w.,µ]+)\nApplying: 20200227231541_test_posts\.sql\nLast insert ID: 1\nRows affected: 1\nApplied: 20200227231541_test_posts\.sql in ([\w.,µ]+)`, output)
+	require.NoError(t, err)
+	require.True(t, matched)
+
+	matched, err = regexp.MatchString(`Rolling back: 20200227231541_test_posts\.sql\nLast insert ID: 0\nRows affected: 0\nRolled back: 20200227231541_test_posts\.sql in ([\w.,µ]+)`, output)
+	require.NoError(t, err)
+	require.True(t, matched)
 }
 
 func testEachURL(t *testing.T, fn func(*testing.T, *url.URL)) {