Firebase-admin unpredictable read times

I have a Firebase database that clients access via a REST API run on node.js, which then reads from my firebase database using the firebase-admin node client. For most of my endpoints, several concurrent database reads are required. For example, for the api/item/:itemKey endpoint, I need to pull the item from the database, then, once that has been received, I concurrently ask for all of the nested spec, panel, query and task objects associated with the retrieved item. This makes for two consecutive "waves" of database calls: the first item retrieval, and then the retrieval of all resources nested within that item.

The problem is that the latency on these calls is wildly unpredictable. For example, here are the logs for two consecutive calls to the same endpoint, done within 5 seconds of each other:

// START REQUEST 1
Endpoint activated (invocation #: 18) ("GET /api/items/:itemKey")
Firebase items READ Success ("id: -LDhjV8Hkievzbh5UVfz"): 78ms
Firebase specs READ Success ("id: -LDIezNhwWX8OmoWXZO3"): 72ms
Firebase specs READ Success ("id: -LDIezNqbVuvkpr9WEf8"): 73ms
Firebase panels READ Success ("id: -LDhjV5y1mAwPmJkE4d3"): 74ms
Firebase queries READ Success ("id: -LDhjV34aJlz_XFwOp6B"): 69ms
Firebase queries READ Success ("id: -LDhjV3QO1AM9UiCVdux"): 71ms
Firebase tasks READ Success ("id: -LDhjV34aJlz_XFwOp6C"): 71ms
Firebase tasks READ Success ("id: -LDhjV3QO1AM9UiCVduy"): 72ms
Endpoint resolution ("GET /api/items/:itemKey"): 305ms
// END REQUEST 1

// START REQUEST 2
Endpoint activated (invocation #: 19) ("GET /api/items/:itemKey")
Firebase items READ Success ("id: -LDhjV8Hkievzbh5UVfz"): 1174ms
Firebase specs READ Success ("id: -LDIezNhwWX8OmoWXZO3"): 1463ms
Firebase specs READ Success ("id: -LDIezNqbVuvkpr9WEf8"): 1463ms
Firebase panels READ Success ("id: -LDhjV5y1mAwPmJkE4d3"): 1464ms
Firebase queries READ Success ("id: -LDhjV34aJlz_XFwOp6B"): 312ms
Firebase queries READ Success ("id: -LDhjV3QO1AM9UiCVdux"): 312ms
Firebase tasks READ Success ("id: -LDhjV34aJlz_XFwOp6C"): 65ms
Firebase tasks READ Success ("id: -LDhjV3QO1AM9UiCVduy"): 65ms
Endpoint resolution ("GET /api/items/:itemKey"): 3032ms
// END REQUEST 2

As you can see, some of the reads on endpoint 2 are more than a second slower than the identical reads from the exact same invocation just a few seconds prior (ex: the first "items" read takes 1174ms vs 78ms!). What could be the cause of this? I've checked to make sure that firebase-admin is not dropping the socket connection in between calls, so I don't think that's the culprit, but otherwise I am out of ideas.

For completeness, here is the function I use to retrieve records from the database:

// Fetch the item in the database that matches a given Firebase id
module.exports = function whenFetchedViaId(table, id, req) {
    const timer = req.log ? req.log.timer() : () => {};

    return req.database
        .ref(`/${table}/${id}`)
        .once('value')
        .then((snapshot) => {
            timer(`Firebase ${table} READ Success`, `id: ${id}`);

            return snapshot.val();
        })
        .catch((error) => {
            timer(`Firebase ${table} READ Failure`, `id: ${id}`);

            throw error;
        });
};

Update

Here is some added logging for one of the READ calls that is taking >1s. Unless I am misreading this log output, it seems like the Firebase backend is just taking over a second to respond. Is this correct?

// START REQUEST
Request ("6ee776c5-2b4e-4888-b83b-ea6dddcae263"), Endpoint activated (invocation #: 4) ("GET /api/items/:itemKey")
[FIREBASE]{96328ms} p:1: Listen called for /items/-LDhjV8Hkievzbh5UVfz default
[FIREBASE]{96328ms} p:1: Listen on /items/-LDhjV8Hkievzbh5UVfz for default
[FIREBASE]{96328ms} p:1: {"r":42,"a":"q","b":{"p":"/items/-LDhjV8Hkievzbh5UVfz","h":""}}
[FIREBASE]{97842ms} p:1: handleServerMessage d {"p":"items/-LDhjV8Hkievzbh5UVfz","d":{"baseSpec":"-LDIezNhwWX8OmoWXZO3","createdAt":1527628300934,"id":"-LDhjV8Hkievzbh5UVfz","label":"Testing","panels":{"-LDhjV5y1mAwPmJkE4d3":true},"targetSpec":"-LDIezNqbVuvkpr9WEf8","x":{"-LD8Ap4ujTBp_GP5jTv9":true},"y":{"-LD89GHnTYjh99W8ltsY":true}}}
[FIREBASE]{97843ms} event: /items/-LDhjV8Hkievzbh5UVfz:value:{"baseSpec":"-LDIezNhwWX8OmoWXZO3","createdAt":1527628300934,"id":"-LDhjV8Hkievzbh5UVfz","label":"Testing","panels":{"-LDhjV5y1mAwPmJkE4d3":true},"targetSpec":"-LDIezNqbVuvkpr9WEf8","x":{"-LD8Ap4ujTBp_GP5jTv9":true},"y":{"-LD89GHnTYjh99W8ltsY":true}}
[FIREBASE]{97843ms} p:1: Unlisten called for /items/-LDhjV8Hkievzbh5UVfz default
[FIREBASE]{97843ms} p:1: Unlisten on /items/-LDhjV8Hkievzbh5UVfz for default
[FIREBASE]{97843ms} p:1: {"r":43,"a":"n","b":{"p":"/items/-LDhjV8Hkievzbh5UVfz"}}
[FIREBASE]{97844ms} p:1: from server: {"r":42,"b":{"s":"ok","d":{}}}
Request ("6ee776c5-2b4e-4888-b83b-ea6dddcae263"), Firebase items READ Success ("id: -LDhjV8Hkievzbh5UVfz"): 1516ms

Update

Recommended topics

Hot tags