Azure Functions の Node Language Worker の同時実行を理解する

# はじめに
Azure Functions Node Language Worker における、関数の同時実行による影響を動かして確認します。

コードサンプルは↓

https://github.com/georgeOsdDev/node-blocking-demo

以下のような 3 つの関数を用意します。

## TimerTrigger1

1秒毎にログ出力をおこない10秒で完了する関数
スケジュールは `"0 */1 * * * *"` とし、毎分 0 秒に開始されるように構成する。

```javascript:TimerTrigger1
module.exports = async function (context, myTimer) {
    context.log(`[Timer1 start] PID:${process.pid}, InvocationId:${context.invocationId}, ${new Date().toISOString()}`);
    let loop = async () => {
        return new Promise((resolve) => {
            let i = 1;
            let timer = setInterval(() => {
                context.log(`Loop of PID:${process.pid}, InvocationId:${context.invocationId}, ${i}, ${new Date().toISOString()}`)
                if (i >= 10) {
                    clearTimeout(timer);
                    resolve();
                } else {
                    i++;
                }
            }, 1000);
        })
    }
    await loop();
    context.log(`[Timer1 end]: PID:${process.pid}, InvocationId:${context.invocationId}, ${new Date().toISOString()}`);
};
```

## TimerTrigger2
`fs`(`fs-extra`)のsync関数を利用して 3000 ファイルをコピーする
スケジュールは `"5 */3 * * * *"` とし、3分毎に 5 秒に開始されるように構成する。


```javascript:TimerTrigger2
const fs = require('fs-extra');
const FROM_DIR = "./dummyDataFrom";
const TO_DIR = "./dummyDataTo";
module.exports = async function (context, myTimer) {
    context.log(`[Timer2(blocking) start] PID:${process.pid}, InvocationId:${context.invocationId}, ${new Date().toISOString()}`);
    const directories = fs.readdirSync(FROM_DIR);
    let coppied=0;
    for (const dir of directories) {
        const stat = fs.statSync(`${FROM_DIR}/${dir}`);
        if (stat.isDirectory()){
            const files = fs.readdirSync(`${FROM_DIR}/${dir}`);
            for (const file of files) {
                const stat2 = fs.statSync(`${FROM_DIR}/${dir}/${file}`);
                if (!stat2.isDirectory()) {
                    try {
                        fs.copySync(`${FROM_DIR}/${dir}/${file}`, `${TO_DIR}/${dir}/${file}`, { preserveTimestamps: true });
                        coppied++;
                    } catch (err) {
                        context.log.error('[Timer2]copySync', err);
                      }
                }
                // context.log(`[Timer2] PID:${process.pid}, InvocationId:${context.invocationId}, ${FROM_DIR}/${dir}/${file}, ${stat2}, ${new Date().toISOString()}`);
            }
        }
    }
    context.log(`[Timer2(blocking) end] PID:${process.pid}, InvocationId:${context.invocationId}, ${coppied}, ${new Date().toISOString()}`);
};
```

## TimerTrigger3
`fs`(`fs-extra`)のasync関数を利用して 3000 ファイルをコピーする
スケジュールは `"5 */5 * * * *"` とし、5分毎に 5 秒に開始されるように構成する。


```javascript:TimerTrigger3
const fs = require('fs-extra');
const FROM_DIR = "./dummyDataFrom";
const TO_DIR = "./dummyDataTo";
module.exports = async function (context, myTimer) {
    context.log(`[Timer3(Non blocking) start] PID:${process.pid}, InvocationId:${context.invocationId}, ${new Date().toISOString()}`);
    const directories = await fs.readdir(FROM_DIR);
    let coppied =0;
    for (const dir of directories) {
        const stat = await fs.stat(`${FROM_DIR}/${dir}`);
        if (stat.isDirectory()){
            const files = await fs.readdir(`${FROM_DIR}/${dir}`);
            for (const file of files) {
                const stat2 = await fs.stat(`${FROM_DIR}/${dir}/${file}`);
                if (!stat2.isDirectory()) {
                    try {
                        await fs.copy(`${FROM_DIR}/${dir}/${file}`, `${TO_DIR}/${dir}/${file}`, { preserveTimestamps: true });
                        coppied++;
                      } catch (err) {
                        context.log.error('[Timer3]copy', err);
                      }
                }
                // context.log(`[Timer3] PID:${process.pid}, InvocationId:${context.invocationId}, ${FROM_DIR}/${dir}/${file}, ${stat2}, ${new Date().toISOString()}`);
            }
        }
    }
    context.log(`[Timer3(Non blocking) end] PID:${process.pid}, InvocationId:${context.invocationId}, ${coppied}, ${new Date().toISOString()}`);
};
```

# FUNCTIONS_WORKER_PROCESS_COUNT を変えてみる

FUNCTIONS_WORKER_PROCESS_COUNT は、Azure Functions が関数を実行する Language Worker のプロセス数を制御するアプリケーション設定となります。
デフォルト値は 1 となり、すなわち 1 つの Node プロセスで全ての関数が実行されることになります。

https://learn.microsoft.com/ja-jp/azure/azure-functions/functions-app-settings#functions_worker_process_count

https://learn.microsoft.com/ja-jp/azure/azure-functions/functions-reference-node?tabs=javascript%2Cwindows-setting-the-node-version&pivots=nodejs-model-v3#scaling-and-concurrency

> ほとんどの Node.js アプリケーションでは、このスケーリング動作で十分です。 CPUにバインドされたアプリケーションの場合、複数の言語ワーカープロセスを使用して、パフォーマンスをさらに向上させることができます。 FUNCTIONS_WORKER_PROCESS_COUNT アプリケーション設定を使用して、ホストあたりのワーカー プロセスの数を既定の 1 から最大 10 まで増やすことができます。 次に、Azure Functions は、これらのワーカー間で同時関数呼び出しを均等に分散しようとします。 この動作により、CPU を集中的に使用する関数が、他の関数の実行をブロックする可能性が低くなります。 この設定は、需要に合わせてアプリケーションをスケールアウトするときに Azure Functions が作成する各ホストに適用されます。

## FUNCTIONS_WORKER_PROCESS_COUNT = 1 の場合

### `TimeTrigger1` 単独で実行されるとき

想定通り 10 秒で関数の実行が完了します。

```
[2023-05-16T11:46:00.006Z] Executing 'Functions.TimerTrigger1' (Reason='Timer fired at 2023-05-16T11:46:00.0058799+00:00', Id=60f8da82-2ac9-4dc2-9cd7-907dd3f2627c)
[2023-05-16T11:46:00.019Z] [Timer1 start] PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 2023-05-16T11:46:00.014Z
[2023-05-16T11:46:01.020Z] Loop of PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 1, 2023-05-16T11:46:01.017Z
[2023-05-16T11:46:02.022Z] Loop of PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 2, 2023-05-16T11:46:02.019Z
[2023-05-16T11:46:03.026Z] Loop of PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 3, 2023-05-16T11:46:03.021Z
[2023-05-16T11:46:04.028Z] Loop of PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 4, 2023-05-16T11:46:04.026Z
[2023-05-16T11:46:05.029Z] Loop of PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 5, 2023-05-16T11:46:05.028Z
[2023-05-16T11:46:06.032Z] Loop of PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 6, 2023-05-16T11:46:06.030Z
[2023-05-16T11:46:07.037Z] Loop of PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 7, 2023-05-16T11:46:07.035Z
[2023-05-16T11:46:08.044Z] Loop of PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 8, 2023-05-16T11:46:08.042Z
[2023-05-16T11:46:09.046Z] Loop of PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 9, 2023-05-16T11:46:09.044Z
[2023-05-16T11:46:10.052Z] Loop of PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 10, 2023-05-16T11:46:10.050Z
[2023-05-16T11:46:10.053Z] [Timer1 end]: PID:14731, InvocationId:60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, 2023-05-16T11:46:10.050Z
[2023-05-16T11:46:10.055Z] Executed 'Functions.TimerTrigger1' (Succeeded, Id=60f8da82-2ac9-4dc2-9cd7-907dd3f2627c, Duration=10049ms)
```

### `TimeTrigger1` と `TimerTrigger2` が同時に動作するとき

`TimerTrigger2` が動作中に `TimeTrigger1` の動作に遅延が発生します。

```
[2023-05-16T11:47:10.059Z] Executed 'Functions.TimerTrigger1' (Succeeded, Id=256f7d58-cd05-4895-bc8b-3688cdce0f27, Duration=10051ms)
[2023-05-16T11:48:00.000Z] Executing 'Functions.TimerTrigger1' (Reason='Timer fired at 2023-05-16T11:47:59.9982551+00:00', Id=5427d7cd-35c3-412b-bfcb-56a5a9818172)
[2023-05-16T11:48:00.012Z] [Timer1 start] PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 2023-05-16T11:48:00.009Z
[2023-05-16T11:48:01.014Z] Loop of PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 1, 2023-05-16T11:48:01.010Z
[2023-05-16T11:48:02.017Z] Loop of PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 2, 2023-05-16T11:48:02.015Z
[2023-05-16T11:48:03.021Z] Loop of PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 3, 2023-05-16T11:48:03.019Z
[2023-05-16T11:48:04.029Z] Loop of PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 4, 2023-05-16T11:48:04.026Z
[2023-05-16T11:48:04.999Z] Executing 'Functions.TimerTrigger2' (Reason='Timer fired at 2023-05-16T11:48:04.9988867+00:00', Id=f7fe22e9-9950-41a2-af6d-368a28bb408b)
[2023-05-16T11:48:06.083Z] [Timer2(blocking) start] PID:14731, InvocationId:f7fe22e9-9950-41a2-af6d-368a28bb408b, 2023-05-16T11:48:05.003Z
[2023-05-16T11:48:06.084Z] [Timer2(blocking) end] PID:14731, InvocationId:f7fe22e9-9950-41a2-af6d-368a28bb408b, 3000, 2023-05-16T11:48:06.082Z
[2023-05-16T11:48:06.085Z] Executed 'Functions.TimerTrigger2' (Succeeded, Id=f7fe22e9-9950-41a2-af6d-368a28bb408b, Duration=1086ms)
[2023-05-16T11:48:06.085Z] Loop of PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 5, 2023-05-16T11:48:06.083Z
[2023-05-16T11:48:07.085Z] Loop of PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 6, 2023-05-16T11:48:07.084Z
[2023-05-16T11:48:08.089Z] Loop of PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 7, 2023-05-16T11:48:08.086Z
[2023-05-16T11:48:09.091Z] Loop of PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 8, 2023-05-16T11:48:09.089Z
[2023-05-16T11:48:10.099Z] Loop of PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 9, 2023-05-16T11:48:10.096Z
[2023-05-16T11:48:11.102Z] Loop of PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 10, 2023-05-16T11:48:11.099Z
[2023-05-16T11:48:11.102Z] [Timer1 end]: PID:14731, InvocationId:5427d7cd-35c3-412b-bfcb-56a5a9818172, 2023-05-16T11:48:11.100Z
[2023-05-16T11:48:11.104Z] Executed 'Functions.TimerTrigger1' (Succeeded, Id=5427d7cd-35c3-412b-bfcb-56a5a9818172, Duration=11105ms)
```

### `TimeTrigger1` と `TimerTrigger3` が同時に動作するとき

`TimerTrigger3` が動作中に `TimeTrigger1` の動作に遅延は発生しません。

```
[2023-05-16T11:50:00.010Z] Executing 'Functions.TimerTrigger1' (Reason='Timer fired at 2023-05-16T11:50:00.0100741+00:00', Id=029a02fc-abe8-4baf-bf75-87a292825114)
[2023-05-16T11:50:00.019Z] [Timer1 start] PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 2023-05-16T11:50:00.015Z
[2023-05-16T11:50:01.026Z] Loop of PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 1, 2023-05-16T11:50:01.024Z
[2023-05-16T11:50:02.036Z] Loop of PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 2, 2023-05-16T11:50:02.032Z
[2023-05-16T11:50:03.039Z] Loop of PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 3, 2023-05-16T11:50:03.037Z
[2023-05-16T11:50:04.050Z] Loop of PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 4, 2023-05-16T11:50:04.045Z
[2023-05-16T11:50:04.999Z] Executing 'Functions.TimerTrigger3' (Reason='Timer fired at 2023-05-16T11:50:04.9987310+00:00', Id=4dd1b56b-6b27-49e9-8c52-ad9f3b77afda)
[2023-05-16T11:50:05.008Z] [Timer3(Non blocking) start] PID:14731, InvocationId:4dd1b56b-6b27-49e9-8c52-ad9f3b77afda, 2023-05-16T11:50:05.005Z
[2023-05-16T11:50:05.046Z] Loop of PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 5, 2023-05-16T11:50:05.045Z
[2023-05-16T11:50:06.046Z] Loop of PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 6, 2023-05-16T11:50:06.045Z
[2023-05-16T11:50:07.046Z] Loop of PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 7, 2023-05-16T11:50:07.045Z
[2023-05-16T11:50:08.046Z] Loop of PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 8, 2023-05-16T11:50:08.045Z
[2023-05-16T11:50:09.046Z] Loop of PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 9, 2023-05-16T11:50:09.045Z
[2023-05-16T11:50:10.046Z] Loop of PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 10, 2023-05-16T11:50:10.045Z
[2023-05-16T11:50:10.046Z] [Timer1 end]: PID:14731, InvocationId:029a02fc-abe8-4baf-bf75-87a292825114, 2023-05-16T11:50:10.045Z
[2023-05-16T11:50:10.047Z] Executed 'Functions.TimerTrigger1' (Succeeded, Id=029a02fc-abe8-4baf-bf75-87a292825114, Duration=10037ms)
[2023-05-16T11:50:13.249Z] [Timer3(Non blocking) end] PID:14731, InvocationId:4dd1b56b-6b27-49e9-8c52-ad9f3b77afda, 3000, 2023-05-16T11:50:13.248Z
[2023-05-16T11:50:13.250Z] Executed 'Functions.TimerTrigger3' (Succeeded, Id=4dd1b56b-6b27-49e9-8c52-ad9f3b77afda, Duration=8251ms)
```

## FUNCTIONS_WORKER_PROCESS_COUNT = 2 の場合

### `TimeTrigger1` と `TimerTrigger2` が同時に動作するとき

`TimeTrigger1` と、`TimerTrigger2` は別プロセスで実行され、`TimerTrigger2` によって、`TimerTrigger1` の動作に遅延が発生することはありません。（※今回の例では影響はないですが、Azure Functions において、Language worker が動作する VM は共通となるので、CPU Time や メモリ、SNAT ポートといった観点では影響なしとは言い切れません。あくまでも Node プロセスが別という意味です。）

```
[2023-05-16T11:56:59.998Z] Executing 'Functions.TimerTrigger1' (Reason='Timer fired at 2023-05-16T11:56:59.9966547+00:00', Id=4e4b10d9-dc8f-49d4-908f-1f93f44c8faa)
[2023-05-16T11:57:00.008Z] [Timer1 start] PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 2023-05-16T11:57:00.005Z
[2023-05-16T11:57:01.009Z] Loop of PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 1, 2023-05-16T11:57:01.008Z
[2023-05-16T11:57:02.013Z] Loop of PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 2, 2023-05-16T11:57:02.011Z
[2023-05-16T11:57:03.013Z] Loop of PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 3, 2023-05-16T11:57:03.011Z
[2023-05-16T11:57:04.016Z] Loop of PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 4, 2023-05-16T11:57:04.014Z
[2023-05-16T11:57:05.001Z] Executing 'Functions.TimerTrigger2' (Reason='Timer fired at 2023-05-16T11:57:05.0006323+00:00', Id=5ea5a5ff-20d9-44ec-99c5-08c2df4b18e5)
[2023-05-16T11:57:05.019Z] Loop of PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 5, 2023-05-16T11:57:05.016Z
[2023-05-16T11:57:06.020Z] Loop of PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 6, 2023-05-16T11:57:06.018Z
[2023-05-16T11:57:06.431Z] [Timer2(blocking) start] PID:16843, InvocationId:5ea5a5ff-20d9-44ec-99c5-08c2df4b18e5, 2023-05-16T11:57:05.028Z
[2023-05-16T11:57:06.431Z] [Timer2(blocking) end] PID:16843, InvocationId:5ea5a5ff-20d9-44ec-99c5-08c2df4b18e5, 3000, 2023-05-16T11:57:06.429Z
[2023-05-16T11:57:06.432Z] Executed 'Functions.TimerTrigger2' (Succeeded, Id=5ea5a5ff-20d9-44ec-99c5-08c2df4b18e5, Duration=1431ms)
[2023-05-16T11:57:07.021Z] Loop of PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 7, 2023-05-16T11:57:07.020Z
[2023-05-16T11:57:08.024Z] Loop of PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 8, 2023-05-16T11:57:08.023Z
[2023-05-16T11:57:09.036Z] Loop of PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 9, 2023-05-16T11:57:09.034Z
[2023-05-16T11:57:10.039Z] Loop of PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 10, 2023-05-16T11:57:10.036Z
[2023-05-16T11:57:10.040Z] [Timer1 end]: PID:16939, InvocationId:4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, 2023-05-16T11:57:10.037Z
[2023-05-16T11:57:10.042Z] Executed 'Functions.TimerTrigger1' (Succeeded, Id=4e4b10d9-dc8f-49d4-908f-1f93f44c8faa, Duration=10046ms)
```

# 補足: `fs` の Sync と Async はどちらが早い？

:::note info
`TimerTrigger2` と `TimerTrigger3` はそれぞれ単独で実行した場合、`TimerTrigger2` は約 1.2 秒、`TimerTrigger3` は約 7.7 秒かかります。
:::

<details><summary>TimerTrigger2 単独実行時</summary>

```
[2023-05-16T21:28:05.060Z] Executing 'Functions.TimerTrigger2' (Reason='Timer fired at 2023-05-16T21:28:05.0296793+00:00', Id=bf583b19-5911-45f8-b66b-441e1cc744c7)
[2023-05-16T21:28:06.281Z] [Timer2(blocking) start] PID:3459, InvocationId:bf583b19-5911-45f8-b66b-441e1cc744c7, 2023-05-16T21:28:05.119Z
[2023-05-16T21:28:06.281Z] [Timer2(blocking) end] PID:3459, InvocationId:bf583b19-5911-45f8-b66b-441e1cc744c7, 3000, 2023-05-16T21:28:06.267Z
[2023-05-16T21:28:06.309Z] Executed 'Functions.TimerTrigger2' (Succeeded, Id=bf583b19-5911-45f8-b66b-441e1cc744c7, Duration=1267ms)
```
</details>

<details><summary>TimerTrigger3 単独実行時</summary>

```
[2023-05-16T21:30:05.045Z] Executing 'Functions.TimerTrigger3' (Reason='Timer fired at 2023-05-16T21:30:05.0125444+00:00', Id=cc27f60c-e97f-4474-b4dd-0b5ef5fe54fd)
[2023-05-16T21:30:05.119Z] [Timer3(Non blocking) start] PID:4276, InvocationId:cc27f60c-e97f-4474-b4dd-0b5ef5fe54fd, 2023-05-16T21:30:05.105Z
[2023-05-16T21:30:12.713Z] [Timer3(Non blocking) end] PID:4276, InvocationId:cc27f60c-e97f-4474-b4dd-0b5ef5fe54fd, 3000, 2023-05-16T21:30:12.709Z
[2023-05-16T21:30:12.780Z] Executed 'Functions.TimerTrigger3' (Succeeded, Id=cc27f60c-e97f-4474-b4dd-0b5ef5fe54fd, Duration=7750ms)
```
</details>

# 参考記事

https://nodejs.org/ja/docs/guides/blocking-vs-non-blocking

https://neos21.net/blog/2021/12/01-01.html