prints the migrate/rollback execution time (#550)

Example output ``` Applying: 20230110131043_change-updated_at-fields.sql Applied: 20230110131043_change-updated_at-fields.sql in 45.098471ms ```
amacneil · Jun 4, 2024 · 9107c09 · 9107c09
1 parent 0e1b2d0
commit 9107c09
Show file tree

Hide file tree

Showing 3 changed files with 23 additions and 4 deletions.
diff --git a/README.md b/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 123µs
 ```
 
 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 123µs
 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 123µs
 Writing: ./db/schema.sql
 ```
 

diff --git a/pkg/dbmate/db.go b/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
 	}

diff --git a/pkg/dbmate/db_test.go b/pkg/dbmate/db_test.go
@@ -4,6 +4,7 @@ import (
 	"net/url"
 	"os"
 	"path/filepath"
+	"regexp"
 	"strings"
 	"testing"
 	"testing/fstest"
@@ -315,17 +316,22 @@ func TestWaitBeforeVerbose(t *testing.T) {
 	output := capturer.CaptureOutput(func() {
 		testWaitBefore(t, true)
 	})
-	require.Contains(t, output,
+	re := regexp.MustCompile(`((Applied|Rolled back): .* in) ([\w.,µ]+)`)
+	maskedOutput := re.ReplaceAllString(output, "$1 ELAPSED")
+	require.Contains(t, maskedOutput,
 		`Applying: 20151129054053_test_migration.sql
 Last insert ID: 1
 Rows affected: 1
+Applied: 20151129054053_test_migration.sql in ELAPSED
 Applying: 20200227231541_test_posts.sql
 Last insert ID: 1
-Rows affected: 1`)
-	require.Contains(t, output,
+Rows affected: 1
+Applied: 20200227231541_test_posts.sql in ELAPSED`)
+	require.Contains(t, maskedOutput,
 		`Rolling back: 20200227231541_test_posts.sql
 Last insert ID: 0
-Rows affected: 0`)
+Rows affected: 0
+Rolled back: 20200227231541_test_posts.sql in ELAPSED`)
 }
 
 func testEachURL(t *testing.T, fn func(*testing.T, *url.URL)) {