question

max avatar image
max asked

Cloud Script Call sometimes takes 6+ seconds when it usually takes 1 second.

Heya, I once reported an issue that our Cloud Script calls sometimes take 6+ seconds when they usually only take 1 second. I didn't have an example back then. But now it once happened and I want to share the data for further investigations. The title was queried with Cloud Scripts before, so it was definitely loaded on the PlayFab Servers.

Title ID: D73D

Here's the exceeding limits data:

{

    "EventName": "title_exceeded_limit",

    "LimitId": "CloudScript:ScriptExecutionTime",

    "LimitDisplayName": "Processing time for a CloudScript function called by the ExecuteCloudScript API.",

    "Unit": "Seconds",

    "LimitValue": 5,

    "Value": 6.7623138,

    "AssociatedEntities": {

        "player": [

            "A447F9DAE211F33C"

        ]

    },

    "Details": {

        "Function": "ReportMatchBegin"

    },

    "EventNamespace": "com.playfab",

    "EntityType": "title",

    "Source": "PlayFab",

    "EventId": "3c552a7ec68b448cb7e421cbb2840ac6",

    "EntityId": "D73D",

    "SourceType": "BackEnd",

    "Timestamp": "2017-05-30T23:19:35.6742706Z",

    "History": null,

    "CustomTags": null,

    "Reserved": null

}

And here the actual call data:




p.p1 {margin: 0.0px 0.0px 0.0px 0.0px; font: 12.0px 'Helvetica Neue'; color: #454545}



{

    "EventName": "player_executed_cloudscript",

    "Source": "CloudScript",

    "FunctionName": "ReportMatchBegin",

    "CloudScriptExecutionResult": {

        "FunctionName": "ReportMatchBegin",

        "Revision": 1328,

        "FunctionResult": true,

        "FunctionResultTooLarge": null,

        "Logs": [

            {

                "Level": "Debug",

                "Message": "NewEntryKey: ADBEDA889CBCAC97#1081635934",

                "Data": null

            },

            {

                "Level": "Debug",

                "Message": "Local Entry:{\"State\":\"Open\",\"OpntID\":\"ADBEDA889CBCAC97\",\"LclPlyrID\":\"A447F9DAE211F33C\",\"LclPlyrDN\":\"Player1496140\",\"OpntDN\":\"Player1496164\",\"OpntMMR\":479,\"LPlyrMMR\":633,\"LPlyrMMRRange\":250,\"MStrtPhTme\":1081635934,\"CDateInS\":1496186368,\"GameValHsh\":655795716,\"MatchType\":\"VsPlayer\",\"BMinRyCHash\":3471906759,\"MinCVer\":73,\"CDateStr\":\"Tue, 30 May 2017 23:19:28 GMT\"}",

                "Data": null

            },

            {

                "Level": "Debug",

                "Message": "MaintenancePerform: EvaluateOpen, Counter:3",

                "Data": null

            },

            {

                "Level": "Debug",

                "Message": "EvaluateOpenMatchesModifyDataOnly",

                "Data": null

            },

            {

                "Level": "Debug",

                "Message": "EvaluateOpenMatches: This piece of data is not old enough yet:ADBEDA889CBCAC97#1081635934 ageInSeconds: 7",

                "Data": null

            }

        ],

        "LogsTooLarge": null,

        "ExecutionTimeSeconds": 6.762313799999999,

        "ProcessorTimeSeconds": 0.016,

        "MemoryConsumedBytes": 4294856224,

        "APIRequestsIssued": 15,

        "HttpRequestsIssued": 0,

        "Error": null

    },

    "EventNamespace": "com.playfab",

    "EntityType": "player",

    "TitleId": "D73D",

    "EventId": "9f21ba85b99f498dab6b043dd2eb1a47",

    "EntityId": "A447F9DAE211F33C",

    "SourceType": "BackEnd",

    "Timestamp": "2017-05-30T23:19:35.6872924Z",

    "History": null,

    "CustomTags": null,

    "Reserved": null

}

I hope this helps finding the issue, or at least discovering what mistake we might have made.

CloudScript
10 |1200

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

1 Answer

·
brendan avatar image
brendan answered

From a quick review of the Cloud Script handler in question, it appears to be making quite a few calls to the Server API, so I'm actually surprised to hear that it runs in 1 second sometimes - I would expect it to take longer, since each Server call is a Web API call from the Cloud Script logic server. Granted, the servers are in the same AWS availability zone, and so do have very low latency to each other, of course.

But I may be mis-reading, as you do have a lot of function calls embedded. Can you walk us through the specific steps in the handler for your test case, and call out each Server API call, so that we can review the potential causes?

4 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.

max avatar image max commented ·

It actually always takes 0.9 to 1.1 seconds. I've never seen it take longer. Just this one time it took 6+ seconds.

Here's the rundown what the function did in this case:

1) GetUserReadOnlyData - Check if player account has done first time setup correctly

2) GetTitleData - Check the client's current gameValues/Balancing hash and find out which version they use

3) GetUserInternalData - Load player's match history (to add the newly reported match to it)

4) GetStatistics - Load player's matchmaking rating

5) GetStatistics - Load opponent's matchmaking rating

6) GetUserReadOnlyData - Get local player's display name (we save it in read-only data) and save it along the match.

7) GetUserReadOnlyData - Get opponent's display name (we save it in read-only data) and save it along the match.

8) SetUserInternalData - Write new match data to database

9) SetUserInternalData - Write other player data to database

11-14) GetUserInternalData/SetStatistics - Get opponent data of some old, not correctly matchEnd-reported matches and close them

15) SetUserInternalData - Write the results of this to database

0 Likes 0 ·
max avatar image max max commented ·

[character limit exceeded, second part here]

-Some of these calls are double and could be optimized still, for example 2x GetUserReadOnlyData for local player. We are aware and we're working on that. When the code was written we have absolutely not been aware that this might cause problems. We never hit the API limit and the call times were < 1 second.

-We should also probably use the load player data stuff instead of loading single data pieces of statistics and read only data

As bad as this function might be coded - still we'd still really like to know why these random spikes happen.

0 Likes 0 ·
max avatar image max max commented ·

[character limit exceeded, third part here]

It would be very helpful if the result (especially the result of a time or API call exceeded call) would show which API calls were done and how long each call took. That would make the debugging and the optimization of Cloud Script so much easier. It would also probably directly save you money. If we knew which Calls take long under which circumstances (and therefore take much CPU / Database time), we could optimize and try to avoid them, also resulting in less waiting times for our users.

Also it would help our API Call Count if it would be possible to load player data of two players with one API call. I have discovered the GrantItemsToUsers function yesterday which can grant items to multiple users. Maybe also loading data from multiple players is possible?

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.