Multiverse/Multiverse-Portals — Issue #129: Loading large numbers of portals is very slow
Author: gmcnew
Created: 2012-03-03 06:09:24+00:00
State: open

In order to investigate [issue 110](https://github.com/Multiverse/Multiverse-Portals/issues/110), I wrote a [simple script](https://gist.github.com/1964594) to generate 1000 portals, intending to start the world up and see how the plugin performed with large numbers of portals. I started my server, but it didn't come online.

I discovered it was stuck in ```MultiversePortals::loadPortals()```. Some debug output showed me it was taking 0.8 seconds per portal:

```
23:36:37 [INFO] [Multiverse-Portals] 10 portals loaded; about 802.4ms each
23:36:45 [INFO] [Multiverse-Portals] 20 portals loaded; about 796.8ms each
23:36:53 [INFO] [Multiverse-Portals] 30 portals loaded; about 771.1ms each
23:37:01 [INFO] [Multiverse-Portals] 40 portals loaded; about 795.2ms each
23:37:09 [INFO] [Multiverse-Portals] 50 portals loaded; about 812.1ms each
...
```
I killed it, but at this rate it would have taken about 13 minutes to load all 1000 portals.

The reason for the extreme slowness is that ```MVPortal```'s constructor, and its static ```loadMVPortalFromConfig()``` method, call several set*() operations, which, in turn, call ```this.plugin.savePortalsConfig()```. This means that for each portal being loaded from a file, we're writing the portals.yml file back several times -- at least 8, by my count -- for absolutely no reason. =)

My portals.yml (with 1000 portals) was 177 KB, or about 181 bytes per portal. Math time!

> 181 bytes * 1000 portals * 8 writes per portal * 1000 portals = 1.4 GB

That's a lot of unnecessary file IO. =) (It doesn't help that it's O(n^2) in the number of portals.) With [my fix](https://github.com/gmcnew/Multiverse-Portals/commit/e75920d11ef5293d497390c44b48e63551cac38c) (which I'll submit a pull request for as soon as my [other pull request](https://github.com/Multiverse/Multiverse-Portals/pull/126) is taken care of), here's what my timing code prints out.

```
00:04:06 [INFO] [Multiverse-Portals] 10 portals loaded; about 0.7ms each
00:04:06 [INFO] [Multiverse-Portals] 20 portals loaded; about 0.7ms each
00:04:06 [INFO] [Multiverse-Portals] 30 portals loaded; about 0.5ms each
...
23:55:39 [INFO] [Multiverse-Portals] 990 portals loaded; about 2.6ms each
23:55:39 [INFO] [Multiverse-Portals] 1000 portals loaded; about 2.8ms each
23:55:39 [INFO] [Multiverse-Portals] 1000 - Portals(s) loaded in 1649 ms
```