最近はユーザーインターフェイス回りの方がパフォーマンスの問題を引き起こしがちらしいですが、データベースへの問い合わせ（SQL）やデータベースのインデックスなどのスキーマに改善余地があることはまだありえます。
問題となる問い合わせをしているメソッドがはっきりしている場合は、メソッドごとのCPU時間プロファイリングで問題箇所を突き止め、そこで出ているSQLを検証すればよいのですが、ORMでSQL文が隠蔽化されている場合はその作業は一筋縄ではいきません。
もっともJavaのプロファイリングツールのVisualVMにはJDBCプロファイリング機能があり、SQL文ごとの経過時間を原則としてアプリケーションのソースコードに手を入れることなく調査することができます。気軽に使える便利な方法なので、一度試しておきましょう。
準備
JDKとMavenはインストールされている状態でVisualVMをインストールし、JDBCを使っているアプリケーションがあれば何でも良いのですが、PostgreSQLにデータベースを新たにつくり、マイクロベンチマーク的なコードを書きます。
VisualVMのインストール
公式サイトからダウンロードしてきて、ホームディレクトリーに配置し、.bashrcでPATHの追加をします。
cd ~ wget https://github.com/oracle/visualvm/releases/download/2.2.1/visualvm_221.zip unzip visualvm_221.zip echo 'export PATH=~/visualvm_221/bin:$PATH' >> ~/.bashrc source ~/.bashrc
PostgreSQLの設定
DBユーザーの作成
まだ作っていなければ、pgusrをつくっておきましょう。PostgreSQL管理者アカウントで psql をして、
SELECT usename, usesysid FROM pg_user WHERE usename='pgusr';
usename | usesysid ---------+---------- (0 rows)
とまだ存在しないことを確認してから、
CREATE ROLE pgusr LOGIN; ALTER USER pgusr with encrypted password 'u0b2u1n9t2s3u'; -- パスワードは適当に変えてください
とすれば作れます。
データベースの作成
PostgreSQL接続ユーザーpgusrを所有者として((pgusrにテーブルの作成をさせます。）)、データベースsieve_dbを作成します。PostgreSQL管理者アカウントで、
createdb -E utf8 -O pgusr sieve_db
とします。
Javaのソースコード
JDBCドライバーとApache Common CSVを用いるのでMavenリポジトリーにします。
cd ~ mvn archetype:generate \ -DgroupId=com.example \ -DartifactId=ProfilingSQL \ -DarchetypeArtifactId=maven-archetype-quickstart \ -DarchetypeVersion=1.5 \ -Dversion=0.1 \ -DinteractiveMode=false cd ProfilingSQL
pom.xml
<?xml version="1.0" encoding="UTF-8"?> <project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd"> <modelVersion>4.0.0</modelVersion> <groupId>com.example</groupId> <artifactId>ProfilingSQL</artifactId> <version>1.0</version> <packaging>jar</packaging> <properties> <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding> <maven.compiler.source>8</maven.compiler.source> <maven.compiler.target>8</maven.compiler.target> <exec.mainClass>com.example.DBOperation</exec.mainClass> </properties> <dependencies> <dependency> <groupId>org.postgresql</groupId> <artifactId>postgresql</artifactId> <version>42.7.10</version> <scope>compile</scope> </dependency> <dependency> <groupId>org.apache.commons</groupId> <artifactId>commons-csv</artifactId> <version>1.14.1</version> </dependency> </dependencies> </project>
PostgreSQLに接続し、SQLでエラトステネスのふるいをかけるクラスです。
src/main/java/com/example/DBOperation.java
package com.example; import java.sql.*; import java.util.Scanner; public class DBOperation { private static final int NumiberOfDML = 100; public static void main(String[] args) { String url = System.getenv("PgConnectionURL"); if (url == null || url.isEmpty()) { System.err.println("エラー: 環境変数 'PgConnectionURL' が設定されていません。Connection Stringを設定してください。"); return; } if(1 > args.length){ System.err.println("引数に1以上の自然数を入れてください"); return; } int NumberofNumbers = Integer.parseInt(args[0]); if(NumberofNumbers < 1){ System.err.println("引数に1以上の自然数を入れてください"); return; } // addBatch()とexecuteBatch()の挙動確認用 boolean IsBatch = false; if(2 <= args.length && args[1].toLowerCase().equals("batch")){ IsBatch = true; } System.out.println("エンターキーを押すとデータベース処理を開始します..."); try (Scanner scanner = new Scanner(System.in)) { scanner.nextLine(); // 入力待ち } // SQL定義 String createTableSql = "CREATE TABLE IF NOT EXISTS sieve (number INTEGER, flag BOOLEAN)"; String truncateSql = "TRUNCATE TABLE sieve"; String insertSql = "INSERT INTO sieve (number, flag) VALUES (?, 'true')"; String deleteMultiplesSql = "DELETE FROM sieve WHERE number > ? AND number % ? = 0"; String updateMultiplesSql = "UPDATE sieve SET flag = 'false' WHERE number > ? AND number % ? = 0"; String selectSql = "SELECT number FROM sieve WHERE flag = 'true' ORDER BY number ASC"; long benchmark_start = System.currentTimeMillis(); // DB操作開始直前時刻を記録 try (Connection conn = DriverManager.getConnection(url); Statement stmt = conn.createStatement(); PreparedStatement insertPstmt = conn.prepareStatement(insertSql); PreparedStatement deletePstmt = conn.prepareStatement(updateMultiplesSql)) { // updateMultiplesSqlをdeleteMultiplesSqlに変えると速くなる conn.setAutoCommit(false); stmt.execute(createTableSql); stmt.execute(truncateSql); System.out.println("--- テーブルの初期化完了 ---"); int m = 0; // Commit前のDMLの数 // 1からNumberofNumbersまで連番挿入 for (int i = 1; i <= NumberofNumbers; i++) { insertPstmt.setInt(1, i); if (IsBatch) { insertPstmt.addBatch(); } else { insertPstmt.execute(); if (NumiberOfDML < ++m) { conn.commit(); m = 0; } } } if (IsBatch) { insertPstmt.executeBatch(); } else { if (0 < m) { conn.commit(); m = 0; } } System.out.println("1から" + NumberofNumbers + "まで連番を挿入しました。"); // nの倍数（n自身を除く）の削除フラグを立てる for (int n = 2; n <= NumberofNumbers; n++) { deletePstmt.setInt(1, n); deletePstmt.setInt(2, n); deletePstmt.executeUpdate(); if(NumiberOfDML < ++m){ conn.commit(); m = 0; } } if(0 < m){ conn.commit(); m = 0; } System.out.println("倍数の削除処理が完了しました。"); // 残ったレコードの表示 System.out.println("\n--- 処理後に残った数値（1と素数） ---"); try (ResultSet rs = stmt.executeQuery(selectSql)) { int count = 0; while (rs.next()) { int num = rs.getInt("number"); System.out.print(num + " "); count++; // 10個ごとに改行して見やすく if (count % 10 == 0) System.out.println(); } System.out.println("\n合計: " + count + " 件"); } } catch (SQLException e) { e.printStackTrace(); } long benchmark_end = System.currentTimeMillis(); // DB操作終了直後の時間を計測 System.err.println("\n経過時間: " + (benchmark_end - benchmark_start) + " ms"); } }
VisualVMの保存CSVファイルを集計するクラスです。RやPythonの方が向いている処理ですが、Javaで行います。Java 1.4で導入された正規表現とApache Common CSVのおかげで意外に簡潔に書けますね。
src/main/java/com/example/Aggregation.java
package com.example; import java.io.File; import java.io.FileReader; import java.io.IOException; import java.io.Reader; import java.text.DecimalFormat; import java.util.regex.Matcher; import java.util.regex.Pattern; import org.apache.commons.csv.CSVFormat; import org.apache.commons.csv.CSVRecord; public class Aggregation { public static void main(String[] args) throws IOException { if(1 > args.length){ System.err.println("引数でファイル名を指定してください"); return; } File file = new File(args[0]); Pattern patternUpdate = Pattern.compile("UPDATE sieve SET flag = 'false' WHERE number > [0-9]+ AND number % [0-9]+ = 0"); Pattern patternInsert = Pattern.compile("INSERT INTO sieve \\(number, flag\\) VALUES \\([0-9]+, 'true'\\)"); Pattern patternTotalTime = Pattern.compile("([0-9.]+) ms \\(([0-9.]+)%\\)"); DecimalFormat df = new DecimalFormat("#,###.00"); double tt_update = 0.0, tt_insert = 0.0, tt_others = 0.0; try (Reader reader = new FileReader(file)) { for (CSVRecord record : CSVFormat.DEFAULT.builder().setHeader("SQL Query", "Total Time", "Invocations", "Average Time", "Command Type", "Tables", "Statement Type").setSkipHeaderRecord(true).get().parse(reader)) { String sql = record.get("SQL Query"); if (patternUpdate.matcher(sql).find()) { String tt = record.get("Total Time"); Matcher m = patternTotalTime.matcher(tt); if (m.find()) { tt_update += Double.parseDouble(m.group(1)); } } else if (patternInsert.matcher(sql).find()) { String tt = record.get("Total Time"); Matcher m = patternTotalTime.matcher(tt); if (m.find()) { tt_insert += Double.parseDouble(m.group(1)); } } else { String tt = record.get("Total Time"); Matcher m = patternTotalTime.matcher(tt); if (m.find()) { tt_others += Double.parseDouble(m.group(1)); } } } } double total = tt_insert + tt_update + tt_others; total /= 2; // CSVがSQLごとの時間の行とSQLを実行したメソッドごとの時間の行の構成で、ダブルカウントになるため System.out.println("total time of insert: " + df.format(tt_insert) + " ms (" + df.format(tt_insert/total*100) + " %)"); System.out.println("total time of update: " + df.format(tt_update) + " ms (" + df.format(tt_update/total*100) + " %)"); } }
コンパイルと実行
環境変数を設定し、Mavenでコンパイルをし、com.example.DBOperationを起動し、エンターキー待ち停止状態で、VisualVMを起動して接続、エンターキーを押して
環境変数の設定
PostgreSQLの状態にあわせてコネクションストリングを環境変数にセットします。
典型的には
export PgConnectionURL="jdbc:postgresql://localhost:5432/sieve_db?user=pgusr&password=u0b2u1n9t2s3u"
となるでしょう。
手元の環境はプライベート認証局によるPostgreSQLのクライアント証明書認証をしているので、
export PgConnectionURL="jdbc:postgresql://localhost:5432/sieve_db?user=pgusr&sslmode=verify-full&sslcert=/home/uncorrelated/.ssl/pgclient-cert.pem&sslkey=/home/uncorrelated/.ssl/pgclient-key.pk8&sslrootcert=/home/uncorrelated/.ssl/ca_DevRealm-crt.pem&sslpassword=password"
となりました。
コンパイル
パッケージのダウンロードからコンパイルまで楽になりました。
mvn compile
実行
VisualVMを起動しておきましょう。
visualvm &
依存クラスをまとめてパッケージングをしたJARを作る設定をしなかったので、Mavenから書いたコードを動かします。
mvn exec:java -Dexec.mainClass=com.example.DBOperation -Dexec.args=10000
エンターキーを押すとデータベース処理を開始します...
この状態で、エンターを押さず、VisualVMでApache Mavenに接続します。
IDEなどMavenを通さずに起動した場合は、アプリ名がcom.example.DBOperationになっていることが多いと思います。
接続したら、VisualVMでタブの中で一番右にあるプロファイラータブを開きます。
JDBCボタンをクリックしましょう。
実行中のcom.example.DBOperationに接続してくれます。
あとは、実行中のcom.example.DBOperationでENTERを押せば、リアルタイムにSQLをトレースして問い合わせの実行時間をリストしてくれます。
com.example.DBOperationが終了すると、以下のメッセージが出るので、YESを選択しましょう。なお、アプリを終了しないでプロファイリングの方をを停止することも可能です。
VisualVMのJDBCプロファリングの実行結果の見せ方には難があります。プレースホルダーなどを使っている場合でも、プレースホルダーに値が代入されたSQL文が個別に計測されているからです。
そこで、プロファイリング結果をCSVファイルとして保存します。profiling_sql.csvとでも名前をつけて、Mavenリポジトリーのpom.xmlと同じディレクトリーに保存しましょう。
CSVファイルの中身は（上の引数の実行結果だと5MBぐらいあるので見ない方がよいと思いますが）例えば以下のようになります。
"SQL Query","Total Time","Invocations","Average Time","Command Type","Tables","Statement Type" "SELECT number FROM sieve WHERE flag = 'true' ORDER BY number ASC;","16.1 ms (27.5%)","1","16.1 ms","SELECT","sieve","regular" " org.postgresql.jdbc.PgStatement.executeQuery(String)","16.1 ms (27.5%)","1","16.1 ms","-","-","-" " com.example.PostgreSQLExample.main(String[])","16.1 ms (27.5%)","1","16.1 ms","-","-","-" "TRUNCATE TABLE sieve;","13.7 ms (23.5%)","1","13.7 ms","other command","-","regular" " org.postgresql.jdbc.PgStatement.execute(String)","13.7 ms (23.5%)","1","13.7 ms","-","-","-" " com.example.PostgreSQLExample.main(String[])","13.7 ms (23.5%)","1","13.7 ms","-","-","-" "CREATE TABLE IF NOT EXISTS sieve (number INTEGER, flag BOOLEAN);","10.8 ms (18.6%)","1","10.8 ms","CREATE","-","regular" " org.postgresql.jdbc.PgStatement.execute(String)","10.8 ms (18.6%)","1","10.8 ms","-","-","-" " com.example.PostgreSQLExample.main(String[])","10.8 ms (18.6%)","1","10.8 ms","-","-","-"
Mavenから
mvn exec:java -Dexec.mainClass=com.example.Aggregation -Dexec.args=profiling_sql.csv
として、もうひとつ書いたAggregationクラスを起動しましょう。
INFOに埋もれて見づらいですが、
total time of insert: 2,629.32 ms (7.50 %) total time of update: 20,713.77 ms (59.07 %)
と言うようなプレースホルダーが入ったSQL文ごとの集計結果が出ます。
注意
VisualVMは、複数のSQL文をまとめて実行するBatchが上手く処理できません。
mvn exec:java -Dexec.mainClass=com.example.DBOperation -Dexec.args="10 batch"
とすると、以下のような長々としたSQL文が計測されているのがわかります。
[INSERT INTO sieve (number, flag) VALUES (1, 'true'), INSERT INTO sieve (number, flag) VALUES (2, 'true'), INSERT INTO sieve (number, flag) VALUES (3, 'true'), INSERT INTO sieve (number, flag) VALUES (4, 'true'), INSERT INTO sieve (number, flag) VALUES (5, 'true'), INSERT INTO sieve (number, flag) VALUES (6, 'true'), INSERT INTO sieve (number, flag) VALUES (7, 'true'), INSERT INTO sieve (number, flag) VALUES (8, 'true'), INSERT INTO sieve (number, flag) VALUES (9, 'true'), INSERT INTO sieve (number, flag) VALUES (10, 'true')]
1万レコードぐらいあると、長過ぎるラベルのノードが表示されるのでVisualVMが停止します。巨大なBatch SQLがある場合は使うのを避けたほうが良さそうです。
