Athena でのクエリ実行時間の内訳を QueryExecution.Statistics / QueryRuntimeStatistics で確認する

2026-08-03 aws

Athena でクエリを実行すると想定より時間がかかったり時間帯によって遅くなったりすることがある。サーバーレスのオーバーヘッドやリソースの枯渇はどうしようもないが、設定やクエリのチューニングによって速くできる可能性があるか QueryExecution.Statistics / QueryRuntimeStatistics の情報が参考になる。

パーティションのチュートリアルのデータを 7ヶ月分, 400MB ほどロードして確認する。

CREATE EXTERNAL TABLE IF NOT EXISTS elb_logs_raw_native_part (
  request_timestamp string, elb_name string, request_ip string, request_port int,
  backend_ip string, backend_port int, request_processing_time double,
  backend_processing_time double, client_response_time double,
  elb_response_code string, backend_response_code string,
  received_bytes bigint, sent_bytes bigint, request_verb string, url string,
  protocol string, user_agent string, ssl_cipher string, ssl_protocol string
)
PARTITIONED BY (dt string)
ROW FORMAT SERDE 'org.apache.hadoop.hive.serde2.RegexSerDe'
WITH SERDEPROPERTIES (
  'serialization.format' = '1',
  'input.regex' = '([^ ]*) ([^ ]*) ([^ ]*):([0-9]*) ([^ ]*)[:-]([0-9]*) ([-.0-9]*) ([-.0-9]*) ([-.0-9]*) (|[-0-9]*) (-|[-0-9]*) ([-0-9]*) ([-0-9]*) \"([^ ]*) ([^ ]*) (- |[^ ]*)\" ("[^"]*") ([A-Z0-9-]+) ([A-Za-z0-9.-]*)$'
)
LOCATION 's3://athena-examples-ap-northeast-1/elb/plaintext/';

ALTER TABLE elb_logs_raw_native_part ADD PARTITION (dt='2015-01-01')
  LOCATION 's3://athena-examples-ap-northeast-1/elb/plaintext/2015/01/01/';
...

QueryRuntimeStatistics には Stage などの詳細な情報が含まれているが、QueryExecution.Statistics にはあるスキャンバイト数は含まれていない。

$ QID=$(aws athena start-query-execution \
    --query-string "SELECT count(*) FROM elb_logs_raw_native_part" \
    --query-execution-context Database=blog_athena_stats \
    --work-group primary --query 'QueryExecutionId' --output text)

$ aws athena get-query-execution --query-execution-id "$QID" --query 'QueryExecution.Statistics'
{
    "EngineExecutionTimeInMillis": 916,
    "DataScannedInBytes": 406582288,
    "TotalExecutionTimeInMillis": 1097,
    "QueryQueueTimeInMillis": 99,
    "ServicePreProcessingTimeInMillis": 51,
    "QueryPlanningTimeInMillis": 278,
    "ServiceProcessingTimeInMillis": 31,
    "ResultReuseInformation": {
        "ReusedPreviousResult": false
    }
}

$ aws athena get-query-runtime-statistics --query-execution-id "$QID" --query 'QueryRuntimeStatistics'
{
    "Timeline": {
        "QueryQueueTimeInMillis": 99,
        "ServicePreProcessingTimeInMillis": 51,
        "QueryPlanningTimeInMillis": 278,
        "EngineExecutionTimeInMillis": 916,
        "ServiceProcessingTimeInMillis": 31,
        "TotalExecutionTimeInMillis": 1097
    },
    "Rows": {
        "InputRows": 1356206,
        "InputBytes": 0,
        "OutputBytes": 9,
        "OutputRows": 1
    },
    "OutputStage": {
        "StageId": 0,
        "State": "FINISHED",
        "OutputBytes": 9,
        "OutputRows": 1,
        "InputBytes": 378,
        "InputRows": 42,
        "ExecutionTime": 1170,
        "QueryStagePlan": {
            "Name": "Output",
            "Identifier": "{\"columnNames\":\"[_col0]\"}",
            "Children": [
                {
                    "Name": "Aggregate",
                    "Identifier": "{\"type\":\"FINAL\",\"keys\":\"\",\"hash\":\"[]\"}",
                    "Children": [
                        {
                            "Name": "LocalExchange",
                            "Identifier": "{\"partitioning\":\"SINGLE\",\"isReplicateNullsAndAny\":\"\",\"hashColumn\":\"[]\",\"arguments\":\"[]\"}",
                            "Children": [
                                {
                                    "Name": "RemoteSource",
                                    "Identifier": "{\"sourceFragmentIds\":\"[1]\"}",
                                    "Children": [],
                                    "RemoteSources": [
                                        "1"
                                    ]
                                }
                            ]
                        }
                    ]
                }
            ]
        },
        "SubStages": [
            {
                "StageId": 1,
                "State": "FINISHED",
                "OutputBytes": 378,
                "OutputRows": 42,
                "InputBytes": 0,
                "InputRows": 1356206,
                "ExecutionTime": 9510,
                "QueryStagePlan": {
                    "Name": "Aggregate",
                    "Identifier": "{\"type\":\"PARTIAL\",\"keys\":\"\",\"hash\":\"[]\"}",
                    "Children": [
                        {
                            "Name": "TableScan",
                            "Identifier": "{\"table\":\"awsdatacatalog:blog_athena_stats:elb_logs_raw_native_part\"}",
                            "Children": []
                        }
                    ]
                },
                "SubStages": []
            }
        ]
    }
}

Timeline の値を見ると、QueryQueueTimeInMillis と ServicePreProcessingTimeInMillis にそれぞれ 100ms, 60ms 程の時間がかかっている。これらを短縮することは難しいが QueryQueueTimeInMillis が大きい場合、同じアカウントで走っている重いクエリがクォータを圧迫している可能性がある。一方、EngineExecutionTimeInMillis については Stage の情報からクエリをチューニングしたり、ファイル形式や粒度を変更することで改善できる可能性がある。また、QueryPlanningTimeInMillis はこれに内包されていて、パーティションやファイルの数が多すぎないようにしたり、構造をフラットにしたりすることで効率化する余地がある。

クエリの実行結果が再利用する ResultReuse を有効にすると QueryPlanningTimeInMillis は返らない。ちなみに LakeFormation 管理下のテーブルは ResultReuse がサポートされていない。

CDK で Glue Data Catalog 上のテーブルに Lake Formation による行やカラムレベルでのアクセス制限をかける - sambaiz-net

$ QID=$(aws athena start-query-execution \
    --query-string "SELECT count(*) FROM elb_logs_raw_native_part" \
    --query-execution-context Database=blog_athena_stats \
    --work-group primary --query 'QueryExecutionId' --output text \
    --result-reuse-configuration 'ResultReuseByAgeConfiguration={Enabled=true,MaxAgeInMinutes=60}')

$ aws athena get-query-execution --query-execution-id "$QID" --query 'QueryExecution.Statistics'
{
    "EngineExecutionTimeInMillis": 114,
    "DataScannedInBytes": 0,
    "TotalExecutionTimeInMillis": 247,
    "QueryQueueTimeInMillis": 84,
    "ServicePreProcessingTimeInMillis": 19,
    "ServiceProcessingTimeInMillis": 30,
    "ResultReuseInformation": {
        "ReusedPreviousResult": true
    }
}

なお、結果を取得するまでにはこの実行時間に加えて State をポーリングして S3 にデータを取りに行く時間もかかる。 EventBridge で State の変更を取得する方法もあるがベストエフォートとのことで、実際 3-8 秒と届くまでの時間にばらつきがあった。また、行数が多いと最大 1000 件ずつしか取れない GetQueryResults を介さず直接 S3 から取得した方が速くなる。例えば 6000 件の結果を取りに行くのに GetQueryResults だと 1668 ms かかるのに対し、直接だと 145 ms で取得できた。