SpannerのTimestampカラムをJavaで取得したときのCPU時間消費検証と改善方法

あるJavaプログラムでSpannerのTimestampカラムを多数含むテーブルをSELECTしたときにやけにCPU使用率が上がってしまった

その時の原因調査と解決法のまとめ

環境

• OS
  • Windows10 Pro 20H2
• Java
  • 1.8.0_282 (AdoptOpenJDK)
• Spanner Client Library
  • google-cloud-spanner-3.2.1
• その他
  • VisualVM 2.0.6

状況確認

まずは状況の確認をするために簡易的な再現プログラムを作ります

テーブル定義

SELECTするためのテーブル定義ですTIMESTAMPのカラムが入っています

ここに適当なデータを10万行ほどあらかじめインサートしておきます

多数の行を入れているのは大量に処理させることでより明確にCPU使用率の差を確認するためです

create table bench_table (
    id          STRING(50)      NOT NULL,
    created_at  TIMESTAMP       NOT NULL
) PRIMARY KEY (id);

プログラム

TIMESTAMP型のカラムをSELECTして処理するプログラムを書きます

SELECTしてResultSetからgetTimestampする部分が重要です

最適化されてしまわないようにいろいろやっていますが特に意味はありません

（Spannerオブジェクト作成からDatabaseClientを取得するところは割愛します）

  public void benchForTimestamp(DatabaseClient client) {
    int count = 0;
    long n = 0;
    final long time = System.currentTimeMillis();
    try (ResultSet rs = client.singleUse()
        .executeQuery(Statement.of(
            "SELECT id,created_at created_at FROM bench_table"))) {
      while (rs.next()) {
        n += rs.getTimestamp("created_at").getSeconds();
        count++;
      }
    }
    final long elapse = System.currentTimeMillis() - time;
    System.out.printf("count=%d, time=%d, n=%d\n", count, elapse, n);
  }

確認

上記プログラムを走らせてVisualVMでCPU使用率をサンプリングして確認します

一番右の数値がCPU処理時間になりますが、ここで注目なのはbenchForTimestampメソッド全体で使用されたCPU時間が804msだったのに対してツリーの一番下のparseTimestampのCPU時間が711msと大半を占めていることです。

これを見るとどうやらSpannerとライブラリ間のプロトコルではTIMESTAMPカラムの値は日時文字列で送られてきており、ライブラリ側でパースしているためそこにCPU時間が消費されていることがわかります。

改善方法

テーブル側の型を修正するのはサービス中のシステムだと難しいと思うので、それ以外の方法を検討します。
（コンソールでの視認性は落ちますがINT64型に日付を保存してしまうのが処理としては最も高速だとは思いますが・・・）

TIMESTAMP型をそのままSELECTしなければよいので UNIX_MILLIS 関数を使ってINT64型にしてしまいました。

改修後プログラム

SELECTでUNIX_MILLIS(created_at)とすることでINT64型に変換してJava側ではgetLongで値を取得します

比較のためTimestamp型にしていますが、longのままや、Instantにしたりというほうが実用的かもしれません

  public void benchForMillis(DatabaseClient client) {
    int count = 0;
    long n = 0;
    final long time = System.currentTimeMillis();
    try (ResultSet rs = client.singleUse()
        .executeQuery(Statement.of(
            "SELECT id,UNIX_MILLIS(created_at) created_at_ms FROM bench_table"))) {
      while (rs.next()) {
        long t = rs.getLong("created_at_ms");
        n += Timestamp.ofTimeSecondsAndNanos(t / 1000, (int)(t % 1000) * 1000000).getSeconds();
        count++;
      }
    }
    final long elapse = System.currentTimeMillis() - time;
    System.out.printf("count=%d, time=%d, n=%d\n", count, elapse, n);
  }

改善確認

サンプリングなので正確な比較は難しいですが、改修前のGrpcStruct.consumeRow()で比較しても711msと93.6msで大幅に改善していることがわかります。

Spanner側でUNIX_MILLISを動かしているため負荷上昇がある可能性がるので、本番で導入する際はそのあたりの確認も必要です。（個人的にはこれの導入により確認できるレベルの負荷変動は観測されていません）

まとめ

• CPUリソースがシビアなシステムにおいてJavaのSpannerクライアントを使う際はTIMESTAMP型のカラムを取得してくるのは避けた方がよさそう（特に複数の行かつ1行に複数のTIMESTAMP型カラムがSELECTされるような場合において）

• 既存のシステムでもスキーマの型変更はせずDao部分を修正することで処理の軽減ができる

• DBや外部APIとの連携があるシステムでは応答待ちも処理時間に入ってしまうのでそれだけ見ていてもCPU負荷はわからない