chakokuのブログ(rev4)

テック・コミック・ごくまれにチャリ

遠隔ベルの遅延を調査

もっさり遅い遠隔操作ベルの動作において、どこで遅延しているのかを調査
結論は以下:

  • 1 Clickボタンのクリックからリクエスト送信完了まで4秒かかっている(ボタンの仕様かと)
  • AWSサーバ内の処理は1秒以下

まず、自宅にある機器の時刻の精度がかなり低いので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のボタンを定刻にタイミングを合わせて押してみた。押した直後白点滅が数秒続き、緑点灯に変わって終了する。白点滅はおおよそ4秒かかっている。緑色は送信完了なんだろうと推測されて、ボタンの処理で最大4秒程度かかっているのでは?と推測される。サーバ側のログのタイムスタンプを調べるとサーバ側でいつリクエストを受け取っているか分かるはず

押下 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)”を呼び出し側(送信元)につけていますが、送信元で時間がかかったのか受信側で時間がかかったのか、切り分け未実施)(資料上、ワナが多すぎますかね)。

もっさりの一番の原因はボタンが押されてからリクエストをサーバの送り終わるまでが約4秒かかっており、これが一番の原因。本来1 Clickボタンは、洗剤とか空になりそうになったらボタンを押して発注するためのものなので、リアルタイム性はそれほど求められていないと思う。1 Clickボタンは電池交換ができないので、長期間放置しておいても安定して動作することが優先され、省電力に重点が置かれていると思う。。。多分*2。一方課題と思ったのは、AWS IoT 1 ClickからLambdaのリクエスト受信までが799msecかかっている。Lambdaの起動に時間がかかっているためかと思うが、、AWS内の単純な処理で799msecというのはかなり致命的な印象。使い方を間違っているのかもしれませんが。。リージョンを間違って海外に作った?? リクエストを中継しているだけなのに、処理時間:799msecは仕事だったら許されないだろう。。趣味だから放置
ログから単純に計算すると、AWSサーバ内の処理は994msecかかっている。ボタンクリックからリクエスト投げるまでにボタン~サーバ間で4秒なので、押してから動くまで最低5秒かかる計算。Lambdaの件はおいといて、、4秒遅延は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にリクエストを飛ばして時間測るぐらいか。

■追記
処理時間(遅延?)についてもう少し調べたいと思い、、以下の2種類を調べることにした。

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のオーバーヘッドは2桁msecなのでほぼ無視してよいとなると、、IoT 1-ClickからLambdaが呼び出されるまでの遅延はIoT 1-Clickから出てくるのが遅いということになる。あるいは、、操作ミスしてIoT 1-ClickのEndPointを遠くのリージョンに作ってしまって、IoT 1-ClickとLambdaのネットワーク的な距離が異常に離れているとか。。

*1:参考にした記事:Raspberry Pi(Raspbian)にやっといたほうがいい設定(運用:NTPでの時刻合わせ) 感謝

*2:WiFiブロックは普段止まっていて、ボタン押されてからWiFiが動き出して、IPを取ったりしてるのだろうと思う

*3:あとから分かったのだが、SMSと連携する場合も一旦Lambdaを経由している。裏側で新しいLambda関数が作られそれをキックしている。今回の場合、iot1click_onclick_sms_20220718123611という関数が作られている。だから、、SMSのタイムスタンプで処理時間を考察するのは意味がない