sehr hohe CPU- und RAM-Auslastung beim neue Weltteile entdecken

Micha · Mar 5th 2018

Wir haben einen recht neugierigen Spieler auf unserem Server. Als er eines schönen Tages so durch die (Spiel-)Welt schlenderte, wurde kurze Zeit später der Server heruntergefahren.
Beim Kontrollieren der Logs stieß ich dann auf diese Fehlermeldung:

Code: restart.log

Wed, 28 Feb 2018 16:42:06 +0100: Stopping server due to heavy CPU (%CPU 891) usage although server has no active players. Please try to fix Plugins or Map or contact support!2018-02-28 15:50:31 Server restart requested (Webinterface)

Die zu diesem Zeitpunkt passende Logdate habe ich dann auch gleich durchgesehn:

Code: 1519833049.log

Rising World - 0.9.2.3 - Dedicated Server
Linux 4.4.26-nitradoV3-MC-1000-nH-dP-d-a  Java 1.8.0_101 (amd64)  Memory: 954 MB
2018/02/28   03:50 PM
____________________________________________________


ARG: serverip=85.131.159.110
ARG: serverport=4255
ARG: maxplayers=10
Start context...
Items initialized!
Plants initialized!
NPCs initialized!
Initialize Static Classes...
Constructions initialized!
Projectile-Definitions initialized!
Weapon-Definitions initialized!
Objects initialized!
Clothing initialized!
Picking initialized!
Food-Definitions initialized!
Crafting-Definitions initialized!
Record-Definitions initialized!
Initializing world (sqlite)
LOAD WORLD Moria
DATABASE TYPE: SQLite
/mnt/Worlds/Moria:::Moria
CREATE WORLD STRUCTURE - DONE!
2018/02/28   03:50 PM   z.a
INFO: DatabaseTaskManager started with ThreadPoolSize 1
WORLDINFO Gamemode: Survival
Gametype set to Survival
WORLDINFO Seed: 6223146022843827
WORLDINFO Caves: false
WORLDINFO Vegetations: true
WORLDINFO OreAmount: 3
WORLDINFO DisabledNPCs: 
WORLDINFO DisabledDungeons: 
WORLDINFO DisabledWaterSources: 
WORLDINFO Worldtype: Normal
WORLDINFOS   seed: 6223146022843827  type: Normal  caves: false  vegetations: true  oreamount: 3  disablednpc: []  disableddungeons: []  disabledwatersources: []
WORLDINFO Time: 31.7.60 17:27:1.5141435
WORLDINFO Creationdate: 1451146250121
WORLDINFO Version: 0.9.2.3_38
TRIGGER UPDATE
Worldconverter: Updating not required
WORLDINFO Spawninventory: 0 0 3 0 0 46 0 0 1 -65 -128 0 0 0 0 0 1 0 48 0 0 1 -65 -128 0 0 0 0 0 5 0 44 0 0 1 -65 -128 0 0 0 0 0 1 3 0 52 0 0 1 -65 -128 0 0 0 0 0
WORLDINFO Spawnclothing: 5 -1 -1 1 0 68 0 -1 -1 -1 0 -1 -1 -1 0 -1 -1 -1 1 0 68 0 -1 -1 -1 0 -1 -1 -1 0 -1 -1 -1 1 0 11 0 -1 -1 -1 0 -1 -1 -1 0 -1 -1 -1
Worldpart generating...
Biomepart generating...
Loaded Biomepart from cache: 0 - 0  (5ms)
Loaded Worldpart (v1) from cache: 0 - 0  (327ms)
WORLDINFO Spawnposition: 948.6988 86.35115 508.78043
WORLDINFO Spawnrotation: 0.0064175134 -0.99330485 0.09248731 0.06892348


Loading custom images...
33 images successfully loaded!


INITIAL WEATHER Default  1998.0
1207 chests loaded from DB!
306 texts loaded from DB!
7 Plants loaded from DB!
42 Furnaces loaded from DB!
Custom logo: LoadingScreen.jpg (51090b)
4281 NPCs loaded from DB!
STARTING RISING WORLD SERVER...
Server bind to IP: 85.131.159.110:4255
2018/02/28   03:50 PM   JIW-Network
INFO: [NetworkServer] Add channel Port:4,255 Type:TCP Index:0
2018/02/28   03:50 PM   JIW-Network
INFO: [NetworkServer] Add channel Port:4,256 Type:UDP Index:1
2018/02/28   03:50 PM   JIW-Network
INFO: [NetworkServer] Add channel Port:4,256 Type:TCP Index:2
2018/02/28   03:50 PM   JIW-Network
INFO: [NetworkServer] Add channel Port:4,257 Type:UDP Index:3
2018/02/28   03:50 PM   JIW-Network
INFO: [NetworkServer] Add channel Port:4,257 Type:TCP Index:4
2018/02/28   03:50 PM   JIW-Network
INFO: [NetworkServer] Add channel Port:4,258 Type:UDP Index:5
2018/02/28   03:50 PM   JIW-Network
INFO: [NetworkServer] Add channel Port:4,258 Type:TCP Index:6
2018/02/28   03:50 PM   I.g
INFO: Default server permissions loaded successfully!
Found 2 files in groups folder
clear items_pickup_chest_denied
clear items_drop_chest_denied
2018/02/28   03:50 PM   I.g
INFO: Group "Bautrupp" permissions loaded successfully!
clear items_pickup_chest_denied
clear items_drop_chest_denied
2018/02/28   03:50 PM   I.g
INFO: Group "admin" permissions loaded successfully!
RISING WORLD SERVER STARTED
Reserve player name: Paknar
Reserve player name: Micha
Reserve player name: Vasgo
Reserve player name: Bedia
Reserve player name: Torsten
Reserve player name: Manuelly
/mnt/scripts
2018/02/28   03:50 PM   JIW-Network
INFO: [NetworkServer] Add channel Port:4,253 Type:TCP Index:0
RCON Server bind to IP: 85.131.159.110:4253
Steam - Load native library: libsteam_api.so  Filesize: 370330 bytes
Steam - Load native library: libsteamworks4j.so  Filesize: 256928 bytes
Steam - Load native library: libsteamworks4j-server.so  Filesize: 76320 bytes
STEAM BIND TO 1434689390 (85.131.159.110), PORT 4255, 4259   Authentication


SteamID: 76561197960265728  (0)
Query IP: 85.131.159.110
Steam Query Server bind to 85.131.159.110:4255  (85.131.159.110)
Steam Servers Connected (-641298644 -> 217.198.143.44)
[TcpSessionHandler] NEW Client Connection from:/87.171.56.194:54251  de.jiw.network.server.session.TcpSessionHandler@2c3f1221  PORT:4255
/87.171.56.194
CLIENT 1 CHANGE STATE: Disconnected -> ConnectingTCP
[TcpSessionHandler] NEW Client Connection from:/87.171.56.194:54316  de.jiw.network.server.session.TcpSessionHandler@38693c1e  PORT:4256
[TcpSessionHandler] NEW Client Connection from:/87.171.56.194:54381  de.jiw.network.server.session.TcpSessionHandler@6d0e9784  PORT:4257
[TcpSessionHandler] NEW Client Connection from:/87.171.56.194:54446  de.jiw.network.server.session.TcpSessionHandler@752d28b0  PORT:4258
CLIENT 1 CHANGE STATE: ConnectingTCP -> ConnectingUDP
CLIENT 1 CHANGE STATE: ConnectingUDP -> Connected
2018/02/28   03:51 PM   G.f
INFO: Client Connected ID: 1 IP: 87.171.56.194
[BeginAuthSession] 91012402 - [20, 0, 0, 0, -1, -5, 112, 30, -71, -65, 111, -4, 50, -67, 108, 5, 1, 0, 16, 1, -56, -75, -106, 90, 24, 0, 0, 0, 1, 0, 0, 0, 2, 0, 0, 0, -62, 56, -85, 87, 0, 0, 0, 0, 18, 63, 109, 0, 2, 0, 0, 0, -78, 0, 0, 0, 50, 0, 0, 0, 4, 0, 0, 0, 50, -67, 108, 5, 1, 0, 16, 1, -16, -15, 4, 0, -62, 56, -85, 87, 100, 2, -88, -64, 0, 0, 0, 0, -13, 38, -108, 90, 115, -42, -81, 90, 1, 0, -19, -57, 0, 0, 0, 0, 0, 0, -106, -30, 28, -87, 111, 103, -79, 124, -110, -14, 98, 8, -46, -4, -34, -46, 88, -23, -91, 45, -6, 127, -111, -20, -98, -96, 111, 125, 7, 124, 80, 39, 83, 96, 94, 78, -48, -125, -107, -33, 81, -26, -125, 110, 75, -23, -88, -84, -98, -95, -114, 56, 39, -33, -10, 118, -16, 20, -97, 2, -89, 89, -72, -42, 50, -2, -25, -33, 84, 126, -84, 103, 112, 124, 18, 104, 52, -69, -55, 72, 29, 44, 99, 45, 115, 53, 23, 37, -100, 124, 20, 83, -63, 114, 5, -21, 24, -31, -110, 109, 12, -88, 109, 28, -79, -6, 63, 30, -13, 57, -2, -6, 86, -12, -123, 13, 38, -92, -107, -14, -123, 43, 117, 58, 19, 5, 127, 59]
PLAYER CONNECT: Manuelly
LOADPLAYER: Manuelly (76561198051278130)
Server Validate Auth Ticket Response: 1100001056cbd32 - 1100001056cbd32  OK
Load WorldPartSQLite 0 -3...
Return WorldPartSQLite 0 -3
Worldpart generating...
Biomepart generating...
Loaded Biomepart from cache: 0 - -2  (2ms)
Loaded Worldpart (v1) from cache: 0 - -3  (116ms)
Load WorldPartSQLite 0 -2...
Return WorldPartSQLite 0 -2
Worldpart generating...
Biomepart generating...
Loaded Biomepart from cache: 0 - -1  (2ms)
Loaded Worldpart (v1) from cache: 0 - -2  (123ms)
Load WorldPartSQLite 1 -3...
Return WorldPartSQLite 1 -3
Worldpart generating...
Loaded Worldpart (v1) from cache: 1 - -3  (121ms)
Load WorldPartSQLite 1 -2...
Return WorldPartSQLite 1 -2
Worldpart generating...
Loaded Worldpart (v1) from cache: 1 - -2  (113ms)
[TcpSessionHandler] NEW Client Connection from:/87.165.188.197:1750  de.jiw.network.server.session.TcpSessionHandler@4245fe2f  PORT:4255
/87.165.188.197
CLIENT 2 CHANGE STATE: Disconnected -> ConnectingTCP
[TcpSessionHandler] NEW Client Connection from:/87.165.188.197:1783  de.jiw.network.server.session.TcpSessionHandler@6538f33a  PORT:4256
[TcpSessionHandler] NEW Client Connection from:/87.165.188.197:1816  de.jiw.network.server.session.TcpSessionHandler@67f6fcf4  PORT:4257
[TcpSessionHandler] NEW Client Connection from:/87.165.188.197:1849  de.jiw.network.server.session.TcpSessionHandler@6051d20c  PORT:4258
CLIENT 2 CHANGE STATE: ConnectingTCP -> ConnectingUDP
CLIENT 2 CHANGE STATE: ConnectingUDP -> Connected
2018/02/28   03:51 PM   G.f
INFO: Client Connected ID: 2 IP: 87.165.188.197
[BeginAuthSession] 78653861 - [20, 0, 0, 0, -89, -118, 4, 104, 81, -16, -37, 16, -91, 41, -80, 4, 1, 0, 16, 1, 74, -58, -106, 90, 24, 0, 0, 0, 1, 0, 0, 0, 2, 0, 0, 0, -59, -68, -91, 87, 39, -78, -88, -64, -88, 9, 45, 0, 3, 0, 0, 0, -78, 0, 0, 0, 50, 0, 0, 0, 4, 0, 0, 0, -91, 41, -80, 4, 1, 0, 16, 1, -16, -15, 4, 0, 56, -65, -91, 87, 39, -78, -88, -64, 0, 0, 0, 0, 35, 107, -119, 90, -93, 26, -91, 90, 1, 0, -19, -57, 0, 0, 0, 0, 0, 0, -119, -114, 82, 10, -9, 14, -101, 62, -91, -35, 125, 6, -106, 115, -17, -22, 56, -33, -83, -22, 71, -62, 41, 84, 42, 22, -72, 20, 9, -53, -1, 109, 123, 84, -82, -69, -13, -45, -82, 12, -70, -34, -62, 75, 64, 78, -101, -36, 52, 37, -74, -78, -99, -118, -69, 51, 40, -118, -113, 40, 24, 85, 85, 92, 24, 53, -119, -61, 14, 81, -112, 42, 68, -14, 125, -97, 67, 116, -121, 30, 57, 96, -71, 105, 51, -94, -21, 18, 82, 13, -113, 82, 89, -5, 41, -43, 52, 90, -23, 96, 120, 44, -85, -47, -113, -123, -48, 119, 44, -96, -128, -50, 27, -82, -91, -78, 119, 99, 67, 74, -125, -5, -124, -14, -24, -34, -96, 71]
PLAYER CONNECT: Torsten
LOADPLAYER: Torsten (76561198038919589)
Load WorldPartSQLite 0 0...
Return WorldPartSQLite 0 0
Server Validate Auth Ticket Response: 110000104b029a5 - 110000104b029a5  OK
Load WorldPartSQLite 0 -1...
Return WorldPartSQLite 0 -1
Worldpart generating...
Loaded Worldpart (v1) from cache: 0 - -1  (122ms)
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:29318  de.jiw.network.server.session.TcpSessionHandler@7553d885  PORT:4256
[TcpSessionHandler ExceptionCaught] /78.143.39.35:29318
2018/02/28   03:52 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:29318
clear temporary voxel maps
Worldpart generating...
DungeonPoints: 100
Worldpart generated: 0 - -4  (2611ms)
Load WorldPartSQLite 0 -4...
Return WorldPartSQLite 0 -4
Worldpart generating...
Loaded Worldpart (v1) from cache: 1 - -4  (139ms)
Load WorldPartSQLite 1 -4...
Return WorldPartSQLite 1 -4
WORLDPART 0 -4 STORED TO CACHE
clear temporary voxel maps
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:14553  de.jiw.network.server.session.TcpSessionHandler@38b014d8  PORT:4256
[TcpSessionHandler ExceptionCaught] /78.143.39.35:14553
2018/02/28   03:54 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:14553
clear temporary voxel maps
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:54739  de.jiw.network.server.session.TcpSessionHandler@69e06188  PORT:4256
... (1) ChunkAdditions saved to DB!
[TcpSessionHandler ExceptionCaught] /78.143.39.35:54739
2018/02/28   03:57 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:54739
clear temporary voxel maps
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:40143  de.jiw.network.server.session.TcpSessionHandler@6bcf71b8  PORT:4256
Worldpart generating...
Biomepart generating...
biomepart offset 0 -3 -> 0 19  (-800496576, -200124144)
Biomepart (2) generated: 0 - -3  (1ms)
BIOMEPART 0 -3 STORED TO CACHE
DungeonPoints: 100
Worldpart generated: 0 - -5  (2360ms)
Create WorldPartSQLite 0 -5...
Worldpart generating...
DungeonPoints: 100
WORLDPART 0 -5 STORED TO CACHE
Worldpart generated: 1 - -5  (2691ms)
Create WorldPartSQLite 1 -5...
Load WorldPartSQLite 1 -5...
Return WorldPartSQLite 1 -5
clear temporary voxel maps
WORLDPART 1 -5 STORED TO CACHE
[TcpSessionHandler ExceptionCaught] /78.143.39.35:40143
2018/02/28   03:59 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:40143
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
2018/02/28   04:00 PM   G.f
SEVERE: ChestRequest: Chest (ID: -1,000,001) not found!
dungeon chest loot bandage (slot: 2)
dungeon chest loot clothes (slot: 6)
dungeon chest loot crossbow (slot: 13)
dungeon chest loot scythe (slot: 20)
dungeon chest loot record (slot: 25)
Assigned new chest id to dungeon chest: 1607
... (1) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
clear temporary voxel maps
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:38866  de.jiw.network.server.session.TcpSessionHandler@4b879358  PORT:4256
              server: replace clothing 1020
[TcpSessionHandler ExceptionCaught] /78.143.39.35:38866
2018/02/28   04:02 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:38866
... (1) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
Worldpart generating...
DungeonPoints: 100
Worldpart generated: 0 - -6  (1584ms)
Create WorldPartSQLite 0 -6...
Worldpart generating...
DungeonPoints: 100
WORLDPART 0 -6 STORED TO CACHE
Worldpart generated: 1 - -6  (1770ms)
Create WorldPartSQLite 1 -6...
Load WorldPartSQLite 1 -6...
Return WorldPartSQLite 1 -6
WORLDPART 1 -6 STORED TO CACHE
... (1) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
Worldpart generating...
Biomepart generating...
biomepart offset 0 -4 -> 0 20  (-800496576, -200124144)
Biomepart (0) generated: 0 - -4  (254ms)
BIOMEPART 0 -4 STORED TO CACHE
DungeonPoints: 100
Worldpart generated: 0 - -7  (1814ms)
Create WorldPartSQLite 0 -7...
Worldpart generating...
DungeonPoints: 100
WORLDPART 0 -7 STORED TO CACHE
Worldpart generated: 1 - -7  (2136ms)
Create WorldPartSQLite 1 -7...
Load WorldPartSQLite 1 -7...
Return WorldPartSQLite 1 -7
WORLDPART 1 -7 STORED TO CACHE
clear temporary voxel maps
... (1) ChunkAdditions saved to DB!
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:16078  de.jiw.network.server.session.TcpSessionHandler@434f9bc2  PORT:4256
[TcpSessionHandler ExceptionCaught] /78.143.39.35:16078
2018/02/28   04:04 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:16078
... (1) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
... (1) ChunkAdditions saved to DB!
Worldpart generating...
DungeonPoints: 100
Worldpart generated: 0 - -8  (1599ms)
Create WorldPartSQLite 0 -8...
Worldpart generating...
DungeonPoints: 100
WORLDPART 0 -8 STORED TO CACHE
Worldpart generated: 1 - -8  (2389ms)
Create WorldPartSQLite 1 -8...
Load WorldPartSQLite 1 -8...
Return WorldPartSQLite 1 -8
WORLDPART 1 -8 STORED TO CACHE
              server: replace clothing 1014
clear temporary voxel maps
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:23758  de.jiw.network.server.session.TcpSessionHandler@3fbd83c  PORT:4256
... (1) ChunkAdditions saved to DB!
Worldpart generating...
Biomepart generating...
biomepart offset 0 -5 -> 0 21  (-800496576, -200124144)
Biomepart (0) generated: 0 - -5  (237ms)
BIOMEPART 0 -5 STORED TO CACHE
DungeonPoints: 100
Worldpart generated: 0 - -9  (1860ms)
Create WorldPartSQLite 0 -9...
Worldpart generating...
DungeonPoints: 100
WORLDPART 0 -9 STORED TO CACHE
Worldpart generated: 1 - -9  (2114ms)
Create WorldPartSQLite 1 -9...
Load WorldPartSQLite 1 -9...
Return WorldPartSQLite 1 -9
WORLDPART 1 -9 STORED TO CACHE
[TcpSessionHandler ExceptionCaught] /78.143.39.35:23758
2018/02/28   04:07 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:23758
clear temporary voxel maps
clear temporary voxel maps
Worldpart generating...
DungeonPoints: 100
Worldpart generated: 0 - -10  (1616ms)
Create WorldPartSQLite 0 -10...
Worldpart generating...
DungeonPoints: 100
WORLDPART 0 -10 STORED TO CACHE
Worldpart generated: 1 - -10  (1698ms)
Create WorldPartSQLite 1 -10...
Load WorldPartSQLite 1 -10...
Return WorldPartSQLite 1 -10
WORLDPART 1 -10 STORED TO CACHE
clear temporary voxel maps
clear temporary voxel maps
Worldpart generating...
Biomepart generating...
biomepart offset 0 -6 -> 0 22  (-800496576, -200124144)
Biomepart (0) generated: 0 - -6  (231ms)
BIOMEPART 0 -6 STORED TO CACHE
DungeonPoints: 100
Worldpart generated: 0 - -11  (1848ms)
Worldpart generating...
... (1) ChunkAdditions saved to DB!
DungeonPoints: 100
WORLDPART 0 -11 STORED TO CACHE
Worldpart generated: 1 - -11  (1686ms)
WORLDPART 1 -11 STORED TO CACHE
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:62734  de.jiw.network.server.session.TcpSessionHandler@4f39e41  PORT:4256
clear temporary voxel maps
[TcpSessionHandler ExceptionCaught] /78.143.39.35:62734
2018/02/28   04:09 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:62734
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
... (1) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
... (1) ChunkAdditions saved to DB!
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:25542  de.jiw.network.server.session.TcpSessionHandler@35afc514  PORT:4256
Worldpart generating...
Biomepart generating...
biomepart offset 1 -4 -> 31 20  (-800496576, -200124144)
Biomepart (0) generated: 1 - -4  (239ms)
BIOMEPART 1 -4 STORED TO CACHE
DungeonPoints: 100
Worldpart generated: 2 - -8  (1721ms)
Create WorldPartSQLite 2 -8...
Worldpart generating...
DungeonPoints: 100
WORLDPART 2 -8 STORED TO CACHE
Worldpart generated: 2 - -7  (1656ms)
Create WorldPartSQLite 2 -7...
Load WorldPartSQLite 2 -7...
Return WorldPartSQLite 2 -7
WORLDPART 2 -7 STORED TO CACHE
[TcpSessionHandler ExceptionCaught] /78.143.39.35:25542
2018/02/28   04:12 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:25542
... (1) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
Worldpart generating...
Biomepart generating...
biomepart offset 1 -5 -> 31 21  (-800496576, -200124144)
Biomepart (3) generated: 1 - -5  (1ms)
BIOMEPART 1 -5 STORED TO CACHE
DungeonPoints: 100
Worldpart generated: 2 - -9  (2452ms)
Create WorldPartSQLite 2 -9...
Load WorldPartSQLite 2 -9...
Return WorldPartSQLite 2 -9
WORLDPART 2 -9 STORED TO CACHE
... (2) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
Load WorldPartSQLite -1 1...
Return WorldPartSQLite -1 1
... (3) ChunkAdditions saved to DB!
... (2) ChunkAdditions saved to DB!
... (1) ChunkAdditions saved to DB!
... (1, 1) Chunks saved to DB!
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:62650  de.jiw.network.server.session.TcpSessionHandler@34d11e20  PORT:4256
... (1) ChunkAdditions saved to DB!
[TcpSessionHandler ExceptionCaught] /78.143.39.35:62650
2018/02/28   04:14 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:62650
clear temporary voxel maps
clear temporary voxel maps
... (3, 0) Chunks saved to DB!
... (4, 1) Chunks saved to DB!
clear temporary voxel maps
... (1, 1) Chunks saved to DB!
Worldpart generating...
Biomepart generating...
Loaded Biomepart from cache: 1 - -2  (2ms)
Loaded Worldpart (v1) from cache: 2 - -3  (117ms)
Worldpart generating...
Biomepart generating...
Loaded Biomepart from cache: 1 - -1  (2ms)
Loaded Worldpart (v1) from cache: 2 - -2  (139ms)
Load WorldPartSQLite 2 -3...
Return WorldPartSQLite 2 -3
Load WorldPartSQLite 2 -2...
Return WorldPartSQLite 2 -2
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:8523  de.jiw.network.server.session.TcpSessionHandler@3e4685d  PORT:4256
[TcpSessionHandler ExceptionCaught] /78.143.39.35:8523
2018/02/28   04:17 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:8523
Worldpart generating...
DungeonPoints: 100
Worldpart generated: 2 - -4  (1706ms)
Create WorldPartSQLite 2 -4...
WORLDPART 2 -4 STORED TO CACHE
clear temporary voxel maps
ccat: newstatus 1  (1)
... (1) ChunkAdditions saved to DB!
Worldpart generating...
Loaded Worldpart (v1) from cache: 1 - -1  (116ms)
Load WorldPartSQLite 1 -1...
Return WorldPartSQLite 1 -1
... (1) ChunkAdditions saved to DB!
clear temporary voxel maps
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:62970  de.jiw.network.server.session.TcpSessionHandler@3ebc2b57  PORT:4256
... (4, 0) Chunks saved to DB!
[TcpSessionHandler ExceptionCaught] /78.143.39.35:62970
2018/02/28   04:19 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:62970
Worldpart generating...
Loaded Worldpart (v1) from cache: 1 - 0  (119ms)
Load WorldPartSQLite 1 0...
Load WorldPartSQLite 1 0...
Return WorldPartSQLite 1 0
Return WorldPartSQLite 1 0
... (2, 0) Chunks saved to DB!
... (2, 0) Chunks saved to DB!
Worldpart generating...
Loaded Worldpart (v1) from cache: 0 - 1  (109ms)
Worldpart generating...
Load WorldPartSQLite 0 1...
Return WorldPartSQLite 0 1
Loaded Worldpart (v1) from cache: 1 - 1  (148ms)
Load WorldPartSQLite 1 1...
Return WorldPartSQLite 1 1
... (2, 0) Chunks saved to DB!
... (2, 0) Chunks saved to DB!
clear temporary voxel maps
... (4, 0) Chunks saved to DB!
... (4, 0) Chunks saved to DB!
Worldpart generating...
Biomepart generating...
Loaded Biomepart from cache: 0 - 1  (1ms)
Loaded Worldpart (v1) from cache: 0 - 2  (105ms)
Worldpart generating...
Loaded Worldpart (v1) from cache: 1 - 2  (107ms)
Load WorldPartSQLite 0 2...
Return WorldPartSQLite 0 2
Load WorldPartSQLite 1 2...
Return WorldPartSQLite 1 2
clear temporary voxel maps
... (1, 0) Chunks saved to DB!
... (1, 0) Chunks saved to DB!
clear temporary voxel maps
... (1, 0) Chunks saved to DB!
... (1, 0) Chunks saved to DB!
[TcpSessionHandler] NEW Client Connection from:/78.143.39.35:62026  de.jiw.network.server.session.TcpSessionHandler@43b3752c  PORT:4256
... (1, 0) Chunks saved to DB!
[TcpSessionHandler ExceptionCaught] /78.143.39.35:62026
2018/02/28   04:22 PM   JIW-Network
WARNING: [TcpSessionHandler ChannelInactive] Unable to find ClientConnection for /78.143.39.35:62026
... (2, 0) Chunks saved to DB!
Worldpart generating...
Loaded Worldpart (v1) from cache: 0 - 3  (115ms)
Worldpart generating...
Load WorldPartSQLite 0 3...
Return WorldPartSQLite 0 3
Loaded Worldpart (v1) from cache: 1 - 3  (718ms)
Load WorldPartSQLite 1 3...
Return WorldPartSQLite 1 3
... (2, 0) Chunks saved to DB!
clear temporary voxel maps
... (1, 0) Chunks saved to DB!
2018/02/28   04:23 PM   I.e
WARNING: Error in NPCAIManager
java.lang.NullPointerException
	at I.e.i(SourceFile:337)
	at I.e.run(SourceFile:687)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
... (1) ChunkAdditions saved to DB!
... (1, 0) Chunks saved to DB!
Worldpart generating...
Biomepart generating...
Loaded Biomepart from cache: 0 - 2  (1ms)
Loaded Worldpart (v2) from cache: 0 - 4  (882ms)
Load WorldPartSQLite 0 4...
Worldpart generating...
Return WorldPartSQLite 0 4
Loaded Worldpart (v2) from cache: 1 - 4  (641ms)
Load WorldPartSQLite 1 4...
Return WorldPartSQLite 1 4
clear temporary voxel maps
... (1, 0) Chunks saved to DB!

Display More

Ich kenn mich ja leider nicht ganz so toll aus, aber schon auffällig sind da die zum Ende hin extremlangen Zeiten beim Laden und generieren der Worldparts. Teils weit über 2000 ms.

Serverbetreiber ist Nitrado.
Dort zeigt es fast Live den CPU- und Speicherverbrauch an. Wir haben das dann nochmal probiert:
- Server Neustart, CPU um die 3 %, RAM knapp über 300 MB
- 2 Leute Arbeiten an den Werkbänken und bauen mit Blöcken und Holz, CPU 5 - 8 %, Ram geht leicht über 500
- so un den Dreh bleiben die Werte dann auch
- bis dann Einer der Beiden entdecken geht, also so dass neue Worldparts generiert werden müssen, also laufen in Gegenden wo noch Niemand vorher war, dann geht die CPU recht schnell auf gut über 90% hoch, nicht dauerhaft, nur ganz kurze Spitzen, der RAM geht ganz fix auf 1034 und hängt dann dort fest, in der Serverconfig sind 1024 MB eingestellt

Leider kann ich nicht sagen seit wann dieser Effekt auftritt, da wir auf unserem Server fast ein Jahr so gut wie nicht mehr gespielt hatten und erst jetzt nach dem Update auf die 0.9.2.3 wieder aktiv werden wollen.
Sicher kann ich aber sagen dass wir solche Probleme früher nicht hatten.

Ein paar Fragen:
- Kann es damit zusammenhängen, dass wir auf unserm Server immernoch SQlite und (noch) nicht MySQL verwenden?
- Sollten wir da umstellen? Oder ab wann (wieviel Spieler oder Weltgröße) lohnt sich das?
- Sollten wir Nitrado ansprechen und für mehr RAM-bereitstellung sorgen?
- Kann ich an der Config was anpassen um die Situation zu verbessern?

Mit freundlichem Gruß
Micha
vom Moria-Server
Serverbetreiber ist Nitrado

red51 · Mar 6th 2018

Dass Worldparts teilweise mehr als 2 Sekunden zum generieren brauchen ist - abhängig von der CPU - normal (immerhin enthält ein Worldpart mehr als 73.000 Chunks) Damit das ganze aber nicht zu problematisch wird, werden Worldparts nach dem erstmaligen Generieren im "cache" Ordner abgespeichert (das Laden dieser Worldparts geht dann deutlich schneller vonstatten). D.h. es fällt vor allem dann ins Gewicht, wenn diese Teile der Welt zum ersten Mal geladen werden (vor allem wenn man fliegt).

Die Meldung von Nitrado ist dennoch problematisch: Der Server wurde heruntergefahren, da er zu viel Last generiert hat obwohl keine Spieler darauf spielen würden. Das Problem ist aber, dass Nitrado nicht erkennt, ob Spieler auf dem Server spielen. Für Queryanfragen wird der falsche Port verwendet (4256 anstelle von 4254), wodurch auch in regelmäßigen Abständen auch im Log ein Fehler auftritt (da der Server das als neuen Client intepretiert). Wir hatten Nitrado bereits diesbezüglich kontaktiert, aber ich fürchte, dass das untergegangen ist...
Jedenfalls ist die Folge, dass Nitrado niemals Spieler auf dem Server erkennt, wodurch er nun durch zu hohe Last abgeschaltet wurde (die Meldung impliziert zumindest, dass das nicht passiert wäre, wenn Spieler online wären).

Andererseits ist 1 GB RAM auch recht wenig. Das ist eher dafür geeignet, wenn nicht viel gebaut wird und nur wenige Spieler auf dem Server spielen. Das kann die Situation in dem Fall nochmals verschärfen.
Das Hauptproblem bleibt aber vermutlich eher die CPU. Hier können wir natürlich keine Aussage darüber treffen, welche CPU bei Nitrado verwendet wird und wieviele Server sich eine CPU teilen. Üblicherweise werden meist größere CPUs verwendet (zB 32 Kerne) und darauf laufen dann viele Server Instanzen.

Ob am RAM was gemacht werden müsste könntest du Ingame überprüfen. Die Memoryanzeige bei Nitrado wird vermutlich nicht den korrekten Memoryverbrauch widerspiegeln, da Java grundsätzlich mehr RAM reserviert, als verbraucht wird (d.h. es kann sein, dass bereits beim Start 1 GB RAM reserviert werden [auch der Windows Taskmanager bspw. würde dann sagen, dass Java 1 GB RAM verbraucht], obwohl der tatsächliche Verbrauch nur bei 400 MB liegt).
Um eine verlässliche Auskunft über den RAM-Verbrauch zu erhalten, kannst du ingame den Konsolenbefehl getserverinfo memory eingeben. Der relevante Wert steht bei "Used memory". Am besten den Befehl mehrmals hintereinander eingeben, da sich der RAM Verbrauch schlagartig ändern kann.

Ein Wechsel von SQLite auf MySQL kann sinnvoll sein, wenn mehrere Spieler auf dem Server spielen. Ansonsten bleibt der Leistungszuwachs eher überschaubar

Ich würde empfehlen, den Nitrado-Support zu kontaktieren. Ein Problem ist hier nämlich die Erkennung, ob Spieler auf dem Server sind oder nicht. Ich weiß natürlich nicht, ob der Server sich anders verhalten hätte, wenn Spieler erkannt worden wären, das wäre aber zumindest naheliegend. Über den Queryport 4254 lässt sich die Spielerzahl auslesen, nicht aber über den von Nitrado verwendeten Port 4256.

Micha · Mar 7th 2018

Hallo red51,

Vielen Dank für die ausführliche Antwort.
Ich habe bei Nitrado mal ein Supportticket geschrieben.
Wenns wirklich nur der Queryport ist, dann sollte das ja nicht weiter problematisch sein und fix behoben werden können.

Danke auch für den TIP mit dem Konsolenbefehl. Ich werde die nächste Zeit den RAM-Verbrauch mal im Auge behalten.

Eigentlich hatten wir ja früher auch keine Probleme. Wir bauen ja recht viel, sind aber meist nur um die 4 bis 5 Leute zur selben Zeit auf dem Server. Also nicht gerade die große Spieleranzahl.

Das mit der Datenbankumwandlung lass ich erstmal. Für uns ist der große Vorteil an SQlite, dass falls mal mit dem Server was ist, ich die Worlddateien einfach auf meine lokale Maschine kopieren und so wieder einen Moriaserver in Berieb nehmen kann. Das einfache kopieren der Dateien macht auch den Umgang mit Sicherungen sehr einfach.

Viele Grüße
Micha

Participate now!