question

Martin Brandel avatar image
Martin Brandel asked

Cloudscript from multiplayer servers take too long (11 seconds) for a response

I have a piece of code like so:

Debug.Log("Player who won: " + playfabPreviouslyConnectedPlayers[wonPlayer]);
PlayFabServerAPI.ExecuteCloudScript(new PlayFab.ServerModels.ExecuteCloudScriptServerRequest()
{
      PlayFabId = playfabPreviouslyConnectedPlayers[wonPlayer],
      FunctionName = "playerWonOnlineMatch",
      FunctionParameter = ***,
      GeneratePlayStreamEvent = true, // Optional - Shows this event in PlayStream
}, OnWinSuccess, OnWinError);


PlayFab.ServerModels.WriteTitleEventRequest request = new PlayFab.ServerModels.WriteTitleEventRequest
{
     EventName = "online_game_complete",
     Body =
     new Dictionary<string, object>{
     { "Players", playfabPreviouslyConnectedPlayers }
     ***
}
};
PlayFabServerAPI.WriteTitleEvent(request, result => Debug.Log("Player Won Playstream Written"), error => Debug.LogError("Error writing error to playstream: " + error.ErrorMessage));

In my server, I get the log for the first debug option at 4 seconds:

{"log":"Player who won: 2A96DFDBE6056076\r\n","stream":"stdout","time":"2021-11-09T13:41:04.568905Z"}

Then, I get the responses to these two calls 11 seconds later:

{"log":"Player Won Playstream Written\r\n","stream":"stdout","time":"2021-11-09T13:41:15.8661417Z"} {"log":"GameManager:OnWinSuccess (PlayFab.ServerModels.ExecuteCloudScriptResult) (at D:/***:3625)\r\n","stream":"stdout","time":"2021-11-09T13:41:16.1011492Z"}

The playstream event is here for the "OnWinSuccess":

{
    "PlayFabEnvironment": {
        "Application": "logicserver",
        "Vertical": "master",
        "Commit": "74c29bd",
        "Cloud": "main"
    },
    "EventNamespace": "com.playfab",
    "Timestamp": "2021-11-09T13:41:15.9989856Z",
    "SourceType": "BackEnd",
    "EntityType": "player",
    "EventName": "player_executed_cloudscript",
    "EntityId": "2A96DFDBE6056076",
    "EventId": "048ca30d38194dd8acfbc3276a14442d",
    "TitleId": "E159E",
    "FunctionName": "playerWonOnlineMatch",
    "CloudScriptExecutionResult": {
        "FunctionName": "playerWonOnlineMatch",
        "ExecutionTimeSeconds": 0.0363139,
        "ProcessorTimeSeconds": 0.001719,
        "MemoryConsumedBytes": 5216,
        "HttpRequestsIssued": 0,
        "APIRequestsIssued": 1,
        "FunctionResult": {
            "messageValue": "Player Won: 2A96DFDBE6056076 Match time: 295.5024",
            "amount": 94
        },
        "Revision": 115,
        "Logs": [
            {
                "Level": "Info",
                "Message": "Player Won: 2A96DFDBE6056076 Match time: 295.5024"
            }
        ]
    },
    "Source": "CloudScript"
}

The timestamp in the playstream event is at 16 seconds, same as when the return is received in my server, execution time is 0.03 in the cloudscript, so it seems it takes 11 seconds for cloudscript to receive the call but almost none for it to be returned.

Why is that? What could I do to fix this?

CloudScriptmultiplayer
10 comments
10 |1200

Up to 2 attachments (including images) can be used with a maximum of 512.0 KiB each and 1.0 MiB total.

Gosen Gao avatar image Gosen Gao commented ·

How often this issue is triggered? If it happens sometimes, this should be a server load issue. If it happens all the time, then the issue should be relevant to the code.

0 Likes 0 ·
Martin Brandel avatar image Martin Brandel Gosen Gao commented ·

It is consistent - it has never been faster than ~8 seconds, but its only for cloudscript, my other server functions to clients are fine, all respond under a second and it does not hang, my server code executes other functions immediately after making the cloudscript call, the delay is only the call to cloudscript.

What other information do you need to see what the issue could be?

0 Likes 0 ·
Gosen Gao avatar image Gosen Gao Martin Brandel commented ·

How many ExecuteCloudScript APIs are there in your server build? If there are more than one. Is there a situation like one Execute request has got a successful response and another Execute request will be sent after it? Will the second one has the same delay?

0 Likes 0 ·
Show more comments
Show more comments
Martin Brandel avatar image Martin Brandel Gosen Gao commented ·

There is no urgent business impact. I can try that and get back to you if it takes a while when there are multiple cloudscript/server calls in a row.

0 Likes 0 ·
Martin Brandel avatar image Martin Brandel Gosen Gao commented ·

It seems your idea of a "cold start" issue may be correct: When I make another cloudscript call immediately afterwards it resolves immediately.

This however is not acceptable; my client's cloudscript has no issue being called immediately, and I cannot wait 15 seconds on the first cloudscript call my server does.

What would be the solution for this?

Thanks.

0 Likes 0 ·
Gosen Gao avatar image Gosen Gao Martin Brandel commented ·

The cold start issue with CloudScript can’t be prevented. It is by design in most serverless services. The CloudScript has become a legacy feature, and we can’t modify the configuration to change how it behaves.

After doing some research, I’ve found that with Azure Functions there are workarounds to reduce the cold start issue. Please note that the Azure Functions also have the same cold start issue. But with the Azure portal, you can change the behavior of Azure Functions.

  • 1. You can consider the Azure Functions Premium plan, there's always an extra server running, no cold start, so it's generally not an issue.
  • 2. Or you can implement a scheduled function which makes a request every 5 minutes(you may need to reduce the time if the cold start issue still occurs) to keep the service warm.

For more information, please refer to Azure functions cloudscript vs JS cloudscript performance - Playfab Community.

0 Likes 0 ·
Show more comments

1 Answer

·
Martin Brandel avatar image
Martin Brandel answered

@Gosen Gao

Did some more testing, and no, it does not seem that it has anything to do with the "cold start".

I've added a cloudscript call to an empty function which occurs every 6 seconds on the server, and it gives me a debug log for the time taken for the function to return: (Time for cloudscript tick is in seconds, and it it the time between the function being called and successfully returned)

{"log":"UnityLog: Time for cloudscript tick: 31.09299\r\n","stream":"stdout","time":"2021-11-16T09:08:19.1131771Z"}
{"log":"UnityLog: Time for cloudscript tick: 1.079956\r\n","stream":"stdout","time":"2021-11-16T09:08:19.2311786Z"}
{"log":"UnityLog: Time for cloudscript tick: 13.15604\r\n","stream":"stdout","time":"2021-11-16T09:08:19.2311786Z"}
{"log":"UnityLog: Time for cloudscript tick: 7.221863\r\n","stream":"stdout","time":"2021-11-16T09:08:19.3251803Z"}
{"log":"UnityLog: Time for cloudscript tick: 19.27444\r\n","stream":"stdout","time":"2021-11-16T09:08:19.3251803Z"}
{"log":"UnityLog: Time for cloudscript tick: 25.43066\r\n","stream":"stdout","time":"2021-11-16T09:08:19.4631817Z"}
{"log":"UnityLog: Time for cloudscript tick: 5.758789\r\n","stream":"stdout","time":"2021-11-16T09:08:29.9302929Z"}
{"log":"UnityLog: Time for cloudscript tick: 0.1422424\r\n","stream":"stdout","time":"2021-11-16T09:08:30.3492963Z"}
{"log":"UnityLog: Time for cloudscript tick: 0.13974\r\n","stream":"stdout","time":"2021-11-16T09:08:36.3873382Z"}
{"log":"UnityLog: Time for cloudscript tick: 0.1853027\r\n","stream":"stdout","time":"2021-11-16T09:08:42.4785107Z"}
{"log":"UnityLog: Time for cloudscript tick: 6.541962\r\n","stream":"stdout","time":"2021-11-16T09:08:54.87079Z"}
{"log":"UnityLog: Time for cloudscript tick: 6.469971\r\n","stream":"stdout","time":"2021-11-16T09:09:00.8309603Z"}
{"log":"UnityLog: Time for cloudscript tick: 5.203308\r\n","stream":"stdout","time":"2021-11-16T09:09:05.5660586Z"}

And this continues to vary widely throughout its life. This can't be a cold start issue, and I can't see how it can be a code issue if it varies so drastically with an empty function.

Please advise, thanks.

5 comments
10 |1200

Up to 2 attachments (including images) can be used with a maximum of 512.0 KiB each and 1.0 MiB total.

Gosen Gao avatar image Gosen Gao commented ·

According to the time of log, this function doesn't seem to be executed every 6 seconds. Did I misunderstand anything?

0 Likes 0 ·
Martin Brandel avatar image Martin Brandel Gosen Gao commented ·

Yes, it is executed every 6 seconds but what is happening here, is the log time is set to when the function is returned, not when it is sent. If you look at the first 6 logs, you can see they are all returned at the same time, but their "execution time" is spaced 6 seconds apart. This could be the "cold start" issue you mentioned.

However after that (as you can see with the rest of the logs) they still take from 0.1-10 seconds, with most of them taking ~ 5 seconds to return. (and I still get ~5-20 seconds on the final function I care about at the end of the game even with constant pings every 6 seconds).

Please advise on that. Thanks.

0 Likes 0 ·
Martin Brandel avatar image Martin Brandel Gosen Gao commented ·

@Gosen Gao, please see my above comment. It is correct, sent every 6 seconds.

0 Likes 0 ·
Gosen Gao avatar image Gosen Gao Martin Brandel commented ·

I don’t know the detail about how you implement this log feature. But the rest logs(besides the first 6) still seem to be in some sort of pattern. They're either almost zero or close to 6. I'm not sure, but it still seems to be a cold start issue for me.

As for the final function, It may be that this method cannot solve the issue in CloudScript, or the CloudScript starts another service to handle this function so it still in “cold start” issue. I would suggest you to add a Boolean parameter named “Warm” or something to the final function, if this parameter is true, the function will return directly. Then you can make this function requests every minute until the final one to keep it warm.

0 Likes 0 ·
Show more comments

Write an Answer

Hint: Notify or tag a user in this post by typing @username.

Up to 2 attachments (including images) can be used with a maximum of 512.0 KiB each and 1.0 MiB total.