I just upgraded a database from ivanchuk to jansa and noticed that each migration took at least 10 seconds according to the production.log, but the screen logging of the migration time was less than 1 second for each.
[----] I, [2020-04-27T10:31:03.356414 #60950:3fd4a4032e20] INFO -- : Migrating to AddEmsIdToStorages (20190729165913)
[----] I, [2020-04-27T10:31:14.093146 #60950:3fd4a4032e20] INFO -- : Migrating to SplitStoragesPerEms (20190729170013)
[----] I, [2020-04-27T10:31:25.213419 #60950:3fd4a4032e20] INFO -- : Migrating to AddInitiatorTypeToMiqRequests (20190731175747)
[----] I, [2020-04-27T10:31:37.329564 #60950:3fd4a4032e20] INFO -- : Migrating to AddEmsRefToDisk (20190801025013)
[----] I, [2020-04-27T10:31:49.562474 #60950:3fd4a4032e20] INFO -- : Migrating to AddEmsRefToGuestDevice (20190801025156)
[----] I, [2020-04-27T10:32:01.290981 #60950:3fd4a4032e20] INFO -- : Migrating to RenameServiceDisplayToVisible (20190827141149)
[----] I, [2020-04-27T10:32:12.112341 #60950:3fd4a4032e20] INFO -- : Migrating to AddSpeedToGuestDevices (20190830133434)
[----] I, [2020-04-27T10:32:24.393485 #60950:3fd4a4032e20] INFO -- : Migrating to AddApplicationBuildTime (20190916132550)
[----] I, [2020-04-27T10:32:36.607199 #60950:3fd4a4032e20] INFO -- : Migrating to AddApplicationUrl (20190916150002)
[----] I, [2020-04-27T10:32:46.943496 #60950:3fd4a4032e20] INFO -- : Migrating to RemoveRailsServerFromSettings (20190918133037)
[----] I, [2020-04-27T10:32:58.401292 #60950:3fd4a4032e20] INFO -- : Migrating to AddResourceGroupIdToCloudNetwork (20190930054405)
[----] I, [2020-04-27T10:33:11.610149 #60950:3fd4a4032e20] INFO -- : Migrating to AddResourceGroupIdToNetworkPort (20190930054416)
[----] I, [2020-04-27T10:33:22.082191 #60950:3fd4a4032e20] INFO -- : Migrating to AddResourceGroupIdToSecurityGroup (20190930054424)
[----] I, [2020-04-27T10:33:34.833832 #60950:3fd4a4032e20] INFO -- : Migrating to RenameChargebackRateDetailCurrencyToCurrency (20191001174700)
[----] I, [2020-04-27T10:33:47.163154 #60950:3fd4a4032e20] INFO -- : Migrating to RemoveQuadiconSettings (20191002103406)
[----] I, [2020-04-27T10:33:59.854438 #60950:3fd4a4032e20] INFO -- : Migrating to AddGeneralIndexes (20191017211747)
[----] I, [2020-04-27T10:34:12.042723 #60950:3fd4a4032e20] INFO -- : Migrating to UpdateOpenstackHostsUidEms (20191023180130)
[----] I, [2020-04-27T10:34:23.257553 #60950:3fd4a4032e20] INFO -- : Migrating to AddEmsRefType (20191023180149)
[----] I, [2020-04-27T10:34:34.094119 #60950:3fd4a4032e20] INFO -- : Migrating to SubclassEmsCluster (20191023180308)
[----] I, [2020-04-27T10:34:45.813718 #60950:3fd4a4032e20] INFO -- : Migrating to MigrateEmsRefObjToEmsRefType (20191023180330)
[----] I, [2020-04-27T10:35:02.471067 #60950:3fd4a4032e20] INFO -- : Migrating to CopyOwnerIdToGroupIdForDashboards (20191112132759)
[----] I, [2020-04-27T10:35:15.533692 #60950:3fd4a4032e20] INFO -- : Migrating to RemoveEmsRefObj (20191113200451)
[----] I, [2020-04-27T10:35:28.842003 #60950:3fd4a4032e20] INFO -- : Migrating to RemoveMiqwidgetRss (20191114131917)
[----] I, [2020-04-27T10:35:42.470636 #60950:3fd4a4032e20] INFO -- : Migrating to CreateMiqWorkerTypes (20191115164358)
[----] I, [2020-04-27T10:35:54.856436 #60950:3fd4a4032e20] INFO -- : Migrating to AddTypeToResourcePools (20191118161213)
[----] I, [2020-04-27T10:36:09.697624 #60950:3fd4a4032e20] INFO -- : Migrating to SubclassResourcePools (20191118161319)
[----] I, [2020-04-27T10:36:23.242021 #60950:3fd4a4032e20] INFO -- : Migrating to SubclassEmsFolders (20191118191722)
[----] I, [2020-04-27T10:36:35.204080 #60950:3fd4a4032e20] INFO -- : Migrating to ReplaceServerCapabilitiesWithVixDiskLib (20191122203218)
[----] I, [2020-04-27T10:36:46.653117 #60950:3fd4a4032e20] INFO -- : Migrating to RemoveMiddlewareColumnsInEventStreams (20191126204129)
[----] I, [2020-04-27T10:36:58.561659 #60950:3fd4a4032e20] INFO -- : Migrating to RemoveMiddlewareTables (20191126204211)
[----] I, [2020-04-27T10:37:10.864266 #60950:3fd4a4032e20] INFO -- : Migrating to AddRestartNeededToVms (20191128111630)
[----] I, [2020-04-27T10:37:22.814334 #60950:3fd4a4032e20] INFO -- : Migrating to DropEmsRefFromHostStorage (20191209162705)
[----] I, [2020-04-27T10:37:33.423428 #60950:3fd4a4032e20] INFO -- : Migrating to AddMaintenanceModeToStorages (20191210135022)
[----] I, [2020-04-27T10:37:44.637845 #60950:3fd4a4032e20] INFO -- : Migrating to AddTypeToStorages (20191210162908)
[----] I, [2020-04-27T10:37:56.224731 #60950:3fd4a4032e20] INFO -- : Migrating to SubclassStorages (20191210163518)
[----] I, [2020-04-27T10:38:07.345826 #60950:3fd4a4032e20] INFO -- : Migrating to RemoveMiqVimBrokerWorkerRows (20200103191549)
[----] I, [2020-04-27T10:38:20.509001 #60950:3fd4a4032e20] INFO -- : Migrating to AddDescStringToMiqGroup (20200109190758)
[----] I, [2020-04-27T10:38:31.418964 #60950:3fd4a4032e20] INFO -- : Migrating to UpgradeDropboxToSupportTool (20200122215829)
[----] I, [2020-04-27T10:38:47.103022 #60950:3fd4a4032e20] INFO -- : Migrating to RemoveVimTypesFromEmsEvents (20200126203714)
[----] I, [2020-04-27T10:39:00.384914 #60950:3fd4a4032e20] INFO -- : Migrating to AddTypeColumnToServiceOrder (20200128122000)
[----] I, [2020-04-27T10:39:10.811633 #60950:3fd4a4032e20] INFO -- : Migrating to DropRedHatDomain (20200211181329)
[----] I, [2020-04-27T10:39:22.739668 #60950:3fd4a4032e20] INFO -- : Migrating to RemoveOvirtSdk4FromEventStream (20200212171537)
[----] I, [2020-04-27T10:39:36.593898 #60950:3fd4a4032e20] INFO -- : Migrating to AddThinAndFormatToDisk (20200219125312)
[----] I, [2020-04-27T10:39:49.767989 #60950:3fd4a4032e20] INFO -- : Migrating to AddAncestryToMiqAeNamespace (20200221200855)
[----] I, [2020-04-27T10:40:03.721574 #60950:3fd4a4032e20] INFO -- : Migrating to DropRegionMigrationsRan (20200227195911)
10:30:53 ~/Code/manageiq (jansa) (2.5.7) + RAILS_ENV=production bin/rake db:migrate
== 20190729165913 AddEmsIdToStorages: migrating ===============================
-- add_reference(:storages, :ems, {:type=>:bigint, :index=>true, :references=>:ext_management_system})
-> 0.0082s
== 20190729165913 AddEmsIdToStorages: migrated (0.0083s) ======================
Seeding :schema_migrations_ran table...
== 20190729170013 SplitStoragesPerEms: migrating ==============================
== 20190729170013 SplitStoragesPerEms: migrated (0.0246s) =====================
Seeding :schema_migrations_ran table...
== 20190731175747 AddInitiatorTypeToMiqRequests: migrating ====================
-- add_column(:miq_requests, :initiated_by, :string)
-> 0.0018s
== 20190731175747 AddInitiatorTypeToMiqRequests: migrated (0.0018s) ===========
Seeding :schema_migrations_ran table...
== 20190801025013 AddEmsRefToDisk: migrating ==================================
-- add_column(:disks, :ems_ref, :string)
-> 0.0009s
== 20190801025013 AddEmsRefToDisk: migrated (0.0009s) =========================
Seeding :schema_migrations_ran table...
== 20190801025156 AddEmsRefToGuestDevice: migrating ===========================
-- add_column(:guest_devices, :ems_ref, :string)
-> 0.0009s
== 20190801025156 AddEmsRefToGuestDevice: migrated (0.0010s) ==================
Seeding :schema_migrations_ran table...
== 20190827141149 RenameServiceDisplayToVisible: migrating ====================
-- rename_column(:services, :display, :visible)
-> 0.0102s
== 20190827141149 RenameServiceDisplayToVisible: migrated (0.0103s) ===========
Seeding :schema_migrations_ran table...
== 20190830133434 AddSpeedToGuestDevices: migrating ===========================
-- add_column(:guest_devices, :speed, :bigint)
-> 0.0010s
== 20190830133434 AddSpeedToGuestDevices: migrated (0.0011s) ==================
Seeding :schema_migrations_ran table...
== 20190916132550 AddApplicationBuildTime: migrating ==========================
-- add_column(:guest_applications, :build_time, :timestamp)
-> 0.0008s
== 20190916132550 AddApplicationBuildTime: migrated (0.0009s) =================
Seeding :schema_migrations_ran table...
== 20190916150002 AddApplicationUrl: migrating ================================
-- add_column(:guest_applications, :url, :string)
-> 0.0009s
== 20190916150002 AddApplicationUrl: migrated (0.0009s) =======================
Seeding :schema_migrations_ran table...
== 20190918133037 RemoveRailsServerFromSettings: migrating ====================
-- Remove rails_server settings
-> 0.0072s
-> 0 rows
== 20190918133037 RemoveRailsServerFromSettings: migrated (0.0074s) ===========
Seeding :schema_migrations_ran table...
== 20190930054405 AddResourceGroupIdToCloudNetwork: migrating =================
-- add_reference(:cloud_networks, :resource_group, {:type=>:bigint, :index=>true})
-> 0.0043s
== 20190930054405 AddResourceGroupIdToCloudNetwork: migrated (0.0044s) ========
Seeding :schema_migrations_ran table...
== 20190930054416 AddResourceGroupIdToNetworkPort: migrating ==================
-- add_reference(:network_ports, :resource_group, {:type=>:bigint, :index=>true})
-> 0.0047s
== 20190930054416 AddResourceGroupIdToNetworkPort: migrated (0.0047s) =========
Seeding :schema_migrations_ran table...
== 20190930054424 AddResourceGroupIdToSecurityGroup: migrating ================
-- add_reference(:security_groups, :resource_group, {:type=>:bigint, :index=>true})
-> 0.0049s
== 20190930054424 AddResourceGroupIdToSecurityGroup: migrated (0.0050s) =======
Seeding :schema_migrations_ran table...
== 20191001174700 RenameChargebackRateDetailCurrencyToCurrency: migrating =====
-- rename_table(:chargeback_rate_detail_currencies, :currencies)
-> 0.0129s
== 20191001174700 RenameChargebackRateDetailCurrencyToCurrency: migrated (0.0129s)
Seeding :schema_migrations_ran table...
== 20191002103406 RemoveQuadiconSettings: migrating ===========================
-- Dropping quadicon settings keys from user settings
-> 0.0057s
== 20191002103406 RemoveQuadiconSettings: migrated (0.0058s) ==================
Seeding :schema_migrations_ran table...
== 20191017211747 AddGeneralIndexes: migrating ================================
-- add_index(:miq_schedules, :updated_at)
-> 0.0035s
-- add_index(:blacklisted_events, [:ems_id, :enabled])
-> 0.0031s
-- add_index(:key_pairs_vms, :vm_id)
-> 0.0030s
-- add_index(:miq_requests, [:tenant_id, :approval_state])
-> 0.0028s
-- add_index(:miq_roles_features, :miq_user_role_id)
-> 0.0032s
-- add_index(:miq_queue, [:state, :handler_type, :handler_id])
-> 0.0089s
-- add_index(:vms, :tenant_id)
-> 0.0054s
-- add_index(:entitlements, :miq_group_id)
-> 0.0034s
-- add_index(:endpoints, [:resource_id, :resource_type])
-> 0.0032s
== 20191017211747 AddGeneralIndexes: migrated (0.0372s) =======================
Seeding :schema_migrations_ran table...
== 20191023180130 UpdateOpenstackHostsUidEms: migrating =======================
== 20191023180130 UpdateOpenstackHostsUidEms: migrated (0.0255s) ==============
Seeding :schema_migrations_ran table...
== 20191023180149 AddEmsRefType: migrating ====================================
-- add_column(:ems_clusters, :ems_ref_type, :string)
-> 0.0009s
-- add_column(:ems_folders, :ems_ref_type, :string)
-> 0.0006s
-- add_column(:hosts, :ems_ref_type, :string)
-> 0.0005s
-- add_column(:resource_pools, :ems_ref_type, :string)
-> 0.0004s
-- add_column(:snapshots, :ems_ref_type, :string)
-> 0.0004s
-- add_column(:storages, :ems_ref_type, :string)
-> 0.0004s
-- add_column(:vms, :ems_ref_type, :string)
-> 0.0004s
== 20191023180149 AddEmsRefType: migrated (0.0040s) ===========================
Seeding :schema_migrations_ran table...
== 20191023180308 SubclassEmsCluster: migrating ===============================
== 20191023180308 SubclassEmsCluster: migrated (0.0789s) ======================
Seeding :schema_migrations_ran table...
== 20191023180330 MigrateEmsRefObjToEmsRefType: migrating =====================
-- Converting ems_ref_obj to ems_ref_type for MigrateEmsRefObjToEmsRefType::EmsCluster
-> 0.0242s
-- Converting ems_ref_obj to ems_ref_type for MigrateEmsRefObjToEmsRefType::EmsFolder
-> 0.0222s
-- Converting ems_ref_obj to ems_ref_type for MigrateEmsRefObjToEmsRefType::Host
-> 0.0286s
-- Converting ems_ref_obj to ems_ref_type for MigrateEmsRefObjToEmsRefType::ResourcePool
-> 0.0263s
-- Converting ems_ref_obj to ems_ref_type for MigrateEmsRefObjToEmsRefType::Snapshot
-> 0.0274s
-- Converting ems_ref_obj to ems_ref_type for MigrateEmsRefObjToEmsRefType::Storage
-> 0.0250s
-- Converting ems_ref_obj to ems_ref_type for MigrateEmsRefObjToEmsRefType::VmOrTemplate
-> 0.0426s
== 20191023180330 MigrateEmsRefObjToEmsRefType: migrated (0.1966s) ============
Seeding :schema_migrations_ran table...
== 20191112132759 CopyOwnerIdToGroupIdForDashboards: migrating ================
-- Copying owner_id to group_id in miq_sets table for each dashboard assigned to group
-> 0.0310s
-> 1 rows
== 20191112132759 CopyOwnerIdToGroupIdForDashboards: migrated (0.0311s) =======
Seeding :schema_migrations_ran table...
== 20191113200451 RemoveEmsRefObj: migrating ==================================
-- remove_column(:ems_clusters, :ems_ref_obj, :string)
-> 0.0041s
-- remove_column(:ems_folders, :ems_ref_obj, :string)
-> 0.0004s
-- remove_column(:hosts, :ems_ref_obj, :string)
-> 0.0007s
-- remove_column(:resource_pools, :ems_ref_obj, :string)
-> 0.0009s
-- remove_column(:snapshots, :ems_ref_obj, :string)
-> 0.0003s
-- remove_column(:storages, :ems_ref_obj, :string)
-> 0.0007s
-- remove_column(:vms, :ems_ref_obj, :string)
-> 0.0004s
== 20191113200451 RemoveEmsRefObj: migrated (0.0079s) =========================
Seeding :schema_migrations_ran table...
== 20191114131917 RemoveMiqwidgetRss: migrating ===============================
== 20191114131917 RemoveMiqwidgetRss: migrated (0.0079s) ======================
Seeding :schema_migrations_ran table...
== 20191115164358 CreateMiqWorkerTypes: migrating =============================
-- create_table(:miq_worker_types, {:id=>:bigserial})
-> 0.0140s
== 20191115164358 CreateMiqWorkerTypes: migrated (0.0144s) ====================
Seeding :schema_migrations_ran table...
== 20191118161213 AddTypeToResourcePools: migrating ===========================
-- add_column(:resource_pools, :type, :string)
-> 0.0009s
== 20191118161213 AddTypeToResourcePools: migrated (0.0010s) ==================
Seeding :schema_migrations_ran table...
== 20191118161319 SubclassResourcePools: migrating ============================
== 20191118161319 SubclassResourcePools: migrated (0.0576s) ===================
Seeding :schema_migrations_ran table...
== 20191118191722 SubclassEmsFolders: migrating ===============================
== 20191118191722 SubclassEmsFolders: migrated (0.0741s) ======================
Seeding :schema_migrations_ran table...
== 20191122203218 ReplaceServerCapabilitiesWithVixDiskLib: migrating ==========
-- add_column(:miq_servers, :has_vix_disk_lib, :boolean)
-> 0.0010s
-- remove_column(:miq_servers, :capabilities)
-> 0.0433s
== 20191122203218 ReplaceServerCapabilitiesWithVixDiskLib: migrated (0.0517s) =
Seeding :schema_migrations_ran table...
== 20191126204129 RemoveMiddlewareColumnsInEventStreams: migrating ============
-- remove_column(:event_streams, :middleware_server_id)
-> 0.0007s
-- remove_column(:event_streams, :middleware_server_name)
-> 0.0006s
-- remove_column(:event_streams, :middleware_deployment_id)
-> 0.0004s
-- remove_column(:event_streams, :middleware_deployment_name)
-> 0.0004s
-- remove_column(:event_streams, :middleware_domain_id)
-> 0.0003s
-- remove_column(:event_streams, :middleware_domain_name)
-> 0.0003s
== 20191126204129 RemoveMiddlewareColumnsInEventStreams: migrated (0.0031s) ===
Seeding :schema_migrations_ran table...
== 20191126204211 RemoveMiddlewareTables: migrating ===========================
-- drop_table(:middleware_datasources, {})
-> 0.0029s
-- drop_table(:middleware_deployments, {})
-> 0.0012s
-- drop_table(:middleware_diagnostic_reports, {})
-> 0.0011s
-- drop_table(:middleware_domains, {})
-> 0.0026s
-- drop_table(:middleware_messagings, {})
-> 0.0016s
-- drop_table(:middleware_server_groups, {})
-> 0.0018s
-- drop_table(:middleware_servers, {})
-> 0.0017s
== 20191126204211 RemoveMiddlewareTables: migrated (0.0748s) ==================
Seeding :schema_migrations_ran table...
== 20191128111630 AddRestartNeededToVms: migrating ============================
-- add_column(:vms, :restart_needed, :boolean)
-> 0.0011s
== 20191128111630 AddRestartNeededToVms: migrated (0.0011s) ===================
Seeding :schema_migrations_ran table...
== 20191209162705 DropEmsRefFromHostStorage: migrating ========================
-- remove_column(:host_storages, :ems_ref, :string)
-> 0.0006s
== 20191209162705 DropEmsRefFromHostStorage: migrated (0.0006s) ===============
Seeding :schema_migrations_ran table...
== 20191210135022 AddMaintenanceModeToStorages: migrating =====================
-- add_column(:storages, :maintenance, :boolean)
-> 0.0009s
-- add_column(:storages, :maintenance_reason, :string)
-> 0.0007s
== 20191210135022 AddMaintenanceModeToStorages: migrated (0.0017s) ============
Seeding :schema_migrations_ran table...
== 20191210162908 AddTypeToStorages: migrating ================================
-- add_column(:storages, :type, :string)
-> 0.0009s
== 20191210162908 AddTypeToStorages: migrated (0.0010s) =======================
Seeding :schema_migrations_ran table...
== 20191210163518 SubclassStorages: migrating =================================
== 20191210163518 SubclassStorages: migrated (0.0646s) ========================
Seeding :schema_migrations_ran table...
== 20200103191549 RemoveMiqVimBrokerWorkerRows: migrating =====================
== 20200103191549 RemoveMiqVimBrokerWorkerRows: migrated (0.0078s) ============
Seeding :schema_migrations_ran table...
== 20200109190758 AddDescStringToMiqGroup: migrating ==========================
-- add_column(:miq_groups, :detailed_description, :string)
-> 0.0011s
== 20200109190758 AddDescStringToMiqGroup: migrated (0.0012s) =================
Seeding :schema_migrations_ran table...
== 20200122215829 UpgradeDropboxToSupportTool: migrating ======================
== 20200122215829 UpgradeDropboxToSupportTool: migrated (0.0233s) =============
Seeding :schema_migrations_ran table...
== 20200126203714 RemoveVimTypesFromEmsEvents: migrating ======================
-- Removing Vim Types from EmsEvents
-> Processing 0 rows
-> 0.0336s
== 20200126203714 RemoveVimTypesFromEmsEvents: migrated (0.0337s) =============
Seeding :schema_migrations_ran table...
== 20200128122000 AddTypeColumnToServiceOrder: migrating ======================
-- add_column(:service_orders, :type, :string)
-> 0.0009s
-- Set service_orders type
-> 0.0270s
-> 0 rows
== 20200128122000 AddTypeColumnToServiceOrder: migrated (0.0280s) =============
Seeding :schema_migrations_ran table...
== 20200211181329 DropRedHatDomain: migrating =================================
-- Remove RedHat domain
-> 0.2316s
== 20200211181329 DropRedHatDomain: migrated (0.2316s) ========================
Seeding :schema_migrations_ran table...
== 20200212171537 RemoveOvirtSdk4FromEventStream: migrating ===================
-- Removing OvirtSDK4 types from EmsEvents
-> Processing 0 rows
-> 0.0237s
== 20200212171537 RemoveOvirtSdk4FromEventStream: migrated (0.0238s) ==========
Seeding :schema_migrations_ran table...
== 20200219125312 AddThinAndFormatToDisk: migrating ===========================
-- add_column(:disks, :thin, :boolean)
-> 0.0011s
-- add_column(:disks, :format, :string)
-> 0.0005s
== 20200219125312 AddThinAndFormatToDisk: migrated (0.0017s) ==================
Seeding :schema_migrations_ran table...
== 20200221200855 AddAncestryToMiqAeNamespace: migrating ======================
-- add_column(:miq_ae_namespaces, :ancestry, :string)
-> 0.0009s
-- add_index(:miq_ae_namespaces, :ancestry)
-> 0.0249s
-- Converting MiqAeNamespaces from parent_id to ancestry
-> 0.2172s
-- remove_index(:miq_ae_namespaces, {:column=>:parent_id})
-> 0.0207s
-- remove_column(:miq_ae_namespaces, :parent_id)
-> 0.0006s
== 20200221200855 AddAncestryToMiqAeNamespace: migrated (0.2646s) =============
Seeding :schema_migrations_ran table...
== 20200227195911 DropRegionMigrationsRan: migrating ==========================
-- remove_column(:miq_regions, :migrations_ran)
-> 0.0008s
== 20200227195911 DropRegionMigrationsRan: migrated (0.0009s) =================
Seeding :schema_migrations_ran table...
10:40:25 ~/Code/manageiq (jansa) (2.5.7)
Note, it took 10 minutes to run a migration locally from ivanchuk to jansa on a small database and none of the steps claimed to take more than 1 second.