Go to Qiita Advent Calendar 2024 Top
LoginSignup
2
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 1 year has passed since last update.

@georgeOsdDev@github(Takeharu Oshida)

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

Last updated at Posted at 2023-05-16

はじめに

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

コードサンプルは↓

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

TimerTrigger1

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

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 秒に開始されるように構成する。

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 秒に開始されるように構成する。

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 プロセスで全ての関数が実行されることになります。

ほとんどの 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 はどちらが早い？

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

TimerTrigger2 単独実行時 
[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)
TimerTrigger3 単独実行時 
[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)

参考記事

2
1
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
2
1

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?