PythonのコードをプロファイルしてLambdaのコストを最適化しよう!

cProfileの出力結果をpyprof2calltreeで変換し、QCacheGrindで分析するなど
2020.03.10

CX事業本部@大阪の岩田です。

とある環境で稼働しているLambda(Python)の利用費が予想以上に高く、コスト削減案を検討する機会がありました。Pythonのプロファイルツールを使うのは初めてだったのですが、ツールを組み合わせることで、サクッと改善案を見つけることができたのでツールの使い方を簡単にご紹介します。

分析対象のコード

こんな感じのコードが分析対象です。実際にはもっと色々と複雑なことをやっていますが、分かりやすいように処理の大枠だけ残してガッツリ改変しています。これだけ見れば改善箇所は一目瞭然なのですが、実際にはもっと色々な処理があり、パット見では改善点が分かりにくい状態でした。

handler.py

import json
import logging
import boto3


logger = logging.getLogger()

def handler(event, context):

  logger.info('start')
  data = json.loads(event)
  body = data['body']
  func1()
  
  x = 0
  for i in range(5):
    body['key1'] = x
    x += i
    logging.info('some log')

  print(x)
  func3()

  body['key2'] = 2
  body['key3'] = 3
  return json.dumps(body)

def func1():

  dynamodb = boto3.resource('dynamodb')
  func2()

def func2():

  client = boto3.client('dynamodb')
  func3()

def func3():

  dynamodb = boto3.resource('dynamodb')
  func4()

def func4():

  client = boto3.client('dynamodb')  

ツール類の導入

まずはプロファイル用のツールを導入します。前職時代はWinCacheGrindを使ってPHPのコードをプロファイルしていた経験があるので、Python on Macの環境でもKCachegrindのようなツールが使えないか調べたところ、GUI処理にKDEではなくQTを使うQCacheGrindというツールがMacでも使えるようでした。

このQCacheGrindと、cProfileの結果をK(Q)CacheGrindから読み込める形式に変換するpyprof2calltreeというツールを導入します。

まずはQCacheGrind

$ brew install qcachegrind

続いてpyprof2calltree

$ pip install pyprof2calltree

これで準備完了です。

やってみる

準備できたので早速プロファイルしてみます。Lambdaのhandlerを呼び出すために別ファイルで以下のコードを用意します。

main.py

import json
from handler import handler

event = {
  'body': {
    'key1': 'val1',
    'key2': 'val2',
    'key3': 'val3'    
  }
}

handler(json.dumps(event) , None)

用意できたらまずcProfileでプロファイルします。

$ python -m cProfile -o main.profile main.py 

これで プロファイル結果のがmain.profileというバイナリファイルに出力されます。pyprof2calltreeで形式を変換しつつ、QCacheGrindから読み込んでみます。

$ pyprof2calltree -k -i main.profile

-iで入力として使用するファイルを指定、-kでK(Q)CacheGrindの起動を指定します。コマンドを実行するとQCacheGrindが立ち上がります。まずはFlat Profile Viewをざっと眺めてみます。すぐにhandler.py というLambdaのコードを書いたファイルが見つかると思います。

QCacheGrindの画面

handler.pyを選択すると、handler.pyの中でどの処理にどれだけの時間がかかっているのかドリルダウンしながら確認することが可能です。今回のプロファイル結果だと、func3の占める割合が大きそうなので、func3をダブルクリックして、さらにドリルダウンしていきます。画面右側のCall Graphを選択してみましょう。func3関連のCall Graphがグラフィカルに表示されます。この結果を見ると、何やらresourceclientといったboto3を使ったプログラミングで良く見かける名前が見つかります。Call Graphを見るとresourceからもclientが呼ばれているので、Call Graphの下側に表示されている青色のclientをダブルクリックしてさらにドリルダウンします。

QCacheGrindでfunc3にドリルダウン

clientまでドリルダウンすると、clientが合計6回呼び出されており、トータルの処理時間の中で結構な割合を占める事が分かります。

QCacheGrindでclientにドリルダウン

ん、、、boto3のclientってLambdaの呼び出し1回につき6回も呼び出すべきものでしたっけ??

パフォーマンスを劣化させないように、グローバルスコープをうまく使うことが推奨されていますね。そう、boto3のresourceclientは「重い」処理なんです。ということで、今回分析対象のLambdaをチューニングするにはresourceclientの無駄な呼び出しを減らすというのが有効なアプローチになりそうです。

resourceclientの処理時間計測

resourceclientが重いといっても、実際どの程度時間がかかるのでしょうか? Python3.8、メモリ割り当て128MのLambdaで以下のコードで計測してみました。

import json
import time
import boto3

def lambda_handler(event, context):
    # TODO implement
    
    for i in range(100):
      start = time.perf_counter()
      boto3.client('dynamodb') 
      end = time.perf_counter()
      print(end - start)
      
    return {
        'statusCode': 200,
        'body': json.dumps('Hello from Lambda!')
    }

ソースをきちんと追えていないので予想にはなりますが、計測結果を見る限り一度clientクラスを動的に生成した以後はbotocoreに内包されるjsonファイルから読み込んだ諸々の情報をキャッシュしているようで、1回目のclient生成処理は2~100回目のclient生成処理に比べて圧倒的に遅かった(数100msレベル)です。2~100回目のclient生成処理だけ抜粋して平均すると、client生成処理1回につき45msほどかかるという結果でした。Lambdaは100ms単位の課金なので、メモリの割当が128Mであればclient生成処理を3回削ることができればコストを改善できそうです。

今回はプロファイル手法の紹介が主題なので割愛しますがclinetresourceの呼び出しを減らせば、インスタンス生成のコスト以外にもTCPの3WayハンドシェイクやTLSのネゴシエーション処理を省略することができ、パフォーマンスの改善が期待できます。これについてはまた別途ブログにしようと思います。この辺りの話は以下のブログを参考にして下さい。

boto3のresourceやclientのインスタンスを再利用してTCPやTLSのオーバーヘッドを削減しよう

まとめ

説明簡略化のためにちょっと極端なコードに改変していますし、clinetの呼び出しを減らすだけで削減できるコストはそう大きく無いと思いますが、ツール類の基本的な考え方は実業務でも通用する部分が多いと思います。いわゆる「札束で殴る」という考え方が通用するのはLambdaの魅力の1つではありますが、やはりコストは低いに越したことはありません。サーバーレスアーキテクチャを導入してみたけど思うようにコストが下がらない...とお悩みの方がいれば、一度ソースコードのプロファイルに挑戦してみるのも良いのではないでしょうか?