Issue: 4.1.5 to 4.1.6 upgrade hangs

Okay, overwrite with 4.1.5 files means it's back online

Please locate your internal-data://vw_logs/upgrade directory, and find the file dated when you last attempted the upgrade. Please email the log contents to support at vaultwiki org.

Yes, there are database changes in this release:
- Existing ratings are counted on each node. This might take 1-2 minutes.
- Links are recalculated for each node, due to a number of requested changes in what counts as a link. While doing this, some node titles are automatically reformatted if they violate certain rules. This might take several minutes.
- Depending on your server, collations on 8 tables may be changed. Potentially this could take a while.

In all, there is a bit of work for the upgrade to do here, but I would be surprised if it did not finish in less than 10 minutes.

== Upgrading to 4.0.0 Alpha 1 ==

== Step 1 (0) ==
rebuilding_data

== Step 2 (0) ==

== Step 3 (0) ==
Updating Version Number

== Upgrading to 4.1.6 ==

== Step 1 (0) ==
Altering table: vw_counter

== Upgrading to 4.1.6 ==

== Step 2 (0) ==
Updating data in table: vw_counter... ((200))

== Upgrading to 4.1.6 ==

== Step 2 (200) ==... ((400))

== Upgrading to 4.1.6 ==

== Step 2 (400) ==
Updating data in table: vw_counter... ((600))

== Upgrading to 4.1.6 ==

== Step 2 (600) ==... ((800))

== Upgrading to 4.1.6 ==

== Step 2 (800) ==
Updating data in table: vw_counter... ((1000))

== Upgrading to 4.1.6 ==

== Step 2 (1000) ==... ((1200))

== Upgrading to 4.1.6 ==

== Step 2 (1200) ==
Updating data in table: vw_counter... ((1400))

== Upgrading to 4.1.6 ==

== Step 2 (1400) ==... ((1600))

== Upgrading to 4.1.6 ==

== Step 2 (1600) ==
Updating data in table: vw_counter... ((1800))

== Upgrading to 4.1.6 ==

== Step 2 (1800) ==... ((2000))

== Upgrading to 4.1.6 ==

== Step 2 (2000) ==
Updating data in table: vw_counter... ((2200))

== Upgrading to 4.1.6 ==

== Step 2 (2200) ==... ((2400))

== Upgrading to 4.1.6 ==

== Step 2 (2400) ==
Updating data in table: vw_counter... ((2600))

== Upgrading to 4.1.6 ==

== Step 2 (2600) ==... ((2800))

== Upgrading to 4.1.6 ==

== Step 2 (2800) ==
Updating data in table: vw_counter... ((3000))

== Upgrading to 4.1.6 ==

== Step 2 (3000) ==... ((3200))

== Upgrading to 4.1.6 ==

== Step 2 (3200) ==
Updating data in table: vw_counter... ((3400))

== Upgrading to 4.1.6 ==

== Step 2 (3400) ==... ((3600))

== Upgrading to 4.1.6 ==

== Step 2 (3600) ==
Updating data in table: vw_counter

== Upgrading to 4.1.6 ==

== Step 3 (0) ==
Updating data in table: vw_feed

== Upgrading to 4.1.6 ==

== Step 4 (0) ==
Updating data in table: vw_page... ((32))

== Upgrading to 4.1.6 ==

== Step 4 (32) ==... ((53))

== Upgrading to 4.1.6 ==

== Step 4 (53) ==
Updating data in table: vw_page... ((85))

== Upgrading to 4.1.6 ==

== Step 4 (85) ==... ((99))

== Upgrading to 4.1.6 ==

== Step 4 (99) ==
Updating data in table: vw_page... ((164))

== Upgrading to 4.1.6 ==

== Step 4 (164) ==... ((184))

== Upgrading to 4.1.6 ==

== Step 4 (184) ==
Updating data in table: vw_page... ((207))

== Upgrading to 4.1.6 ==

== Step 4 (207) ==... ((222))

== Upgrading to 4.1.6 ==

== Step 4 (222) ==
Updating data in table: vw_page... ((235))

== Upgrading to 4.1.6 ==

== Step 4 (235) ==... ((255))

== Upgrading to 4.1.6 ==

== Step 4 (255) ==
Updating data in table: vw_page... ((268))

== Upgrading to 4.1.6 ==

== Step 4 (268) ==... ((287))

== Upgrading to 4.1.6 ==

== Step 4 (287) ==
Updating data in table: vw_page... ((300))

== Upgrading to 4.1.6 ==

== Step 4 (300) ==... ((314))

== Upgrading to 4.1.6 ==

== Step 4 (314) ==
Updating data in table: vw_page... ((334))

== Upgrading to 4.1.6 ==

== Step 4 (334) ==... ((347))

== Upgrading to 4.1.6 ==

== Step 4 (347) ==
Updating data in table: vw_page... ((362))

== Upgrading to 4.1.6 ==

== Step 4 (362) ==... ((378))

== Upgrading to 4.1.6 ==

== Step 4 (378) ==
Updating data in table: vw_page... ((394))

== Upgrading to 4.1.6 ==

== Step 4 (394) ==... ((407))

== Upgrading to 4.1.6 ==

== Step 4 (407) ==
Updating data in table: vw_page... ((431))

== Upgrading to 4.1.6 ==

== Step 4 (431) ==... ((447))

== Upgrading to 4.1.6 ==

== Step 4 (447) ==
Updating data in table: vw_page... ((463))

== Upgrading to 4.1.6 ==

== Step 4 (463) ==... ((479))

== Upgrading to 4.1.6 ==

== Step 4 (479) ==
Updating data in table: vw_page... ((497))

== Upgrading to 4.1.6 ==

== Step 4 (497) ==... ((512))

== Upgrading to 4.1.6 ==

== Step 4 (512) ==
Updating data in table: vw_page... ((527))

== Upgrading to 4.1.6 ==

== Step 4 (527) ==... ((542))

== Upgrading to 4.1.6 ==

== Step 4 (542) ==
Updating data in table: vw_page... ((556))

== Upgrading to 4.1.6 ==

== Step 4 (556) ==... ((573))

== Upgrading to 4.1.6 ==

== Step 4 (573) ==
Updating data in table: vw_page... ((590))

== Upgrading to 4.1.6 ==

== Step 4 (590) ==... ((607))

== Upgrading to 4.1.6 ==

== Step 4 (607) ==
Updating data in table: vw_page... ((624))

== Upgrading to 4.1.6 ==

== Step 4 (624) ==... ((640))

== Upgrading to 4.1.6 ==

== Step 4 (640) ==
Updating data in table: vw_page... ((654))

== Upgrading to 4.1.6 ==

== Step 4 (654) ==... ((670))

== Upgrading to 4.1.6 ==

== Step 4 (670) ==
Updating data in table: vw_page... ((685))

== Upgrading to 4.1.6 ==

== Step 4 (685) ==... ((700))

== Upgrading to 4.1.6 ==

== Step 4 (700) ==
Updating data in table: vw_page... ((715))

== Upgrading to 4.1.6 ==

== Step 4 (715) ==... ((731))

== Upgrading to 4.1.6 ==

== Step 4 (731) ==
Updating data in table: vw_page... ((754))

== Upgrading to 4.1.6 ==

== Step 4 (754) ==... ((772))

== Upgrading to 4.1.6 ==

== Step 4 (772) ==
Updating data in table: vw_page... ((786))

== Upgrading to 4.1.6 ==

== Step 4 (786) ==... ((804))

== Upgrading to 4.1.6 ==

== Step 4 (804) ==
Updating data in table: vw_page... ((824))

== Upgrading to 4.1.6 ==

== Step 4 (824) ==... ((838))

== Upgrading to 4.1.6 ==

== Step 4 (838) ==
Updating data in table: vw_page... ((861))

== Upgrading to 4.1.6 ==

== Step 4 (861) ==... ((889))

== Upgrading to 4.1.6 ==

== Step 4 (889) ==
Updating data in table: vw_page... ((903))

== Upgrading to 4.1.6 ==

== Step 4 (903) ==... ((919))

== Upgrading to 4.1.6 ==

== Step 4 (919) ==
Updating data in table: vw_page... ((934))

== Upgrading to 4.1.6 ==

== Step 4 (934) ==... ((950))

== Upgrading to 4.1.6 ==

== Step 4 (950) ==
Updating data in table: vw_page... ((968))

== Upgrading to 4.1.6 ==

== Step 4 (968) ==... ((986))

== Upgrading to 4.1.6 ==

== Step 4 (986) ==
Updating data in table: vw_page... ((1004))

== Upgrading to 4.1.6 ==

== Step 4 (1004) ==... ((1020))

== Upgrading to 4.1.6 ==

== Step 4 (1020) ==
Updating data in table: vw_page... ((1035))

== Upgrading to 4.1.6 ==

== Step 4 (1035) ==... ((1050))

== Upgrading to 4.1.6 ==

== Step 4 (1050) ==
Updating data in table: vw_page... ((1068))

== Upgrading to 4.1.6 ==

== Step 4 (1068) ==... ((1085))

== Upgrading to 4.1.6 ==

== Step 4 (1085) ==
Updating data in table: vw_page... ((1102))

== Upgrading to 4.1.6 ==

== Step 4 (1102) ==... ((1120))

== Upgrading to 4.1.6 ==

== Step 4 (1120) ==
Updating data in table: vw_page... ((1139))

== Upgrading to 4.1.6 ==

== Step 4 (1139) ==... ((1163))

== Upgrading to 4.1.6 ==

== Step 4 (1163) ==
Updating data in table: vw_page

Any chance we can run these sql changes manually on the database?

Honestly if that is the whole log, I don't see anything wrong. It looks like it just takes a long time to process some of your pages for the new links. The batch is set to 200, but your server can only handle about 20-25 at once. So the pages are probably long or have complex BB-Code. If it's already at that stage, it's done most of the hard work already (about 1100 pages have been processed too). I would be concerned if it has been going for a few minutes and there is no change to the (number) on each step line.

The thing I would worry about taking a while is the collation change, which happens at the end. But I would need your MySQL version to determine the appropriate manual SQL.

I think I have 4000 pages.

What order of magnitude of time should I be expecting for the end to end process under these conditions?

Can I do anything to make this upgrade time sensible?

What would I be looking at if I was sized like some of my competitors and had 100,000 pages of this type?

Is that final step an ~N scaling or ~N^2 etc

I would say that about 1000 pages per minute is a good target. This doesn't apply to every upgrade, just ones that happen to process every page for changes. This target may be more or less feasible depending on the complexity of the pages, though. Worst case scenario you should be doing 60 pages per minute, which would mean those pages are loading really slowly on the front-end, and you should consider upgrading your CPU or reducing the page complexity. It's also possible that if your internal-data is stored remotely, that the logging is slowing things down more than it should (maybe 1-2 seconds per batch).

Since it involves changing some indexes, changing the collations could be ~N.log(N), by table size, not page count. People talk about millions of rows taking a few minutes under this condition. I don't think you will have a problem. Your biggest affected table probably has about half a million rows.

Internal data is on S3. I'll try and do the upgrade tomorrow morning out of hours. If it reaches an hour I might have to kill it again.

I'd run through approximately 100 pages a minute.

The server is resourced to have enough for my needs and an overhead. I can't scale it just for vaultwiki upgrades.

Could it be something in the PHP config that's limiting VW upgrade scripts?

Here are the resource specs during that time:

Hm... CPU really shouldn't be spiking like that. It's basically just saving 1 page at a time without changes, which is something you do normally without having spikes. This could be blocking due to low memory, or another issue like slow queries. Are there reports of MySQL slow queries? I wonder about that 20% increase in memory, which seems unusual. Almost like there's no garbage collection happening. But still, based on your processing rate in the logs, loading 1 page uses ~1% total memory? So basically you have room for 100 concurrent users, if 100% was allocated to PHP... Is this server memory, or PHP memory?

The php pool config is relatively static so the memory jump is strange. That's total of 2GB VM memory and is fairly loaded at all times because of that.

I've tweaked the config I'll try the install tomorrow and monitor the php pool usage closely.

Each PHP process in the pool tends to use ~100mb and there are a max of 16 of them.

Here is it with a static php config day to day:



Just sitting around idly waiting for users. Each request is typically handled in a fraction of a second, so there is no issue with user concurrency and memory. It 100 requests came at the same instant, some would be waiting in nginx, but not for long.

I've turned on slow sql query logging.

Y'all got any more of them joins?


# Time: 2022-11-25T08:49:06.270019Z
# User@Host: username[username] @ localhost [] Id: 29085
# Query_time: 0.002306 Lock_time: 0.000198 Rows_sent: 20 Rows_examined: 360
SET timestamp=1669366146;
SELECT `liked`.*,`di`.*,`l`.*,`ch`.*,`c`.*,`i`.*,`r`.*,`page`.*, `area`.*,`liked`.`reaction_content_id` AS `like_id`,`iplog2`.`ip` AS `ipaddress`,`iplog`.`ip` AS `creatorip`,`likes`.`reactions`,`likes`.`reaction_users`, `rv`.`vote` AS `myrating`,`rv`.`reason` AS `myratingreason`,`nk`.`readtime` AS `cascadetime`,`sub`.`subscribeid` AS `issubscribed`,`sub`.`notifytype` AS `subscribetype`,`sub`.`options` AS `subscribeoptions`,`mk`.`readtime`,`di`.`userid` AS `disambig_userid`,`l`.`userid` AS `translate_userid`,`ch`.`userid` AS `chapter_userid`,`t`.`discussionid` AS `discussionid`,`t`.`comments` AS `commentcount`,`r`.`dateline` AS `edit_dateline`,`r`.`flags` + 0 AS `flags`,`r`.`parentid` AS `edit_parentid`,`area`.`parentid` AS `parentid`,`area`.`areaid` AS `primaryid`,`area`.`pageid` FROM `xf_vw_area` `area` LEFT JOIN `xf_vw_page` `page` ON (`page`.`pageid` = `area`.`pageid`)
LEFT JOIN `xf_vw_route` `i` ON (`page`.`pageid` = `i`.`itemid` AND `i`.`itemtypeid` = 1)
LEFT JOIN `xf_vw_counter` `c` ON (`c`.`routeid` = `i`.`routeid`)
LEFT JOIN `xf_vw_revision` `r` ON (`r`.`revisionid` = `page`.`revisionid`)
LEFT JOIN `xf_vw_chapter` `ch` ON (`page`.`pageid` = `ch`.`pageid`)
LEFT JOIN `xf_vw_langitem` `l` ON (`page`.`pageid` = `l`.`pageid`)
LEFT JOIN `xf_vw_disambigitem` `di` ON (`page`.`pageid` = `di`.`contentid` AND `di`.`contenttypeid` = 1)
LEFT JOIN `xf_vw_discussion` `t` ON (`t`.`contentid` = `page`.`pageid` AND `t`.`displayorder` = 0 AND `t`.`contenttypeid` = 1)
LEFT JOIN `xf_vw_markread` `mk` ON (`mk`.`itemtypeid` = 1 AND `mk`.`itemid` = `page`.`pageid` AND `mk`.`userid` = 8)
LEFT JOIN `xf_vw_subscribe` `sub` ON (`sub`.`nodetypeid` = 1 AND `sub`.`nodeid` = `page`.`pageid` AND `sub`.`userid` = 8)
LEFT JOIN `xf_vw_noderead` `nk` ON (`nk`.`nodeid` = `page`.`pageid` AND `nk`.`nodetypeid` = 1 AND `nk`.`userid` = 8)
LEFT JOIN `xf_vw_rate` `rv` ON (`rv`.`contenttypeid` = 7 AND `rv`.`contentid` = `page`.`revisionid` AND `rv`.`userid` = 8)
LEFT JOIN `xf_vw_reactions` `likes` ON (`likes`.`itemtypeid` = 1 AND `likes`.`itemid` = `page`.`pageid`)
LEFT JOIN `xf_ip` `iplog` ON (`iplog`.`ip_id` = `page`.`creator_ip_id`)
LEFT JOIN `xf_ip` `iplog2` ON (`iplog2`.`ip_id` = `r`.`ip_id`)
LEFT JOIN `xf_reaction_content` `liked` ON (`liked`.`content_type` = 'vwpage' AND `liked`.`content_id` = `page`.`pageid` AND `liked`.`reaction_user_id` = 8) WHERE 0 < `page`.`areaid` ORDER BY `area`.`displayorder` ASC;

Pretty CPU intensive upgrade

All done in 46 minutes. The longest upgrade for xenforo core or any addon by a good 35 minutes!

This is a very, very standard virtual machine Xenforo config, with the possible exception of using S3 for flat file storage. This might need a warning for people with many more tables than this!

I'm marking this as fixed in the next release. I spent a few days adding various optimizations and micro-optimizations, such as adding some shorter code paths, and reducing file system access (your I/O graph). Basically when doing repetitive actions, we can speed things up by remembering the result of a similar action instead of doing it again. All told with my test data set (which likely is nothing like yours) I've reduced processing time on batch/repetitive saves like this by about 40%, at the expense of 10% greater memory usage. So if your data set was exactly like mine, your 46 minute upgrade could have taken 30 minutes instead.

While the benefits are also usable in normal wiki browsing, the speed benefit is probably much smaller (single digit % at best), because in general you are only able to view or edit 1 wiki page at a time.

It may be possible to reduce memory usage a little. I feel like certain objects are still held in memory after they should have been destroyed. So maybe I can get memory usage back down to where it was before, while also having these optimizations in place. But I'm also reading in various places that PHP is lazy about freeing memory until memory actually starts getting low, so maybe that's all we were seeing.

I'm considering another template-related optimization, but I'm not sure yet whether the benefit will be significant enough to justify the effort.

In theory, if you use 2 or more template calls that have exactly the same parameters within the same surrounding context, they would typically have the same output. So we wouldn't need to process the extra calls. But I can't really imagine how common it would be to do that, aside from a malicious user trying to eat up CPU cycles.

Since you tend to use templates rather frequently, I'm curious how often you find yourself doing this -- that is, using the same template more than once with the same inputs, in the same page. And if so, what do you use this pattern to accomplish?