Kazuyuki Eguchi Factory | オーナーの好きな事を書いています。

経緯

M5STACK用の拡張３Gボードを評価しているところなのですが、通信が可能になるIPアドレス取得できるまでの時間が長いので、何に時間かかっているのか？を調べてみた。

IPアドレス取得までの時間を計測するコード

#include <M5Stack.h>

#define CONSOLE Serial
#define MODEM Serial2

#define TINY_GSM_DEBUG Serial
#define TINY_GSM_MODEM_UBLOX

#include <TinyGsmClient.h>

TinyGsm modem(Serial2);
TinyGsmClient ctx(modem);

void setup() {
  char buf[64];
  int nRet;
  
  M5.begin();
  M5.Lcd.clear(BLACK);
  M5.Lcd.setTextColor(WHITE);
  M5.Lcd.println(F("M5Stack + 3G Module"));

  MODEM.begin(115200, SERIAL_8N1, 16, 17);    // 3G MODULE

  uint64_t t1 = millis();
    
  CONSOLE.println(F("modem.restart()"));
  M5.Lcd.print(F("modem.restart()"));
  modem.restart();
  M5.Lcd.println(F("done"));

  CONSOLE.println(F("getModemInfo:"));
  M5.Lcd.print(F("getModemInfo:"));
  String modemInfo = modem.getModemInfo();
  M5.Lcd.println(modemInfo);

  CONSOLE.println(F("waitForNetwork()"));
  M5.Lcd.print(F("waitForNetwork()"));
  while (!modem.waitForNetwork()) M5.Lcd.print(".");
  M5.Lcd.println(F("Ok"));

  CONSOLE.println(F("gprsConnect(soracom.io)"));
  M5.Lcd.print(F("gprsConnect(soracom.io)"));
  modem.gprsConnect("soracom.io", "sora", "sora");
  // modem.gprsConnect("mineo-d.jp", "mineo@k-opti.com", "mineo");
  M5.Lcd.println(F("done"));

  CONSOLE.println(F("isNetworkConnected()"));
  M5.Lcd.print(F("isNetworkConnected()"));
  while (!modem.isNetworkConnected()) M5.Lcd.print(".");
  M5.Lcd.println(F("Ok"));

  M5.Lcd.print(F("My IP addr: "));
  IPAddress ipaddr = modem.localIP();
  M5.Lcd.print(ipaddr);
  CONSOLE.println(ipaddr);


  CONSOLE.printf("Time = %d [ms]\r\n",millis() - t1);
}

void loop() {
  if (MODEM.available() > 0) {
    CONSOLE.write(MODEM.read());
  }

  if (CONSOLE.available()) {
    MODEM.write(CONSOLE.read());
  }
}

３つのSIMで計測してみた(Docomo網）

SORACOM IoT SIM(Plan01s)
１回目 51433ms、２回目 51984ms、３回目 67185ms

SORACOM IoT SIM(Plan-D)
１回目 51802ms、２回目 65727ms、３回目 50859ms

mineo Docomoプラン(APN変更しての測定）
１回目 52164ms、２回目 68773ms、３回目 53348ms

結果としては、SIMに関係なく、大体１分近く時間がかかることが判明

どんなATコマンドをやりとりしているのか？

TinyGSMCommon.h内のsendAT関数内のコメントアウトされていたATコマンドを表示するように設定した状況で、取得したログ

13:13:14.696 -> modem.restart()
13:13:14.696 -> [765] ### AT: 
13:13:15.009 -> [1064] ### AT: 
13:13:15.302 -> [1363] ### AT: 
13:13:15.589 -> [1662] ### AT: 
13:13:15.912 -> [1961] ### AT: 
13:13:16.196 -> [2260] ### AT: 
13:13:16.508 -> [2559] ### AT: 
13:13:16.800 -> [2858] ### AT: 
13:13:17.089 -> [3157] ### AT: 
13:13:17.382 -> [3456] ### AT: 
13:13:17.702 -> [3755] ### AT: 
13:13:17.702 -> [3758] ### AT: +CFUN=16
13:13:21.200 -> [7246] ### TinyGSM Version: 0.7.9
13:13:21.200 -> [7246] ### AT: 
13:13:21.491 -> [7545] ### AT: 
13:13:21.784 -> [7844] ### AT: 
13:13:22.072 -> [8143] ### AT: 
13:13:22.395 -> [8442] ### AT: 
13:13:22.685 -> [8741] ### AT: 
13:13:22.962 -> [9040] ### AT: 
13:13:23.273 -> [9339] ### AT: 
13:13:23.273 -> [9342] ### AT: E0
13:13:23.273 -> [9347] ### AT: +CMEE=2
13:13:23.273 -> [9351] ### AT: +CGMI
13:13:23.307 -> [9355] ### AT: +GMM
13:13:23.307 -> [9359] ### Modem: u-blox SARA-U201
13:13:23.307 -> [9360] ### AT: +CPIN?
13:13:24.308 -> [10367] ### AT: +CPIN?
13:13:24.308 -> getModemInfo:
13:13:24.308 -> [10374] ### AT: I
13:13:24.346 -> waitForNetwork()
13:13:24.346 -> [10393] ### AT: +CGREG?
13:13:24.596 -> [10649] ### AT: +CGREG?
13:13:24.852 -> [10904] ### AT: +CGREG?
13:13:25.102 -> [11160] ### AT: +CGREG?
13:13:25.351 -> [11416] ### AT: +CGREG?
13:13:25.607 -> [11672] ### AT: +CGREG?
13:13:25.856 -> [11928] ### AT: +CGREG?
13:13:26.109 -> [12183] ### AT: +CGREG?
13:13:26.362 -> [12438] ### AT: +CGREG?
13:13:26.619 -> [12693] ### AT: +CGREG?
13:13:26.902 -> [12948] ### AT: +CGREG?
13:13:27.151 -> [13203] ### AT: +CGREG?
13:13:27.403 -> [13458] ### AT: +CGREG?
13:13:27.650 -> [13714] ### AT: +CGREG?
13:13:27.903 -> [13969] ### AT: +CGREG?
13:13:28.150 -> [14224] ### AT: +CGREG?
13:13:28.436 -> [14479] ### AT: +CGREG?
13:13:28.687 -> [14735] ### AT: +CGREG?
13:13:28.938 -> [14991] ### AT: +CGREG?
13:13:29.191 -> [15246] ### AT: +CGREG?
13:13:29.437 -> [15502] ### AT: +CGREG?
13:13:29.688 -> [15758] ### AT: +CGREG?
13:13:29.946 -> [16013] ### AT: +CGREG?
13:13:30.196 -> [16268] ### AT: +CGREG?
13:13:30.447 -> [16524] ### AT: +CGREG?
13:13:30.726 -> [16779] ### AT: +CGREG?
13:13:30.981 -> [17035] ### AT: +CGREG?
13:13:31.232 -> [17290] ### AT: +CGREG?
13:13:31.487 -> [17545] ### AT: +CGREG?
13:13:31.736 -> [17800] ### AT: +CGREG?
13:13:31.986 -> [18056] ### AT: +CGREG?
13:13:32.240 -> [18312] ### AT: +CGREG?
13:13:32.491 -> [18567] ### AT: +CGREG?
13:13:32.746 -> [18822] ### AT: +CGREG?
13:13:33.031 -> [19077] ### AT: +CGREG?
13:13:33.031 -> gprsConnect(soracom.io)
13:13:33.031 -> [19084] ### AT: +UPSDA=0,4
13:13:33.031 -> [19092] ### AT: +CGATT=1
13:13:33.031 -> [19097] ### AT: +UPSD=0,1," soracom.io "
13:13:33.031 -> [19103] ### AT: +UPSD=0,2," sora "
13:13:33.031 -> [19108] ### AT: +UPSD=0,3," sora "
13:13:33.068 -> [19116] ### AT: +UPSD=0,7,"0.0.0.0"
13:13:33.068 -> [19121] ### AT: +UPSDA=0,3
13:14:06.034 -> [52112] ### AT: +UPSND=0,8
13:14:06.071 -> isNetworkConnected()
13:14:06.071 -> [52120] ### AT: +CGREG?
13:14:06.071 -> [52127] ### AT: +UPSND=0,0
13:14:06.071 -> 10.234.40.104
13:14:06.071 -> Time = 51370 [ms]

解説

modem.restart()関数内では、モデムの応答を確認した後、初期化コマンド(AT+CFUN=16)を送った後に、エコーOFFとかやった後に、SIMの状態を確認するというないようで、モデムが応答するまで、３〜４秒もかかっているのが気になりますが、MODEMが起動するのに、それだけかかるということなのでしょう。

waitForNetwork()関数は、3Gの網を探して、接続するということで、見つかるまでに９秒ぐらいかかっているようです。

gprsConnect()関数は、PDPに接続する為、APNの情報や認証情報を送った後に、PDPに接続するまで、３３秒程度かかっているようです。（ここが遅い原因！？）

isNetworkConnected()は、PDPに接続できているのか？を確認する関数で、これは、あってもなくてもいいかな？と思います。

とりあえず、９秒かかっているwaitForNetwork()関数を抜いてみるとどうなるのか？

13:35:57.697 -> modem.restart()
13:35:57.697 -> [765] ### AT: 
13:35:57.980 -> [1064] ### AT: 
13:35:58.264 -> [1363] ### AT: 
13:35:58.577 -> [1662] ### AT: 
13:35:58.890 -> [1961] ### AT: 
13:35:59.181 -> [2260] ### AT: 
13:35:59.464 -> [2559] ### AT: 
13:35:59.791 -> [2858] ### AT: 
13:36:00.074 -> [3157] ### AT: 
13:36:00.374 -> [3456] ### AT: 
13:36:00.662 -> [3755] ### AT: 
13:36:00.662 -> [3758] ### AT: +CFUN=16
13:36:04.158 -> [7245] ### TinyGSM Version: 0.7.9
13:36:04.158 -> [7245] ### AT: 
13:36:04.452 -> [7544] ### AT: 
13:36:04.741 -> [7843] ### AT: 
13:36:05.060 -> [8142] ### AT: 
13:36:05.349 -> [8441] ### AT: 
13:36:05.673 -> [8740] ### AT: 
13:36:05.966 -> [9039] ### AT: 
13:36:06.247 -> [9338] ### AT: 
13:36:06.247 -> [9341] ### AT: E0
13:36:06.247 -> [9345] ### AT: +CMEE=2
13:36:06.286 -> [9349] ### AT: +CGMI
13:36:06.286 -> [9353] ### AT: +GMM
13:36:06.286 -> [9358] ### Modem: u-blox SARA-U201
13:36:06.286 -> [9359] ### AT: +CPIN?
13:36:07.265 -> [10365] ### AT: +CPIN?
13:36:07.301 -> getModemInfo:
13:36:07.301 -> [10372] ### AT: I
13:36:07.301 -> gprsConnect(soracom.io)
13:36:07.301 -> [10392] ### AT: +UPSDA=0,4
13:36:07.301 -> [10400] ### AT: +CGATT=1
13:36:15.988 -> [19076] ### AT: +UPSD=0,1," soracom.io "
13:36:15.988 -> [19081] ### AT: +UPSD=0,2," sora "
13:36:15.988 -> [19087] ### AT: +UPSD=0,3," sora "
13:36:16.026 -> [19093] ### AT: +UPSD=0,7,"0.0.0.0"
13:36:16.026 -> [19098] ### AT: +UPSDA=0,3
13:36:49.863 -> [52949] ### AT: +UPSND=0,8
13:36:49.863 -> isNetworkConnected()
13:36:49.863 -> [52956] ### AT: +CGREG?
13:36:49.863 -> [52963] ### AT: +UPSND=0,0
13:36:49.901 -> 10.234.40.104
13:36:49.901 -> Time = 52205 [ms]

考察

waitForNetwork()を抜いてみても、トータルの時間は変わらずってことで、今度は何処に時間がかかっているのか？を見てみると、gprsConnect()関数で、AT+CGATT=1の応答が、長くなっているのがわかります。AT+CGATT=1で、3Gの網に接続を確認しているので、内部的には、waitForNetwork()と同様のことをやっているので、トータル時間は変わらないですね。PDPの接続完了がどうやったら、早くできるのか？が鍵のようです。

以上、ご参考までに