Upgrading 5.32 to ESR (5.37.10)

Troubleshooting
1

Summary
SystemD Mattermost.service starting (activating) after 4 hours (8 million posts and 100+ channels)

Steps to reproduce
Attempting to upgrade MM Team Version 5.32 to 5.37.10

Expected behavior
Successful upgrade to nearest ESR to upgrade all the way to latest release.

Observed behavior
The start up service is still running and appears to be doing nothing (tasks aren’t utilising much memory and no CPU) - No errors or warnings in mySQL logs, journalctl or syslog.

Log content from opt/mattermost/logs:-

{"level":"warn","ts":1681540763.7665532,"caller":"sqlstore/upgrade.go:243","msg":"Attempting to upgrade the database schema version","stored_version":"5.32.0","current_version":"5.32.0","new_version":"5.33.0"}
{"level":"warn","ts":1681540763.773967,"caller":"sqlstore/upgrade.go:224","msg":"The database schema version has been upgraded","version":"5.33.0"}
{"level":"warn","ts":1681540763.7744527,"caller":"sqlstore/upgrade.go:243","msg":"Attempting to upgrade the database schema version","stored_version":"5.33.0","current_version":"5.33.0","new_version":"5.34.0"}
{"level":"warn","ts":1681540763.7827187,"caller":"sqlstore/upgrade.go:224","msg":"The database schema version has been upgraded","version":"5.34.0"}
{"level":"info","ts":1681544365.637209,"caller":"app/server.go:269","msg":"Server is initializing...","go_version":"go1.16.7"}
{"level":"info","ts":1681544365.6373296,"caller":"app/web_hub.go:93","msg":"Starting websocket hubs","number_of_hubs":8}
{"level":"info","ts":1681544365.6544635,"caller":"i18n/i18n.go:93","msg":"Loaded system translations","for locale":"en","from locale":"/opt/mattermost/i18n/en.json"}
{"level":"info","ts":1681544365.6631057,"caller":"sqlstore/store.go:306","msg":"Pinging SQL","database":"master"}
{"level":"info","ts":1681544365.6680076,"caller":"sqlstore/store.go:306","msg":"Pinging SQL","database":"migrations"}
{"level":"info","ts":1681544652.7801394,"caller":"app/server.go:269","msg":"Server is initializing...","go_version":"go1.16.7"}
{"level":"info","ts":1681544652.7802536,"caller":"app/web_hub.go:93","msg":"Starting websocket hubs","number_of_hubs":8}
{"level":"info","ts":1681544652.780973,"caller":"i18n/i18n.go:93","msg":"Loaded system translations","for locale":"en","from locale":"/opt/mattermost/i18n/en.json"}
{"level":"info","ts":1681544652.785659,"caller":"sqlstore/store.go:306","msg":"Pinging SQL","database":"master"}
{"level":"info","ts":1681544652.7890236,"caller":"sqlstore/store.go:306","msg":"Pinging SQL","database":"migrations"}

Or…am I just underestimating how long the process should take?

2

Hi @roakley and welcome to the Mattermost forums!

I’m not sure in what state your sytsem is currently, are you sure that the application is still running and that it has not been killed by systemd’s timer? Running large migrations sometimes is a problem via systemd because there’s a startup timer and if the application takes longer to start, systemd will kill it and try to restart it and then the process repeats.
Check your systemd unit for a value called TimeoutStartSec, I’ve set it to 3600 on my setup which gives it an hour to start:

[Service]
Type=notify
ExecStart=/opt/mattermost/bin/mattermost
TimeoutStartSec=3600

You can also run the upgrades manually by logging in to the mattermost user on the console and executing the command directly in the shell without systemd (at least for the first time you want to start it to make sure the migrations work as expected and have enough time to unfold):

su - mattermost
cd /opt/mattermost
bin/mattermost

(this is of course only valid if you used the suggested directories and usernames, if you changed them, modify the commands accordingly).

Mattermost will then run in the foreground and you can monitor what it’s doing.

3

Hi @agriesser

The systemd timeout was adjusted to 10 hours (36000 secs). Here are the contents of /lib/systemd/system/mattermost.service :-

[Unit]
Description=Mattermost
After=network.target
After=mysql.service
BindsTo=mysql.service

[Service]
Type=notify
ExecStart=/opt/mattermost/bin/mattermost
TimeoutStartSec=36000
Restart=always
RestartSec=10
WorkingDirectory=/opt/mattermost
User=mattermost
Group=mattermost
LimitNOFILE=49152

[Install]
WantedBy=mysql.service

Starting the app without systemd is a great idea. I will give this a go in the next downtime window.

4

Running in the foreground doesn’t seem to output anything at all. At least, not after 5 minutes. Here is what I am seeing (attached image)

image

5

In /opt/mattermost/logs/mattermost.log the same output(s) are observed too. The schema has updated but nothing more. Could it just be our data is taking this long?

Additionally, I can now see this (new to my eyes):-

{"level":"warn","ts":1681652567.9478245,"caller":"app/post_metadata.go:120","msg":"Failed to get files for a post","post_id":"itxabszg5prubj94dq5gcrfhqw","error":"GetFileInfosForPost: Unable to get the file info for the post., failed to find FileInfos with postId=itxabszg5prubj94dq5gcrfhqw: sql: database is closed"}

6

In this case, your console loglevel is probably not set correctly.
Can you check for the following settings in your config.json?

  "LogSettings": {
    "EnableConsole": true,
    "ConsoleLevel": "INFO",
    "ConsoleJson": true,
    "EnableFile": true,
    "FileLevel": "INFO",
    "FileJson": true,
    "AdvancedLoggingConfig": ""
  },

These are some of the default configurations in this section, you should have them too. Console and File Level logging is enabled and both are set to level INFO - in your case, console level logging is probably disabled and therefore you don’t see anything.
I’d also suggest to set it to DEBUG while we’re trying to find out what’s going on here.

When you start Mattermost the next time directly in the console with logging turned on, please do also open a second shell and login to your database server and check if it is running the migration queries and if so, if there are any that take very long to finish:

-- PostgreSQL
select pid,backend_start,query_start,state_change,waiting,state,query from pg_stat_activity;

-- MySQL
show full processlist;
7

We have started a new migration attempt on a cloned VM…

Here is a snippet from the process list, in mySQL, immediately after starting:-

|  5 | event_scheduler | localhost       | NULL       | Daemon  | 2919 | Waiting on empty queue | NULL  
| 52 | mmuser          | localhost:54960 | mattermost | Query   |   79 | copy to tmp table      | ALTER TABLE Posts ADD RemoteId VARCHAR(26)
8

One of our Senior Programmers commented, “The Copy to tmp table state implies it will copy the entire table, add the column, then copy it back. Definitely going to be slow and probably bound by disk IO and not CPU time which might explain things.”

9

Yes, in-place schema upgrades are not always possible unfortunately, depending on the data structure and the involved versions.
You can monitor the process by installing iostat out of the sysstat package and you can check the file sizes in /var/lib/mysql on your database server; you should see the creation of a new file there with tmp in its name and it will grow until it reaches the size of the Posts table - this should help you with your estimates.
As long as the query is running, you should be good to go, just keep monitoring it.

10

All I can see is the following:-

-rw-r----- 1 mysql mysql   104857600 Apr 17 06:22  Audits.ibd
-rw-r----- 1 mysql mysql      114688 Apr 16 14:33  Bots.ibd
-rw-r----- 1 mysql mysql    26214400 Apr 14 18:41  ChannelMemberHistory.ibd
-rw-r----- 1 mysql mysql    75497472 Apr 17 06:21  ChannelMembers.ibd
-rw-r----- 1 mysql mysql    41943040 Apr 17 06:20  Channels.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  ClusterDiscovery.ibd
-rw-r----- 1 mysql mysql      131072 Apr 13 16:54  CommandWebhooks.ibd
-rw-r----- 1 mysql mysql      180224 Apr 13 13:18  Commands.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  Compliances.ibd
-rw-r----- 1 mysql mysql      671744 Apr 14 14:42  Emoji.ibd
-rw-r----- 1 mysql mysql  1065353216 Apr 17 05:59  FileInfo.ibd
-rw-r----- 1 mysql mysql      147456 Feb 13  2021  GroupChannels.ibd
-rw-r----- 1 mysql mysql      131072 Feb 13  2021  GroupMembers.ibd
-rw-r----- 1 mysql mysql      147456 Feb 13  2021  GroupTeams.ibd
-rw-r----- 1 mysql mysql      196608 Jul 13  2022  IncomingWebhooks.ibd
-rw-r----- 1 mysql mysql    13631488 Apr 17 05:47  Jobs.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  Licenses.ibd
-rw-r----- 1 mysql mysql   150994944 Apr 15 16:49  LinkMetadata.ibd
-rw-r----- 1 mysql mysql      180224 Feb 13  2021  OAuthAccessData.ibd
-rw-r----- 1 mysql mysql      131072 Feb 13  2021  OAuthApps.ibd
-rw-r----- 1 mysql mysql      131072 Feb 13  2021  OAuthAuthData.ibd
-rw-r----- 1 mysql mysql      180224 Feb 13  2021  OutgoingWebhooks.ibd
-rw-r----- 1 mysql mysql      163840 Jul 22  2022  PluginKeyValueStore.ibd
-rw-r----- 1 mysql mysql 11861491712 Apr 17 06:20  Posts.ibd
-rw-r----- 1 mysql mysql   117440512 Apr 17 06:19  Preferences.ibd
-rw-r----- 1 mysql mysql      425984 Apr 15 15:39  ProductNoticeViewState.ibd
-rw-r----- 1 mysql mysql      409600 Apr 12 07:56  PublicChannels.ibd
-rw-r----- 1 mysql mysql   171966464 Apr 17 10:02  Reactions.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  RemoteClusters.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:01  RetentionPolicies.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:01  RetentionPoliciesChannels.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  RetentionPoliciesTeams.ibd
-rw-r----- 1 mysql mysql      131072 Apr 17 10:02  Roles.ibd
-rw-r----- 1 mysql mysql      180224 Feb 13  2021  Schemes.ibd
-rw-r----- 1 mysql mysql     8388608 Apr 17 06:22  Sessions.ibd
-rw-r----- 1 mysql mysql      131072 Apr 17 10:02  SharedChannelAttachments.ibd
-rw-r----- 1 mysql mysql      131072 Apr 17 10:02  SharedChannelRemotes.ibd
-rw-r----- 1 mysql mysql      131072 Apr 17 10:02  SharedChannelUsers.ibd
-rw-r----- 1 mysql mysql      131072 Apr 17 10:02  SharedChannels.ibd
-rw-r----- 1 mysql mysql      425984 Apr 17 10:02  SidebarCategories.ibd
-rw-r----- 1 mysql mysql    12582912 Apr 14 18:41  SidebarChannels.ibd
-rw-r----- 1 mysql mysql      409600 Apr 17 09:20  Status.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  Systems.ibd
-rw-r----- 1 mysql mysql      311296 Apr 12 13:14  TeamMembers.ibd
-rw-r----- 1 mysql mysql      229376 Apr 19  2021  Teams.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  TermsOfService.ibd
-rw-r----- 1 mysql mysql   255852544 Apr 17 06:21  ThreadMemberships.ibd
-rw-r----- 1 mysql mysql    71303168 Apr 17 06:20  Threads.ibd
-rw-r----- 1 mysql mysql      114688 Apr 14 12:52  Tokens.ibd
-rw-r----- 1 mysql mysql      147456 Apr 19  2021  UploadSessions.ibd
-rw-r----- 1 mysql mysql      163840 Mar 23 09:14  UserAccessTokens.ibd
-rw-r----- 1 mysql mysql      180224 Feb 13  2021  UserGroups.ibd
-rw-r----- 1 mysql mysql      131072 Feb 13  2021  UserTermsOfService.ibd
-rw-r----- 1 mysql mysql      737280 Apr 17 10:02  Users.ibd
-rw-r----- 1 mysql mysql  2462056448 Apr 14 16:04  fts_000000000000055b_0000000000000340_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_0000000000000340_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_0000000000000340_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_0000000000000340_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_0000000000000340_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Mar 23 13:45  fts_000000000000055b_0000000000000340_index_6.ibd
-rw-r----- 1 mysql mysql     2097152 Apr 14 08:33  fts_000000000000055b_0000000000000347_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_0000000000000347_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_0000000000000347_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_0000000000000347_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_0000000000000347_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_0000000000000347_index_6.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_being_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_being_deleted_cache.ibd
-rw-r----- 1 mysql mysql      114688 Apr 14 16:04  fts_000000000000055b_config.ibd
-rw-r----- 1 mysql mysql    13631488 Apr 17 05:52  fts_000000000000055b_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000055b_deleted_cache.ibd
-rw-r----- 1 mysql mysql      229376 Jan 31 06:53  fts_000000000000056e_000000000000035d_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000056e_000000000000035d_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000056e_000000000000035d_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000056e_000000000000035d_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000056e_000000000000035d_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000056e_000000000000035d_index_6.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000056e_being_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000056e_being_deleted_cache.ibd
-rw-r----- 1 mysql mysql      114688 Jan 31 06:53  fts_000000000000056e_config.ibd
-rw-r----- 1 mysql mysql      114688 Apr  5 13:12  fts_000000000000056e_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Feb 13  2021  fts_000000000000056e_deleted_cache.ibd
-rw-r----- 1 mysql mysql    15728640 Mar 31 13:23  fts_00000000000005af_00000000000003dd_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005af_00000000000003dd_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005af_00000000000003dd_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005af_00000000000003dd_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005af_00000000000003dd_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005af_00000000000003dd_index_6.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005af_being_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005af_being_deleted_cache.ibd
-rw-r----- 1 mysql mysql      114688 Mar 31 13:23  fts_00000000000005af_config.ibd
-rw-r----- 1 mysql mysql      114688 Apr 13 11:09  fts_00000000000005af_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005af_deleted_cache.ibd
-rw-r----- 1 mysql mysql    37748736 Apr  4 14:04  fts_00000000000005bb_00000000000003ef_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003ef_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003ef_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003ef_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003ef_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003ef_index_6.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003fc_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003fc_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003fc_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003fc_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003fc_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_00000000000003fc_index_6.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_being_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_being_deleted_cache.ibd
-rw-r----- 1 mysql mysql      114688 Apr  4 14:04  fts_00000000000005bb_config.ibd
-rw-r----- 1 mysql mysql    10485760 Apr 14 09:58  fts_00000000000005bb_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Apr 19  2021  fts_00000000000005bb_deleted_cache.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000844_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000844_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000844_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000844_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000844_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000844_index_6.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_000000000000084b_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_000000000000084b_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_000000000000084b_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_000000000000084b_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_000000000000084b_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_000000000000084b_index_6.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000852_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000852_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000852_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000852_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000852_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000852_index_6.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000859_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000859_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000859_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000859_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000859_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_0000000000000859_index_6.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_being_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_being_deleted_cache.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_config.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008d3_deleted_cache.ibd
-rw-r----- 1 mysql mysql  1128267776 Apr 17 12:12  fts_00000000000008f1_0000000000000870_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_0000000000000870_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_0000000000000870_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_0000000000000870_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_0000000000000870_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 12:03  fts_00000000000008f1_0000000000000870_index_6.ibd
-rw-r----- 1 mysql mysql      344064 Apr 17 12:12  fts_00000000000008f1_0000000000000877_index_1.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_0000000000000877_index_2.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_0000000000000877_index_3.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_0000000000000877_index_4.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_0000000000000877_index_5.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_0000000000000877_index_6.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_being_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_being_deleted_cache.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 12:12  fts_00000000000008f1_config.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_deleted.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:02  fts_00000000000008f1_deleted_cache.ibd
-rw-r----- 1 mysql mysql      114688 Apr 17 10:01  schema_migrations.ibd
11

Alright, your Posts table is 12GB in size - can you confirm that you have at least this diskspace additionally available on your databas server?
Also, can you share the output of the following query:

mysql> show variables like "%tmpdir";
+---------------------+-------+
| Variable_name       | Value |
+---------------------+-------+
| innodb_tmpdir       |       |
| replica_load_tmpdir | /tmp  |
| slave_load_tmpdir   | /tmp  |
| tmpdir              | /tmp  |
+---------------------+-------+
4 rows in set (0.01 sec)

On my demo system, the directory /tmp will be used to store temporary files and tables, so if you have partitioned your system and /tmp is on a separate partition, it needs to have enough space for the rebuild of the tables.

12

We have a lot of free space (801GB free/ 1.12TB used).

Output from show variables like "%tmpdir"; =

mysql> show variables like "%tmpdir";
+---------------------+-------+
| Variable_name       | Value |
+---------------------+-------+
| innodb_tmpdir       |       |
| replica_load_tmpdir | /tmp  |
| slave_load_tmpdir   | /tmp  |
| tmpdir              | /tmp  |
+---------------------+-------+
4 rows in set (0.64 sec)

/tmp isn’t provisioned on a separate part.

Thanks in advance for your help on this.

13

Running ls -l /proc/1087/fd shows :-

lr-x------ 1 mysql mysql 64 Apr 17 13:15 0 -> /dev/null
l-wx------ 1 mysql mysql 64 Apr 17 13:15 1 -> /var/log/mysql/error.log
lrwx------ 1 mysql mysql 64 Apr 17 13:15 10 -> /var/lib/mysql/ibdata1
lrwx------ 1 mysql mysql 64 Apr 17 13:15 100 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000877_index_3.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 101 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000877_index_4.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 102 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000877_index_5.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 103 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000877_index_6.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 104 -> 'socket:[603359]'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 11 -> /var/lib/mysql/#innodb_redo/#ib_redo9974
lrwx------ 1 mysql mysql 64 Apr 17 13:15 12 -> /var/lib/mysql/undo_001
lrwx------ 1 mysql mysql 64 Apr 17 13:15 13 -> '/tmp/#8126470 (deleted)'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 14 -> /var/lib/mysql/undo_002
lrwx------ 1 mysql mysql 64 Apr 17 13:15 15 -> /var/lib/mysql/ibtmp1
lrwx------ 1 mysql mysql 64 Apr 17 13:15 16 -> /var/lib/mysql/mysql.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 17 -> 'anon_inode:[eventpoll]'
lr-x------ 1 mysql mysql 64 Apr 17 13:15 18 -> 'pipe:[26292]'
l-wx------ 1 mysql mysql 64 Apr 17 13:15 19 -> 'pipe:[26292]'
l-wx------ 1 mysql mysql 64 Apr 17 13:15 2 -> /var/log/mysql/error.log
lrwx------ 1 mysql mysql 64 Apr 17 13:15 20 -> 'anon_inode:[eventfd]'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 21 -> 'socket:[26293]'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 22 -> 'socket:[26294]'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 23 -> /var/lib/mysql/#innodb_temp/temp_1.ibt
l-wx------ 1 mysql mysql 64 Apr 17 13:15 24 -> /var/lib/mysql/binlog.000856
lrwx------ 1 mysql mysql 64 Apr 17 13:15 25 -> /var/lib/mysql/#innodb_temp/temp_2.ibt
lrwx------ 1 mysql mysql 64 Apr 17 13:15 26 -> /var/lib/mysql/#innodb_temp/temp_3.ibt
lrwx------ 1 mysql mysql 64 Apr 17 13:15 27 -> 'socket:[26295]'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 28 -> /var/lib/mysql/#innodb_temp/temp_4.ibt
lrwx------ 1 mysql mysql 64 Apr 17 13:15 29 -> /var/lib/mysql/#innodb_temp/temp_5.ibt
lrwx------ 1 mysql mysql 64 Apr 17 13:15 3 -> 'socket:[26138]'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 30 -> /var/lib/mysql/#innodb_temp/temp_6.ibt
lrwx------ 1 mysql mysql 64 Apr 17 13:15 31 -> /var/lib/mysql/#innodb_temp/temp_7.ibt
lrwx------ 1 mysql mysql 64 Apr 17 13:15 32 -> /var/lib/mysql/#innodb_temp/temp_8.ibt
lrwx------ 1 mysql mysql 64 Apr 17 13:15 33 -> /var/lib/mysql/#innodb_temp/temp_9.ibt
lrwx------ 1 mysql mysql 64 Apr 17 13:15 34 -> /var/lib/mysql/#innodb_temp/temp_10.ibt
lrwx------ 1 mysql mysql 64 Apr 17 13:15 35 -> 'socket:[26296]'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 36 -> /var/lib/mysql/mattermost/Status.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 37 -> /var/lib/mysql/mattermost/Sessions.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 38 -> 'socket:[272790]'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 39 -> /var/lib/mysql/mattermost/Systems.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 4 -> /var/lib/mysql/binlog.index
lrwx------ 1 mysql mysql 64 Apr 17 13:15 40 -> /var/lib/mysql/mattermost/Preferences.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 41 -> /var/lib/mysql/mattermost/Posts.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 42 -> /var/lib/mysql/mattermost/schema_migrations.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 43 -> /var/lib/mysql/mattermost/#sql-43f_34.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 44 -> /var/lib/mysql/mattermost/Bots.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 45 -> /var/lib/mysql/mattermost/SharedChannels.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 46 -> /var/lib/mysql/mattermost/Channels.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 47 -> /var/lib/mysql/mattermost/SharedChannelRemotes.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 48 -> /var/lib/mysql/mattermost/SharedChannelUsers.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 49 -> /var/lib/mysql/mattermost/SharedChannelAttachments.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 5 -> /var/lib/mysql/#ib_16384_0.dblwr
lrwx------ 1 mysql mysql 64 Apr 17 13:15 50 -> /var/lib/mysql/mattermost/Reactions.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 51 -> /var/lib/mysql/mattermost/SidebarCategories.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 52 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000870_index_1.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 53 -> /var/lib/mysql/mattermost/RetentionPolicies.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 54 -> /var/lib/mysql/mattermost/RetentionPoliciesChannels.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 55 -> /var/lib/mysql/mattermost/RetentionPoliciesTeams.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 56 -> /var/lib/mysql/mattermost/RemoteClusters.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 57 -> /var/lib/mysql/mattermost/Roles.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 58 -> /var/lib/mysql/mattermost/Users.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 59 -> /var/lib/mysql/mattermost/fts_00000000000008d3_being_deleted.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 6 -> '/tmp/#8126466 (deleted)'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 60 -> /var/lib/mysql/mattermost/fts_00000000000008d3_being_deleted_cache.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 61 -> /var/lib/mysql/mattermost/fts_00000000000008d3_config.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 62 -> /var/lib/mysql/mattermost/fts_00000000000008d3_deleted.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 63 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000844_index_1.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 64 -> /var/lib/mysql/mattermost/fts_00000000000008d3_deleted_cache.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 65 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000844_index_2.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 66 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000844_index_3.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 67 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000844_index_4.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 68 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000844_index_5.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 69 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000844_index_6.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 7 -> '/tmp/#8126467 (deleted)'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 70 -> /var/lib/mysql/mattermost/fts_00000000000008d3_000000000000084b_index_1.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 71 -> /var/lib/mysql/mattermost/fts_00000000000008d3_000000000000084b_index_2.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 72 -> /var/lib/mysql/mattermost/fts_00000000000008d3_000000000000084b_index_3.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 73 -> /var/lib/mysql/mattermost/fts_00000000000008d3_000000000000084b_index_4.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 74 -> /var/lib/mysql/mattermost/fts_00000000000008d3_000000000000084b_index_5.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 75 -> /var/lib/mysql/mattermost/fts_00000000000008d3_000000000000084b_index_6.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 76 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000852_index_1.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 77 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000852_index_2.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 78 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000852_index_3.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 79 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000852_index_4.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 8 -> '/tmp/#8126468 (deleted)'
lrwx------ 1 mysql mysql 64 Apr 17 13:15 80 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000852_index_5.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 81 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000852_index_6.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 82 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000859_index_1.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 83 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000859_index_2.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 84 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000859_index_3.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 85 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000859_index_4.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 86 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000859_index_5.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 87 -> /var/lib/mysql/mattermost/fts_00000000000008d3_0000000000000859_index_6.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 88 -> /var/lib/mysql/mattermost/fts_00000000000008f1_being_deleted.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 89 -> /var/lib/mysql/mattermost/fts_00000000000008f1_being_deleted_cache.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 9 -> /var/lib/mysql/#ib_16384_1.dblwr
lrwx------ 1 mysql mysql 64 Apr 17 13:15 90 -> /var/lib/mysql/mattermost/fts_00000000000008f1_config.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 91 -> /var/lib/mysql/mattermost/fts_00000000000008f1_deleted.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 92 -> /var/lib/mysql/mattermost/fts_00000000000008f1_deleted_cache.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 93 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000870_index_2.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 94 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000870_index_3.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 95 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000870_index_4.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 96 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000870_index_5.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 97 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000870_index_6.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 98 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000877_index_1.ibd
lrwx------ 1 mysql mysql 64 Apr 17 13:15 99 -> /var/lib/mysql/mattermost/fts_00000000000008f1_0000000000000877_index_2.ibd
14

OK, interesting - is the query still running?
You could also check with iotop which should show you the files with the highest disk I/O (and in theory, the temporary new table should be in the top list).

15

It is still running, yes.

iotop --only shows the following:-

image
image754×301 8.36 KB

16

OK, at least the innodb log is commiting something and working with about 35MB/s.

17

Is this just a case of having to wait? Seems like we might be doing so for quite a while!

18

I don’t know exactly what your MySQL server is doing at the moment - there might be some options to tweak it in order for it to behave faster during the schema changes; could be that you have some transaction related values set that are bad for the performance, but it’s hard to tell for me without knowing a lot more details about your MySQL server including version and the relevant configuration.
Do you have a MySQL DBA at hand in your company you could ask to support you on that? Basically we’re looking for insights into what the server is doing right now and what configuration settings could be tuned to make it faster.

19

No DBAs, sadly.

Here is our mySQL version - mysql Ver 8.0.32 ubuntu 20.04.2

The MM server is a VM (4 vCPUs, 8GB Memory, 2TB storage)

20

The MM logs just started reporting that the upgrade has completed. It only took 12 hours! :stuck_out_tongue: