extremely slow schema updates after MUPdate

[davepacheco]

On a customer system, after a MUPdate, we found that the normal schema migration that Nexus does was proceeding very slowly. In fact, we initially thought Nexus hadn't come up because:

$ omdb nexus update-status
note: Nexus URL not specified.  Will pick one from DNS.
note: using DNS from system config (typically /etc/resolv.conf)
note: (if this is not right, use --dns-server to specify an alternate DNS server)
warning: failed to connect to NexusLockstep at ...:12232: connect "...:12232": Connection refused (os error 146)
warning: failed to connect to NexusLockstep at ...:12232: connect "...:12232": Connection refused (os error 146)
warning: failed to connect to NexusLockstep at ...:12232: connect "...:12232": Connection refused (os error 146)
Error: failed to connect to any instances of NexusLockstep

We looked at it for a while before realizing that Nexus was making forward progress, just very slowly. Nexus completes schema migrations before opening up its listening sockets, which is why we got the error above.

For reference:

• I believe this was a MUPdate from R18 to R19.
• The rack was parked for MUPdate around 2026-04-30T16:00:00Z, or 9am PT.

We were able to tell that schema upgrade steps were happening very slowly but it wasn't clear why. We looked at various data:

• Nexus logs
• output from a DTrace script showing queries executing by Nexus nodes
• the jobs table reported by CockroachDB
• CockroachDB logs

More details coming.

[davepacheco]

DTrace output from Nexus

I had Claude write a tool to summarize the DTrace output and jobs table in various ways.

• I see several surprising gaps, where a particular Nexus node gets woken up for no obvious reason (which makes me wonder why it went to sleep). An example is one waking at 2026-05-01T00:49:40.106Z after being asleep for a few minutes, but what it wakes up to do looks like resume normal schema update operations (so what was it waiting for?).
• I see several wakeups after several minutes where it woke up on a transaction completing. Some of these are creating indexes, some of them are drop tables. Examples are at the end of the timeline: 2026-05-01T00:58:24.070Z, 2026-05-01T00:58:24.176Z, and 2026-05-01T00:58:24.412Z. Interestingly: all three Nexus instances wake up at about the same time to complete transactions. It's like they were all stuck. Two of them had been waiting to drop a table, while one had been waiting to create an index.

Of note from source inspection:

• the backoff policy for retrying the whole schema update goes up to 3 minutes.
• the beginning of the schema update process selects the db_metadata row (version, target_version) only
• then for each step:
  • set time_modified, target_version in db_metadata

[davepacheco]

SHOW JOBS from CockroachDB

We went to the SHOW JOBS output to see if we could use that to make a timeline. Here's a postprocessed summary:

timestamp                     delta  jobid                event     description
2026-04-30 19:49:30.731              1171482773878603777  created   ALTER TABLE omicron.public.bp_sled_metadata ADD COLUMN IF NOT EXISTS measurements omicron.public.bp_sled_measurements NOT NULL DEFAULT 'unknown'
2026-04-30 19:49:30.765       0.034  1171482773878603777  started   ALTER TABLE omicron.public.bp_sled_metadata ADD COLUMN IF NOT EXISTS measurements omicron.public.bp_sled_measurements NOT NULL DEFAULT 'unknown'
2026-04-30 19:49:30.908       0.142  1171482773878603777  finished  ALTER TABLE omicron.public.bp_sled_metadata ADD COLUMN IF NOT EXISTS measurements omicron.public.bp_sled_measurements NOT NULL DEFAULT 'unknown'
2026-04-30 19:49:30.915       0.007  1171482774470197249  created   ALTER TABLE omicron.public.bp_sled_metadata ALTER COLUMN measurements DROP DEFAULT
2026-04-30 19:49:30.976       0.061  1171482774470197249  started   ALTER TABLE omicron.public.bp_sled_metadata ALTER COLUMN measurements DROP DEFAULT
2026-04-30 19:49:30.988       0.011  1171482774470197249  finished  ALTER TABLE omicron.public.bp_sled_metadata ALTER COLUMN measurements DROP DEFAULT
2026-04-30 19:49:31.010       0.021  1171482774805282817  created   ALTER TABLE omicron.public.inv_zpool ADD COLUMN IF NOT EXISTS health omicron.public.inv_zpool_health NOT NULL DEFAULT 'online'
2026-04-30 19:49:31.042       0.032  1171482774805282817  started   ALTER TABLE omicron.public.inv_zpool ADD COLUMN IF NOT EXISTS health omicron.public.inv_zpool_health NOT NULL DEFAULT 'online'
2026-04-30 19:49:31.971       0.929  1171482774805282817  finished  ALTER TABLE omicron.public.inv_zpool ADD COLUMN IF NOT EXISTS health omicron.public.inv_zpool_health NOT NULL DEFAULT 'online'
2026-04-30 19:49:32.000       0.028  1171482778046824449  created   ALTER TABLE omicron.public.inv_zpool ALTER COLUMN health DROP DEFAULT
2026-04-30 19:49:32.065       0.065  1171482778046824449  started   ALTER TABLE omicron.public.inv_zpool ALTER COLUMN health DROP DEFAULT
2026-04-30 19:49:32.076       0.010  1171482778046824449  finished  ALTER TABLE omicron.public.inv_zpool ALTER COLUMN health DROP DEFAULT
2026-04-30 19:49:32.102       0.025  1171482778516488193  created   ALTER TABLE omicron.public.silo_user ALTER COLUMN user_provision_type SET NOT NULL
2026-04-30 19:49:32.194       0.092  1171482778516488193  started   ALTER TABLE omicron.public.silo_user ALTER COLUMN user_provision_type SET NOT NULL
2026-04-30 19:49:32.335       0.141  1171482778516488193  finished  ALTER TABLE omicron.public.silo_user ALTER COLUMN user_provision_type SET NOT NULL
2026-04-30 19:49:32.342       0.006  1171482779148058625  created   ALTER TABLE omicron.public.silo_user DROP CONSTRAINT IF EXISTS user_provision_type_required_for_non_deleted
2026-04-30 19:49:32.385       0.043  1171482779148058625  started   ALTER TABLE omicron.public.silo_user DROP CONSTRAINT IF EXISTS user_provision_type_required_for_non_deleted
2026-04-30 19:49:32.505       0.119  1171482779148058625  finished  ALTER TABLE omicron.public.silo_user DROP CONSTRAINT IF EXISTS user_provision_type_required_for_non_deleted
2026-04-30 19:49:32.511       0.006  1171482779769110529  created   ALTER TABLE omicron.public.silo_group ALTER COLUMN user_provision_type SET NOT NULL
2026-04-30 19:49:32.557       0.045  1171482779769110529  started   ALTER TABLE omicron.public.silo_group ALTER COLUMN user_provision_type SET NOT NULL
2026-04-30 19:49:32.652       0.095  1171482779769110529  finished  ALTER TABLE omicron.public.silo_group ALTER COLUMN user_provision_type SET NOT NULL
2026-04-30 19:49:32.659       0.006  1171482780187164673  created   ALTER TABLE omicron.public.silo_group DROP CONSTRAINT IF EXISTS user_provision_type_required_for_non_deleted
2026-04-30 19:49:32.683       0.023  1171482780187164673  started   ALTER TABLE omicron.public.silo_group DROP CONSTRAINT IF EXISTS user_provision_type_required_for_non_deleted
2026-04-30 19:49:32.762       0.079  1171482780187164673  finished  ALTER TABLE omicron.public.silo_group DROP CONSTRAINT IF EXISTS user_provision_type_required_for_non_deleted
2026-04-30 19:49:32.770       0.007  1171482780545908737  created   ALTER TABLE omicron.public.virtual_provisioning_collection ALTER COLUMN time_modified DROP DEFAULT
2026-04-30 19:49:32.789       0.019  1171482780545908737  started   ALTER TABLE omicron.public.virtual_provisioning_collection ALTER COLUMN time_modified DROP DEFAULT
2026-04-30 19:49:32.796       0.006  1171482780545908737  finished  ALTER TABLE omicron.public.virtual_provisioning_collection ALTER COLUMN time_modified DROP DEFAULT
2026-04-30 19:49:32.801       0.005  1171482780646309889  created   ALTER TABLE omicron.public.virtual_provisioning_resource ALTER COLUMN time_modified DROP DEFAULT
2026-04-30 19:49:32.820       0.018  1171482780646309889  started   ALTER TABLE omicron.public.virtual_provisioning_resource ALTER COLUMN time_modified DROP DEFAULT
2026-04-30 19:49:32.827       0.006  1171482780646309889  finished  ALTER TABLE omicron.public.virtual_provisioning_resource ALTER COLUMN time_modified DROP DEFAULT
2026-04-30 19:49:32.843       0.016  1171482780813918209  created   ALTER TABLE omicron.public.loopback_address ADD COLUMN IF NOT EXISTS switch_slot omicron.public.switch_slot
2026-04-30 19:49:32.886       0.042  1171482780813918209  started   ALTER TABLE omicron.public.loopback_address ADD COLUMN IF NOT EXISTS switch_slot omicron.public.switch_slot
2026-04-30 19:49:32.921       0.035  1171482780813918209  finished  ALTER TABLE omicron.public.loopback_address ADD COLUMN IF NOT EXISTS switch_slot omicron.public.switch_slot
2026-04-30 19:49:32.946       0.024  1171482781148250113  created   removing index "lookup_loopback_address" dependent on column "switch_location" which is being dropped; full details: omicron.public.loopback_address; ALTER TABLE omicron.public.loopback_address DROP COLUMN IF EXISTS switch_location
2026-04-30 19:49:32.978       0.032  1171482781148250113  started   removing index "lookup_loopback_address" dependent on column "switch_location" which is being dropped; full details: omicron.public.loopback_address; ALTER TABLE omicron.public.loopback_address DROP COLUMN IF EXISTS switch_location
2026-04-30 19:49:33.039       0.060  1171482781148250113  finished  removing index "lookup_loopback_address" dependent on column "switch_location" which is being dropped; full details: omicron.public.loopback_address; ALTER TABLE omicron.public.loopback_address DROP COLUMN IF EXISTS switch_location
2026-04-30 19:49:33.045       0.006  1171482781446995969  created   ALTER TABLE omicron.public.bfd_session ADD COLUMN IF NOT EXISTS switch_slot omicron.public.switch_slot
2026-04-30 19:49:33.071       0.025  1171482781446995969  started   ALTER TABLE omicron.public.bfd_session ADD COLUMN IF NOT EXISTS switch_slot omicron.public.switch_slot
2026-04-30 19:49:33.121       0.050  1171482781446995969  finished  ALTER TABLE omicron.public.bfd_session ADD COLUMN IF NOT EXISTS switch_slot omicron.public.switch_slot
2026-04-30 19:49:33.143       0.021  1171482781774708737  created   removing index "lookup_bfd_session" dependent on column "switch" which is being dropped; full details: omicron.public.bfd_session; ALTER TABLE omicron.public.bfd_session DROP COLUMN IF EXISTS switch
2026-04-30 19:49:33.172       0.029  1171482781774708737  started   removing index "lookup_bfd_session" dependent on column "switch" which is being dropped; full details: omicron.public.bfd_session; ALTER TABLE omicron.public.bfd_session DROP COLUMN IF EXISTS switch
2026-04-30 19:49:33.235       0.063  1171482781774708737  finished  removing index "lookup_bfd_session" dependent on column "switch" which is being dropped; full details: omicron.public.bfd_session; ALTER TABLE omicron.public.bfd_session DROP COLUMN IF EXISTS switch
2026-04-30 19:49:33.242       0.007  1171482782093148161  created   ALTER TABLE omicron.public.switch_port ADD COLUMN IF NOT EXISTS switch_slot omicron.public.switch_slot
2026-04-30 19:49:33.265       0.022  1171482782093148161  started   ALTER TABLE omicron.public.switch_port ADD COLUMN IF NOT EXISTS switch_slot omicron.public.switch_slot
2026-04-30 19:49:33.314       0.049  1171482782093148161  finished  ALTER TABLE omicron.public.switch_port ADD COLUMN IF NOT EXISTS switch_slot omicron.public.switch_slot
2026-04-30 19:49:33.358       0.043  1171482782524407809  created   removing references for view bgp_peer_view from table switch_port(268)
2026-04-30 19:49:33.358       0.000  1171482782526898177  created   removing references for view bgp_peer_view from table switch_port_settings_bgp_peer_config(287)
2026-04-30 19:49:33.358       0.000  1171482782529421313  created   removing references for view bgp_peer_view from table bgp_config(291)
2026-04-30 19:49:33.358       0.000  1171482782532829185  created   DROP VIEW IF EXISTS omicron.public.bgp_peer_view
2026-04-30 19:49:33.399       0.041  1171482782529421313  started   removing references for view bgp_peer_view from table bgp_config(291)
2026-04-30 19:49:33.399       0.000  1171482782524407809  started   removing references for view bgp_peer_view from table switch_port(268)
2026-04-30 19:49:33.399       0.000  1171482782532829185  started   DROP VIEW IF EXISTS omicron.public.bgp_peer_view
2026-04-30 19:49:33.400       0.000  1171482782526898177  started   removing references for view bgp_peer_view from table switch_port_settings_bgp_peer_config(287)
2026-04-30 19:49:33.406       0.006  1171482782532829185  finished  DROP VIEW IF EXISTS omicron.public.bgp_peer_view
2026-04-30 19:49:33.407       0.001  1171482782529421313  finished  removing references for view bgp_peer_view from table bgp_config(291)
2026-04-30 19:49:33.407       0.000  1171482782526898177  finished  removing references for view bgp_peer_view from table switch_port_settings_bgp_peer_config(287)
2026-04-30 19:49:33.409       0.001  1171482782524407809  finished  removing references for view bgp_peer_view from table switch_port(268)
2026-04-30 19:49:33.415       0.005  1171482782665605121  created   removing index "switch_port_rack_locaction_name_unique" dependent on column "switch_location" which is being dropped; full details: omicron.public.switch_port; removing index "switch_port_id_and_name" dependent on column "switch_location" which is being dropped; full details: omicron.public.switch_port; ALTER TABLE omicron.public.switch_port DROP COLUMN IF EXISTS switch_location
2026-04-30 19:49:33.445       0.030  1171482782665605121  started   removing index "switch_port_rack_locaction_name_unique" dependent on column "switch_location" which is being dropped; full details: omicron.public.switch_port; removing index "switch_port_id_and_name" dependent on column "switch_location" which is being dropped; full details: omicron.public.switch_port; ALTER TABLE omicron.public.switch_port DROP COLUMN IF EXISTS switch_location
2026-04-30 19:49:33.507       0.062  1171482782665605121  finished  removing index "switch_port_rack_locaction_name_unique" dependent on column "switch_location" which is being dropped; full details: omicron.public.switch_port; removing index "switch_port_id_and_name" dependent on column "switch_location" which is being dropped; full details: omicron.public.switch_port; ALTER TABLE omicron.public.switch_port DROP COLUMN IF EXISTS switch_location
2026-04-30 19:49:33.513       0.006  1171482782999904257  created   updating view reference "omicron.public.bgp_peer_view" in table switch_port(268)
2026-04-30 19:49:33.513       0.000  1171482783004852225  created   updating view reference "omicron.public.bgp_peer_view" in table bgp_config(291)
2026-04-30 19:49:33.513       0.000  1171482783002230785  created   updating view reference "omicron.public.bgp_peer_view" in table switch_port_settings_bgp_peer_config(287)
2026-04-30 19:49:33.553       0.040  1171482782999904257  started   updating view reference "omicron.public.bgp_peer_view" in table switch_port(268)
2026-04-30 19:49:33.553       0.000  1171482783002230785  started   updating view reference "omicron.public.bgp_peer_view" in table switch_port_settings_bgp_peer_config(287)
2026-04-30 19:49:33.554       0.000  1171482783004852225  started   updating view reference "omicron.public.bgp_peer_view" in table bgp_config(291)
2026-04-30 19:49:33.562       0.007  1171482783002230785  finished  updating view reference "omicron.public.bgp_peer_view" in table switch_port_settings_bgp_peer_config(287)
2026-04-30 19:49:33.562       0.000  1171482783004852225  finished  updating view reference "omicron.public.bgp_peer_view" in table bgp_config(291)
2026-04-30 19:49:33.563       0.001  1171482782999904257  finished  updating view reference "omicron.public.bgp_peer_view" in table switch_port(268)
2026-04-30 19:49:33.570       0.006  1171482783170199553  created   ALTER TABLE omicron.public.loopback_address ALTER COLUMN switch_slot SET NOT NULL
2026-04-30 19:49:33.602       0.032  1171482783170199553  started   ALTER TABLE omicron.public.loopback_address ALTER COLUMN switch_slot SET NOT NULL
2026-04-30 19:49:33.672       0.069  1171482783170199553  finished  ALTER TABLE omicron.public.loopback_address ALTER COLUMN switch_slot SET NOT NULL
2026-04-30 19:49:33.678       0.006  1171482783522390017  created   ALTER TABLE omicron.public.bfd_session ALTER COLUMN switch_slot SET NOT NULL
2026-04-30 19:49:33.702       0.024  1171482783522390017  started   ALTER TABLE omicron.public.bfd_session ALTER COLUMN switch_slot SET NOT NULL
2026-04-30 19:49:33.771       0.068  1171482783522390017  finished  ALTER TABLE omicron.public.bfd_session ALTER COLUMN switch_slot SET NOT NULL
2026-04-30 19:49:33.778       0.006  1171482783849906177  created   ALTER TABLE omicron.public.switch_port ALTER COLUMN switch_slot SET NOT NULL
2026-04-30 19:49:33.806       0.027  1171482783849906177  started   ALTER TABLE omicron.public.switch_port ALTER COLUMN switch_slot SET NOT NULL
2026-04-30 19:49:33.885       0.079  1171482783849906177  finished  ALTER TABLE omicron.public.switch_port ALTER COLUMN switch_slot SET NOT NULL
2026-04-30 19:49:33.891       0.006  1171482784220971009  created   CREATE UNIQUE INDEX IF NOT EXISTS lookup_bfd_session ON omicron.public.bfd_session (remote, switch_slot) WHERE time_deleted IS NULL
2026-04-30 19:49:33.916       0.025  1171482784220971009  started   CREATE UNIQUE INDEX IF NOT EXISTS lookup_bfd_session ON omicron.public.bfd_session (remote, switch_slot) WHERE time_deleted IS NULL
2026-04-30 19:49:34.349       0.432  1171482784220971009  finished  CREATE UNIQUE INDEX IF NOT EXISTS lookup_bfd_session ON omicron.public.bfd_session (remote, switch_slot) WHERE time_deleted IS NULL
2026-04-30 19:49:34.380       0.030  1171482785823588353  created   CREATE UNIQUE INDEX IF NOT EXISTS lookup_loopback_address ON omicron.public.loopback_address (address, rack_id, switch_slot)
2026-04-30 19:49:34.403       0.022  1171482785823588353  started   CREATE UNIQUE INDEX IF NOT EXISTS lookup_loopback_address ON omicron.public.loopback_address (address, rack_id, switch_slot)
2026-04-30 19:49:42.099       7.695  1171482785823588353  finished  CREATE UNIQUE INDEX IF NOT EXISTS lookup_loopback_address ON omicron.public.loopback_address (address, rack_id, switch_slot)
2026-04-30 19:49:42.130       0.031  1171482811220754433  created   ALTER TABLE omicron.public.switch_port ADD CONSTRAINT IF NOT EXISTS switch_port_rack_locaction_name_unique UNIQUE (rack_id, switch_slot, port_name)
2026-04-30 19:49:42.153       0.023  1171482811220754433  started   ALTER TABLE omicron.public.switch_port ADD CONSTRAINT IF NOT EXISTS switch_port_rack_locaction_name_unique UNIQUE (rack_id, switch_slot, port_name)
2026-04-30 19:49:42.536       0.382  1171482811220754433  finished  ALTER TABLE omicron.public.switch_port ADD CONSTRAINT IF NOT EXISTS switch_port_rack_locaction_name_unique UNIQUE (rack_id, switch_slot, port_name)
2026-04-30 19:49:42.598       0.062  1171482812752494593  created   CREATE INDEX IF NOT EXISTS switch_port_id_and_name ON omicron.public.switch_port (port_settings_id, port_name) STORING (switch_slot)
2026-04-30 19:49:42.622       0.024  1171482812752494593  started   CREATE INDEX IF NOT EXISTS switch_port_id_and_name ON omicron.public.switch_port (port_settings_id, port_name) STORING (switch_slot)
2026-04-30 19:49:51.599       8.976  1171482812752494593  finished  CREATE INDEX IF NOT EXISTS switch_port_id_and_name ON omicron.public.switch_port (port_settings_id, port_name) STORING (switch_slot)
2026-04-30 19:49:51.644       0.044  1171482842399211521  created   ALTER TABLE omicron.public.bfd_session ALTER COLUMN mode SET NOT NULL
2026-04-30 19:49:51.672       0.027  1171482842399211521  started   ALTER TABLE omicron.public.bfd_session ALTER COLUMN mode SET NOT NULL
2026-04-30 19:49:51.741       0.069  1171482842399211521  finished  ALTER TABLE omicron.public.bfd_session ALTER COLUMN mode SET NOT NULL
2026-04-30 19:49:51.748       0.006  1171482842762215425  created   ALTER TABLE omicron.public.internet_gateway_ip_address ALTER COLUMN internet_gateway_id SET NOT NULL
2026-04-30 19:49:51.777       0.029  1171482842762215425  started   ALTER TABLE omicron.public.internet_gateway_ip_address ALTER COLUMN internet_gateway_id SET NOT NULL
2026-04-30 19:49:51.830       0.052  1171482842762215425  finished  ALTER TABLE omicron.public.internet_gateway_ip_address ALTER COLUMN internet_gateway_id SET NOT NULL
2026-04-30 19:49:51.835       0.005  1171482843020001281  created   ALTER TABLE omicron.public.internet_gateway_ip_address ALTER COLUMN address SET NOT NULL
2026-04-30 19:49:51.855       0.019  1171482843020001281  started   ALTER TABLE omicron.public.internet_gateway_ip_address ALTER COLUMN address SET NOT NULL
2026-04-30 19:49:51.932       0.077  1171482843020001281  finished  ALTER TABLE omicron.public.internet_gateway_ip_address ALTER COLUMN address SET NOT NULL
2026-04-30 19:49:51.937       0.005  1171482843378974721  created   ALTER TABLE omicron.public.internet_gateway_ip_pool ALTER COLUMN internet_gateway_id SET NOT NULL
2026-04-30 19:49:51.966       0.028  1171482843378974721  started   ALTER TABLE omicron.public.internet_gateway_ip_pool ALTER COLUMN internet_gateway_id SET NOT NULL
2026-04-30 19:49:52.025       0.058  1171482843378974721  finished  ALTER TABLE omicron.public.internet_gateway_ip_pool ALTER COLUMN internet_gateway_id SET NOT NULL
2026-04-30 19:49:52.030       0.005  1171482843656945665  created   ALTER TABLE omicron.public.internet_gateway_ip_pool ALTER COLUMN ip_pool_id SET NOT NULL
2026-04-30 19:49:52.050       0.020  1171482843656945665  started   ALTER TABLE omicron.public.internet_gateway_ip_pool ALTER COLUMN ip_pool_id SET NOT NULL
2026-04-30 19:49:52.104       0.054  1171482843656945665  finished  ALTER TABLE omicron.public.internet_gateway_ip_pool ALTER COLUMN ip_pool_id SET NOT NULL
2026-04-30 19:49:52.602       0.497  1171482847050399746  created   ALTER TABLE omicron.public.inv_collection_error ALTER COLUMN message SET NOT NULL
2026-04-30 19:49:53.109       0.507  1171482847050399746  started   ALTER TABLE omicron.public.inv_collection_error ALTER COLUMN message SET NOT NULL
2026-04-30 19:59:17.604     564.494  1171484697707937793  created   ALTER TABLE omicron.public.inv_collection_error ALTER COLUMN message SET NOT NULL
2026-04-30 19:59:17.684       0.080  1171482847050399746  finished  ALTER TABLE omicron.public.inv_collection_error ALTER COLUMN message SET NOT NULL
2026-04-30 19:59:17.699       0.014  1171484698620198914  created   ALTER TABLE omicron.public.inv_nvme_disk_firmware ALTER COLUMN slot1_is_read_only SET NOT NULL
2026-04-30 19:59:17.884       0.184  1171484697707937793  started   ALTER TABLE omicron.public.inv_collection_error ALTER COLUMN message SET NOT NULL
2026-04-30 19:59:18.211       0.327  1171484698620198914  started   ALTER TABLE omicron.public.inv_nvme_disk_firmware ALTER COLUMN slot1_is_read_only SET NOT NULL
2026-04-30 20:04:16.638     298.427  1171484697707937793  finished  ALTER TABLE omicron.public.inv_collection_error ALTER COLUMN message SET NOT NULL
2026-04-30 20:16:44.500     747.862  1171484698620198914  finished  ALTER TABLE omicron.public.inv_nvme_disk_firmware ALTER COLUMN slot1_is_read_only SET NOT NULL
2026-04-30 20:16:44.508       0.008  1171488128215449602  created   ALTER TABLE omicron.public.inv_nvme_disk_firmware ALTER COLUMN slot_firmware_versions SET NOT NULL
2026-04-30 20:16:44.772       0.263  1171488128215449602  started   ALTER TABLE omicron.public.inv_nvme_disk_firmware ALTER COLUMN slot_firmware_versions SET NOT NULL
2026-04-30 20:26:59.863     615.091  1171488128215449602  finished  ALTER TABLE omicron.public.inv_nvme_disk_firmware ALTER COLUMN slot_firmware_versions SET NOT NULL
2026-04-30 20:26:59.872       0.008  1171490143863373826  created   ALTER TABLE omicron.public.multicast_group_member ALTER COLUMN source_ips SET NOT NULL
2026-04-30 20:26:59.913       0.040  1171490143863373826  started   ALTER TABLE omicron.public.multicast_group_member ALTER COLUMN source_ips SET NOT NULL
2026-04-30 20:42:07.479     907.566  1171490143863373826  finished  ALTER TABLE omicron.public.multicast_group_member ALTER COLUMN source_ips SET NOT NULL
2026-04-30 20:42:07.488       0.008  1171493117938532354  created   ALTER TABLE omicron.public.vmm ALTER COLUMN cpu_platform SET NOT NULL
2026-04-30 20:42:07.519       0.030  1171493117938532354  started   ALTER TABLE omicron.public.vmm ALTER COLUMN cpu_platform SET NOT NULL
2026-04-30 21:02:02.072    1194.553  1171493117938532354  finished  ALTER TABLE omicron.public.vmm ALTER COLUMN cpu_platform SET NOT NULL
2026-04-30 21:02:02.080       0.007  1171497032377630722  created   ALTER TABLE omicron.public.switch_port ALTER COLUMN port_name SET NOT NULL
2026-04-30 21:02:02.108       0.028  1171497032377630722  started   ALTER TABLE omicron.public.switch_port ALTER COLUMN port_name SET NOT NULL
2026-04-30 21:16:33.706     871.597  1171497032377630722  finished  ALTER TABLE omicron.public.switch_port ALTER COLUMN port_name SET NOT NULL
2026-04-30 21:16:33.715       0.009  1171499888551395330  created   ALTER TABLE omicron.public.switch_port ALTER COLUMN rack_id SET NOT NULL
2026-04-30 21:16:33.746       0.030  1171499888551395330  started   ALTER TABLE omicron.public.switch_port ALTER COLUMN rack_id SET NOT NULL
2026-04-30 21:26:27.558     593.811  1171499888551395330  finished  ALTER TABLE omicron.public.switch_port ALTER COLUMN rack_id SET NOT NULL
2026-04-30 21:29:20.400     172.842  1171502400893386753  created   CREATE INDEX IF NOT EXISTS lookup_fm_alert_requests_for_case ON omicron.public.fm_alert_request (sitrep_id, case_id)
2026-04-30 21:29:20.453       0.053  1171502400893386753  started   CREATE INDEX IF NOT EXISTS lookup_fm_alert_requests_for_case ON omicron.public.fm_alert_request (sitrep_id, case_id)
2026-04-30 21:29:20.647       0.193  1171502400893386753  finished  CREATE INDEX IF NOT EXISTS lookup_fm_alert_requests_for_case ON omicron.public.fm_alert_request (sitrep_id, case_id)
2026-04-30 21:34:10.683     290.036  1171503352145510404  created   ALTER TABLE omicron.public.alert ADD COLUMN IF NOT EXISTS case_id UUID
2026-04-30 21:34:10.761       0.077  1171503352145510404  started   ALTER TABLE omicron.public.alert ADD COLUMN IF NOT EXISTS case_id UUID
2026-04-30 21:43:12.659     541.898  1171505127968899074  created   ALTER TABLE omicron.public.multicast_group DROP CONSTRAINT IF EXISTS mvlan_valid_range
2026-04-30 21:43:12.693       0.033  1171505127968899074  started   ALTER TABLE omicron.public.multicast_group DROP CONSTRAINT IF EXISTS mvlan_valid_range
2026-04-30 21:46:32.339     199.646  1171503352145510404  finished  ALTER TABLE omicron.public.alert ADD COLUMN IF NOT EXISTS case_id UUID
2026-04-30 21:56:26.166     593.826  1171507728284942338  created   ALTER TABLE omicron.public.multicast_group DROP COLUMN IF EXISTS mvlan
2026-04-30 21:56:26.246       0.080  1171507728284942338  started   ALTER TABLE omicron.public.multicast_group DROP COLUMN IF EXISTS mvlan
2026-04-30 21:56:26.264       0.017  1171507728452943877  created   CREATE INDEX IF NOT EXISTS audit_log_incomplete_by_time_started ON omicron.public.audit_log (time_started, id) WHERE time_completed IS NULL
2026-04-30 21:56:26.309       0.045  1171507728452943877  started   CREATE INDEX IF NOT EXISTS audit_log_incomplete_by_time_started ON omicron.public.audit_log (time_started, id) WHERE time_completed IS NULL
2026-04-30 22:06:30.642     604.332  1171507728284942338  finished  ALTER TABLE omicron.public.multicast_group DROP COLUMN IF EXISTS mvlan
2026-04-30 22:06:30.730       0.088  1171505127968899074  finished  ALTER TABLE omicron.public.multicast_group DROP CONSTRAINT IF EXISTS mvlan_valid_range

This release includes a lot of schema migrations and many of them are very quick -- right up until 19:49Z, at which point they all get very slow. Before that, they were all taking less than a second. After that point, they were taking several minutes each. Of particular note is that job 1171482847050399746 is created and started for inv_collection_error, then 564 seconds later, a second job 1171484697707937793 is created for the same thing. 80ms after that, the first one finishes. The second job finishes 298s later. It's as though the creation of the second job unblocked the first job. Why? And why did both take so long?

Claude also got us down the path of why schema changes might take so long in terms of expiring table descriptor leases. See https://github.com/cockroachdb/cockroach/blob/master/docs/tech-notes/jobs.md. I did the experiment of seeing what happens when you try to change the schema of a table with an open transaction, and indeed, the schema change blocks until the transaction has been open for up to 5 minutes. A second concurrent attempt to change the schema didn't, though: it failed right away with an error about the operation being in progress:

session 1:
    create table foo (a INT);
    BEGIN;

session 2:
demo@127.0.0.1:26257/movr> ALTER TABLE foo ADD COLUMN b INT;
ALTER TABLE


Time: 284.048s total (execution 284.048s / network 0.000s)

session 3:

demo@127.0.0.1:26257/movr> SELECT NOW();
               now
---------------------------------
  2026-05-01 21:09:55.489007+00
(1 row)


Time: 1ms total (execution 0ms / network 0ms)

demo@127.0.0.1:26257/movr> ALTER TABLE foo ADD COLUMN b INT;
ERROR: duplicate: column "b" in the middle of being added, not yet public
SQLSTATE: 42701

[davepacheco]

CockroachDB logs

The CockroachDB logs have a lot more information about what was going on, but we haven't yet figured out the problem. We did see evidence that nodes were taking multiple minutes waiting for leases on table descriptors to expire. (We don't know who or what was holding onto them.) We also found evidence that two nodes were offline for 35 days prior to all of this. Their rangefeeds were very far behind, but they were pretty quickly repaired using snapshots from other nodes. At least one of the affected ranges (r6) includes the one that stores table descriptors, so it's conceivable that was why that node wasn't finding out about changes quickly? But this doesn't explain why things continued to be slow for hours after the rangefeed problem was repaired.

What we know:

1. schema updates were slow at least in part because of descriptor leases held
2. two nodes appear to have been offline for weeks prior to this and had a lot of catching up to do
3. that catch-up relates to r6, which contains information about the descriptors
4. r7, which also has information related to leases, was also sad at points for reasons I don't think we can tell from the log ("raft receive queue for r7 is full" messages)

Possible next avenues:

• Dig deeper into the implementation to better understand exactly what these operations could have been blocked on. This is probably a good investment of time, but I can't see prioritizing it.
• Change the config to log more detailed information about leases. But I'm not sure we can afford to log leases acquired/released during ordinary transactions -- there are so many.
• Update Nexus to periodically log the contents of system.lease and system.descriptor. (Well, system.descriptor is basically a bunch of blobs so we'd have to write a decoder for that, too.)
• Try to reproduce the problem elsewhere by doing a schema update after a node's been offline for a long time.

However, I'm putting this aside for now. It isn't a burning fire and we've got lots of other work to do.