はじめに

「お気に入りのテレビ番組の有無を答えてくれるAlexaスキルを作ってみた」でNode.js製のLambdaを作ったのですが、

ただ、スキルを呼び出した後、返答が返ってくるまで少しタイムラグがあるのが気になりますね
…
いずれにしてもX-RAYを仕掛けて、番組表取得で遅くなっているのか、その後の処理で遅くなっているのかなどを見極めたいと思っています。

ということで、X-RAYを使って、速度が遅くなっている箇所を特定したいと思います。

コンソールからの設定

まず最初にコードには手を入れず、LambdaのコンソールからX-RAYの設定をしてみます。
Lambdaのコンソールにて、対象関数の「AWS X-RAY」の箇所のチェックボックスをONにします。

この状態でLambdaを動かした後、X-RAYのコンソールの「Service Map」を開くとこんな感じで表示されます。

「Traces」から詳細を見ることができます。

この時点だとLambdaの実処理としては2.1秒かかっている、というのがわかる程度ですね。

コード修正1：外部とのhttp通信時間を調べる

処理の内訳を調べるため、まず外部とのhttp通信の時間がどれくらいを占めているのかを調べてみます。
今回のコードはaxiosを使ってyahooのテレビ表をhttpsで取りに言っているのですが、その所要時間を調べるために以下のコードを冒頭に入れてみます。
※xray-sdkは事前にnpmなりyarnなりで用意しておいてください。

const awsXRay = require('aws-xray-sdk')
awsXRay.captureHTTPsGlobal(require('https'))
awsXRay.capturePromise()

このコードを追加した状態で、再度ビルド、デプロイした後、実際に動作、X-RAYコンソールを開く、という操作をしてみます。

Service Map

Traces

ざっくりですが、2秒ちょっとの処理時間のうち前半約1秒がhttpsを使った番組表取得に費やされていることがわかります。

コード修正2：任意の区間を計測する

今度はコードに手を入れていきます。
経過時間を測りたい区間にcaptureFuncやcaptureAsyncFuncを埋め込んでいきます。

    awsXRay.captureFunc('Cheerio.load', () => {
      $ = Cheerio.load(response.data)
    })

      awsXRay.captureFunc('scrape', () => {
        const left = $('div.leftarea', elm)
        const right = $('div.rightarea', elm)
        dateString = $('p:first-of-type > em', left).text()
        timeString = $('p:nth-of-type(2) > em', left).text()
        titleString = $('p:first-of-type > a', right).text()
      })

    awsXRay.captureFunc('make-speechText', () => {
      if (filtered.length > 0) {
        // 今日ある場合は、番組詳細まで返す
        const subStr = filtered.map(x => {
          const timeString = x.time.replace('～', 'から')
          const result = timeString + 'に' + x.title + 'が'
          return result
        }).join('、')
        speechText = '今日は' + subStr + 'あります。'
      } else if (programInfos.length > 0) {
        // 今日はないけど、明日以降見つかったら、日付と時刻を返す。
        const subStr = programInfos.map(x => {
          const result = x.date.replace('/', '月') + '日' + x.time.replace('～', 'から')
          return result
        }).join('と、')
        speechText = '今日はイッテQはありませんが、' + subStr + 'にあるようです。'
      } else {
        // ない
        speechText = '今日はイッテQはありません。'
      }
    })

今までと同じく実行後にX-RAYコンソール…
Service Mapは特に変わらないので、Tracesのみ。

これで、先に見たテレビ欄の取得とCheerioでのhtmlロードで処理時間の大半を使っていることがわかりました。

終わりに

今回のX-RAYでの調査により、遅いと感じていたAlexaスキルの処理時間の大半はHTTPS通信(1回)とCheerio.loadによるHTMLの読み込み処理(1回)で占められていることがわかりました。

となると、対応方法としては、以下のどちらかかな、と考えています。

番組表取得(HTTPS通信)とCheerioによるHTML解析処理は定期処理で事前に終わらせておく。Alexaスキルから呼び出されたときは解析済みの結果を使って文言整形する
Cheerio以外のHTMLパーサを使用する(libxmljsとか???)

X-RAYは万能薬ではないですが、使ってみるとなかなか便利な機能だと思いますので、まだ使ったことない方は、ぜひともお試しあれ。