Firestore and Realtime Database operation are very slow during Cold Start

[bagratkirakosian]

Related issues

430 issue is pretty related but in our case queries are very slow and not only for firestore

263 this issue has the same description but the solution is to clean the global scope which is done in our case. The issue is not cold start in this case, but the databases behavior during it.

Version info

node: v8.16.0

firebase-functions: ^3.0.1

firebase-tools: 7.0.0

firebase-admin: ^8.1.0

Test case

Brief: Realtime databse trigger matches two players together that is why it has a transaction in it. In the transaction after validation it calls create game function that has two database operations - one is getting users from Firestore, the other one save game in Realtime Database.

Note: To provide as less code as possible, removed game JSON making part which are just static function calls. Added the entire log of functions lifecycle (firestore & realtime database logging eneabled) to provide as much valuable information as possible.

export const playerQueueOnUpdate = functions.database.ref('game/queue/player_queue').onUpdate(async (change: functions.Change<functions.database.DataSnapshot>, context: functions.EventContext) => {
    const t0: number = performance.now();
    return change.after.ref.transaction((queue: any) => {
        if (queue === null || Object.keys(queue).length < 2) {
            return queue;
        }

        const playerOneKey: string = Object.keys(queue)[0];
        const playerTwoKey: string = Object.keys(queue)[1];

        delete queue[playerOneKey];
        delete queue[playerTwoKey];

        const t1: number = performance.now();
        console.log(`Calling create game after ${(t1 - t0) / 1000} seconds`);
        gameService.createGame(playerOneKey, playerTwoKey).catch(function (error: any): void {
                console.log(`Failed to create game ${JSON.stringify(error)}`);
            });

        return queue;
    }); 
});

export const createGame = async function (playerOneKey: string, playerTwoKey: string): Promise<any> {
    const t0: number = performance.now();
    // Validate queue

    if (queue === null || Object.keys(queue).length < 2) {
        return queue;
    }

    // Get players data from firestore

    let playerOneUserData: FirebaseFirestore.DocumentData;
    let playerTwoUserData: FirebaseFirestore.DocumentData;

    try {
        const t8: number = performance.now();
        const firestore = DataModel.instance.firestore;
        const t9: number = performance.now();
        console.log(`Created firestore instance in ${(t9 - t8)/1000} seconds`);

        const t10: number = performance.now();
        const task1: Promise<FirebaseFirestore.DocumentSnapshot> = firestore.collection('users').doc(playerOneKey).get();
        const task2: Promise<FirebaseFirestore.DocumentSnapshot> = firestore.collection('users').doc(playerTwoKey).get();
        const t11: number = performance.now();
        console.log(`Made firestore tasks in ${(t11 - t10)/1000} seconds`);

        const t4: number = performance.now();
        const [playerOneDoc, playerTwoDoc]: FirebaseFirestore.DocumentSnapshot[] = await Promise.all([task1, task2]);
        playerOneUserData = playerOneDoc.data();
        playerTwoUserData = playerTwoDoc.data();
        const t5: number = performance.now();
        console.log(`Fetched users data in ${(t5 - t4)/1000} seconds`);
    } catch (error) {
        console.log(`Error getting db users: ${error.message}`);
    }

    // HERE GOES SOME STATIC FUNCTIONS THAT MAKE JSON

    // Saving game to realtime databse

    try {
        const t1: number = performance.now();
        console.log(`Started save game after ${(t1 - t0)/1000} seconds`);

        const t6: number = performance.now();
        const gameRef = DataModel.instance.database.ref('/game/all_games').child(gameId);
        const t7: number = performance.now();
        console.log(`Made game ref after ${(t7 - t6)/1000} seconds`);

        const t2: number = performance.now();
        await gameRef.set(updates);
        const t3: number = performance.now();
        console.log(`Ended save game after ${(t3 - t2)/1000} seconds`);

        return Promise.all([
            gameUtils.makePairTask(playerOneId, constants.KEY_PLAYER_ONE, playerTwoCharacter, playerTwoUserData, gameId),
            gameUtils.makePairTask(playerTwoId, constants.KEY_PLAYER_TWO, playerOneCharacter, playerOneUserData, gameId)
        ]);
    } catch (error) {
        console.log(`Error creating game with - error: ${JSON.stringify(error)}`);
        return null;
    }
}

Steps to reproduce

Deploying functions on firebase. In our case we have them in seperate files but do not think that has anything to do with the core issue.

Expected behavior

It is expected for Firestore get operations and Realtime Database save operations to take as long during cold start as long during warm start. The logs take in count that Firestore SDK takes like 3 seconds to initalization during cold start.

Actual behavior

During cold start after Firestore initalization get query takes ~20 seconds but during warm start the same query is less than a second. Same for Realtime Database, save query is ~6 seconds vs less than a second. Also I would like to highlight a very strange fact, that when the Firestore get queries are removed, Realtime Database save operation jumps from ~6 seconds to ~15 seconds.

5:20:13.094 PM\ playerQueueOnUpdate\ p:1: {"r":5,"a":"p","b":{"p":"/game/pairs/yXoz6vOlMjeqc3BZNfafWr8GPeu2","d":{"enemy_character":"character-1","game_id":"CkHnKxRxbOcbZAqvCUe23AFd1FH2yXoz6vOlMjeqc3BZNfafWr8GPeu2","player_key":"player_two"}}}

5:20:13.094 PM\ playerQueueOnUpdate\ 1: set {"path":"/game/pairs/yXoz6vOlMjeqc3BZNfafWr8GPeu2","value":{"game_id":"CkHnKxRxbOcbZAqvCUe23AFd1FH2yXoz6vOlMjeqc3BZNfafWr8GPeu2","player_key":"player_two","enemy_character":"character-1"},"priority":null}

5:20:13.093 PM\ playerQueueOnUpdate\ p:1: {"r":4,"a":"p","b":{"p":"/game/pairs/CkHnKxRxbOcbZAqvCUe23AFd1FH2","d":{"enemy_character":"character-1","game_id":"CkHnKxRxbOcbZAqvCUe23AFd1FH2yXoz6vOlMjeqc3BZNfafWr8GPeu2","player_key":"player_one"}}}

5:20:12.995 PM\ playerQueueOnUpdate\ 1: set {"path":"/game/pairs/CkHnKxRxbOcbZAqvCUe23AFd1FH2","value":{"game_id":"CkHnKxRxbOcbZAqvCUe23AFd1FH2yXoz6vOlMjeqc3BZNfafWr8GPeu2","player_key":"player_one","enemy_character":"character-1"},"priority":null}

5:20:12.896 PM\ playerQueueOnUpdate\ Ended save game after 4.803863183000009 seconds

5:20:12.893 PM\ playerQueueOnUpdate\ p:1: p response {"s":"ok","d":""}

5:20:12.893 PM\ playerQueueOnUpdate\ p:1: from server: {"r":3,"b":{"s":"ok","d":""}}

5:20:12.394 PM\ playerQueueOnUpdate\ p:1: from server: {"r":2,"b":{"s":"ok","d":{"auth":null,"expires":1560781211}}}

5:20:12.292 PM\ playerQueueOnUpdate\ c:1:1: Primary connection is healthy.

5:20:12.292 PM\ playerQueueOnUpdate\ c:1:1: got pong on primary.

5:20:12.195 PM\ playerQueueOnUpdate\ p:1: from server: {"r":1,"b":{"s":"ok","d":""}}

5:20:11.892 PM\ playerQueueOnUpdate\ c:1:1: sending ping on primary.

5:20:09.293 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:09.293Z YbXiM [Firestore.request]: Sending request: {"database":"projects/chingo-club-fefcc/databases/(default)","writes":[{"update":{"name":"projects/chingo-club-fefcc/databases/(default)/documents/users/yXoz6vOlMjeqc3BZNfafWr8GPeu2","fields":{"currentCharacter":{"stringValue":"character-1"}}},"updateMask":{"fieldPaths":["currentCharacter"]},"currentDocument":{"exists":true}}]}

5:20:09.293 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:09.293Z 8hvrQ [Firestore.request]: Sending request: {"database":"projects/chingo-club-fefcc/databases/(default)","writes":[{"update":{"name":"projects/chingo-club-fefcc/databases/(default)/documents/users/CkHnKxRxbOcbZAqvCUe23AFd1FH2","fields":{"currentCharacter":{"stringValue":"character-1"}}},"updateMask":{"fieldPaths":["currentCharacter"]},"currentDocument":{"exists":true}}]}

5:20:09.093 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:09.093Z YbXiM [WriteBatch.commit]: Sending 1 writes

5:20:09.093 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:09.093Z 8hvrQ [WriteBatch.commit]: Sending 1 writes

5:20:08.793 PM\ playerQueueOnUpdate\ p:1: {"r":3,"a":"p","b":{"p":"/game/all_games/CkHnKxRxbOcbZAqvCUe23AFd1FH2yXoz6vOlMjeqc3BZNfafWr8GPeu2","d":{"actions":{"0":"start"},"board":{"player_one":{"11":{"visible":false,"weapon":"scissors"},"12":{"visible":false,"weapon":"paper"},"21":{"visible":false,"weapon":"paper"},"22":{"visible":false,"weapon":"scissors"},"31":{"visible":false,"weapon":"paper"},"32":{"visible":false,"weapon":"scissors"},"41":{"visible":false,"weapon":"rock"},"42":{"visible":false,"weapon":"scissors"},"51":{"visible":false,"weapon":"rock"},"52":{"visible":false,"weapon":"rock"},"61":{"visible":false,"weapon":"rock"},"62":{"visible":false,"weapon":"paper"},"71":{"visible":false,"weapon":"paper"},"72":{"visible":false,"weapon":"scissors"}},"player_two":{"15":{"visible":false,"weapon":"paper"},"16":{"visible":false,"weapon":"scissors"},"25":{"visible":false,"weapon":"scissors"},"26":{"visible":false,"weapon":"paper"},"35":{"visible":false,"weapon":"paper"},"36":{"visible":false,"weapon":"rock"},"45":{"visible":false,"weapon":"rock"},"46":{"visible":false,"weapon":"rock"},"55":{"visible":false,"weapon":"rock"},"56":{"visible":false,"weapon":"scissors"},"65":{"visible":false,"weapon":"paper"},"66":{"visible":false,"weapon":"scissors"},"75":{"visible":false,"weapon":"paper"},"76":{"visible":false,"weapon":"rock"}}},"player_one":{"avatar":"","character":"character-1","connected":false,"id":"CkHnKxRxbOcbZAqvCUe23AFd1FH2","last_move":{"action":"empty","from":"00","progress":0,"to":"00"},"name":"Bagrat Kirakosian","shuffles":0,"timeouts":0,"trap_kills":0,"turn":true},"player_two":{"avatar":"","character":"character-1","connected":false,"id":"yXoz6vOlMjeqc3BZNfafWr8GPeu2","last_move":{"action":"empty","from":"00","progress":0,"to":"00"},"name":"bvnb","shuffles":0,"timeouts":0,"trap_kills":0,"turn":false},"shared":{"action":"create","action_player_key":"player_two","from":{"position":"00","weapon":"empty"},"progress":0,"to":{"position":"00","weapon":"empty"},"turn_player_key":"player_one"}}}}

5:20:08.197 PM\ playerQueueOnUpdate\ 1: set {"path":"/game/all_games/CkHnKxRxbOcbZAqvCUe23AFd1FH2yXoz6vOlMjeqc3BZNfafWr8GPeu2","value":{"shared":{"action":"create","from":{"position":"00","weapon":"empty"},"to":{"position":"00","weapon":"empty"},"action_player_key":"player_two","turn_player_key":"player_one","progress":0},"actions":{"0":"start"},"board":{"player_one":{"11":{"weapon":"scissors","visible":false},"12":{"weapon":"paper","visible":false},"21":{"weapon":"paper","visible":false},"22":{"weapon":"scissors","visible":false},"31":{"weapon":"paper","visible":false},"32":{"weapon":"scissors","visible":false},"41":{"weapon":"rock","visible":false},"42":{"weapon":"scissors","visible":false},"51":{"weapon":"rock","visible":false},"52":{"weapon":"rock","visible":false},"61":{"weapon":"rock","visible":false},"62":{"weapon":"paper","visible":false},"71":{"weapon":"paper","visible":false},"72":{"weapon":"scissors","visible":false}},"player_two":{"15":{"weapon":"paper","visible":false},"16":{"weapon":"scissors","visible":false},"25":{"weapon":"scissors","visible":false},"26":{"weapon":"paper","visible":false},"35":{"weapon":"paper","visible":false},"36":{"weapon":"rock","visible":false},"45":{"weapon":"rock","visible":false},"46":{"weapon":"rock","visible":false},"55":{"weapon":"rock","visible":false},"56":{"weapon":"scissors","visible":false},"65":{"weapon":"paper","visible":false},"66":{"weapon":"scissors","visible":false},"75":{"weapon":"paper","visible":false},"76":{"weapon":"rock","visible":false}}},"player_one":{"id":"CkHnKxRxbOcbZAqvCUe23AFd1FH2","character":"character-1","name":"Bagrat Kirakosian","avatar":"","last_move":{"from":"00","to":"00","action":"empty","progress":0},"turn":true,"connected":false,"timeouts":0,"shuffles":0,"trap_kills":0,"flag_kill_weapon":null},"player_two":{"id":"yXoz6vOlMjeqc3BZNfafWr8GPeu2","character":"character-1","name":"bvnb","avatar":"","last_move":{"from":"00","to":"00","action":"empty","progress":0},"turn":false,"connected":false,"timeouts":0,"shuffles":0,"trap_kills":0,"flag_kill_weapon":null}},"priority":null}

5:20:08.092 PM\ playerQueueOnUpdate\ Made game ref after 0.09702955800003837 seconds

5:20:07.995 PM\ playerQueueOnUpdate\ Started save game after 17.892670362999954 seconds

5:20:07.293 PM\ playerQueueOnUpdate\ Fetched users data in 16.46923389099998 seconds

5:20:06.793 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:06.793Z nPtTi [Firestore.getAll_]: Received 1 results

5:20:06.793 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:06.793Z nPtTi [Firestore._initializeStream]: Received stream end

5:20:06.497 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:06.497Z XE62C [Firestore.getAll_]: Received 1 results

5:20:06.496 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:06.496Z XE62C [Firestore._initializeStream]: Received stream end

5:20:04.894 PM\ playerQueueOnUpdate\ p:1: {"r":2,"a":"gauth","b":{"cred":"ya29.c.EqEBKgcw4OWIBQgzZ9p-QaATYPiKb07xz5cJZrk4wjtzNPwgtAxrzBo-Xr8u_HKIst62OnoeFnlaPWVVw0-NosKIi47tS3GRa2t4c0L_z6A_qUCH-mZx6BWHhWIqNgLfZQempnl7tkV4QwTD5yzMnIgq5SIgbzVhA3SBYkA4logT0cwlcAG4UAAmhPClus7MNcqJ_BH9dMpqv3Rx_ZbEDaK0HUs"}}

5:20:04.693 PM\ playerQueueOnUpdate\ p:1: {"r":1,"a":"s","b":{"c":{"sdk.admin_node.8-1-0":1}}}

5:20:04.693 PM\ playerQueueOnUpdate\ p:1: reportStats {"c":{"sdk.admin_node.8-1-0":1}}

5:20:04.693 PM\ playerQueueOnUpdate\ p:1: connection ready

5:20:04.693 PM\ playerQueueOnUpdate\ c:1:1: Realtime connection established.

5:20:04.593 PM\ playerQueueOnUpdate\ c:1:1:0 Websocket connected.

5:20:04.397 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:04.397Z XE62C [Firestore.getAll_]: Received document: projects/chingo-club-fefcc/databases/(default)/documents/users/yXoz6vOlMjeqc3BZNfafWr8GPeu2

5:20:04.396 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:04.396Z XE62C [Firestore._initializeStream]: Releasing stream

5:20:04.396 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:04.396Z XE62C [Firestore.readStream]: Received response: {"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1560777597","nanos":633435000},"found":{"fields":{"lastSpin":{"nullValue":"NULL_VALUE","valueType":"nullValue"},"winChallanges":{"integerValue":"0","valueType":"integerValue"},"friends":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"enemiesKilledByYourTrap":{"integerValue":"0","valueType":"integerValue"},"winBattlesInARow":{"integerValue":"0","valueType":"integerValue"},"language":{"stringValue":"en","valueType":"stringValue"},"receivedGameRequests":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"winBattles":{"integerValue":"0","valueType":"integerValue"},"online":{"booleanValue":true,"valueType":"booleanValue"},"extraSpins":{"integerValue":"0","valueType":"integerValue"},"purchases":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"didWinLastTime":{"booleanValue":true,"valueType":"booleanValue"},"useShuffle":{"integerValue":"0","valueType":"integerValue"},"_displayNameSearch":{"stringValue":"bvnb","valueType":"stringValue"},"winDoubleChallanges":{"integerValue":"0","valueType":"integerValue"},"createdAt":{"timestampValue":{"seconds":"1560777581","nanos":341000000},"valueType":"timestampValue"},"displayName":{"stringValue":"bvnb","valueType":"stringValue"},"rating":{"integerValue":"0","valueType":"integerValue"},"winTripleChallanges":{"integerValue":"0","valueType":"integerValue"},"winBattlesInARowCurrent":{"integerValue":"0","valueType":"integerValue"},"notifications":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"receivedFriendRequests":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"xp":{"integerValue":"0","valueType":"integerValue"},"avatar":{"stringValue":"","valueType":"stringValue"},"uid":{"stringValue":"yXoz6vOlMjeqc3BZNfafWr8GPeu2","valueType":"stringValue"},"scissorsFlagKills":{"integerValue":"0","valueType":"integerValue"},"characters":{"arrayValue":{"values":[{"stringValue":"character-1","valueType":"stringValue"}]},"valueType":"arrayValue"},"points":{"integerValue":"100","valueType":"integerValue"},"notificationTokens":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"rockFlagKills":{"integerValue":"0","valueType":"integerValue"},"paperFlagKills":{"integerValue":"0","valueType":"integerValue"},"currentCharacter":{"stringValue":"character-1","valueType":"stringValue"},"sentGameRequests":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"killedByEnemyTrap":{"integerValue":"0","valueType":"integerValue"},"sentFriendRequests":{"arrayValue":{"values":[]},"valueType":"arrayValue"}},"name":"projects/chingo-club-fefcc/databases/(default)/documents/users/yXoz6vOlMjeqc3BZNfafWr8GPeu2","createTime":{"seconds":"1560777581","nanos":467115000},"updateTime":{"seconds":"1560777582","nanos":485610000}},"result":"found"}

5:20:03.694 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:03.694Z nPtTi [Firestore.getAll_]: Received document: projects/chingo-club-fefcc/databases/(default)/documents/users/CkHnKxRxbOcbZAqvCUe23AFd1FH2

5:20:02.797 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:02.797Z nPtTi [Firestore._initializeStream]: Releasing stream

5:20:02.593 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:20:02.593Z nPtTi [Firestore.readStream]: Received response: {"transaction":{"type":"Buffer","data":[]},"readTime":{"seconds":"1560777597","nanos":633991000},"found":{"fields":{"extraSpins":{"integerValue":"14","valueType":"integerValue"},"purchases":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"didWinLastTime":{"booleanValue":true,"valueType":"booleanValue"},"useShuffle":{"integerValue":"2","valueType":"integerValue"},"_displayNameSearch":{"stringValue":"bagratkirakosian","valueType":"stringValue"},"winDoubleChallanges":{"integerValue":"0","valueType":"integerValue"},"createdAt":{"timestampValue":{"seconds":"1560176691","nanos":647000000},"valueType":"timestampValue"},"displayName":{"stringValue":"Bagrat Kirakosian","valueType":"stringValue"},"rating":{"integerValue":"150","valueType":"integerValue"},"winTripleChallanges":{"integerValue":"0","valueType":"integerValue"},"winBattlesInARowCurrent":{"integerValue":"3","valueType":"integerValue"},"notifications":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"receivedFriendRequests":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"xp":{"integerValue":"1100","valueType":"integerValue"},"avatar":{"stringValue":"","valueType":"stringValue"},"uid":{"stringValue":"CkHnKxRxbOcbZAqvCUe23AFd1FH2","valueType":"stringValue"},"scissorsFlagKills":{"integerValue":"0","valueType":"integerValue"},"characters":{"arrayValue":{"values":[{"stringValue":"character-1","valueType":"stringValue"},{"stringValue":"character-3","valueType":"stringValue"}]},"valueType":"arrayValue"},"points":{"integerValue":"205","valueType":"integerValue"},"notificationTokens":{"arrayValue":{"values":[{"stringValue":"euBm_wZAbNY:APA91bFWRZVJPyg1IHkE2Zii9RilOmtjggCSj7JBW6Y1xlS6Es-xMgChcemmul1kaN9h0OeWS-rGhNmfmRS-cVtOjrvv0FtQ-z7AwHSNXHpoJRFA67FaWxBgHPuz2TgDD5zk-nItzmjd","valueType":"stringValue"},{"stringValue":"dsdBOUW8_-E:APA91bHp69V6YJmzyPAtdUs2whnCU-3_RPm3QH3gsqBthojGSwtlt5whRmlh2Qw5LRJA2vub1wwEXb1aQGM0pwvURX5Z831X0vg6gsHdCczmaCY35TPawlJzFlA_7tvVK5vnPL1LH3Om","valueType":"stringValue"}]},"valueType":"arrayValue"},"rockFlagKills":{"integerValue":"0","valueType":"integerValue"},"paperFlagKills":{"integerValue":"0","valueType":"integerValue"},"currentCharacter":{"stringValue":"character-1","valueType":"stringValue"},"sentGameRequests":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"killedByEnemyTrap":{"integerValue":"0","valueType":"integerValue"},"sentFriendRequests":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"lastSpin":{"timestampValue":{"seconds":"1560709100","nanos":839000000},"valueType":"timestampValue"},"winChallanges":{"integerValue":"0","valueType":"integerValue"},"friends":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"enemiesKilledByYourTrap":{"integerValue":"0","valueType":"integerValue"},"winBattlesInARow":{"doubleValue":3.5,"valueType":"doubleValue"},"language":{"stringValue":"en","valueType":"stringValue"},"receivedGameRequests":{"arrayValue":{"values":[]},"valueType":"arrayValue"},"winBattles":{"integerValue":"9","valueType":"integerValue"},"online":{"booleanValue":true,"valueType":"booleanValue"}},"name":"projects/chingo-club-fefcc/databases/(default)/documents/users/CkHnKxRxbOcbZAqvCUe23AFd1FH2","createTime":{"seconds":"1560176691","nanos":700007000},"updateTime":{"seconds":"1560777566","nanos":631651000}},"result":"found"}

5:19:53.906 PM\ playerQueueOnUpdate\ Function execution took 4861 ms, finished with status: 'ok'

5:19:53.812 PM\ playerQueueOnUpdate\ c:1:1:0 Websocket connecting to wss://s-usc1c-nss-230.firebaseio.com/.ws?v=5&ns=chingo-club-fefcc

5:19:53.809 PM\ playerQueueOnUpdate\ p:0: from server: {"r":6,"b":{"s":"ok","d":""}}

5:19:53.809 PM\ playerQueueOnUpdate\ c:1:1: Connection created

5:19:53.809 PM\ playerQueueOnUpdate\ getToken() completed. Creating connection.

5:19:53.809 PM\ playerQueueOnUpdate\ p:1: Auth token refreshed

5:19:53.801 PM\ playerQueueOnUpdate\ p:0: {"r":6,"a":"n","b":{"p":"/game/queue/player_queue"}}

5:19:53.801 PM\ playerQueueOnUpdate\ p:0: Unlisten on /game/queue/player_queue for default

5:19:53.801 PM\ playerQueueOnUpdate\ p:0: Unlisten called for /game/queue/player_queue default

5:19:53.798 PM\ playerQueueOnUpdate\ 0: transaction put response {"path":"/game/queue/player_queue","status":"ok"}

5:19:53.798 PM\ playerQueueOnUpdate\ p:0: p response {"s":"ok","d":null}

5:19:53.798 PM\ playerQueueOnUpdate\ p:0: from server: {"r":5,"b":{"s":"ok","d":null}}

5:19:53.798 PM\ playerQueueOnUpdate\ p:0: handleServerMessage d {"p":"game/queue/player_queue","d":null}

5:19:53.795 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:19:53.795Z XE62C [Firestore.readStream]: Sending request: {"database":"projects/chingo-club-fefcc/databases/(default)","documents":["projects/chingo-club-fefcc/databases/(default)/documents/users/yXoz6vOlMjeqc3BZNfafWr8GPeu2"]}

5:19:53.708 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:19:53.708Z nPtTi [Firestore.readStream]: Sending request: {"database":"projects/chingo-club-fefcc/databases/(default)","documents":["projects/chingo-club-fefcc/databases/(default)/documents/users/CkHnKxRxbOcbZAqvCUe23AFd1FH2"]}

5:19:53.707 PM\ playerQueueOnUpdate\ p:1: Making a connection attempt

5:19:53.701 PM\ playerQueueOnUpdate\ Firestore (2.2.1) 2019-06-17T13:19:53.700Z ##### [Firestore]: Initialized Firestore GAPIC Client

5:19:50.828 PM\ playerQueueOnUpdate\ p:0: {"r":5,"a":"p","b":{"p":"/game/queue/player_queue","d":null,"h":"/LAbxqqJ/qkTCZXVHz/EwIMp24M="}}

5:19:50.824 PM\ playerQueueOnUpdate\ Made firestore tasks in 0.0011047370000160299 seconds

5:19:50.822 PM\ playerQueueOnUpdate\ Created firestore instance in 0.7197552520000027 seconds

5:19:50.101 PM\ playerQueueOnUpdate\ Calling create game after 0.9876235969999688 seconds

5:19:49.047 PM playerQueueOnUpdate\ Function execution started

Were you able to successfully deploy your functions?

Yes, functions are deployed properly, no errors occured during deployment

[thechenky]

Hi @bagratkirakosian thank you for such a detailed report. I'm a bit stumped as to why you would be experiencing such drastic differences in cold/warm start times calling Firestore and Realtime Database. We recently rolled out gRPC-JS, even, which should have made gRPC initializations even faster (available in firebase-admin 8.0.0).

I'm wondering if this has to do with the transactions, which will run repeatedly if there was a new value written to the database before your transaction succeeded: https://firebase.google.com/docs/database/web/read-and-write#save_data_as_transactions. This would explain how at certain times the same operation may take much longer. Are you able to remove the transaction just to test to see if this problem still occurs?

[bagratkirakosian]

Hi @thechenky very grateful for such a quick response. The latency is very strange for me as well, especially that it happens with both Firestore and Realtime Database.

I am familiar that the transaction can be called multiple times, but I don't think it can be the cause of latency in database operations. Even if the transaction is called multiple times, it will just run the functions in transaction block multiple times without any hold because I didn’t use await for them. As per your suggestion I removed transaction still nothing was really changed.

Is gRPC-JS only responsible for Firestore connections? When I enabled Firestore logging I saw this line [Firestore]: Initialized Firestore GAPIC Client which I assume means that gRPC initializations are done because right after that it sends the read request [Firestore.readStream]: Sending request and ~10 seconds later it just receives [Firestore.getAll_]: Received document. I believe 10 seconds is a really long time from a read operation to the response of it. Indexation can't be a problem as well because we have ~600 user records and the query is just getting document by id firestore.collection('users').doc(playerId).get().

Updating to firebase-admin 8.0.0 is done recently but I hope that after firebase deploy it also updated dependancies on firebase. Is there any other logging I can enable to get more details? Please let me know what extra information I can provide to progress.

[thechenky]

@bagratkirakosian this is rather difficult to debug since there is a lot going on in your functions :) are you able to reproduce this behavior consistently with a much simpler function? I would be curious to see whether you see the same behavior with this:

export const myFunc = function.database.ref('game/queue/player_queue').onUpdate(async (change: functions.Change<functions.database.DataSnapshot>, context: functions.EventContext) => {
  // something like this to call firestore to get the document:
  console.log("Started call to Firestore"); 
  firestore.collection('users').doc(playerOneKey).get();
  console.log("Ended call to Firestore"); 

  // something like this to call RTDB to set path:
  console.log("Started call to RTDB");
  database.ref('some/test/path').set('test');
  console.log("Ended call to RTDB"); 
}

[thechenky]

Also make sure that Firestore and your functions are in the same region (or a region close by) as this can add a lot of latency if they're far apart. Additionally, Firestore triggers are in beta and looks like they can take up to 10s to trigger according to this documentation.

[bagratkirakosian]

@thechenky much thanks for your willingness to help! I understand as well that the issue is a complicated case so I am trying to get as much information to the discussion as possible.

this is rather difficult to debug since there is a lot going on in your functions :) are you able to reproduce this behavior consistently with a much simpler function? I would be curious to see whether you see the same behavior with this:

I gave it a try to make a smaller version of the function as you suggested but can't reproduce the same behavior yet. I think something else is the cause, so I will try to make closer replica of the function that mirrors the same steps in a simpler way. One of the main differences in replica and original flow so far is the file structure. Just noticed that in original case database listener and create service are in two different files, do you think this can somehow be an issue? Will test this case too.

Also make sure that Firestore and your functions are in the same region (or a region close by) as this can add a lot of latency if they're far apart. Additionally, Firestore triggers are in beta and looks like they can take up to 10s to trigger according to this documentation.

Under Project Settings Google Cloud Platform (GCP) resource location is nam5 (us-central) and under the Functions Dashboard all functions' Region are us-central1. Looking at the list of regions I think those two are the same location, though it says multi-region. If the regions are the case, the latency will be always rather than only on cold start, right? In this case we use only Realtime Database triggers not Firestore triggers so that's not the case I guess. The issue appears after the trigger is fired and the service function is called. Similar ~10 second latency appears in firestore.get() operation. Also I saw that RTDB .set() call is ~5 seconds which is pretty slow too because usually they are less than a second. I will also try to narrow down this case as much as possible.

[thechenky]

@bagratkirakosian thanks for confirming the regions (yep, they are both in the same region)! You're right that this should impact both warm and cold starts but I just wanted to ensure regionality is not adding to this issue. Thank you for your efforts in trying to reproduce with a simpler use case, this would make it much easier for us to debug :) The function being in different files should not have any impact because all functions are uploaded together in one bundle on firebase deploy. Btw, you can see the source that is uploaded in the cloud console functions page. I'm still skeptical of the transaction - I think it may be messing with the timing in some way - are you able to replicate this behavior in the simple use case if you add a transaction to it?

[bagratkirakosian]

@thechenky thanks for the clarification. I had the doubts too that transaction can be the problem so in the quick example I added it the same way as I used before but it didn’t reproduce the time issue. I will definitely try to make simple one to one replica as soon as I can get my hands on it.

Btw, you can see the source that is uploaded in the cloud console functions page.

This is nice, never found a way how can I see the deployed code for the specific function. Any hint how I can see that? Is it being deployed taking in count the dependancies of files or the dependencies are just being resolved at the runtime?

[thechenky]

@bagratkirakosian interesting that the transaction does not surface the issue - I'm very stumped as to what may be going on here. If we are not able to solve your issue here, we would need to direct you to Cloud Support, where they can really dig into your project and see all the logs of what's happening.

For the source in cloud console, yeah its a bit hidden and I think it may only show your source if it's not too big. To get to it, navigate to the cloud console > Cloud Functions > click on the function > click on Source

Source will not include the dependencies as those are pulled in during the build step so this should show only your source. Also, you can download the zip of the source if you scroll all the way down after clicking on Source. Does this help?

[google-oss-bot]

Hey @bagratkirakosian. We need more information to resolve this issue but there hasn't been an update in 7 days. I'm marking the issue as stale and if there are no new updates in the next 3 days I will close it automatically.

If you have more information that will help us get to the bottom of this, just add a comment!

[google-oss-bot]

Since there haven't been any recent updates here, I am going to close this issue.

@bagratkirakosian if you're still experiencing this problem and want to continue the discussion just leave a comment here and we are happy to re-open this.