AWS Lambda のランタイムプロセスはコンテナとともに生き続ける

3
Like
0
Comment

koshigoe

Edited at 2017-11-10

Serverless Framework を利用して AWS Lambda を雰囲気で使ってきましたが、初歩的な仕組みを理解できていませんでした…。

誤解していたこと

コンテナは使い回してもランタイムプロセス(?)は使い回さない(ｷﾘｯ

今の認識

コンテナを使い回してランタイムプロセスも使い回す(ｷﾘｯ

注) 正確(厳密)ではありません。イメージです。

AWS Lambda 関数をデプロイ
AWS Lambda 関数をリクエスト
1. 初回のためコンテナを作成(コールドスタート)
2. コンテナ上でランタイムプロセスが生成される
3. ランタイムプロセスが関数を実行し結果を返す
4. ランタイムプロセスは次のリクエストを待つ ← ここ、終了するものだと思っていた。
時間を空けずに AWS Lambda 関数をリクエスト
1. 前回作成したコンテナが使えるので使い回す
2. コンテナではランタイムプロセスが待機中 ← ここ、毎回生成されるものだと思っていた。
3. ランタイムプロセスが関数を実行し結果を返す
4. ランタイムプロセスは次のリクエストを待つ ← ここ、終了するものだと思っていた。

※ あと、コールドスタートにかかった時間は、 REPORT のログに記録されている Billed Duration には含まれていない、という点も正しく理解できていなかった。

確認

以下のハンドラファイルをデプロイして、ランタイムプロセスが生き続ける事を確認する。

print("Handler file loaded.")

import os
import subprocess

counter = 0

def hello(event, context):
    global counter
    counter += 1

    print("$ uptime")
    print(subprocess.check_output(["uptime"]).decode('UTF-8').rstrip())

    print(f"$ ps u {os.getpid()}")
    print(subprocess.check_output(["ps", "u", str(os.getpid())]).decode('UTF-8').rstrip())

    return {"counter": counter}

適当に、1分間隔で関数を呼び出していく。

uptime でシステムの稼働時間を確認する
ps でランタイムプロセスの開始時間を確認する
グローバル変数で同一プロセスであることを確認する

$ seq 1 10 | xargs -n1 -I% bash -c '{ sls invoke -f hello -l ; sleep 60; }'
{
    "counter": 1
}
--------------------------------------------------------------------
START RequestId: 4f67b37f-c60d-11e7-bf2a-df09c904a01a Version: $LATEST
$ uptime
 11:50:13 up  1:29,  0 users,  load average: 0.03, 0.01, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1 12.0  0.4 170480 19184 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 4f67b37f-c60d-11e7-bf2a-df09c904a01a
REPORT RequestId: 4f67b37f-c60d-11e7-bf2a-df09c904a01a  Duration: 49.17 ms      Billed Duration: 100 ms         Memory Size: 128 MB     Max Memory Used: 22 MB


{
    "counter": 2
}
--------------------------------------------------------------------
START RequestId: 74d1a410-c60d-11e7-8dcf-39cccc39d67a Version: $LATEST
$ uptime
 11:51:15 up  1:30,  0 users,  load average: 0.01, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.1  0.4 170480 19192 ?        Rs   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 74d1a410-c60d-11e7-8dcf-39cccc39d67a
REPORT RequestId: 74d1a410-c60d-11e7-8dcf-39cccc39d67a  Duration: 179.24 ms     Billed Duration: 200 ms         Memory Size: 128 MB     Max Memory Used: 22 MB


{
    "counter": 3
}
--------------------------------------------------------------------
START RequestId: 99fa6e49-c60d-11e7-a48c-c30a58fa8fe6 Version: $LATEST
$ uptime
 11:52:17 up  1:31,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 99fa6e49-c60d-11e7-a48c-c30a58fa8fe6
REPORT RequestId: 99fa6e49-c60d-11e7-a48c-c30a58fa8fe6  Duration: 221.70 ms     Billed Duration: 300 ms         Memory Size: 128 MB     Max Memory Used: 23 MB


{
    "counter": 4
}
--------------------------------------------------------------------
START RequestId: beea7400-c60d-11e7-8613-f14355ee452d Version: $LATEST
$ uptime
 11:53:19 up  1:32,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: beea7400-c60d-11e7-8613-f14355ee452d
REPORT RequestId: beea7400-c60d-11e7-8613-f14355ee452d  Duration: 218.70 ms     Billed Duration: 300 ms         Memory Size: 128 MB     Max Memory Used: 23 MB


{
    "counter": 5
}
--------------------------------------------------------------------
START RequestId: e3d7e1d3-c60d-11e7-a7b2-dd75a5557d07 Version: $LATEST
$ uptime
 11:54:21 up  1:33,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: e3d7e1d3-c60d-11e7-a7b2-dd75a5557d07
REPORT RequestId: e3d7e1d3-c60d-11e7-a7b2-dd75a5557d07  Duration: 212.90 ms     Billed Duration: 300 ms         Memory Size: 128 MB     Max Memory Used: 23 MB


{
    "counter": 6
}
--------------------------------------------------------------------
START RequestId: 090280cf-c60e-11e7-908b-fb62b83e79bf Version: $LATEST
$ uptime
 11:55:24 up  1:34,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 090280cf-c60e-11e7-908b-fb62b83e79bf
REPORT RequestId: 090280cf-c60e-11e7-908b-fb62b83e79bf  Duration: 198.22 ms     Billed Duration: 200 ms         Memory Size: 128 MB     Max Memory Used: 23 MB


{
    "counter": 7
}
--------------------------------------------------------------------
START RequestId: 2de7fefe-c60e-11e7-b46e-117670d5c3cc Version: $LATEST
$ uptime
 11:56:26 up  1:35,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 2de7fefe-c60e-11e7-b46e-117670d5c3cc
REPORT RequestId: 2de7fefe-c60e-11e7-b46e-117670d5c3cc  Duration: 232.23 ms     Billed Duration: 300 ms         Memory Size: 128 MB     Max Memory Used: 23 MB


{
    "counter": 8
}
--------------------------------------------------------------------
START RequestId: 532b2e07-c60e-11e7-908b-fb62b83e79bf Version: $LATEST
$ uptime
 11:57:28 up  1:36,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 532b2e07-c60e-11e7-908b-fb62b83e79bf
REPORT RequestId: 532b2e07-c60e-11e7-908b-fb62b83e79bf  Duration: 201.68 ms     Billed Duration: 300 ms         Memory Size: 128 MB     Max Memory Used: 23 MB


{
    "counter": 9
}
--------------------------------------------------------------------
START RequestId: 78025558-c60e-11e7-8c38-ade05bfd80af Version: $LATEST
$ uptime
 11:58:30 up  1:37,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 78025558-c60e-11e7-8c38-ade05bfd80af
REPORT RequestId: 78025558-c60e-11e7-8c38-ade05bfd80af  Duration: 185.42 ms     Billed Duration: 200 ms         Memory Size: 128 MB     Max Memory Used: 23 MB


{
    "counter": 10
}
--------------------------------------------------------------------
START RequestId: 9d0e47dd-c60e-11e7-bb2e-9b3c16936470 Version: $LATEST
$ uptime
 11:59:32 up  1:38,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 9d0e47dd-c60e-11e7-bb2e-9b3c16936470
REPORT RequestId: 9d0e47dd-c60e-11e7-bb2e-9b3c16936470  Duration: 172.61 ms     Billed Duration: 200 ms         Memory Size: 128 MB     Max Memory Used: 23 MB

1行目の print("Handler file loaded.") の結果は sls invoke コマンドの出力では見られないが、 CloudWatch Logs の方には記録されている。

初回リクエストのランタイムプロセスが生成され、ハンドラモジュールがロードされたタイミングで評価される。そのため、二回目以降は評価されていない。

Serverless Framework を利用して AWS Lambda を雰囲気で使ってきましたが、初歩的な仕組みを理解できていませんでした…。

誤解していたこと
----

コンテナは使い回してもランタイムプロセス(?)は使い回さない(ｷﾘｯ

今の認識
----

コンテナを使い回してランタイムプロセスも使い回す(ｷﾘｯ

注) 正確(厳密)ではありません。イメージです。

1. AWS Lambda 関数をデプロイ
1. AWS Lambda 関数をリクエスト
    1. 初回のためコンテナを作成(コールドスタート)
    1. コンテナ上でランタイムプロセスが生成される
    1. ランタイムプロセスが関数を実行し結果を返す
    1. ランタイムプロセスは次のリクエストを待つ **← ここ、終了するものだと思っていた。**
1. 時間を空けずに AWS Lambda 関数をリクエスト
    1. 前回作成したコンテナが使えるので使い回す
    1. コンテナではランタイムプロセスが待機中 **← ここ、毎回生成されるものだと思っていた。**
    1. ランタイムプロセスが関数を実行し結果を返す
    1. ランタイムプロセスは次のリクエストを待つ **← ここ、終了するものだと思っていた。**

確認
----

以下のハンドラファイルをデプロイして、ランタイムプロセスが生き続ける事を確認する。

```python
print("Handler file loaded.")

import os
import subprocess

counter = 0

def hello(event, context):
    global counter
    counter += 1

print("$ uptime")
    print(subprocess.check_output(["uptime"]).decode('UTF-8').rstrip())

print(f"$ ps u {os.getpid()}")
    print(subprocess.check_output(["ps", "u", str(os.getpid())]).decode('UTF-8').rstrip())

return {"counter": counter}
```

適当に、1分間隔で関数を呼び出していく。

- `uptime` でシステムの稼働時間を確認する
- `ps` でランタイムプロセスの開始時間を確認する
- グローバル変数で同一プロセスであることを確認する

```
$ seq 1 10 | xargs -n1 -I% bash -c '{ sls invoke -f hello -l ; sleep 60; }'
{
    "counter": 1
}
--------------------------------------------------------------------
START RequestId: 4f67b37f-c60d-11e7-bf2a-df09c904a01a Version: $LATEST
$ uptime
 11:50:13 up  1:29,  0 users,  load average: 0.03, 0.01, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1 12.0  0.4 170480 19184 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 4f67b37f-c60d-11e7-bf2a-df09c904a01a
REPORT RequestId: 4f67b37f-c60d-11e7-bf2a-df09c904a01a  Duration: 49.17 ms      Billed Duration: 100 ms         Memory Size: 128 MB     Max Memory Used: 22 MB

{
    "counter": 2
}
--------------------------------------------------------------------
START RequestId: 74d1a410-c60d-11e7-8dcf-39cccc39d67a Version: $LATEST
$ uptime
 11:51:15 up  1:30,  0 users,  load average: 0.01, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.1  0.4 170480 19192 ?        Rs   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 74d1a410-c60d-11e7-8dcf-39cccc39d67a
REPORT RequestId: 74d1a410-c60d-11e7-8dcf-39cccc39d67a  Duration: 179.24 ms     Billed Duration: 200 ms         Memory Size: 128 MB     Max Memory Used: 22 MB

{
    "counter": 3
}
--------------------------------------------------------------------
START RequestId: 99fa6e49-c60d-11e7-a48c-c30a58fa8fe6 Version: $LATEST
$ uptime
 11:52:17 up  1:31,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 99fa6e49-c60d-11e7-a48c-c30a58fa8fe6
REPORT RequestId: 99fa6e49-c60d-11e7-a48c-c30a58fa8fe6  Duration: 221.70 ms     Billed Duration: 300 ms         Memory Size: 128 MB     Max Memory Used: 23 MB

{
    "counter": 4
}
--------------------------------------------------------------------
START RequestId: beea7400-c60d-11e7-8613-f14355ee452d Version: $LATEST
$ uptime
 11:53:19 up  1:32,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: beea7400-c60d-11e7-8613-f14355ee452d
REPORT RequestId: beea7400-c60d-11e7-8613-f14355ee452d  Duration: 218.70 ms     Billed Duration: 300 ms         Memory Size: 128 MB     Max Memory Used: 23 MB

{
    "counter": 5
}
--------------------------------------------------------------------
START RequestId: e3d7e1d3-c60d-11e7-a7b2-dd75a5557d07 Version: $LATEST
$ uptime
 11:54:21 up  1:33,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: e3d7e1d3-c60d-11e7-a7b2-dd75a5557d07
REPORT RequestId: e3d7e1d3-c60d-11e7-a7b2-dd75a5557d07  Duration: 212.90 ms     Billed Duration: 300 ms         Memory Size: 128 MB     Max Memory Used: 23 MB

{
    "counter": 6
}
--------------------------------------------------------------------
START RequestId: 090280cf-c60e-11e7-908b-fb62b83e79bf Version: $LATEST
$ uptime
 11:55:24 up  1:34,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 090280cf-c60e-11e7-908b-fb62b83e79bf
REPORT RequestId: 090280cf-c60e-11e7-908b-fb62b83e79bf  Duration: 198.22 ms     Billed Duration: 200 ms         Memory Size: 128 MB     Max Memory Used: 23 MB

{
    "counter": 7
}
--------------------------------------------------------------------
START RequestId: 2de7fefe-c60e-11e7-b46e-117670d5c3cc Version: $LATEST
$ uptime
 11:56:26 up  1:35,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 2de7fefe-c60e-11e7-b46e-117670d5c3cc
REPORT RequestId: 2de7fefe-c60e-11e7-b46e-117670d5c3cc  Duration: 232.23 ms     Billed Duration: 300 ms         Memory Size: 128 MB     Max Memory Used: 23 MB

{
    "counter": 8
}
--------------------------------------------------------------------
START RequestId: 532b2e07-c60e-11e7-908b-fb62b83e79bf Version: $LATEST
$ uptime
 11:57:28 up  1:36,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 532b2e07-c60e-11e7-908b-fb62b83e79bf
REPORT RequestId: 532b2e07-c60e-11e7-908b-fb62b83e79bf  Duration: 201.68 ms     Billed Duration: 300 ms         Memory Size: 128 MB     Max Memory Used: 23 MB

{
    "counter": 9
}
--------------------------------------------------------------------
START RequestId: 78025558-c60e-11e7-8c38-ade05bfd80af Version: $LATEST
$ uptime
 11:58:30 up  1:37,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 78025558-c60e-11e7-8c38-ade05bfd80af
REPORT RequestId: 78025558-c60e-11e7-8c38-ade05bfd80af  Duration: 185.42 ms     Billed Duration: 200 ms         Memory Size: 128 MB     Max Memory Used: 23 MB

{
    "counter": 10
}
--------------------------------------------------------------------
START RequestId: 9d0e47dd-c60e-11e7-bb2e-9b3c16936470 Version: $LATEST
$ uptime
 11:59:32 up  1:38,  0 users,  load average: 0.00, 0.00, 0.00
$ ps u 1
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
478          1  0.0  0.4 170480 19192 ?        Ss   11:50   0:00 /var/lang/bin/python3.6 /var/runtime/awslambda/bootstrap.py
END RequestId: 9d0e47dd-c60e-11e7-bb2e-9b3c16936470
REPORT RequestId: 9d0e47dd-c60e-11e7-bb2e-9b3c16936470  Duration: 172.61 ms     Billed Duration: 200 ms         Memory Size: 128 MB     Max Memory Used: 23 MB

```

1行目の `print("Handler file loaded.")` の結果は `sls invoke` コマンドの出力では見られないが、 CloudWatch Logs の方には記録されている。

![image.png](https://qiita-image-store.s3.amazonaws.com/0/22442/e9b95acb-369f-516b-3b7d-92c4dfe682f7.png)

Toot

koshigoe

232Contribution