Repository: pressly/goose (language: go)

Issue:
Print out duration of execution time of each migration
```diff
- OK    10000000000819_uuid.sql
+ OK    10000000000819_uuid.sql (took 32s)
goose: no migrations to run. current version: 10000000000819
```


Discussion / hints:
I almost wish we stored this in the database. But Ye, logging this is a good idea.

I can implement this soon-ish if no one gets around to it.
I had a go at this https://github.com/pressly/goose/pull/403. Please let me know what you think.

Fix patch:
diff --git a/migration.go b/migration.go
index 775dc779c..b4fdba952 100644
--- a/migration.go
+++ b/migration.go
@@ -63,14 +63,16 @@ func (m *Migration) run(db *sql.DB, direction bool) error {
 			return fmt.Errorf("ERROR %v: failed to parse SQL migration file: %w", filepath.Base(m.Source), err)
 		}
 
+		start := time.Now()
 		if err := runSQLMigration(db, statements, useTx, m.Version, direction, m.noVersioning); err != nil {
 			return fmt.Errorf("ERROR %v: failed to run SQL migration: %w", filepath.Base(m.Source), err)
 		}
+		finish := truncateDuration(time.Since(start))
 
 		if len(statements) > 0 {
-			log.Println("OK   ", filepath.Base(m.Source))
+			log.Printf("OK   %s (%s)\n", filepath.Base(m.Source), finish)
 		} else {
-			log.Println("EMPTY", filepath.Base(m.Source))
+			log.Printf("EMPTY %s (%s)\n", filepath.Base(m.Source), finish)
 		}
 
 	case ".go":
@@ -107,15 +109,16 @@ func (m *Migration) run(db *sql.DB, direction bool) error {
 				}
 			}
 		}
-
+		start := time.Now()
 		if err := tx.Commit(); err != nil {
 			return fmt.Errorf("ERROR failed to commit transaction: %w", err)
 		}
+		finish := truncateDuration(time.Since(start))
 
 		if fn != nil {
-			log.Println("OK   ", filepath.Base(m.Source))
+			log.Printf("OK   %s (%s)\n", filepath.Base(m.Source), finish)
 		} else {
-			log.Println("EMPTY", filepath.Base(m.Source))
+			log.Printf("EMPTY %s (%s)\n", filepath.Base(m.Source), finish)
 		}
 
 		return nil
@@ -146,3 +149,16 @@ func NumericComponent(name string) (int64, error) {
 
 	return n, e
 }
+
+func truncateDuration(d time.Duration) time.Duration {
+	for _, v := range []time.Duration{
+		time.Second,
+		time.Millisecond,
+		time.Microsecond,
+	} {
+		if d > v {
+			return d.Round(v / time.Duration(100))
+		}
+	}
+	return d
+}


Test patch: