migrate: Print execution time of migrations
Debugging slow migrations, as in issue #3973 (closed) is difficult
because there is no indication which migration is being run. Admins
will need to check pg_stat_activity
, then search the Gitaly source
for that query to find out which migration is misbehaving.
This MR updates the sql-migrate
subcommand to execute migrations
one by one and displays their execution times.
This requires a bit of work as the Exec
API exposed by sql-migrate
does not provide a simple way to execute only one migration. The obvious
option of passing a slice with a single migration does not work due to
how ToApply() works. If current
is not empty, which will be when one
or more migrations are up, then it will iterate over the migration slice
until current
is found, returning the remainder of the migrations. If
current
is not present in the slice, then an empty slice is returned
and the target migration is not executed.
To work around this, we include all migrations prior to the target
migration in the slice, ensuring that the current
migration is
present.
Example output:
praefect sql-migrate: migrations to apply: 3
= 2022-02-01T17:01:37 20211025113445_remove_cancelled_replication_events: migrating
== 2022-02-01T17:01:37 20211025113445_remove_cancelled_replication_events: applied (9.010133ms)
= 2022-02-01T17:01:37 20211105100456_check_non_null_repository_id: migrating
== 2022-02-01T17:01:37 20211105100456_check_non_null_repository_id: applied (8.423652ms)
= 2022-02-01T17:01:37 20211105100458_non_nullable_repository_id: migrating
== 2022-02-01T17:01:37 20211105100458_non_nullable_repository_id: applied (12.438743ms)
praefect sql-migrate: OK (applied 3 migrations)
Also, add a -verbose
flag for sql-migrate
to print the statement being executed for each migration.
Example output:
= 2022-02-01T16:00:56 20200109161404_hello_world: migrating
[CREATE TABLE hello_world (id integer)]
== 2022-02-01T16:00:56 20200109161404_hello_world: applied (9.525348ms)