Page MenuHomeSchine - Phabricator
Create Task
Maniphest T1529

Starmade | Server hangs on faction updates
Closed, FinishedPublic
Actions

Description

40 seconds is WAY too long for updates in turns on a 977kb file.

FACTIONS.fac also available upon request; out of consideration for our players, I'd prefer its not available for public access/download.

[2016-06-05 17:10:31] RETRY STATUS: Retries: 9; waiting for pong true (1465146631772/1465146632769); ProcessorID: 478
[2016-06-05 17:10:31] RETRY STATUS: Retries: 9; waiting for pong true (1465146631773/1465146632769); ProcessorID: 488
[2016-06-05 17:10:31] RETRY STATUS: Retries: 9; waiting for pong true (1465146631773/1465146632768); ProcessorID: 486
[2016-06-05 17:10:31] RETRY STATUS: Retries: 9; waiting for pong true (1465146631773/1465146633769); ProcessorID: 1031
[2016-06-05 17:10:31] RETRY STATUS: Retries: 9; waiting for pong true (1465146631867/1465146632814); ProcessorID: 1288
[2016-06-05 17:10:31] RETRY STATUS: Retries: 9; waiting for pong true (1465146631867/1465146632814); ProcessorID: 1173
[2016-06-05 17:10:31] RETRY STATUS: Retries: 9; waiting for pong true (1465146631867/1465146632814); ProcessorID: 38
[2016-06-05 17:10:31] RETRY STATUS: Retries: 9; waiting for pong true (1465146631867/1465146632813); ProcessorID: 1352
[2016-06-05 17:10:31] [FACTIONMANAGER] faction update took: 40528ms
[2016-06-05 17:10:31] [SERVER][UPDATE] WARNING: object local update of SenableGameState(1) took 40529
[2016-06-05 17:10:31] [AI] Setting callback Server(0) Ship[Station_Piratestation Beta_-156_20_-12_14623186303118](26742) Executing send callback: true
[2016-06-05 17:10:31] [AI] Setting callback Server(0) Ship[Station_Piratestation Beta_-156_20_-12_14623186303118](26742) Executing send callback: true
[2016-06-05 17:10:31] [AI] Auto Set Ship[Station_Piratestation Beta_-156_20_-12_14623186303118](26742) from Ship mode to Turret mode because it's docked

Details

Task Type
Bug
Testing Results
Affected Gamemode(s)
Serverside
Reproducible
uncertain
Category
Engine
First occurrence (version)
0.198.146
Hardware/Software/System
OS-Specific
No
Hardware-Specific
No
Video Card Vendor
uncertain
Steps to reproduce

Been watching this really closely today. Timing of whole-server lag is dead-on consistent with these entries.

[2016-06-05 20:11:53] [FACTIONMANAGER] MAKING FACTION TURN: Sun Jun 05 19:11:38 UTC 2016; 442; Turn: 60.0
[2016-06-05 20:12:37] [FACTIONMANAGER] faction update took: 44494ms
Serverconfig (server.cfg)
<replace this line with the file content>
Clientconfig (settings.cfg)
<replace this line with the file content>

Related Objects

Event Timeline

Restricted Application added a project: Issue Navigation. · View Herald TranscriptJun 5 2016, 5:14 PM
lancake added a subscriber: lancake.Jun 8 2016, 10:00 PM
lancake claimed this task.

-feedback-

Test server has one of 589KB so should be noticeable too, don't know how to trigger a faction manager update though.
See slack

lancake shifted this object from the S1 Public space to the S3 Starmade space.Jun 8 2016, 10:00 PM
lancake changed the visibility from "Custom Policy" to "Public (No Login Required)".
lancake changed the edit policy from "Task Author" to "Starmade (Project)".
lancake changed Affected Gamemode(s) from none/unspecified to Serverside.
lancake changed Category from none/unspecified to Engine.
lancake set First occurrence (version) to 0.198.146.
lancake triaged this task as High priority.
Restricted Application added a subscriber: AndyP. · View Herald TranscriptJun 8 2016, 10:00 PM
erthparadine added a comment.Jun 9 2016, 1:04 AM

/faction_point_turn

erthparadine added a comment.EditedJun 13 2016, 3:26 AM

Nobody wants to play on a server that hangs and kicks everyone every hour, this is killing us...

[2016-06-13 02:58:38] RETRY STATUS: Retries: 0; waiting for pong true (1465786718651/1465786727650); ProcessorID: 2285
[2016-06-13 02:58:38] RETRY STATUS: Retries: 0; waiting for pong true (1465786718651/1465786727651); ProcessorID: 2379
[2016-06-13 02:58:38] RETRY STATUS: Retries: 0; waiting for pong true (1465786718656/1465786727650); ProcessorID: 3037
[2016-06-13 02:58:39] [FACTIONMANAGER] faction update took: 122423ms

FACTIONS.fac file is currently 1,098,624 bytes in size

What can we do about this?

erthparadine added a comment.Jul 31 2016, 11:25 PM

We're still seeing very painful lag on faction turns, one instance resulted in a full lagoff, and 8 minute overall server hang today:

Jul 30 05:45:25 stars SMPrd: [FACTIONMANAGER] faction update took: 7248ms
Jul 30 06:45:32 stars SMPrd: [FACTIONMANAGER] faction update took: 7678ms
Jul 30 07:45:39 stars SMPrd: [FACTIONMANAGER] faction update took: 7138ms
Jul 30 08:45:55 stars SMPrd: [FACTIONMANAGER] faction update took: 15658ms
Jul 30 09:46:36 stars SMPrd: [FACTIONMANAGER] faction update took: 41092ms
Jul 30 10:48:09 stars SMPrd: [FACTIONMANAGER] faction update took: 90833ms
Jul 30 11:48:17 stars SMPrd: [FACTIONMANAGER] faction update took: 8518ms
Jul 30 12:55:35 stars SMPrd: [FACTIONMANAGER] faction update took: 437663ms
Jul 30 13:55:42 stars SMPrd: [FACTIONMANAGER] faction update took: 6716ms
Jul 30 14:55:49 stars SMPrd: [FACTIONMANAGER] faction update took: 7459ms
Jul 30 15:55:57 stars SMPrd: [FACTIONMANAGER] faction update took: 7330ms
Jul 30 16:56:04 stars SMPrd: [FACTIONMANAGER] faction update took: 7232ms
Jul 30 17:56:12 stars SMPrd: [FACTIONMANAGER] faction update took: 7734ms
Jul 30 18:56:20 stars SMPrd: [FACTIONMANAGER] faction update took: 8659ms
Jul 30 19:56:35 stars SMPrd: [FACTIONMANAGER] faction update took: 14145ms
Jul 30 20:56:42 stars SMPrd: [FACTIONMANAGER] faction update took: 7342ms
Jul 30 21:56:49 stars SMPrd: [FACTIONMANAGER] faction update took: 7500ms
Jul 30 22:57:08 stars SMPrd: [FACTIONMANAGER] faction update took: 17777ms
Jul 30 23:57:15 stars SMPrd: [FACTIONMANAGER] faction update took: 7127ms
Jul 31 00:57:22 stars SMPrd: [FACTIONMANAGER] faction update took: 7192ms
Jul 31 01:57:30 stars SMPrd: [FACTIONMANAGER] faction update took: 8171ms
Jul 31 02:57:39 stars SMPrd: [FACTIONMANAGER] faction update took: 8180ms
Jul 31 03:57:47 stars SMPrd: [FACTIONMANAGER] faction update took: 8118ms
Jul 31 04:58:11 stars SMPrd: [FACTIONMANAGER] faction update took: 23767ms
Jul 31 05:58:35 stars SMPrd: [FACTIONMANAGER] faction update took: 23968ms
Jul 31 06:59:05 stars SMPrd: [FACTIONMANAGER] faction update took: 30173ms
Jul 31 07:59:23 stars SMPrd: [FACTIONMANAGER] faction update took: 17995ms
Jul 31 09:01:58 stars SMPrd: [FACTIONMANAGER] faction update took: 155364ms
Jul 31 10:03:22 stars SMPrd: [FACTIONMANAGER] faction update took: 83679ms
Jul 31 11:11:26 stars SMPrd: [FACTIONMANAGER] faction update took: 484654ms
Jul 31 12:11:35 stars SMPrd: [FACTIONMANAGER] faction update took: 8943ms
Jul 31 13:11:43 stars SMPrd: [FACTIONMANAGER] faction update took: 7704ms
Jul 31 14:11:52 stars SMPrd: [FACTIONMANAGER] faction update took: 8500ms
Jul 31 15:11:59 stars SMPrd: [FACTIONMANAGER] faction update took: 7180ms
Jul 31 16:12:13 stars SMPrd: [FACTIONMANAGER] faction update took: 13866ms
Jul 31 17:12:21 stars SMPrd: [FACTIONMANAGER] faction update took: 8009ms
Jul 31 18:12:28 stars SMPrd: [FACTIONMANAGER] faction update took: 7395ms
Jul 31 19:12:37 stars SMPrd: [FACTIONMANAGER] faction update took: 9099ms
Jul 31 20:12:56 stars SMPrd: [FACTIONMANAGER] faction update took: 18189ms
Jul 31 21:13:39 stars SMPrd: [FACTIONMANAGER] faction update took: 43287ms
Jul 31 22:13:52 stars SMPrd: [FACTIONMANAGER] faction update took: 12399ms
Jul 31 23:14:14 stars SMPrd: [FACTIONMANAGER] faction update took: 22363ms

FACTIONS.fac is 1,262,450 bytes.

Restricted Application added a project: Starmade. · View Herald TranscriptJul 31 2016, 11:25 PM
AndyP changed the task status from Open to Feedback.Feb 21 2017, 8:53 PM
Restricted Application added a project: Waiting on Author. · View Herald TranscriptFeb 21 2017, 8:53 PM
erthparadine added a comment.EditedFeb 21 2017, 8:55 PM

Still seeing this issue:

Feb 21 04:51:22 stars SMPrd: [FACTIONMANAGER] faction update took: 14559ms
Feb 21 05:51:36 stars SMPrd: [FACTIONMANAGER] faction update took: 14022ms
Feb 21 06:51:49 stars SMPrd: [FACTIONMANAGER] faction update took: 13266ms
Feb 21 07:52:03 stars SMPrd: [FACTIONMANAGER] faction update took: 13878ms
Feb 21 08:52:16 stars SMPrd: [FACTIONMANAGER] faction update took: 13437ms
Feb 21 09:52:29 stars SMPrd: [FACTIONMANAGER] faction update took: 12471ms
Feb 21 10:52:43 stars SMPrd: [FACTIONMANAGER] faction update took: 13832ms
Feb 21 11:52:57 stars SMPrd: [FACTIONMANAGER] faction update took: 13834ms
Feb 21 12:53:10 stars SMPrd: [FACTIONMANAGER] faction update took: 13691ms
Feb 21 13:53:23 stars SMPrd: [FACTIONMANAGER] faction update took: 13119ms
Feb 21 14:53:38 stars SMPrd: [FACTIONMANAGER] faction update took: 14711ms
Feb 21 15:53:53 stars SMPrd: [FACTIONMANAGER] faction update took: 14671ms
Feb 21 16:54:07 stars SMPrd: [FACTIONMANAGER] faction update took: 14188ms
Feb 21 17:54:22 stars SMPrd: [FACTIONMANAGER] faction update took: 14146ms
Feb 21 18:54:34 stars SMPrd: [FACTIONMANAGER] faction update took: 12681ms
Feb 21 19:54:47 stars SMPrd: [FACTIONMANAGER] faction update took: 12824ms
Feb 21 20:55:02 stars SMPrd: [FACTIONMANAGER] faction update took: 14754ms

Seeing hangs up to 1 minute, as recently as Feb 19th:

Feb 19 00:18:35 stars SMPrd: [FACTIONMANAGER] faction update took: 56474ms
Restricted Application edited projects, added Customer responded; removed Waiting on Author. · View Herald TranscriptFeb 21 2017, 8:55 PM
Restricted Application changed the task status from Feedback to Open. · View Herald Transcript
erthparadine added a comment.EditedMar 11 2017, 2:01 PM

@lancake asked that I upload our factions.fac file. It is attached.

FACTIONS.fac.zip11 MBDownload

However, note that this file has ballooned from the original report's size to now nearly 380MB. Which could suggest that the originally-reported issue has been resolved, and we're just observing the server's response to a comparatively huge factions.fac file now...is there any way to prune this file, without forcing a server-wide factions reset?

timmymorrison1 added a subscriber: timmymorrison1.EditedMar 20 2017, 3:43 PM

the server I'm on is having the same problem, its even corrupting the factions because of this issue. we've seen this bug since the faction update with npcs.

lancake moved this task from Feedback to Confirmed on the Issue Navigation board.Jun 8 2017, 10:40 AM
schema changed the task status from Open to Resolved.Jul 14 2017, 2:03 PM
lancake moved this task from Backlog / Unclassed to Coordinate multiplayer test on the Quality Assurance board.Jul 14 2017, 9:00 PM

-QA Testing-

the 2 faction files we had were greatly reduced in size after the first save. 800MB -> 2MB and 380 -> 2MB.
All factions are still there and new ones seem to be saved just fine. Leaving this one on open for a while as requires more than a single look.

AndyP moved this task from Backlog / Unclassed to General on the Engine board.Jul 20 2017, 11:10 PM
AndyP edited projects, added Engine (General); removed Engine.
AndyP moved this task from Backlog / Unclassed to Alpha on the Engine (General) board.
lancake closed this task as Closed.Jul 21 2017, 3:55 PM
Restricted Application removed a project: Quality Assurance. · View Herald TranscriptJul 21 2017, 3:55 PM
Restricted Application removed a subscriber: AndyP. · View Herald Transcript
AndyP moved this task from Unclassed to Archived on the Starmade board.Jul 22 2017, 9:55 PM