Re-use runtime workers #1733

samtstern · 2019-10-17T23:46:35Z

Description

New architecture:

The functions emulator manages a RuntimeWorkerPool full of RuntimeWorkers. These wrap an instance of FunctionsRuntimeInstance which were previously launched as one-time-use.

A RuntimeWorker listens for important changes within the FunctionsRuntimeInstance and summarizes them into a state. This worker is also responsible for sending IPC messages to the child process.

A RuntimeWorker has four possible states:

IDLE - ready to receive a request.
BUSY - currently executing a request.
FINISHING - BUSY but will never return to IDLE. Basically "die when you're done please".
FINISHED - the process is dead. Will never be revived, this worker is trash now.

Within the runtime I changed the execution flow. The main() function only does the trigger discovery and stubbing at first. Then it listens for an IPC message telling it to run a function. This message handler can support mutliple invocations as long as the function doesn't experience any unhandled errors.

Scenarios Tested

All scenarios use this test code:

const functions = require('firebase-functions');
const admin = require('firebase-admin');
admin.initializeApp();

console.log("Code Reloaded:", new Date());

exports.simpleFunction = functions.https.onRequest(async (req, res) => {
    console.log('simpleFunction');
    res.json({ name: 'simpleFunction', date: new Date() });
});

exports.slowFunction = functions.https.onRequest(async (req, res) => {
    console.log('slowFunction');
    setTimeout(() => {
        res.json({ name: 'slowFunction', date: new Date() });
    }, 5000);
});

exports.functionThatSometimesThrows = functions.https.onRequest(async (req, res) => {
    console.log('functionThatSometimesThrows');
    const rand = Math.random();
    if (rand <= 0.33) {
        throw new Error('Ooops I did a bad thing!');
    }

    res.json({ name: 'functionThatSometimesThrows', date: new Date() });
});

exports.firestoreWriter = functions.https.onRequest(async (req, res) => {
    console.log('firestoreWriter');
    await admin.firestore().doc('/foo/bar').set({ date: new Date() });
    console.log(`Wrote to /foo/bar`);
    res.json({ name: 'firestoreWriter', date: new Date() });
});

exports.firestoreReader = functions.firestore.document('/foo/bar').onWrite(async (change, ctx) => {
    console.log('firestoreReader');
    console.log(`Detected change at ${change.after.ref.path}`);
    return true;
});

Repeated execution, same code
Notice the code above the function definition is only executed one time.

>  Code Reloaded: 2019-10-18T22:12:27.050Z
i  functions: Beginning execution of "simpleFunction"
>  simpleFunction
i  functions: Finished "simpleFunction" in ~1s
i  functions: Beginning execution of "simpleFunction"
>  simpleFunction
i  functions: Finished "simpleFunction" in ~1s
i  functions: Beginning execution of "simpleFunction"
>  simpleFunction
i  functions: Finished "simpleFunction" in ~1s

Repeated execution with a code change in the middle
Notice that the code reloads and then the console.log is different. Unfortunately we need to do two reloads of the code after a file save: one "diagnostic" to do trigger discovery and then a second one to actually run the function for the first time.

>  Code Reloaded: 2019-10-18T22:12:59.143Z
i  functions: Beginning execution of "simpleFunction"
>  simpleFunction
i  functions: Finished "simpleFunction" in ~1s
>  Code Reloaded: 2019-10-18T22:13:06.256Z
>  Code Reloaded: 2019-10-18T22:13:11.251Z
i  functions: Beginning execution of "simpleFunction"
>  simpleFunction - xxx
i  functions: Finished "simpleFunction" in ~1s
i  functions: Beginning execution of "simpleFunction"
>  simpleFunction - xxx
i  functions: Finished "simpleFunction" in ~1s
i  functions: Beginning execution of "simpleFunction"
>  simpleFunction - xxx
i  functions: Finished "simpleFunction" in ~1s

Function that sometimes throws errors
This test is meant to show how an error thrown in a function will cause the worker to be discarded.

>  Code Reloaded: 2019-10-18T22:15:04.667Z
i  functions: Beginning execution of "functionThatSometimesThrows"
>  functionThatSometimesThrows
i  functions: Finished "functionThatSometimesThrows" in ~1s
i  functions: Beginning execution of "functionThatSometimesThrows"
>  functionThatSometimesThrows
⚠  functions: Error: Ooops I did a bad thing!
    at exports.functionThatSometimesThrows.functions.https.onRequest (/tmp/tmp.e4vfaKijHH/functions/index.js:23:15)
    at Run (/usr/local/google/home/samstern/Projects/firebase/firebase-tools/lib/emulator/functionsEmulatorRuntime.js:612:20)
    at /usr/local/google/home/samstern/Projects/firebase/firebase-tools/lib/emulator/functionsEmulatorRuntime.js:586:19
    at Generator.next (<anonymous>)
    at /usr/local/google/home/samstern/Projects/firebase/firebase-tools/lib/emulator/functionsEmulatorRuntime.js:7:71
    at new Promise (<anonymous>)
    at __awaiter (/usr/local/google/home/samstern/Projects/firebase/firebase-tools/lib/emulator/functionsEmulatorRuntime.js:3:12)
    at Run (/usr/local/google/home/samstern/Projects/firebase/firebase-tools/lib/emulator/functionsEmulatorRuntime.js:579:12)
    at /usr/local/google/home/samstern/Projects/firebase/firebase-tools/lib/emulator/functionsEmulatorRuntime.js:611:15
    at Generator.next (<anonymous>)
⚠  Your function was killed because it raised an unhandled error.
>  Code Reloaded: 2019-10-18T22:15:11.150Z
i  functions: Beginning execution of "functionThatSometimesThrows"
>  functionThatSometimesThrows
i  functions: Finished "functionThatSometimesThrows" in ~1s

Slow Function
Here I call the same function twice before the first one finishes, which means that we need a second worker (scale up) and therefore the globals are loaded twice. However a third invocation that waits for one to finish re-uses an existing idling worker.

>  Code Reloaded: 2019-10-18T22:16:57.435Z
i  functions: Beginning execution of "slowFunction"
>  slowFunction
>  Code Reloaded: 2019-10-18T22:16:58.933Z
i  functions: Beginning execution of "slowFunction"
>  slowFunction
i  functions: Finished "slowFunction" in ~5s
i  functions: Finished "slowFunction" in ~5s
i  functions: Beginning execution of "slowFunction"
>  slowFunction
i  functions: Finished "slowFunction" in ~5s

Background Triggers
Just to show that this all works for non-HTTP triggers. Each separate trigger has its own worker pool so running this chain twice causes two code reloads (would be 4 in the old system).

>  Code Reloaded: 2019-10-18T22:18:10.268Z
i  functions: Beginning execution of "firestoreWriter"
>  firestoreWriter
>  Wrote to /foo/bar
i  functions: Finished "firestoreWriter" in ~1s
>  Code Reloaded: 2019-10-18T22:18:11.060Z
i  functions: Beginning execution of "firestoreReader"
>  firestoreReader
>  Detected change at foo/bar
i  functions: Finished "firestoreReader" in ~1s
i  functions: Beginning execution of "firestoreWriter"
>  firestoreWriter
>  Wrote to /foo/bar
i  functions: Beginning execution of "firestoreReader"
>  firestoreReader
>  Detected change at foo/bar
i  functions: Finished "firestoreReader" in ~1s
i  functions: Finished "firestoreWriter" in ~1s

Sample Commands

N/A

coveralls · 2019-10-17T23:52:30Z

Coverage increased (+1.0%) to 66.197% when pulling 0d27e12 on ss-runtime-workers into c9019ff on master.

src/emulator/functionsEmulator.ts

src/emulator/functionsEmulatorRuntime.ts

bkendall · 2019-10-21T17:57:58Z

src/emulator/functionsRuntimeWorker.ts

+    });
+  }
+
+  getIdleWorker(triggerId: string | undefined): RuntimeWorker | undefined {


why does this accept undefined? I think I can see the use of returning undefined, but I don't see any use case in your code of accepting undefined...

FunctionsRuntimeBundle has triggerId?: string. A bundle with no triggerId means "I want to run the runtime but no function in particular. It's used to diagnose the user environment.

src/emulator/functionsRuntimeWorker.ts

src/emulator/functionsEmulator.ts

src/emulator/functionsRuntimeWorker.ts

yuchenshi

Mostly LGTM with a few comments.

yuchenshi · 2019-10-21T23:54:39Z

src/emulator/functionsEmulator.ts

-      // this log entry to happen during the readying.
-      const triggerLogPromise = waitForLog(runtime.events, "SYSTEM", "triggers-parsed");
-
+      // TODO(samstern): Is this a race condition?  Could 'ready' happen before we're listening for it?


It's not a race condition right now since we attach the listener synchronously but it's super hard to tell until you go and inspect the code. If we use observables, I'd suggest BehaviorSubject for the state so we don't have to do this. Otherwise, please make the worker expose a promise like worker.ready and use the listener in the worker constructor to maintain it, so we keep the concern local and easy to reason about. In fact, I may suggest to drop the waitForSystemLog and just expose promises for anything we want to listen to.

Ok this sounds like a big (but good) change so I need your help unpacking it:

What is BehaviorSubject?

What do you mean "use the listener in the worker constructor to maintain it"?

In fact, I may suggest to drop the waitForSystemLog and just expose promises for anything we want to listen to. --> waitForSystemLog waits for the next log of a certain type so a promise isn't a suitable replacement

Also since I see you approved: do you think these improvements should be made in this PR or should they be future improvements?

First, the improvements can totally be done in a separate PR, and I approve this PR as-is. The log race condition issue is not the focus here and we can address that later.

I was suggesting BehaviorSubject from rxjs, but since we don't actually use Observables, I'd drop that idea since I don't want more things that we need to keep in mind when navigating the code base.

In details, I'd suggest that we keep the logic to wait on logs within FunctionsRuntimeInstance. In addition to .exit, it should also expose .ready and .triggerParsed, both promises. The promises themselves can of course be driven by logs, but we should not call waitForLog outside FunctionsRuntimeInstance. If we need more waits, we should expose each as a promise. In this way, we don't need to reason about the ordering outside.

👍 that makes sense, thanks for the explanation! Will do those as a follow-up.

src/emulator/functionsRuntimeWorker.ts

lookfirst · 2019-10-25T01:27:43Z

Just curious, why not implement the nodejs cluster api?

samtstern · 2019-10-25T16:40:22Z

@lookfirst in our case the "hub" and the runtime process need to be totally separate environments. In the runtime processes we need to be able to have a separate require cache, mock out libraries, etc. As far as I know this is not possible with cluser.

samtstern added 3 commits October 17, 2019 15:12

Move args to IPC, set up new system

0e06efd

Ok it's kinda working now

62ce3b6

ITS ALIVEEEE

52462e2

googlebot added the cla: yes Manual indication that this has passed CLA. label Oct 17, 2019

samtstern mentioned this pull request Oct 17, 2019

code reloads on every request in 6.10.0 #1353

Closed

samtstern added 5 commits October 17, 2019 17:02

Fix small bug

9b15afa

Start cleaning things up

f5970ac

Clean up

8c23442

More tests passing now

1815297

All tests pass!

7234783

samtstern mentioned this pull request Oct 18, 2019

[WIP] Functions work queue #1725

Closed

3 tasks

samtstern added 5 commits October 18, 2019 10:52

Code reloading, logging, etc

4d5efe4

Kill all workers on exit

49eb4f4

Merge branch 'master' into ss-runtime-workers

b3e835b

Clear remaining TODOs

5dc377b

Unit tests for workers

d55bd4d

samtstern requested review from abeisgoat and yuchenshi October 18, 2019 22:18

samtstern changed the title ~~[WIP] Re-use runtime workers~~ Re-use runtime workers Oct 18, 2019

samtstern requested a review from ryanpbrewster October 18, 2019 22:19

Fix logging and listener leak

1594840

bkendall reviewed Oct 21, 2019

View reviewed changes

samtstern added 2 commits October 22, 2019 11:30

Rename functions

77c3926

Sync message handling

b1786a1

ryanpbrewster reviewed Oct 22, 2019

View reviewed changes

src/emulator/functionsEmulator.ts Outdated Show resolved Hide resolved

src/emulator/functionsRuntimeWorker.ts Outdated Show resolved Hide resolved

Ryan's review comments

d521c8c

yuchenshi approved these changes Oct 22, 2019

View reviewed changes

samtstern added 2 commits October 23, 2019 17:41

Migrate to real Map

a87fa06

Merge branch 'master' into ss-runtime-workers

0ce5de6

samtstern requested a review from yuchenshi October 24, 2019 00:44

Fix test

21b3d6e

yuchenshi reviewed Oct 24, 2019

View reviewed changes

src/emulator/functionsRuntimeWorker.ts Outdated Show resolved Hide resolved

Fix nit

0d27e12

abeisgoat approved these changes Oct 28, 2019

View reviewed changes

samtstern merged commit 2487823 into master Oct 28, 2019

samtstern mentioned this pull request Nov 8, 2019

Follow up to RuntimeWorkers change #1778

Merged

samtstern deleted the ss-runtime-workers branch November 14, 2019 21:47

This was referenced Apr 7, 2022

[Snyk] Fix for 1 vulnerabilities Jeremip11/firebase-tools#19

Open

[Snyk] Security upgrade winston from 3.2.1 to 3.3.0 XirdigH/firebase-tools#39

Open

[Snyk] Security upgrade winston from 3.2.1 to 3.3.0 Manny27nyc/firebase-tools#23

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Re-use runtime workers #1733

Re-use runtime workers #1733

samtstern commented Oct 17, 2019 •

edited

Loading

coveralls commented Oct 17, 2019 •

edited

Loading

bkendall Oct 21, 2019

samtstern Oct 22, 2019

yuchenshi left a comment

yuchenshi Oct 21, 2019

samtstern Oct 24, 2019 •

edited

Loading

samtstern Oct 24, 2019

yuchenshi Oct 24, 2019

samtstern Oct 24, 2019

lookfirst commented Oct 25, 2019

samtstern commented Oct 25, 2019

Re-use runtime workers #1733

Re-use runtime workers #1733

Conversation

samtstern commented Oct 17, 2019 • edited Loading

Description

Scenarios Tested

Sample Commands

coveralls commented Oct 17, 2019 • edited Loading

bkendall Oct 21, 2019

Choose a reason for hiding this comment

samtstern Oct 22, 2019

Choose a reason for hiding this comment

yuchenshi left a comment

Choose a reason for hiding this comment

yuchenshi Oct 21, 2019

Choose a reason for hiding this comment

samtstern Oct 24, 2019 • edited Loading

Choose a reason for hiding this comment

samtstern Oct 24, 2019

Choose a reason for hiding this comment

yuchenshi Oct 24, 2019

Choose a reason for hiding this comment

samtstern Oct 24, 2019

Choose a reason for hiding this comment

lookfirst commented Oct 25, 2019

samtstern commented Oct 25, 2019

samtstern commented Oct 17, 2019 •

edited

Loading

coveralls commented Oct 17, 2019 •

edited

Loading

samtstern Oct 24, 2019 •

edited

Loading