Background updates do not continue when Synapse is restarted after they are started

[turt2live]

First query is from 12+ hours ago, second is from minutes ago. Logs don't show them progressing at all. The server was restarted several times after updating from 0.99.2 to 1.0.0, which included a restart shortly after the first update - this is likely to have interrupted the background updates.

synapse=# select * from background_updates ;
              update_name              |        progress_json         |              depends_on
---------------------------------------+------------------------------+---------------------------------------
 delete_soft_failed_extremities        | {}                           |
 populate_stats_cleanup                | {}                           | populate_stats_process_rooms
 user_ips_device_unique_index          | {}                           | user_ips_remove_dupes
 user_ips_drop_nonunique_index         | {}                           | user_ips_device_unique_index
 populate_user_directory_cleanup       | {}                           | populate_user_directory_process_users
 populate_stats_process_rooms          | {"remaining": 1032}          | populate_stats_createtables
 user_ips_remove_dupes                 | {"last_seen": 1560794275025} |
 populate_user_directory_process_users | {"remaining": 1320}          | populate_user_directory_process_rooms
(8 rows)

synapse=# select * from background_updates ;
              update_name              |        progress_json         |              depends_on
---------------------------------------+------------------------------+---------------------------------------
 delete_soft_failed_extremities        | {}                           |
 populate_stats_cleanup                | {}                           | populate_stats_process_rooms
 user_ips_device_unique_index          | {}                           | user_ips_remove_dupes
 user_ips_drop_nonunique_index         | {}                           | user_ips_device_unique_index
 populate_user_directory_cleanup       | {}                           | populate_user_directory_process_users
 populate_stats_process_rooms          | {"remaining": 1032}          | populate_stats_createtables
 user_ips_remove_dupes                 | {"last_seen": 1560794275025} |
 populate_user_directory_process_users | {"remaining": 1320}          | populate_user_directory_process_rooms
(8 rows)

[richvdh]

They should do! Anything in the logs?

[turt2live]

They're pretty much quiet.

This happens twice in the last 8 hours:

2019-06-18 10:45:37,108 - synapse.storage._base - 423 - WARNING - background_updates-0- [TXN OPERROR] {user_ips_dups_remove-620} could not serialize access due to concurrent update

This happens more than twice, but still not very often:

2019-06-18 06:03:00,865 - synapse.storage.TIME - 380 - INFO - - Total database time: 0.001% {set_received_txn_response(4): 0.001%, get_received_txn_response(4): 0.000%, check_background_updates(1): 0.000%} {}

[richvdh]

I think this is just a symptom of #4430.

[turt2live]

ftr the problem was that the user_ips table got stuck in a lock for 6+ months, so it was never able to run the background update. Ultimately ended up with 4800 live rows and 126 million dead rows in the table, which were contributing to the complexity of the table's indexes. Because the table hadn't been updated in so long (and the vacuum was still running after 21 hours), the table was dropped and re-created from the existing schema. This allows the background update to progress forwards and move on to the other tasks.