【解決済】GoのS3 ListObjectsはPythonより遅いのか？問題

はじめに

S3から大量Objectをダウンロードする場合、Objectサイズに関わらず中々速度が出ないですよね。
Pythonで書いている時も、concurrent.futuresなどで頑張ってたのですが、もしかしてGoroutineで出来るのでは？と思い、Golangデビューしてみました。

やろうと思ったこと

• ListObjectV2を用いて、S3の特定Prefix配下のKeyをすべて取得
• 取得したKeyをGoroutineでいい感じにダウンロード

実際起こったこと

• ListObject部分を試しに書いてみたが、はっきり言って遅い。
• なんならPythonで書いた方が早い気が？

ん？API叩くだけなので同じ速度。だったらまだ納得は出来るが、スクリプト言語よりGoの方が遅いというのはちょっと気になる。
予定を急遽変更して、本件を少し検証してみました。

ソースコード

Go版

というわけでこちらやこちらを参考に書いてみる。

main.go

package main

import (
	"fmt"
	"github.com/aws/aws-sdk-go/aws"
	"github.com/aws/aws-sdk-go/aws/session"
	"github.com/aws/aws-sdk-go/service/s3"
	"os"
)

func main() {
	bucket := os.Getenv("BUCKET")
	prefix := os.Getenv("PREFIX")
	region := os.Getenv("REGION")

	sess := session.Must(session.NewSession())
	svc := s3.New(sess, &aws.Config{
		Region: &region,
	})
	params := &s3.ListObjectsV2Input{
		Bucket: &bucket,
		Prefix: &prefix,
	}
	fmt.Println("Start:")
	err := svc.ListObjectsV2Pages(params,
		func(p *s3.ListObjectsV2Output, last bool) (shouldContinue bool) {
			for _, obj := range p.Contents {
				fmt.Println(*obj.Key)
			}
			return true
		})
	fmt.Println("End:")
	if err != nil {
		fmt.Println(err.Error())
		return
	}
}

Python版

こちらもサクッと書いてみる。
Goと条件を合わせる為、低レベルクライアントで。

main.py

# !/usr/bin/env python
# -*- coding: utf-8 -*-
import os
import boto3
bucket = os.environ["BUCKET"]
prefix = os.environ["PREFIX"]
region = os.environ["REGION"]

# r = boto3.resource('s3').Bucket(bucket).objects.filter(Prefix=prefix)
# [print(r.key) for r in r]
# 普段は上記の様に取得するが、Golangへ寄せるため下記のコードにて測定

s3_client = boto3.client('s3', region)

contents = []
next_token = ''
while True:
    if next_token == '':
        response = s3_client.list_objects_v2(Bucket=bucket, Prefix=prefix)
    else:
        response = s3_client.list_objects_v2(Bucket=bucket, Prefix=prefix, ContinuationToken=next_token)

    contents.extend(response['Contents'])
    if 'NextContinuationToken' in response:
        next_token = response['NextContinuationToken']
    else:
        break

[print(r["Key"]) for r in contents]

環境

サーバ等

• 基本的にCloud9 on EC2(t2.micro)で実行。

ビルド・デプロイ等

• 環境を汚したくない&面倒なので、全部Dockerで構築。

$ docker-compose up -d --build

• ちなみに構築資材は下記を参照。

Dockerfile

FROM golang:1.13.5-stretch as build
RUN go get \
  github.com/aws/aws-sdk-go/aws \
  github.com/aws/aws-sdk-go/aws/session \
  github.com/aws/aws-sdk-go/service/s3 
COPY . /work
WORKDIR /work
RUN CGO_ENABLED=0 GOOS=linux GOARCH=amd64 go build -o main main.go

FROM python:3.7.6-stretch as release
RUN pip install boto3
COPY --from=build /work/main /usr/local/bin/main
COPY --from=build /work/main.py /usr/local/bin/main.py
WORKDIR /usr/local/bin/

docker-compose.yml

version: '3'
services:
  app:
    build:
      context: .
    container_name: "app"
    tty: True
    environment:
      BUCKET: <Bucket>
      PREFIX: test/
      REGION: ap-northeast-1

S3バケット

東京リージョンにバケットを一つ作って、以下のツールで1000件程度作成。

# /bin/bash

Bucket=<Bucket>
Prefix="test"

# テストファイル作成
dd if=/dev/zero of=testobj bs=1 count=30
# マスタファイルのコピー
aws s3 cp testobj s3://${Bucket}/${Prefix}/testobj
# マスタファイルを複製
for i in $(seq 0 9); do
    for k in $(seq 0 99); do
        aws s3 cp s3://${Bucket}/${Prefix}/testobj s3://${Bucket}/${Prefix}/${i}/${k}/${i}_${k}.obj
    done
done

測定

測定結果(1000 Object)

• Go

$ time docker-compose exec app ./main

～略～

real    0m21.888s
user    0m0.580s
sys     0m0.107s

• Python

$ time docker-compose exec app ./main.py

～略～

real    0m2.671s
user    0m0.577s
sys     0m0.104s

GoがPythonより10倍遅い。なんでや！

Object数を増やしてみる

• もうすこしobjectを増やしてみましょう。とりあえず10000件あたりで。

# 差分のみ
for i in $(seq 0 99); do
    for k in $(seq 0 99); do

• ちなみにアップロード完了までに3、4時間かかりました。ツールはちゃんと作っとけばよかったね…

再測定結果(10000 Object)

• Go

$ time docker-compose exec app ./main

～略～

real    0m23.276s
user    0m0.617s
sys     0m0.128s

• Python

$ time docker-compose exec app ./main.py

～略～
real    0m5.973s
user    0m0.576s
sys     0m0.114s

今回は4倍程度の差。
というよりObject数によらず18秒ほど差が出ている様子。うーむ。

終わりに

• ライブラリの設定起因か、言語仕様の理解不足な気もしているので、もう少し情報を漁ってみたい。
• そもそもの目的であるGoroutineでの並列ダウンロード処理の効率が良ければ20秒程度は誤差な気もするので、残りも実装してみます。

気になるところ

• よく見るとuser, sysは同じ程度なのでS3でI/O周りが怪しい。
• goのコードを雑にprintデバッグしたところ("Start:", "End:")、list objectが処理時間の大半を占めている様子。もしやboto3とはS3設定のデフォルト値が異なるのだろうか。
• 同じコンテナで動かしてるので、T系インスタンスのCPUクレジット問題やNW帯域の差も関係ないと思うが……
  • 前者はm5.largeに代えても解決しなかったので関係なさげ。

続報(2020/01/18)

コメント欄でアドバイスいただいた通り、SDKをデバッグしてみたところ
IAMのCredentialを探すのに時間がかかっていたことが分かりました。
「-stretch」のOSのデフォルト値が悪さしていたのか。
その後何度か試しましたが、こちらの環境でも再現しなくなったのでいったん解決とします。モヤモヤしますが…

@nabekenさん ありがとうございました！