Nextcloud 12.0.2 upgrade - stuck or just slow?

pfaff · August 16, 2017, 11:58am

I’m upgrading Nextcloud-11.0.3 to 12.0.2.

The upgrade is being done manually with:

occ upgrade -vvv -n

According to output, the upgrade has been at this step for the past 8 hours:

Repair step: Repair mime types

I realize that some steps may take a long time depending on the size of the installation, but is there any way to diagnose progress other than the output of the occ upgrade command? I want to confirm that the process is proceeding as expected and I just have to be patient, or whether it is stuck and, if so, how I should proceed (e.g. kill the occ upgrade php process? then what?).

Help please! Thanks!

BernhardPosselt · August 16, 2017, 12:07pm

check data/nextcloud.log

pfaff · August 16, 2017, 12:13pm

I’ve done that. I’m not seeing anything there that isn’t reflected in the occ upgrade -vvv output, and there’s nothing new being logged other than regular messages about the cron jobs being skipped until upgrade is done.

pfaff · August 16, 2017, 12:22pm

Which Nextcloud database table(s) does the “repair mime types” step operate on?

Does it, for example, have to touch every row in the oc_filecache table?

I ask since, as I’ve said in another recent forum post, our filecache table has about 400 million rows.

It would be helpful if there were a more granular way to see the progress of each upgrade step.

pfaff · August 16, 2017, 1:12pm

The mysql server shows this in its processlist.

Is there any way to dig deeper into this mysql transaction to get a sense of its progress?

pfaff · August 16, 2017, 2:49pm

I’m getting my shovel out and digging deeper. I’m learning more mysql as I go, but I’d still appreciate any guidance from Nextcloud and MySQL experts on this forum to help me get to the buried treasure more quickly - the buried treasure being a completed Nextcloud-12.0.2 upgrade of course.

mysql> show processlist\G;

*************************** 1. row ***************************
Id: 135582
User: oc_admin
Host: 192.168.168.168:36098
db: owncloud
Command: Query
Time: 10587
State: updating
Info: UPDATE oc_filecache
SET mimetype = '138’
WHERE mimetype <> ‘2’ AND mimetype <> ‘138’ A

mysql> select * from performance_schema.threads where processlist_id=135582\G;

*************************** 1. row ***************************
THREAD_ID: 135616
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 135582
PROCESSLIST_USER: oc_admin
PROCESSLIST_HOST: 192.168.168.168
PROCESSLIST_DB: owncloud
PROCESSLIST_COMMAND: Query
PROCESSLIST_TIME: 10735
PROCESSLIST_STATE: updating
PROCESSLIST_INFO: UPDATE oc_filecache
SET mimetype = '138’
WHERE mimetype <> ‘2’ AND mimetype <> ‘138’ AND name COLLATE UTF8_general_ci LIKE '%.bat’
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: TCP/IP
THREAD_OS_ID: 22181

mysql> select thread_id,event_id,end_event_id,event_name,sql_text from performance_schema.events_statements_history where thread_id=135616\G;

*************************** 1. row ***************************
thread_id: 135616
event_id: 2601
end_event_id: 2601
event_name: statement/sql/select
sql_text: SELECT id
FROM oc_mimetypes
WHERE mimetype = ‘application/x-msdos-program’
*************************** 2. row ***************************
thread_id: 135616
event_id: 2592
end_event_id: 2592
event_name: statement/sql/select
sql_text: SELECT count(mimetype)
FROM oc_mimetypes
WHERE mimetype = ‘image/webp’
*************************** 3. row ***************************
thread_id: 135616
event_id: 2593
end_event_id: 2593
event_name: statement/sql/insert
sql_text: INSERT INTO oc_mimetypes ( mimetype )
VALUES ( ‘image/webp’ )
*************************** 4. row ***************************
thread_id: 135616
event_id: 2594
end_event_id: 2594
event_name: statement/sql/select
sql_text: SELECT id
FROM oc_mimetypes
WHERE mimetype = ‘image/webp’
*************************** 5. row ***************************
thread_id: 135616
event_id: 2595
end_event_id: 2595
event_name: statement/sql/update
sql_text: UPDATE oc_filecache
SET mimetype = '137’
WHERE mimetype <> ‘2’ AND mimetype <> ‘137’ AND name COLLATE UTF8_general_ci LIKE ‘%.webp’
*************************** 6. row ***************************
thread_id: 135616
event_id: 2596
end_event_id: 2596
event_name: statement/sql/select
sql_text: SELECT count(mimetype)
FROM oc_mimetypes
WHERE mimetype = ‘text/plain’
*************************** 7. row ***************************
thread_id: 135616
event_id: 2597
end_event_id: 2597
event_name: statement/sql/select
sql_text: SELECT id
FROM oc_mimetypes
WHERE mimetype = ‘text/plain’
*************************** 8. row ***************************
thread_id: 135616
event_id: 2598
end_event_id: 2598
event_name: statement/sql/update
sql_text: UPDATE oc_filecache
SET mimetype = '15’
WHERE mimetype <> ‘2’ AND mimetype <> ‘15’ AND name COLLATE UTF8_general_ci LIKE ‘%.htaccess’
*************************** 9. row ***************************
thread_id: 135616
event_id: 2599
end_event_id: 2599
event_name: statement/sql/select
sql_text: SELECT count(mimetype)
FROM oc_mimetypes
WHERE mimetype = ‘application/x-msdos-program’
*************************** 10. row ***************************
thread_id: 135616
event_id: 2600
end_event_id: 2600
event_name: statement/sql/insert
sql_text: INSERT INTO oc_mimetypes ( mimetype )
VALUES ( ‘application/x-msdos-program’ )

pfaff · August 16, 2017, 3:27pm

mysql> show engine innodb status\G;

---TRANSACTION 168868838, ACTIVE 1729 sec fetching rows
mysql tables in use 1, locked 1
8073598 lock struct(s), heap size 722657488, 10996 row lock(s), undo log entries
 10996
MySQL thread id 135582, OS thread handle 140063858198272, query id 5526995 10.113.48.19 oc_admin updating
UPDATE `oc_filecache`
                        SET `mimetype` = '139'
                        WHERE `mimetype` <> '2' AND `mimetype` <> '139' AND `name` COLLATE UTF8_general_ci LIKE '%.cmd'
--------

pfaff · August 16, 2017, 4:54pm

For the record, it does appear that progress is being made, based on timestamps of mysql db files.

It is now 12:50PM EST. The upgrade is still performing the “Repair mime types” step.

The upgrade process began at 12:14AM EST, and most tables .ibd files have last change times close to that start time. These two tables have changed more recently:

oc_mimetypes.ibd 10:54AM EST
oc_filecache.ibd 12:14PM EST

I guess we’ll just have to wait this out.

Are there any more steps after “Repair mime types” that I can expect to take as long?

pfaff · August 16, 2017, 6:34pm

Progress!

At 1:43PM it completed “Repair mime types” and began “Clean tags and favourites”. It proceeded quickly through that step and eight others and is now on “Repair invalid paths in file cache”. I’m guessing that this step, which is also presumably going to operate on every row in filecache, will take a long time. Hopefully not another 12 hours.

At least I know it was just slow and not stuck. The sad part is that to plan for service upgrades we will need to schedule a service outage of at least 24 hours, and this is only bound to get worse over time as filecache grows.

pfaff · August 19, 2017, 1:04am

The upgrade process finally completed at about 9pm that evening.

adrianwi · August 28, 2017, 5:11pm

I’m currently facing the same issue with an upgrade from 12.0 to 12.0.2. About 7 hours and counting so far, but it looks almost identical to your experience.

Surely there is an issue here somewhere as I’ve never known an update (oC or NC) to take this length of time?

Did you migrate from an ownCloud database back at version 9?