Server Died.

Post here your questions about SFS2X. Here we discuss all server-side matters. For client API questions see the dedicated forums.

Moderators: Lapo, Bax

trianglehead
Posts: 90
Joined: 13 Aug 2016, 04:28

Server Died.

Postby trianglehead » 12 Jul 2019, 15:09

Hi I have been running this server for several months with no issue, I have had more players before and no issue. Today I noticed that the server died and there are no error logs. The last few lines of logs before it died are:

Code: Select all

12 Jul 2019 | 06:33:13,286 | INFO  | qtp1620187937-4690128 | bitswarm.sessions.DefaultSessionManager |     | Session created: { Id: 243792, Type: BLUEBOX, Logged: No, IP: null } on Server port: 0 <---> 0
12 Jul 2019 | 06:33:06,661 | INFO  | qtp1620187937-3281247 | bitswarm.sessions.DefaultSessionManager |     | Session created: { Id: 243791, Type: BLUEBOX, Logged: No, IP: null } on Server port: 0 <---> 0
12 Jul 2019 | 06:32:56,187 | INFO  | qtp1620187937-127 | bitswarm.sessions.DefaultSessionManager |     | Session created: { Id: 243790, Type: BLUEBOX, Logged: No, IP: null } on Server port: 0 <---> 0
12 Jul 2019 | 06:33:34,100 | INFO  | pool-1-thread-1 | bitswarm.sessions.DefaultSessionManager |     | Session removed: { Id: 243788, Type: BLUEBOX, Logged: No, IP: 174.86.192.39 }
12 Jul 2019 | 06:32:54,496 | INFO  | Scheduler1-thread-1 | bitswarm.sessions.DefaultSessionManager |     | Terminated idle logged-in session: { Id: 241991, Type: DEFAULT, Logged: Yes, IP: 24.144.218.128:57934 }


Are there any logs in linux that I can look at to find out what might have happened? Is it a OOM error, etc?

Here's my server's Dashboard screenshot after restarting it:
Image
Annotation 2019-07-12 091606.jpg
(213.92 KiB) Not downloaded yet


Also noticed the server monitor there's a spike in network in a little before the crash:
Image

Same as cpu
Image
Attachments
Annotation 2019-07-12 095810.jpg
(81.86 KiB) Not downloaded yet
Annotation 2019-07-12 094816.jpg
(58.01 KiB) Not downloaded yet
trianglehead
Posts: 90
Joined: 13 Aug 2016, 04:28

Re: Server Died.

Postby trianglehead » 12 Jul 2019, 16:10

I also noticed a lot of these around the crash time:

8.3.123.139 - - [12/Jul/2019:07:31:00 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:01 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 7189
8.3.123.139 - - [12/Jul/2019:07:31:01 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:01 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2749
8.3.123.139 - - [12/Jul/2019:07:31:02 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2217
8.3.123.139 - - [12/Jul/2019:07:31:02 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:03 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 5473
8.3.123.139 - - [12/Jul/2019:07:31:03 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2577
8.3.123.139 - - [12/Jul/2019:07:31:04 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 833
8.3.123.139 - - [12/Jul/2019:07:31:05 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1513
8.3.123.139 - - [12/Jul/2019:07:31:05 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:05 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1461
8.3.123.139 - - [12/Jul/2019:07:31:06 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 3277
8.3.123.139 - - [12/Jul/2019:07:31:07 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2165
8.3.123.139 - - [12/Jul/2019:07:31:07 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 4545
8.3.123.139 - - [12/Jul/2019:07:31:07 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:08 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 3117
8.3.123.139 - - [12/Jul/2019:07:31:08 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1781
8.3.123.139 - - [12/Jul/2019:07:31:09 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 4397
8.3.123.139 - - [12/Jul/2019:07:31:10 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 4609
8.3.123.139 - - [12/Jul/2019:07:31:10 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:10 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:10 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 3249
8.3.123.139 - - [12/Jul/2019:07:31:11 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 4561
8.3.123.139 - - [12/Jul/2019:07:31:12 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1101
8.3.123.139 - - [12/Jul/2019:07:31:12 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1577
8.3.123.139 - - [12/Jul/2019:07:31:13 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2309
8.3.123.139 - - [12/Jul/2019:07:31:14 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2421
8.3.123.139 - - [12/Jul/2019:07:31:14 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:14 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2009
8.3.123.139 - - [12/Jul/2019:07:31:15 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1165
8.3.123.139 - - [12/Jul/2019:07:31:15 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:15 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1977
8.3.123.139 - - [12/Jul/2019:07:31:16 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 4093
8.3.123.139 - - [12/Jul/2019:07:31:17 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 4865
8.3.123.139 - - [12/Jul/2019:07:31:17 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2337
8.3.123.139 - - [12/Jul/2019:07:31:18 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:18 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 3741
8.3.123.139 - - [12/Jul/2019:07:31:19 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2541
8.3.123.139 - - [12/Jul/2019:07:31:19 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 3197
8.3.123.139 - - [12/Jul/2019:07:31:20 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2837
8.3.123.139 - - [12/Jul/2019:07:31:20 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:20 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:20 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:20 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2217
8.3.123.139 - - [12/Jul/2019:07:31:21 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1161
8.3.123.139 - - [12/Jul/2019:07:31:22 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1893
8.3.123.139 - - [12/Jul/2019:07:31:22 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 3433
8.3.123.139 - - [12/Jul/2019:07:31:23 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:23 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 4445
8.3.123.139 - - [12/Jul/2019:07:31:23 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1961
8.3.123.139 - - [12/Jul/2019:07:31:24 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 1837
8.3.123.139 - - [12/Jul/2019:07:31:25 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 2513
8.3.123.139 - - [12/Jul/2019:07:31:25 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:25 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 3725
8.3.123.139 - - [12/Jul/2019:07:31:26 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 0
8.3.123.139 - - [12/Jul/2019:07:31:26 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 6085
8.3.123.139 - - [12/Jul/2019:07:31:27 +0000] "POST //xxxxx.net:####/BlueBox/BlueBox.do HTTP/1.1" 200 4069
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Server Died.

Postby Lapo » 12 Jul 2019, 21:51

Hi,
usually when the JVM dies it leaves a log file in the SFS2X root called something like hs_err_pidXXXX.log, where the Xs are replaced with the process id.
If the file is not there, then the process death might have been initiated from outside, e.g. from the system itself.
I would suggest to inspect the OS' system logs at the time of the event.

From the dashboard's screenshot I can't see anything too suspicious, apart from the thread count which doesn't look good for the low amount of users connected. What are all those extra threads? Is your server side code generating them?

As regards the BlueBox logs, those are the Jetty logs so it's expected to see some BlueBox activity. It doesn't look suspicious though.

Thanks
Lapo
--
gotoAndPlay()
...addicted to flash games
trianglehead
Posts: 90
Joined: 13 Aug 2016, 04:28

Re: Server Died.

Postby trianglehead » 13 Jul 2019, 01:14

Thanks alot. Looks like it's memory. Those threads are normal. I have another game with much higher user base that reserves these thread pools and they don't cause issue. This game is just a clone of the other game but with currently low user base so I'm leaving all those threads the same.
This had actually happened once a few months ago, now that I looked at the list of hs***.log file...

Based on this error, what do you suggest I do? Should I decrease heap size, since the system only has 4 gigs ram and -xmx is set to 3500, maybe that's an issue? Or do I simply need more physical memory?


Code: Select all

#
# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (mmap) failed to map 133693440 bytes for committing reserved memory.
# Possible reasons:
#   The system is out of physical RAM or swap space
#   In 32 bit mode, the process size limit was hit
# Possible solutions:
#   Reduce memory load on the system
#   Increase physical memory or swap space
#   Check if swap backing store is full
#   Use 64 bit Java on a 64 bit OS
#   Decrease Java heap size (-Xmx/-Xms)
#   Decrease number of Java threads
#   Decrease Java thread stack sizes (-Xss)
#   Set larger code cache with -XX:ReservedCodeCacheSize=
# This output file may be truncated or incomplete.
#
#  Out of Memory Error (os_linux.cpp:2627), pid=11514, tid=0x00007fe6f43b9700
#
# JRE version: Java(TM) SE Runtime Environment (8.0_102-b14) (build 1.8.0_102-b14)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (25.102-b14 mixed mode linux-amd64 compressed oops)
# Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#

---------------  T H R E A D  ---------------

Current thread (0x00007fe70407b800):  VMThread [stack: 0x00007fe6f42ba000,0x00007fe6f43ba000] [id=11518]

Stack: [0x00007fe6f42ba000,0x00007fe6f43ba000],  sp=0x00007fe6f43b82e0,  free space=1016k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0xac52aa]  VMError::report_and_die()+0x2ba
V  [libjvm.so+0x4fc29b]  report_vm_out_of_memory(char const*, int, unsigned long, VMErrorType, char const*)+0x8b
V  [libjvm.so+0x922603]  os::Linux::commit_memory_impl(char*, unsigned long, bool)+0x103
V  [libjvm.so+0x922b59]  os::pd_commit_memory(char*, unsigned long, unsigned long, bool)+0x29
V  [libjvm.so+0x91ce5a]  os::commit_memory(char*, unsigned long, unsigned long, bool)+0x2a
V  [libjvm.so+0x9915e3]  PSVirtualSpace::expand_by(unsigned long)+0x53
V  [libjvm.so+0x9929e8]  PSYoungGen::resize_generation(unsigned long, unsigned long)+0xf8
V  [libjvm.so+0x991b42]  PSYoungGen::resize(unsigned long, unsigned long)+0x22
V  [libjvm.so+0x98ee1b]  PSScavenge::invoke_no_policy()+0xf3b
V  [libjvm.so+0x98f5a1]  PSScavenge::invoke()+0x41
V  [libjvm.so+0x9462f0]  ParallelScavengeHeap::failed_mem_allocate(unsigned long)+0x70
V  [libjvm.so+0xac6cc7]  VM_ParallelGCFailedAllocation::doit()+0x97
V  [libjvm.so+0xace7a5]  VM_Operation::evaluate()+0x55
V  [libjvm.so+0xaccb7a]  VMThread::evaluate_operation(VM_Operation*)+0xba
V  [libjvm.so+0xaccefe]  VMThread::loop()+0x1ce
V  [libjvm.so+0xacd370]  VMThread::run()+0x70
V  [libjvm.so+0x9249c8]  java_start(Thread*)+0x108

VM_Operation (0x00007fe69ee6ec20): ParallelGCFailedAllocation, mode: safepoint, requested by thread 0x00007fe6ec249800
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Server Died.

Postby Lapo » 13 Jul 2019, 10:07

Hi,
I would try to run the JVM without manual memory settings and see if it improves. Usually the JVM manages RAM better without manual intervention.

Also are you using websockets? If so make sure to update to the latest SFS2X 2.13.6 as improvements have been introduced with that release for websocket users.

Finally, is the server dedicated to SFS2X only or does it run other services as well? If so you may want to migrate those to their dedicated servers, so that SFS2X can use more of the available RAM.

Let us know how it goes.
Lapo

--

gotoAndPlay()

...addicted to flash games
trianglehead
Posts: 90
Joined: 13 Aug 2016, 04:28

Re: Server Died.

Postby trianglehead » 13 Jul 2019, 13:50

If I don't set the max ram what is the default? I think I had set it for my previous game because it was needed. Lots of cache objects when over 1000 CCU. Also I don't use websockets. But I have patched to that latest version indeed.
User avatar
Lapo
Site Admin
Posts: 23008
Joined: 21 Mar 2005, 09:50
Location: Italy

Re: Server Died.

Postby Lapo » 15 Jul 2019, 07:07

nepoez wrote:If I don't set the max ram what is the default? I think I had set it for my previous game because it was needed. Lots of cache objects when over 1000 CCU. Also I don't use websockets. But I have patched to that latest version indeed.

The JVM allocates RAM based on what's available in the system, if no manual input is given.
What are these "cache objects" you've mentioned?

What about this question?
is the server dedicated to SFS2X only or does it run other services as well? If so you may want to migrate those to their dedicated servers, so that SFS2X can use more of the available RAM.


Thanks
Lapo

--

gotoAndPlay()

...addicted to flash games
trianglehead
Posts: 90
Joined: 13 Aug 2016, 04:28

Re: Server Died.

Postby trianglehead » 15 Jul 2019, 15:17

Thanks for the helps! I have now set the max heap size to 3/4 of the available system memory and over the weekend with higher traffic than the traffic during the 2 crash incidents and it has survived. Hopefully that's all!

Just for record's sake I've answered the questions.

The JVM allocates RAM based on what's available in the system, if no manual input is given.

Hi I read from Oracle for maximum heap size = "Smaller of 1/4th of the physical memory or 1GB"

What are these "cache objects" you've mentioned?

For each player I have a custom "session" dataset that is synced to the database and these can get big depending on what the player is doing, or what state he's in etc. There's also a bunch of other caches used for saving game state, and for performance purposes. I remember using the JVM default was not enough when player count goes beyond 1-2k. That's why the previous game had manual setting for max heap size and I'm just copying the same settings to the new game, in case when it grows I won't need to try to remember what to change.


is the server dedicated to SFS2X only or does it run other services as well? If so you may want to migrate those to their dedicated servers, so that SFS2X can use more of the available RAM.

Yes this server is dedicated to SFS2X only.

Return to “SFS2X Questions”

Who is online

Users browsing this forum: No registered users and 41 guests