search

LiteLDev / LegacyScriptEngine

A plugin engine for running LLSE plugins on LeviLamina
GNU General Public License v3.0
48 stars 8 forks source link

LLSE(JS) 在一游戏刻内获取大量方块时内存异常增大，并影响到处理速度 #14

Open ENIACJushi opened 2 years ago

ENIACJushi commented 2 years ago

异常模块

ScriptEngine（脚本引擎）

操作系统

Windows 11

LiteLoader版本

2.5.1

BDS版本

1.19.20

发生了什么?

我写了一个保存范围内全部方块的插件，在1.18.x时它能在两秒内遍历一个区块的方块，而在BDS 1.19.20 LL2.5.0/2.5.1，遍历一个区块需要几分钟，获取方块的速度随着获取数量的增多而减慢，内存占用也异常增大。 在这里下载经过处理的那个插件（删除了无关操作），遍历方块在1051~1065行： https://wwz.lanzouw.com/ieODm09kgomh

    var y = start_y;
    var blockI = -1;
    for(var iy = 0; iy < y_offset; iy++){
        var x = start_x;
        logger.info(`y=${y}`)
        for(var ix = 0; ix < x_offset; ix++){
            var z = start_z;
            for(var iz = 0; iz < z_offset; iz++){
                var bl = mc.getBlock(x, y, z, dim_id);
                delete bl;
                z++;
            }
            x++;
        }
        y++;
    }
    return structure;

复现此问题的步骤

  1. 装载上一段提供的插件，然后打开任意世界；
  2. 在控制台输入/wheatbuilder area save 0 0 3 3 0 test 0 这个指令将会自动设置一个常加载区域，然后获取区块坐标在0,0~3,3之间的区块
  3. 在处理一个区块的一层方块（16×16=256）前，控制台会输出该层的高度（代码1055行），可以观察到一开始的速度达到数十层/秒，而后快速变慢，在较短的时间便慢到了3层/秒。
  4. 检查内存占用也会发现异常，在我测试时，指令执行前是260MB，短短40秒（遍历一个区块的时间）便增大到330MB。

有关的日志/输出

Click to expand ```shell （可以通过日志时间看出速度的变化） /wheatbuilder area save 0 0 3 3 0 test 0 00:21:30 INFO [WB] [[0,0,4,3,0]] 00:21:30 INFO [Server] Chunk save task created. 00:21:31 INFO [WB] /tickingarea add 0 -64 0 72 320 63 movechunk0 00:21:31 INFO [Server] Added ticking area from 0, 0, 0 to 79, 0, 63. 00:21:31 INFO [Server] 1/10 ticking areas in use. 00:21:31 INFO [WB] save chunks from 0, 0 to 4, 3... 00:21:33 INFO [WB] get chunk 0, 0 00:21:33 INFO [WB] get structure: 0, 0, -64, 0, 15, 319, 15, mode 0. 00:21:33 INFO [WB] y=-64 00:21:33 INFO [WB] y=-63 00:21:33 INFO [WB] y=-62 00:21:33 INFO [WB] y=-61 00:21:33 INFO [WB] y=-60 00:21:33 INFO [WB] y=-59 00:21:33 INFO [WB] y=-58 00:21:33 INFO [WB] y=-57 00:21:33 INFO [WB] y=-56 00:21:33 INFO [WB] y=-55 00:21:33 INFO [WB] y=-54 00:21:33 INFO [WB] y=-53 00:21:33 INFO [WB] y=-52 00:21:33 INFO [WB] y=-51 00:21:33 INFO [WB] y=-50 00:21:33 INFO [WB] y=-49 00:21:33 INFO [WB] y=-48 00:21:33 INFO [WB] y=-47 00:21:33 INFO [WB] y=-46 00:21:33 INFO [WB] y=-45 00:21:33 INFO [WB] y=-44 00:21:33 INFO [WB] y=-43 00:21:33 INFO [WB] y=-42 00:21:33 INFO [WB] y=-41 00:21:33 INFO [WB] y=-40 00:21:33 INFO [WB] y=-39 00:21:33 INFO [WB] y=-38 00:21:33 INFO [WB] y=-37 00:21:33 INFO [WB] y=-36 00:21:33 INFO [WB] y=-35 00:21:33 INFO [WB] y=-34 00:21:33 INFO [WB] y=-33 00:21:33 INFO [WB] y=-32 00:21:33 INFO [WB] y=-31 00:21:33 INFO [WB] y=-30 00:21:33 INFO [WB] y=-29 00:21:33 INFO [WB] y=-28 00:21:33 INFO [WB] y=-27 00:21:33 INFO [WB] y=-26 00:21:33 INFO [WB] y=-25 00:21:33 INFO [WB] y=-24 00:21:33 INFO [WB] y=-23 00:21:33 INFO [WB] y=-22 00:21:33 INFO [WB] y=-21 00:21:33 INFO [WB] y=-20 00:21:33 INFO [WB] y=-19 00:21:33 INFO [WB] y=-18 00:21:33 INFO [WB] y=-17 00:21:33 INFO [WB] y=-16 00:21:33 INFO [WB] y=-15 00:21:33 INFO [WB] y=-14 00:21:33 INFO [WB] y=-13 00:21:33 INFO [WB] y=-12 00:21:33 INFO [WB] y=-11 00:21:33 INFO [WB] y=-10 00:21:33 INFO [WB] y=-9 00:21:33 INFO [WB] y=-8 00:21:33 INFO [WB] y=-7 00:21:33 INFO [WB] y=-6 00:21:33 INFO [WB] y=-5 00:21:34 INFO [WB] y=-4 00:21:34 INFO [WB] y=-3 00:21:34 INFO [WB] y=-2 00:21:34 INFO [WB] y=-1 00:21:34 INFO [WB] y=0 00:21:34 INFO [WB] y=1 00:21:34 INFO [WB] y=2 00:21:34 INFO [WB] y=3 00:21:34 INFO [WB] y=4 00:21:34 INFO [WB] y=5 00:21:34 INFO [WB] y=6 00:21:34 INFO [WB] y=7 00:21:34 INFO [WB] y=8 00:21:34 INFO [WB] y=9 00:21:34 INFO [WB] y=10 00:21:34 INFO [WB] y=11 00:21:34 INFO [WB] y=12 00:21:34 INFO [WB] y=13 00:21:34 INFO [WB] y=14 00:21:34 INFO [WB] y=15 00:21:34 INFO [WB] y=16 00:21:34 INFO [WB] y=17 00:21:34 INFO [WB] y=18 00:21:34 INFO [WB] y=19 00:21:34 INFO [WB] y=20 00:21:34 INFO [WB] y=21 00:21:34 INFO [WB] y=22 00:21:34 INFO [WB] y=23 00:21:34 INFO [WB] y=24 00:21:34 INFO [WB] y=25 00:21:34 INFO [WB] y=26 00:21:34 INFO [WB] y=27 00:21:34 INFO [WB] y=28 00:21:34 INFO [WB] y=29 00:21:34 INFO [WB] y=30 00:21:34 INFO [WB] y=31 00:21:34 INFO [WB] y=32 00:21:34 INFO [WB] y=33 00:21:34 INFO [WB] y=34 00:21:34 INFO [WB] y=35 00:21:34 INFO [WB] y=36 00:21:34 INFO [WB] y=37 00:21:34 INFO [WB] y=38 00:21:34 INFO [WB] y=39 00:21:34 INFO [WB] y=40 00:21:34 INFO [WB] y=41 00:21:34 INFO [WB] y=42 00:21:34 INFO [WB] y=43 00:21:34 INFO [WB] y=44 00:21:34 INFO [WB] y=45 00:21:34 INFO [WB] y=46 00:21:34 INFO [WB] y=47 00:21:34 INFO [WB] y=48 00:21:34 INFO [WB] y=49 00:21:34 INFO [WB] y=50 00:21:34 INFO [WB] y=51 00:21:34 INFO [WB] y=52 00:21:35 INFO [WB] y=53 00:21:35 INFO [WB] y=54 00:21:35 INFO [WB] y=55 00:21:35 INFO [WB] y=56 00:21:35 INFO [WB] y=57 00:21:35 INFO [WB] y=58 00:21:35 INFO [WB] y=59 00:21:35 INFO [WB] y=60 00:21:35 INFO [WB] y=61 00:21:35 INFO [WB] y=62 00:21:35 INFO [WB] y=63 00:21:35 INFO [WB] y=64 00:21:35 INFO [WB] y=65 00:21:35 INFO [WB] y=66 00:21:35 INFO [WB] y=67 00:21:35 INFO [WB] y=68 00:21:35 INFO [WB] y=69 00:21:35 INFO [WB] y=70 00:21:35 INFO [WB] y=71 00:21:35 INFO [WB] y=72 00:21:35 INFO [WB] y=73 00:21:35 INFO [WB] y=74 00:21:35 INFO [WB] y=75 00:21:35 INFO [WB] y=76 00:21:35 INFO [WB] y=77 00:21:35 INFO [WB] y=78 00:21:35 INFO [WB] y=79 00:21:35 INFO [WB] y=80 00:21:35 INFO [WB] y=81 00:21:35 INFO [WB] y=82 00:21:35 INFO [WB] y=83 00:21:35 INFO [WB] y=84 00:21:35 INFO [WB] y=85 00:21:35 INFO [WB] y=86 00:21:35 INFO [WB] y=87 00:21:35 INFO [WB] y=88 00:21:36 INFO [WB] y=89 00:21:36 INFO [WB] y=90 00:21:36 INFO [WB] y=91 00:21:36 INFO [WB] y=92 00:21:36 INFO [WB] y=93 00:21:36 INFO [WB] y=94 00:21:36 INFO [WB] y=95 00:21:36 INFO [WB] y=96 00:21:36 INFO [WB] y=97 00:21:36 INFO [WB] y=98 00:21:36 INFO [WB] y=99 00:21:36 INFO [WB] y=100 00:21:36 INFO [WB] y=101 00:21:36 INFO [WB] y=102 00:21:36 INFO [WB] y=103 00:21:36 INFO [WB] y=104 00:21:36 INFO [WB] y=105 00:21:36 INFO [WB] y=106 00:21:36 INFO [WB] y=107 00:21:36 INFO [WB] y=108 00:21:36 INFO [WB] y=109 00:21:36 INFO [WB] y=110 00:21:36 INFO [WB] y=111 00:21:36 INFO [WB] y=112 00:21:36 INFO [WB] y=113 00:21:37 INFO [WB] y=114 00:21:37 INFO [WB] y=115 00:21:37 INFO [WB] y=116 00:21:37 INFO [WB] y=117 00:21:37 INFO [WB] y=118 00:21:37 INFO [WB] y=119 00:21:37 INFO [WB] y=120 00:21:37 INFO [WB] y=121 00:21:37 INFO [WB] y=122 00:21:37 INFO [WB] y=123 00:21:37 INFO [WB] y=124 00:21:37 INFO [WB] y=125 00:21:37 INFO [WB] y=126 00:21:37 INFO [WB] y=127 00:21:37 INFO [WB] y=128 00:21:37 INFO [WB] y=129 00:21:37 INFO [WB] y=130 00:21:38 INFO [WB] y=131 00:21:38 INFO [WB] y=132 00:21:38 INFO [WB] y=133 00:21:38 INFO [WB] y=134 00:21:38 INFO [WB] y=135 00:21:38 INFO [WB] y=136 00:21:38 INFO [WB] y=137 00:21:38 INFO [WB] y=138 00:21:38 INFO [WB] y=139 00:21:38 INFO [WB] y=140 00:21:38 INFO [WB] y=141 00:21:38 INFO [WB] y=142 00:21:38 INFO [WB] y=143 00:21:38 INFO [WB] y=144 00:21:38 INFO [WB] y=145 00:21:38 INFO [WB] y=146 00:21:38 INFO [WB] y=147 00:21:39 INFO [WB] y=148 00:21:39 INFO [WB] y=149 00:21:39 INFO [WB] y=150 00:21:39 INFO [WB] y=151 00:21:39 INFO [WB] y=152 00:21:39 INFO [WB] y=153 00:21:39 INFO [WB] y=154 00:21:39 INFO [WB] y=155 00:21:39 INFO [WB] y=156 00:21:39 INFO [WB] y=157 00:21:39 INFO [WB] y=158 00:21:39 INFO [WB] y=159 00:21:39 INFO [WB] y=160 00:21:40 INFO [WB] y=161 00:21:40 INFO [WB] y=162 00:21:40 INFO [WB] y=163 00:21:40 INFO [WB] y=164 00:21:40 INFO [WB] y=165 00:21:40 INFO [WB] y=166 00:21:40 INFO [WB] y=167 00:21:40 INFO [WB] y=168 00:21:40 INFO [WB] y=169 00:21:40 INFO [WB] y=170 00:21:40 INFO [WB] y=171 00:21:41 INFO [WB] y=172 00:21:41 INFO [WB] y=173 00:21:41 INFO [WB] y=174 00:21:41 INFO [WB] y=175 00:21:41 INFO [WB] y=176 00:21:41 INFO [WB] y=177 00:21:41 INFO [WB] y=178 00:21:41 INFO [WB] y=179 00:21:41 INFO [WB] y=180 00:21:41 INFO [WB] y=181 00:21:42 INFO [WB] y=182 00:21:42 INFO [WB] y=183 00:21:42 INFO [WB] y=184 00:21:42 INFO [WB] y=185 00:21:42 INFO [WB] y=186 00:21:42 INFO [WB] y=187 00:21:42 INFO [WB] y=188 00:21:42 INFO [WB] y=189 00:21:42 INFO [WB] y=190 00:21:43 INFO [WB] y=191 00:21:43 INFO [WB] y=192 00:21:43 INFO [WB] y=193 00:21:43 INFO [WB] y=194 00:21:43 INFO [WB] y=195 00:21:43 INFO [WB] y=196 00:21:43 INFO [WB] y=197 00:21:43 INFO [WB] y=198 00:21:44 INFO [WB] y=199 00:21:44 INFO [WB] y=200 00:21:44 INFO [WB] y=201 00:21:44 INFO [WB] y=202 00:21:44 INFO [WB] y=203 00:21:44 INFO [WB] y=204 00:21:44 INFO [WB] y=205 00:21:44 INFO [WB] y=206 00:21:45 INFO [WB] y=207 00:21:45 INFO [WB] y=208 00:21:45 INFO [WB] y=209 00:21:45 INFO [WB] y=210 00:21:45 INFO [WB] y=211 00:21:45 INFO [WB] y=212 00:21:46 INFO [WB] y=213 00:21:46 INFO [WB] y=214 00:21:46 INFO [WB] y=215 00:21:46 INFO [WB] y=216 00:21:46 INFO [WB] y=217 00:21:46 INFO [WB] y=218 00:21:46 INFO [WB] y=219 00:21:47 INFO [WB] y=220 00:21:47 INFO [WB] y=221 00:21:47 INFO [WB] y=222 00:21:47 INFO [WB] y=223 00:21:47 INFO [WB] y=224 00:21:47 INFO [WB] y=225 00:21:48 INFO [WB] y=226 00:21:48 INFO [WB] y=227 00:21:48 INFO [WB] y=228 00:21:48 INFO [WB] y=229 00:21:48 INFO [WB] y=230 00:21:48 INFO [WB] y=231 00:21:49 INFO [WB] y=232 00:21:49 INFO [WB] y=233 00:21:49 INFO [WB] y=234 00:21:49 INFO [WB] y=235 00:21:49 INFO [WB] y=236 00:21:49 INFO [WB] y=237 00:21:50 INFO [WB] y=238 00:21:50 INFO [WB] y=239 00:21:50 INFO [WB] y=240 00:21:50 INFO [WB] y=241 00:21:51 INFO [WB] y=242 00:21:51 INFO [WB] y=243 00:21:51 INFO [WB] y=244 00:21:51 INFO [WB] y=245 00:21:51 INFO [WB] y=246 00:21:51 INFO [WB] y=247 00:21:52 INFO [WB] y=248 00:21:52 INFO [WB] y=249 00:21:52 INFO [WB] y=250 00:21:52 INFO [WB] y=251 00:21:52 INFO [WB] y=252 00:21:53 INFO [WB] y=253 00:21:53 INFO [WB] y=254 00:21:53 INFO [WB] y=255 00:21:53 INFO [WB] y=256 00:21:53 INFO [WB] y=257 00:21:54 INFO [WB] y=258 00:21:54 INFO [WB] y=259 00:21:54 INFO [WB] y=260 00:21:54 INFO [WB] y=261 00:21:54 INFO [WB] y=262 00:21:55 INFO [WB] y=263 00:21:55 INFO [WB] y=264 00:21:55 INFO [WB] y=265 00:21:55 INFO [WB] y=266 00:21:55 INFO [WB] y=267 00:21:56 INFO [WB] y=268 00:21:56 INFO [WB] y=269 00:21:56 INFO [WB] y=270 00:21:56 INFO [WB] y=271 00:21:56 INFO [WB] y=272 00:21:57 INFO [WB] y=273 00:21:57 INFO [WB] y=274 00:21:57 INFO [WB] y=275 00:21:57 INFO [WB] y=276 00:21:57 INFO [WB] y=277 00:21:58 INFO [WB] y=278 00:21:58 INFO [WB] y=279 00:21:58 INFO [WB] y=280 00:21:58 INFO [WB] y=281 00:21:58 INFO [WB] y=282 00:21:59 INFO [WB] y=283 00:21:59 INFO [WB] y=284 00:21:59 INFO [WB] y=285 00:21:59 INFO [WB] y=286 00:21:59 INFO [WB] y=287 00:22:00 INFO [WB] y=288 00:22:00 INFO [WB] y=289 00:22:00 INFO [WB] y=290 00:22:00 INFO [WB] y=291 00:22:01 INFO [WB] y=292 00:22:01 INFO [WB] y=293 00:22:01 INFO [WB] y=294 00:22:01 INFO [WB] y=295 00:22:02 INFO [WB] y=296 00:22:02 INFO [WB] y=297 00:22:02 INFO [WB] y=298 00:22:03 INFO [WB] y=299 00:22:03 INFO [WB] y=300 00:22:03 INFO [WB] y=301 00:22:03 INFO [WB] y=302 00:22:04 INFO [WB] y=303 00:22:04 INFO [WB] y=304 00:22:04 INFO [WB] y=305 00:22:05 INFO [WB] y=306 00:22:05 INFO [WB] y=307 00:22:05 INFO [WB] y=308 00:22:05 INFO [WB] y=309 00:22:06 INFO [WB] y=310 00:22:06 INFO [WB] y=311 00:22:06 INFO [WB] y=312 00:22:06 INFO [WB] y=313 00:22:07 INFO [WB] y=314 00:22:07 INFO [WB] y=315 00:22:07 INFO [WB] y=316 00:22:07 INFO [WB] y=317 00:22:08 INFO [WB] y=318 00:22:08 INFO [WB] y=319 ```

插件列表

00:11:05 INFO [Server] 插件列表 [5]
00:11:05 INFO [Server] - LLMoney [v2.5.0] (LLMoney.dll)
00:11:05 INFO [Server]   EconomyCore for LiteLoaderBDS
00:11:05 INFO [Server] - ScriptEngine-Lua [v2.5.1] (LiteLoader.Lua.dll)
00:11:05 INFO [Server]   Lua ScriptEngine for LiteLoaderBDS
00:11:05 INFO [Server] - ScriptEngine-QuickJs [v2.5.1] (LiteLoader.Js.dll)
00:11:05 INFO [Server]   Javascript ScriptEngine for LiteLoaderBDS
00:11:05 INFO [Server] - WheatBuilder_bug.js [v1.0.0] (WheatBuilder_bug.js)
00:11:05 INFO [Server]   WheatBuilder_bug.js
00:11:05 INFO [Server] - ScriptEngine-NodeJs [v2.5.1] (LiteLoader.NodeJs.dll)
00:11:05 INFO [Server]   Node.js ScriptEngine for LiteLoaderBDS
dreamguxiang commented 2 years ago

怪，我用隔壁worldedit 复制几个区块都是ms级别

ENIACJushi commented 2 years ago

怪，我用隔壁worldedit 复制几个区块都是ms级别

C++插件应该是获取levelChunk然后遍历其中的方块，SE插件可能每次获取方块都要获取一次levelChunk，速度就慢了 内存出现异常应该是某处没有释放（猜测） （在邮件里回复后发现在这里没有显示，又发了一遍）

Redbeanw44602 commented 2 years ago

最近应该是把getBlock的底层接口换成了获取失败的检查（以前失败直接抛异常），可能多了一些检查的性能开销。 对于性能敏感的插件，我的建议是最好不要用llse写，c++做出来性能可能提升几十近百倍。

ENIACJushi commented 2 years ago

最近应该是把getBlock的底层接口换成了获取失败的检查（以前失败直接抛异常），可能多了一些检查的性能开销。 对于性能敏感的插件，我的建议是最好不要用llse写，c++做出来性能可能提升几十近百倍。

这样的话算法复杂度仍为O(n)，总处理时间 - 方块数量应该是线性关系，而实际上经过测试，这一关系更接近于O(n^2)表现出来的，也就是说随着处理方块数量的增大，它（总处理时间 - 方块数量）的增长率越来越大，单个方块的处理时间越来越长。所以性能下降应该另有原因。 屏幕截图 2022-08-15 130158 还有一点，这种情况只会在所有处理全部集中于一个游戏刻时发生，如果处理一部分方块再等待几个游戏刻，单个方块的处理速度会返回到起点。

Redbeanw44602 commented 2 years ago

可能是BDS内部接口的问题，有待进一步定位。

dreamguxiang commented 2 years ago

1.19.10后 bds内部处理方块变得非常拉胯导致

yqs112358 commented 2 years ago

此问题能被定位原因嘛？有无人跑下Profile