もっさり遅い遠隔操作ベルの動作において、どこで遅延しているのかを調査
結論は以下：
- 1 Clickボタンのクリックからリクエスト送信完了まで４秒かかっている（ボタンの仕様かと）
- ＡＷＳサーバ内の処理は１秒以下
まず、自宅にある機器の時刻の精度がかなり低いのでNTP同期に変更
電波時計を会社に置いてきたので、ラズパイを時計代わりにする
ラズパイの設定：
JSTに変更
ln -sf /usr/share/zoneinfo/Asia/Tokyo /etc/localtime
NTP同期を有効化
file:/etc/systemd/timesyncd.conf
[Time] NTP=ntp.jst.mfeed.ad.jp ntp.nict.jp FallbackNTP=time.google.com
NTP同期有効化*1
timedatectl set-ntp true systemctl daemon-reload systemctl restart systemd-timesyncd.service systemctl status systemd-timesyncd
ESP32側は以下でNTP同期にする
import utime import ntptime ntptime.settime() # 同期化 print(utime.localtime()) # 時刻表示
計測（自宅内の情報）
ほぼNTP同期しているとして、IoT 1 Clickのボタンを定刻にタイミングを合わせて押してみた。押した直後白点滅が数秒続き、緑点灯に変わって終了する。白点滅はおおよそ４秒かかっている。緑色は送信完了なんだろうと推測されて、ボタンの処理で最大４秒程度かかっているのでは？と推測される。サーバ側のログのタイムスタンプを調べるとサーバ側でいつリクエストを受け取っているか分かるはず
| 押下 | LED:緑 | uPy 表示 |
| 09:50:30 | 09:50:34 | (2022, 7, 18, 0, 50, 35, 0, 199) (09:50:35) |
| 09:52:00 | 09:52:04 | (2022, 7, 18, 0, 52, 5, 0, 199) (09:52:05) |
AWSサーバ側のログを確認
厳密にいうと、各ブロックごとに、リクエストの受信時刻、処理時間、リクエストの送信時刻で構成されるべきですが、そこまで詳細にログ取っていないので、受信時刻と送信時刻が混在しています。基本受信時刻ですが、AWS IoT Coreは送信時刻です。
| AWS IoT 1 Click | AWS Lambda (called IoT 1 Click) |
AWS IoT Core |
| reportedTime: 2022-07-18T00:50:34.903Z | 2022-07-18T09:50:35.702+09:00 | 2022-07-18 00:50:35.897 |
| reportedTime: 2022-07-18T00:52:05.092Z | 2022-07-18T09:52:05.957+09:00 | 2022-07-18 00:52:06.164 |
数字だけだと分かりにくいので図式化（送信、受信の線の位置は不正確、遅延を表す”}nnn(ms)”を呼び出し側（送信元）につけていますが、送信元で時間がかかったのか受信側で時間がかかったのか、切り分け未実施）（資料上、ワナが多すぎますかね）。
もっさりの一番の原因はボタンが押されてからリクエストをサーバの送り終わるまでが約４秒かかっており、これが一番の原因。本来1 Clickボタンは、洗剤とか空になりそうになったらボタンを押して発注するためのものなので、リアルタイム性はそれほど求められていないと思う。1 Clickボタンは電池交換ができないので、長期間放置しておいても安定して動作することが優先され、省電力に重点が置かれていると思う。。。多分*2。一方課題と思ったのは、AWS IoT 1 ClickからLambdaのリクエスト受信までが799msecかかっている。Lambdaの起動に時間がかかっているためかと思うが、、AWS内の単純な処理で799msecというのはかなり致命的な印象。使い方を間違っているのかもしれませんが。。リージョンを間違って海外に作った？？ リクエストを中継しているだけなのに、処理時間：799msecは仕事だったら許されないだろう。。趣味だから放置
ログから単純に計算すると、AWSサーバ内の処理は994msecかかっている。ボタンクリックからリクエスト投げるまでにボタン～サーバ間で４秒なので、押してから動くまで最低５秒かかる計算。Lambdaの件はおいといて、、４秒遅延は1 Clickのボタンの仕様だからしょうがないかと。
■補足
AWS IoT Coreのログ
2022-07-18T09:50:35.897+09:00
{
"timestamp": "2022-07-18 00:50:35.897",
"logLevel": "INFO",
"traceId": "86146418-bff3-56de-d572-7c5d26dd3844",
"accountId": "36xxxxxxxxxx74",
"status": "Success",
"eventType": "Publish-Out",
"protocol": "MQTT",
"topicName": "req/upk/esp32_01",
"clientId": "esp32_01",
"principalId": "6bdbcf28690556bba8c6eb89096ea1dc640ad39721faa4517ef130d76c2ba5b5",
"sourceIp": "121.118.xxx.xxx",
"sourcePort": 62xxx
}2022-07-18T09:52:06.164+09:00
{
"timestamp": "2022-07-18 00:52:06.164",
"logLevel": "INFO",
"traceId": "80c69fd1-5bd8-f43c-e312-518ad947d5ba",
"accountId": "36xxxxxxxxxx74",
"status": "Success",
"eventType": "Publish-Out",
"protocol": "MQTT",
"topicName": "req/upk/esp32_01",
"clientId": "esp32_01",
"principalId": "6bdbcf28690556bba8c6eb89096ea1dc640ad39721faa4517ef130d76c2ba5b5",
"sourceIp": "121.118.xxx.xxx",
"sourcePort": 62xxx
}■追記
単純にLambdaの起動が遅いと書いたけど、計測点が少なく、1-Clickからのリクエスト送信が遅いのか、Lambdaの受信が遅いのかまでは切り分けができていない。1-Clickはボタンからのリクエストを受け取った後、Lambdaをキックするので、その遅延があるのかもしれない(なんだか1-ClickってAWSコンソールも閑散とした印象だし)。切り分けるには、EC2等の常時稼働サーバを立てて、起動オーバーヘッドがない状態と比べる必要があるのかも。しかし、1-ClickはEC2とは連携できないので、、SNSにリクエストを飛ばして時間測るぐらいか。
■追記
処理時間（遅延？）についてもう少し調べたいと思い、、以下の２種類を調べることにした。
AWS IoT 1-Click ----> SMSのタイムスタンプ EC2-------> Lambda のタイムスタンプ
AWS IoT 1-Clickは受けたイベントをトリガーとしてSMSに飛ばすことができる。ProjectでActionsをSMSに設定してテスト実施、ボタンクリックは、13:07:10で、AWS IoT 1-Clickがイベントを受け取ったのは、13:07:14.449となった。SMSの送信ログは、04:07:15.983。だから、IoT 1-Clickがイベントを受け取ってからSMSが送信するまで、1.534秒かかっている。遅すぎてこれは考察に使ってはいけない気がする*3。あとできることとしては、、EC2のインスタンスからLambdaをキックするのにかかる時間を測ってみるぐらいか。。
| AWS IoT 1-Click log | SMS Log |
| reportedTime: 2022-07-18T04:07:14.449Z | timestamp:2022-07-18 04:07:15.983 |
SMSの送信ログ
"notification": {
"messageId": "2ec46837-8dfb-587a-ae88-337953484809",
"timestamp": "2022-07-18 04:07:15.983"
},EC2を立てて、以下のプログラムでLambdaを起動して時間を測った
#!/usr/bin/python3
import boto3
import json
import datetime
client = boto3.client('lambda',region_name="ap-northeast-1")
FUNCTION_NAME = "aws_iot_one_click"
message = bytes(json.dumps({"var1" : "value of var1", "var2" : "value of var2"}),"UTF-8")
print("start")
print(datetime.datetime.now())
response = client.invoke(
FunctionName = FUNCTION_NAME,
InvocationType = 'RequestResponse',
Payload = message
)
print("end")
print(datetime.datetime.now())
res = response['Payload'].read()
print(res)アプリ側の表示は以下、リクエストが完了するまでの時間は、246msと良い値。
$ ./test.py
start
2022-07-18 05:10:00.386224
end
2022-07-18 05:10:00.633187
b'{"statusCode": 200, "body": "\\"Hello from Lambda!\\""}'CloudWatchよりLambdaがキックされた時刻は以下
2022-07-18T14:10:00.435+09:00
前回の図はいろいろ言い訳付きで書きましたが、自分の理解整理もかねて、分かっている所、分からない所を極力正確に表現すると以下
Pythonプログラム側で発生するAPI呼び出しの時間、Lambda起動時間、それぞれ単体の時間は測れませんが、プログラムからLambdaの関数を呼び出して、Lambdaが動き始めるまで49msecで収まっているのが分かります。だからまぁLambdaの起動にかかる時間はほぼ無視していいオーバーヘッドかと。。多分。。細かいことを言い出すと、全く使っていない状態からの初期実行と、連続使用状態でまた時間が変わるとか。。うーん。。
Lambdaのオーバーヘッドは２桁msecなのでほぼ無視してよいとなると、、IoT 1-ClickからLambdaが呼び出されるまでの遅延はIoT 1-Clickから出てくるのが遅いということになる。あるいは、、操作ミスしてIoT 1-ClickのEndPointを遠くのリージョンに作ってしまって、IoT 1-ClickとLambdaのネットワーク的な距離が異常に離れているとか。。
