GameApplication - Setup takes a while

Options
MaximeS
MaximeS ✭
in Photon Server
Hello!

Me and my team are currently working on a game using PhotonPUN and we have a weird behaviour, I would like to confirm that it is normal.

For context, we are using Photon-OnPremise-Server-SDK_v4-0-29-11263 in localhost with the master server and the game server being on the same machine as the game itself.

So we connect to the master server with no problem, then we call 
JoinOrCreateRoom
and that's where things go weird.

the server output this line in GSCode : 
INFO  Photon.LoadBalancing.GameServer.GameApplication - Setup: serverId=ea1042c8-2498-4652-a729-1b165babf52c
that take between 1 and 15 secondes to complete, depending on the machine we run it on. Unfortunately, JoinOrCreateRoom times out after 10 seconds, so on some of our PC, the first time we try to create a room times out.

Is this a normal behaviour and we only need to set the timeout a bit higher or do we do something wrong?

Here is the full GSGame.log
2020-02-20 10:41:08,623 [19] INFO  Photon.LoadBalancing.GameServer.GameApplication - Setup: serverId=ea1042c8-2498-4652-a729-1b165babf52c
2020-02-20 10:41:10,683 [19] INFO  Photon.SocketServer.Diagnostics.HttpQueuePerformanceCounters - HTTP Queue performance counters successfully initialized
2020-02-20 10:41:10,683 [19] INFO  Photon.SocketServer.Diagnostics.HttpQueuePerformanceCounters - Internal HTTP Queue performance counters successfully created
2020-02-20 10:41:10,688 [19] INFO  Photon.LoadBalancing.GameServer.GameApplication - TokenCreator intialized with an expiration of 02:46:40
2020-02-20 10:41:14,575 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter Business Logic Queue
2020-02-20 10:41:14,576 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter ENet Queue
2020-02-20 10:41:14,577 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter bytes in/sec
2020-02-20 10:41:14,578 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter bytes out/sec
2020-02-20 10:41:14,579 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter ENet Threads Processing
2020-02-20 10:41:14,580 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter ENet Threads Active
2020-02-20 10:41:14,581 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter Time Spent In Server: In (ms)
2020-02-20 10:41:14,582 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter Time Spent In Server: Out (ms)
2020-02-20 10:41:14,583 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter TCP: Disconnected Peers +/sec
2020-02-20 10:41:14,584 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter TCP: Disconnected Peers (C) +/sec
2020-02-20 10:41:14,585 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter TCP: Peers
2020-02-20 10:41:14,586 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter UDP: Disconnected Peers +/sec
2020-02-20 10:41:14,586 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter UDP: Disconnected Peers (C) +/sec
2020-02-20 10:41:14,587 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - Did not find counter UDP: Peers
2020-02-20 10:41:14,597 [19] WARN  Photon.Common.LoadBalancer.LoadShedding.FeedbackControlSystem - Could not initialize Feedback Control System from configuration: Invalid configuration file P:\production\UNITY_Production\REDACTED\BuildSettings\Arcade\Photon\PhotonServer\deploy\Workload.config. Using default settings... (Le fichier 'P:\production\UNITY_Production\REDACTED\BuildSettings\Arcade\Photon\PhotonServer\deploy\Workload.config' est introuvable.)
2020-02-20 10:41:14,611 [19] INFO  Photon.Common.LoadBalancer.ServerStateManager - Watching for application state file in P:\production\UNITY_Production\REDACTED\BuildSettings\Arcade\Photon\PhotonServer\deploy\ServerState.txt
2020-02-20 10:41:14,613 [19] INFO  Photon.Common.LoadBalancer.ServerStateManager - Server state is set to online
2020-02-20 10:41:14,619 [19] INFO  Photon.LoadBalancing.GameServer.GameApplication - Initializing master server connection ...
2020-02-20 10:41:14,665 [19] INFO  Photon.LoadBalancing.GameServer.MasterServerConnectionBase - Connecting to master at 127.0.0.1:4520, serverId=ea1042c8-2498-4652-a729-1b165babf52c
2020-02-20 10:41:14,708 [19] INFO  Photon.SocketServer.ApplicationBase - Application start: AppId=Game; AppPath=P:\production\UNITY_Production\REDACTED\BuildSettings\Arcade\Photon\PhotonServer\deploy\LoadBalancing\GameServer, Type=Photon.LoadBalancing.GameServer.GameApplication 
2020-02-20 10:41:14,716 [19] INFO  Photon.SocketServer.Diagnostics.CounterPublisher - CounterPublisher started publishing ExitGames.Diagnostics.Monitoring.CounterSamplePublisher to ExitGames.Diagnostics.Monitoring.CounterSampleSender
2020-02-20 10:41:14,745 [19] INFO  Photon.LoadBalancing.GameServer.GameApplication - OnStopRequested: serverid=5d662a4c-5333-4b05-bf38-17be0c7d41fa
2020-02-20 10:41:14,747 [19] INFO  Photon.SocketServer.ApplicationBase - Application is stopping: AppId=Game
2020-02-20 10:41:14,759 [15] INFO  Photon.LoadBalancing.GameServer.OutgoingMasterServerPeer - connection to master closed (id=7, reason=ManagedDisconnect, detail=Application abort), serverId=5d662a4c-5333-4b05-bf38-17be0c7d41fa
2020-02-20 10:41:14,762 [19] INFO  Photon.LoadBalancing.GameServer.GameApplication - TearDown: serverId=5d662a4c-5333-4b05-bf38-17be0c7d41fa
2020-02-20 10:41:14,763 [19] INFO  Photon.SocketServer.ApplicationBase - Application stop: AppId=Game
2020-02-20 10:41:14,792 [17] INFO  Photon.LoadBalancing.GameServer.MasterServerConnectionBase - Master connection established: address:127.0.0.1
2020-02-20 10:41:14,797 [17] INFO  Photon.Common.LoadBalancer.ServerStateManager - Server state is set to online
2020-02-20 10:41:14,803 [17] INFO  Photon.LoadBalancing.GameServer.OutgoingMasterServerPeer - Registering game server with address 192.168.4.14, TCP 4531, UDP 5056, WebSocket 9091, Secure WebSocket 19091, HTTP 80, ServerID ea1042c8-2498-4652-a729-1b165babf52c, Hostname localhost, IPv6Address 
2020-02-20 10:41:14,843 [17] INFO  Photon.LoadBalancing.GameServer.OutgoingMasterServerPeer - Successfully registered at master server: serverId=ea1042c8-2498-4652-a729-1b165babf52c
2020-02-20 10:41:15,744 [25] INFO  Photon.Common.LoadBalancer.LoadShedding.FeedbackController - Transit CpuUsage from Lowest to Low with input 35
2020-02-20 10:41:15,745 [25] INFO  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - FeedbackLevel changed: old=Lowest, new=Low
2020-02-20 10:41:17,755 [24] INFO  Photon.Common.LoadBalancer.LoadShedding.FeedbackController - Transit CpuUsage from Low to Normal with input 52
2020-02-20 10:41:17,755 [24] INFO  Photon.Common.LoadBalancer.LoadShedding.WorkloadController - FeedbackLevel changed: old=Low, new=Normal

You can see that it take approx. 6 seconds from the setup line ( the first one ) and the "server state set to online" line.


and here what we call in order :
1 -> PhotonNetwork.ConnectUsingSettings();
2 (OnConnectedToMaster) -> PhotonNetwork.JoinLobby();
3 (When the lobby is join, click on a button) -> PhotonNetwork.JoinOrCreateRoom()
4 Sometime it time out right here.

Here are our 2 servers config files:
Master - http://txt.do/16g1v
GameServer - http://txt.do/16g1w


So is this a normal behaviour? if so, is there a way to pre-create the gameserver before trying to create a room?

Thanks in advance :)

PS: if you need more log/code sample hit me up!

Comments

  • chvetsov
    chvetsov mod
    Options
    Hi, @MaximeS

    it is not ok. It is also bad idea to run Game on same machine as server. It is very good practice to have dedicated server machine

    best,
    ilya
  • MaximeS
    MaximeS ✭
    edited February 2020
    Options
    Hello @chvetsov

    Thank you for your quick answer,

    Can you elaborate on "it is not ok" ? I'm not sure what exactly you are talking about.

    We have a very particular setup with 4 machines in local, we are making 4 players arcade cabinet that can start game in every configuration possible ( ex : 1 four player game, 2 two player game, etc. )

    Once the game is started there is absolutly no issues with our configuration.

    The only issue we have is when we try to create a room for the first time.

    So can you confirm to me if this is normal behaviour or not? and if it is normal behaviour what is the solution? can we wait for the game server to be created or do we just set our timeout higher?

    Thank you.

    PS: Just to clarify, we did buy the Photon PUN 2+ package on the asset store.
  • chvetsov
    chvetsov mod
    Options
    @MaximeS, it is not normal behavior in general. Something is wrong. Wrong in the sense that it is too slow. Even with thousands of players in cloud games are created quite quickly.

    Logs you provided are confusing. Are you updating server binaries without stopping Photon? I do not understand why some application stopping and at the same time connection to master is established.

    Also according to logs you spend 52% of cpu. that is a lot to have influence on the way how system schedule time for threads. Could you setup server on machine without unity? if not then try to increase timeout

    best,
    ilya

  • MaximeS
    MaximeS ✭
    edited February 2020
    Options
    @chvetsov We tried to run it on a dedicated machine, it was faster but not instant.

    But you had a point, we do update server binaries on the fly, and that causes photon to restart, and that is why it takes a while.

    We don't really have a choice to do that since we have 4 pc in LAN and any of them can be turned off at any time, so we decided that the best way to solve the problem for us was to simply wait 10 seconds when updating the server.

    Thank you very much for your help!

    EDIT: how can I set this to resolved? X)
  • chvetsov
    chvetsov mod
    Options
    @MaximeS do not have any clue

    best,
    ilya

Cookies,
anyone?

We use cookies and related technologies to enhance your experience, show you personalised content and analyze performance and traffic on our website. By clicking on the „Accept All“ button you consent to the use of non-functional cookies and the subsequent processing of personal data to optimize our website and services as described in more detail in our Privacy and Cookie Policy.

By clicking on the „Customize or Deny all“ button you can decide otherwise. Clicking on the „Customize“ button will take you to a page where you can configure the usage of non-functional cookies (and related technologies) or deny all of them. You can access these settings at any time and also subsequently deselect cookies at any time in the footer area of our website.

ACCEPT ALL

Cookie Overview

We use the following categories of cookies and related technologies to enhance your experience, show you personalized content, and analyze performance and traffic on our website. We respect your right to privacy and accordingly you can chose to not allow some types of cookies (and related technologies). Click on the different category sliders and change our default settings to manage your cookie settings.

For more information on the specific cookies/related technologies we use and on how we use these, please see section 15 E. of our Privacy and Cookie Policy.

ABSOLUTELY NECESSARY

Authentication cookies we use are required to run our services … Cookies are required: Link

FUNCTIONAL AND MARKETING COOKIES

These cookies collect anonymous data and allow us to optimize our website and user experience. These cookies are listed here:

ANALYTICS

Help us to understand how visitors interact with our services, enables us to analyze and improve our services (also through third party analytics).