EspruinoではCC3000を用いることで、センサー情報をWiFi経由でクラウドに飛ばすことが出来る訳ですが、これで実際にサービスを運用しようとすると安定化の面で壁にぶちあたることと思います。今回の内容はその"安定化"を目指す上で留意しておいた方がよいポイントです。

Tips

WiFiに接続するため、wlan.connect / wlan.reconnectを呼び出す前には、clearIntervalと{clearTimeout`を呼び出して、時限性の非同期処理が走っていない状態にした方が良い。

解説

WiFi接続時の謎挙動

Espruino&CC3000を使っていると気づくと思うのですが、wlan.connect/wlan.reconnectメソッドによるWiFi接続処理は、他の非同期で走っている時限性の処理(setTimeout,setInterval等)をブロッキング します。つまり、WiFiに接続しようとしている間、setTimeoutやsetIntervalを仕掛けた処理は実行されないということですね。

これだけなら特に気をつける必要はないし、いちいちclearInterval,clearTimeoutなどすることはなさそうなのですが、色々運用していく中で、二つの厄介な挙動を発見しました。如何その挙動です。

1. WiFi接続中に実行されるはずだったsetIntervalの処理は全てスタックされ、接続完了後のタイミングで一気に実行される
2. setTimeoutの再帰を用いて仕掛けた時限処理が、WiFi接続処理中に実行されようとしたとき、Wifi接続完了後に大量の再帰処理が呼び出される。

なんのこっちゃ分からんと思いますので、詳しく知りたく無い人はとりあえずタイトルの通り、wlan.connect() , wlan.reconnect()するときはclearInterval()とclearTimeout()と覚えておけば大丈夫です。

ここからは謎挙動の解説と検証結果をつらつら書いていきますね。

謎挙動１

WiFi接続中に実行されるはずだったsetIntervalの処理は全てスタックされ、接続完了後のタイミングで一気に実行される

具体例を挙げると、、、、

例えばsetIntervalで１秒おきにとある処理aを実行しているとします。このときにwlan.reconnect()を実行すると、一旦Espruino上の処理が全て止まったかのように見えますね。ここまではいつもの挙動です。ところが5〜10秒後、WiFinに接続されると共にsetIntervalで仕掛けておいた処理aが同タイミングに５回程度実行されてしまいます。以下、検証プログラムと結果です。

検証プログラム

以下プログラムをWebIDEで走らせると、1秒毎にコンソール上で数値がカウントアップされていきます。@以下は Espruinoを起動してからの時間(秒) となります。

/** WiFi 接続情報 */
var wifiConfig = {
  ssid: "BCW710J-83EEA-G",
  key: "d5433a48fe448"
};

/** getTime()の少数を切った値を返す */
function getTimeSec(){
  return Math.floor( getTime()  );
}

/* 
 * 1秒に1ずつカウントアップする
 * setIntervalの再帰で実装
 */
function intervalCount( ){
  var cnt = 0;
  setInterval( function(){
    console.log( cnt++ + "@" + getTimeSec() );
  } , 1000);
}


var wlan = require("CC3000").connect();

/**
 * WiFi接続処理
 */
function execConnect(){ 
  wlan.connect( wifiConfig.ssid, wifiConfig.key, function (s) {
    if (s=="dhcp") {
      console.log("connected@" + getTimeSec() );
    }
  });
}

execConnect();   /* wifi 接続を実行 */
intervalCount(); /* setIntervalによるカウントアップを開始 */

カウントアップの最中に、WebIDEの左側のコンソールにwlan.reconnect()を実行してみましょう。

Wifi接続成功時にカウントアップが一気に５個程進みます。注目すべきはこのときの@以下の値で、一定間隔で実行されて欲しい処理が同時に実行されてしまっていることが分かります。

問題なところ

例えばこのsetIntervalで仕掛けていた処理が、サーバにセンサーが生存していることを伝えるためのpingの役割をもったhttpリクエストだった場合、WiFiに再接続した瞬間に大量リクエストを送ろうと試み、再びWiFiモジュールが落ちる、、、という事態に陥ります。他にも、setIntervalで仕掛けた処理が複数ある場合、並列で走るとマズい処理を仕掛けていた場合、等々も問題になりそうですね。

という訳で、reconnect/connectの前にはclearIntervalをした方が良さそうです。

謎挙動2

setTimeoutの再帰を用いて仕掛けた時限処理が、WiFi接続処理中に実行されようとしたとき、Wifi接続完了後に大量の再帰処理が呼び出される。

これは実際にやってみて頂きたいです。凄い事になります。再現性も100%コレだ！とは突き止められていませんが、相当悩まされたので的外れな内容ではないはずです。

検証プログラム

以下プログラムをWebIDEで走らせると、1秒毎にコンソール上で数値がカウントアップされていきます。今度の処理はsetTimeoutの再帰で実装してあります。@以下は Espruinoを起動してからの時間(秒) となります。

/** WiFi 接続情報 */
var wifiConfig = {
  ssid: "XXXXXXXXXXXXXX",
  key: "XXXXXXXXXXXXXX"
};

/** getTime()の少数を切った値を返す */
function getTimeSec(){ 
  return Math.floor( getTime()  );
}

/* 
 * 1秒に1ずつカウントアップする
 * SetTimeoutの再帰で実装
 */
function timerCount( cnt ){ 
  var timer = function( count ){
    setTimeout(function(){
      console.log(count + "@" + getTimeSec() );
      timer( ++count );
    }, 1000);
  };
  timer( cnt );
}

/**
 * WiFi接続を実行
 */
function execConnect(){ 
  wlan.connect( wifiConfig.ssid, wifiConfig.key, function (s) {
    if (s=="dhcp") {
      console.log("connected@" + getTimeSec() );
    }
  });
}


var wlan = require("CC3000").connect();

execConnect(); /* コネクション確立 */
timerCount(0); /* 0からカウント開始 */

カウントアップの最中に、WebIDEの左側のコンソールにwlan.reconnect()を実行してみましょう。

Wifi接続成功時にトンでもない事がおこると思います。凄い数まで一気にカウントアップが進みます。負荷がかかる処理だったら大変なことになりますね。

なぜ問題なのか

自明ですね。必ずclearTimeoutを実行するか、ループにsetTimeoutの再帰を使わないようにするかした方が良いと思います。

ちなみに私はEspruinoの死活監視用pingリクエスト、二つのセンサーの値のPOST、計つの処理を全てsetTimeoutの再帰で実装しており、WiFiの再起動がかかった瞬間に再びWifiが落ち、、、ということを繰り返して苦しんだ事があります。処理の内容がhttpリクエストというそれなりに時間を食う処理だったので、追い越しが発生しないように配慮したのが仇になった感じです。

おまけ

アドベントカレンダー最終日の記事ということで、 センサーデバイスとかその辺使ってサービス考えると幅が広がるよ！ という香ばしい記事を書こうと思っていたのですが、、ぶっちゃけ途中は抜けになってしまったところもあり、何を言っても格好着かないのでやめました。色々と試行錯誤をして、ちゃんと面白いものを世に出したタイミングで、ドヤ顔で書いてやろうと思います。ありがとうございました。