チャットメッセージ送信 RTT 6,980ms → 386ms — 6回の改善記録

Last updated at 2026-03-14Posted at 2026-03-14

メッセージ送信パフォーマンス測定記録

機械翻訳を使用しているため、翻訳がおかしい場合があります
初めて学びながら勉強している振り返り記録・メモのような性格のため、おかしい部分があるかもしれません。ご指摘いただければ学んでいきます

問題状況

本番デプロイを前に、現在のメッセージ送信機能のパフォーマンスを測定しようとした
目標は、第一段階として友人や知人がアプリに登録して使用すると仮定した
1つのルームに50人（第一目標）、オンライン：オフラインの比率を2：3（20人：30人）に設定してテストを進めようとした

状況設定

テスト用ルームにユーザー50人が参加
そのうち20人がWebSocketに同時接続している状態で1人がメッセージを送信
20人 = 地域コミュニティアプリの初期リリース時、ルーム1つの目標同時接続者数
サーバーがメッセージ1件あたりオンライン20人全員にブロードキャストする際のパフォーマンスを確認する

テストシナリオ詳細

項目	設定	根拠
ルームメンバー数	50人	地域チャットルーム1つの想定最大登録者数
同時接続	20人（sender 1 + listener 19）	初期リリース時、ルーム1つの目標同時接続者数
オフラインユーザー	30人	メッセージ保存＋プッシュ通知の対象。ブロードキャスト対象から除外
メッセージ送信頻度	200ms間隔で50件（5 msg/s）	活発なグループチャットで短いメッセージを連続入力するシナリオ。サーバーが入力速度に追いつけるか確認
テスト継続時間	〜10秒（50件 × 200ms）	瞬間的な負荷ではなく、持続的な負荷状態でのキュー蓄積有無を観察
測定ツール	k6（WebSocket）＋ Prometheus（サーバーメトリクス）	クライアントRTTとサーバー内部処理時間を同時測定

なぜ200ms間隔なのか？
チャットで1行ずつ短く連打するパターンが、サーバーに最も負荷がかかるシナリオである。通常の使用では5〜10秒に1件程度だが、「サーバーが連打に耐えられるか」を確認することが目的のため、極限の頻度に設定した。

オフライン30人はどのように処理されるのか？
意図した設計は、オンライン20人にのみWebSocketブロードキャストを行い、オフラインユーザーにのみプッシュ通知を送信することだった。しかし実際の実装では、第4次改善以前はオンライン状態に関わらず、sender を除く全メンバー（49人）に通知処理を行っていた。メッセージ自体はDBに保存され、次回接続時に取得される。

パフォーマンス目標：RTT 500ms以下

Jakob Nielsenの応答時間研究によると、100ms以内は即時反応として感じられ、1,000msを超えるとユーザーが遅延を認識し始める。チャットアプリでメッセージを送信後、1秒以内に画面に表示されれば「速い」と感じ、それ以上になるとラグとして認識される。

中間値である500msを目標に設定した。1対1メッセンジャー（カカオトーク、LINE）よりは余裕を持たせつつ、ユーザーが遅延を認識する1秒よりも十分に速くなければならない。P95基準で1,000ms以下を安定性目標とした。

テスト環境

項目	スペック
EC2	2vCPU ARM（Graviton）、1929MB RAM
JVM	OpenJDK 21、G1GC、ヒープ 256〜512MB（`-Xms256m -Xmx512m`）
HikariCP	プールサイズ 10（max 10、min-idle 10）
`@Async` スレッドプール	`ThreadPoolTaskExecutor` — core 5、max 20、queue capacity 200
ネットワーク	k6クライアント（日本）→ EC2（韓国）、TCP RTT 〜50ms（推定）

上記テスト環境はBefore〜5次のbaseline基準である。6次ではHikariCP のmaximum-pool-sizeとminimum-idleを10（デフォルト値）→7に調整した。

すべてのコンポーネント（Nginx、Spring Boot、MySQL、Redis）が同一EC2インスタンス上でDocker Composeで実行される。2コアを4つのプロセスが共有する環境である。

k6スクリプト注意事項：6次改善の過程で、k6テストスクリプトにイベントループブロッキングのバグを発見した。このバグはRTTを実際より均一に見せ、各改善回次のパフォーマンス差を隠していた。3次〜6次のk6 RTT数値は、バグを修正したスクリプトで再測定した結果である。Before（原本）と1次は再測定していないが、サーバー自体が遅かったため（同期パス 893ms）、RTTが高いのはバグとは無関係に事実である。Grafanaサーバーメトリクス（同期/非同期処理時間）はk6バグとは無関係なサーバー側の指標である。ただし10秒前後の短いテストでは、scrapeインターバル（15秒）のため、一部の回次で単一ポイントのスナップショットとして記録されており、精密な平均比較よりも、ボトルネックの位置と変化の方向を把握する用途として解釈すべきである

結果

k6

指標	値	基準	判定
RTT Avg	6,410ms	< 500ms	FAIL
RTT P95	9,680ms	< 1,000ms	FAIL
RTT Max	10,050ms	-	-
Error Rate	24%	< 1%	FAIL
Messages Sent	50件	-	-
Messages Received	38件	50件	sender echo基準 12件欠落
Connection Time	233ms	-	良好

1人が200ms間隔で50件送信するところ、元のk6基準ではRTT平均が6.4秒と観測された。ただしこの数値には、後に発見されたk6イベントループブロッキングバグの影響が一部含まれているため、絶対値よりも**「非常に遅かった」というシグナル**として解釈するのが適切である。そして50件中12件はまったく返ってこなかった。

Messages Receivedの測定範囲：k6で測定するRTTと受信件数は、sender 1人が自分のメッセージをブロードキャストで受け取った（echo）件数である。listener 19人それぞれの受信有無と受信遅延は別途測定していない。したがって「欠落0件」はsender echo基準であり、listener全員へのfanout delivery検証は含まれない。

Grafanaサーバーメトリクス — どこで時間を使っているか

テスト中、Grafanaダッシュボードでサーバーメトリクスを収集した
RTTは「クライアントが体感する全体の時間」である

RTT, Round-Trip Time

クライアントがメッセージを送信した時点から、そのメッセージがブロードキャストで返ってきた時点までの時間

同期パス — ユーザーが待つ区間

同期処理パイプライン — 平均所要時間

Name	Mean	Max
chat.ws.send（全体）	893 ms	1.12 s
chat.message.send（トランザクション）	788 ms	1.01 s
chat.message.send（TaskRejected）	717 ms	717 ms
chat.message.read（既読処理）	45.2 ms	47.1 ms
chat.message.response.build（レスポンスビルド）	352 µs	446 µs
chat.hashtag.process（ハッシュタグ）	95.2 µs	121 µs

同期処理 — Max所要時間（スパイク検出）

Name	Mean	Max
chat.ws.send MAX	185 ms	1.78 s
chat.message.send MAX	121 ms	1.19 s
chat.message.send MAX (TaskRejected)	157 ms	1.51 s
chat.message.response.build MAX	209 µs	2.03 ms
chat.hashtag.process MAX	118 µs	1.15 ms
chat.message.read MAX	35.2 ms	340 ms

非同期パス（ブロードキャスト）

非同期処理 — 平均所要時間

Name	Mean	Max
chat.event.message.sent（イベントハンドラ）	313 ms	401 ms
chat.broadcast.room（ブロードキャスト）	202 ms	255 ms

サーバースループット

Name	Mean	Max
メッセージ処理/s	0.0261 ops/s	2.33 ops/s
ブロードキャスト/s	0.0261 ops/s	2.33 ops/s
イベント処理/s	0.0261 ops/s	2.33 ops/s
TaskRejected/s	0.00825 ops/s	0.800 ops/s

インフラ — JVM / DB / CPU

HikariCP コネクションプール

Active	Idle	Pending	Total	Avg Acquire	Max Acquire
7	3	0	10	56.6ms	600ms

下記のDB Connection Acquire Timeパネル（133µs）と数値が異なる理由：このパネルはGrafana scrapeインターバル（15秒）中の平均であるため負荷スパイクが含まれているのに対し、下記パネルは特定時点（01:03:45）のスナップショットである。2つの数値は同じメトリクスの異なる集計区間を示している。

CPU

JVM 62.1%, System 99.9%

Jvm thread

Timestamp	Live Threads	Peak Threads	Daemon Threads
2026-03-03 01:01:45	67	76	32

Hibernate Query

Timestamp	Queries/s	Inserts/s	Loads/s
2026-03-03 01:01:45	919 ops/s	105 ops/s	1.22K ops/s

DB Connection Acquire Time

Timestamp	Avg Acquire Time	Max Acquire Time
2026-03-03 01:03:45	133 µs	600 ms

分析

同期パス：時間はどこで消費されているか

chat.ws.send 893msのうち88%がchat.message.send（788ms）である
その中でresponse.build（352µs）とhashtag（95.2µs）は合計しても0.4msで、事実上0である。787msはMicrometerの計測がない区間であり、大部分はDBクエリ実行だが、トランザクション管理・Hibernateの永続化コンテキストflush・JDBCシリアライズなどのオーバーヘッドも含まれる
chat.message.sendが2行ある理由：Micrometerがexceptionタグで分離するためである。788msの行は正常完了、717msの行はTaskRejectedExceptionが発生した件である

非同期パス：なぜRTTが6秒なのか？

同期パス（893ms）だけではRTT 6.4秒の説明がつかない。非同期パスが原因である
chat.event.message.sentがメッセージ1件あたり313msである。senderは200ms間隔で送信しているが、非同期処理は1件あたり313msかかる。入力速度 > 処理速度であるためキューが蓄積される。50件目のメッセージは前の49件が完了するまで待たなければならない
サーバースループットパネルでも同期パスのピークが2.33 ops/sと観測される。ただしこのops/sはPrometheusのscrapeインターバル（15秒）と集計方式の産物であるため、絶対的なスループットとして解釈するのは難しい。サーバーが入力（5 msg/s）に追いつけなかったという判断は、RTTの線形増加パターンとキュー蓄積の計算によって裏付けられる

なぜRTTが6秒なのか：
今回のシナリオでRTTの主成分は同期パス＋非同期キュー遅延である（ネットワークRTT・STOMPフレーム処理なども含まれるが、ボトルネックの大部分はサーバー側のキューイングだった）。非同期イベントハンドラ（chat.event.message.sent）が1件あたり313msであるのに対し、入力間隔は200msである。入力速度が処理速度を超えるためキューが線形に蓄積し、後半のメッセージほど待機時間が長くなる。これにCPU 99.9%飽和状態での同期パスのスパイク（平均893ms、max 1.78s）も重なり、RTTが全体的に高くなった。

BeforeのRTT 6,410msはk6イベントループバグが含まれた値であるため、この数値からサーバー側の遅延のみを正確に逆算することは難しい。確実なのはGrafanaで確認された同期パス893msと、非同期イベントハンドラ313ms > 入力間隔200msという構造的問題である

CPU飽和：sender 1人のfanoutで100%

System CPU 99.9%。送信者は1人だが、メッセージ1件が20人へのブロードキャスト＋30人へのプッシュ通知処理にfanoutされるため、2コアのEC2が飽和した。JVMが62.1%、残り38%はMySQL＋Redis＋OSである
原因はHibernateのクエリ数にある。Grafanaで919 queries/sと2.33 ops/sが観測されたが、15秒scrapeベースの集計＋バースト負荷＋同期/非同期混在の状況では、この2つを割って1メッセージあたりのクエリ数を推定するのは難しい。その後の1次改善でHibernateログを直接分析した結果、実際にはメッセージ1件あたり642件のクエリが実行されていた
コードレベルでは、同期パスのクエリは10〜12件であるため、残り**〜630件は非同期パス**で発生している
非同期ブロードキャストがsenderを除く49人に対して個別クエリを実行すると：630 ÷ 49 = メンバー1人あたり〜12.9件のクエリ。ユーザー照会・ブロック確認・未読数計算・オンラインチェックなどがメンバーごとに個別実行される典型的なN+1問題である

HikariCP：コネクション

プール10個中、Active 7個。sender 1人なのに70%を占有している。同期パス＋既読処理＋非同期ブロードキャストが同時にコネクションを保持しているためである
Avg Acquire Timeは133µsで良好だが、Max Acquire Timeは600msである。通常はすぐに取得できるが、コネクションが集中した際に返却を0.6秒待ったことがあるということを意味する

リアルタイム配信欠落（以下「欠落」）：TaskRejectedException

RejectedExecutionException: Task rejected from ThreadPoolTaskExecutor [Running, pool size = 20, active threads = 20, queued tasks = 200, completed tasks = 7709]

@Async のスレッドプール設定は以下の通りだ：

// AsyncConfig.java
executor.setCorePoolSize(5);       // コアスレッド5個
executor.setMaxPoolSize(20);       // 最大スレッド20個
executor.setQueueCapacity(200);    // 待機キュー200個
executor.setRejectedExecutionHandler(new ThreadPoolExecutor.AbortPolicy()); // 超過時に拒否

エラーログを読むと：pool size = 20, active threads = 20（最大プールまで拡張後、全て使用中）、queued tasks = 200（待機キューも満杯）。20 + 200 = 220個の容量が全て埋まった状態で、221番目のタスクが拒否された。

12件欠落の原因である。chat.message.sendにexception=TaskRejectedExceptionタグが付いたメトリクスが、スループットパネルで0.800 ops/sのピークとして記録された
メッセージはDBに保存されたがブロードキャストが実行されなかったため、senderに返ってこなかった。データは欠落していないが、リアルタイム配信が失敗したということである

スパイクパネルとの差異

平均パネルとスパイクパネルの差が大きい

メトリクス	平均	スパイク Max
chat.ws.send	893ms	1.78s
chat.message.send	788ms	1.51s
chat.message.read	45.2ms	340ms

chat.message.readが特に顕著である。平均45msなのに最悪340msと7.5倍の差がある。当時CPU 99.9%、HikariCPコネクション待機 Max 600msだった

まとめ

観測：CPU 99.9%、HikariCP Acquire Max 600ms、同期パスのスパイク1.78s。解釈：非同期ブロードキャストでメンバー50人に対して個別クエリを実行するN+1問題が根本原因と見られた。その後HibernateログのAnalysisでメッセージ1件あたり642件のクエリを確認し、この仮説が検証された。N+1がCPU飽和とスレッドプール飽和の両方を引き起こしている可能性が高いため、まずクエリ数を削減することを優先課題とした。

1次改善

改善箇所を特定するために、別途簡易テストを実施した

テスト条件

ルームメンバー：50人
sender 1人、listener 2人（オンライン3人 / オフライン47人）
メッセージ3件送信

テスト分析

Hibernateログ分析

まずHibernateログを抽出した
同一クエリが繰り返されるパターンが見られる
これについて分析を行ったところ
Hibernate: で始まる行をカウントすると1,926件
メッセージ3件送信のため、1件あたり平均642クエリ

クエリ	3件合計	1件あたり	パターン
`SELECT users WHERE id=?`	297	99	メンバー別ユーザー照会
`SELECT count(*) FROM user_blocks`	294	98	メンバー別ブロック確認
`SELECT count(messages) LEFT JOIN user_blocks`	153	51	メンバー別未読数
`SELECT user_location_history`	147	49	メンバー別位置確認
`SELECT user_devices`	147	49	メンバー別デバイス照会
`UPDATE user_devices SET badge_count+1`	147	49	メンバー別バッジ増加
`SELECT global_notification_settings`	147	49	メンバー別通知設定
`SELECT room_notification_mutes`	147	49	メンバー別ミュート確認
`SELECT connections`	147	49	メンバー別接続関係
`INSERT INTO notifications`	147	49	メンバー別通知保存
`SELECT room_members` (JOIN users)	12	4	ルームメンバー一覧照会
`SELECT rooms`	14	~5	ルーム情報照会
`INSERT INTO messages`	3	1	メッセージ保存
`UPDATE rooms`	3	1	ルームのlast_message_at更新
`UPDATE room_members`	3	1	既読処理
その他	~118	~39	roomsの追加SELECT、Hibernate内部flushなど

正確に49回繰り返すクエリ

繰り返されるクエリがあり、これらは全て49回繰り返されている
しかしテスト条件ではオンラインユーザーは3人だけである。なぜだろうか？
49回 = ルームメンバー50人 - sender 1人。オンライン/オフラインの区別なく、全メンバーに同じ処理をしている

ルームメンバー50人、sender 1人、listener 2人（オンライン3人 / オフライン47人）

~~（実はテスト前は、当然オンラインユーザー3人にだけクエリが発生すると思っていた）~~

コード追跡

メッセージ送信のエントリーポイントであるMessageService.sendMessage()を追っていった

ここで非同期ロジックだけを見ると

（同期は全て単件の照会であるため、今の過程では省略した）

publishNotifications(savedMessage, roomId, userId, user, parentMessage, mentionedUsers);


publishMessageSentEvent(response, room, member, request.parentMessageId());
        roomListEventPublisher.publishMessageSent(roomId, savedMessage);

以下のように非同期メソッドハンドラ3つがトリガーされる

1. NotificationFallbackHandler

問題のコードを発見した

 List<User> recipients = activeMembers.stream()
                    .filter(member -> !member.getUser().getId().equals(senderId))
                    .filter(member -> canReceiveNotification(member, roomLocationId))
                    .map(RoomMember::getUser)
                    .toList();

            recipients.forEach(user ->
                    notificationService.sendMessageNotification(user.getId(), room, sender, message));

以下のコードで内部ユーザーの数（recipients.length()）だけnotificationService.sendMessageNotification(user.getId(), room, sender, message));を呼び出している

このメソッドの内部を要約すると

notificationStorageService.saveMessageNotification(...);   // 通知保存
shouldSkipNotification(recipientUserId, room.getId(), ...); // 通知スキップ判定
userDeviceRepository.incrementBadgeCountByUserId(...);      // バッジ +1
pushNotificationService.sendLocalizedNotificationToUser(...); // プッシュ送信

一つ一つ見ていくと

notificationStorageService.saveMessageNotification()

これが上記のNotificationFallbackHandlerのforループ内で49回（全ユーザー分）呼び出される
しかしN回呼び出してもメッセージ送信者（sender）は変わらない。それにもかかわらず毎回照会し続けている
ループの外で一度送信者を照会して変数に入れれば、このN回のクエリがなくなる

shouldSkipNotification()

1人あたり2クエリが発生する（ミュート確認、グローバル通知設定確認）
つまり49人分で98件のクエリがここで発生する

ループを回す前に49人分をまとめてIN句で取得する

// Before: 49回個別照会
for (User user : recipients) {
    shouldSkipNotification(user.getId(), roomId, type);
}
// After: 2クエリで完結
Set<Long> mutedUserIds = roomMuteRepository.findMutedUserIds(recipientIds, roomId);
Map<Long, Settings> settingsMap = globalSettingsRepository.findAllByUserIdIn(recipientIds);

userDeviceRepository.incrementBadgeCountByUserId(...)

更新を1人あたり1クエリ実行している。つまり49人分で49クエリ
これもIN句を使用して1クエリに変換する

pushNotificationService.sendLocalizedNotificationToUser(...);

ここでも1人あたり1クエリ、49人分で49クエリが発生する
WHERE user_id IN (...) で1クエリに変換する

2. ConnectionMessageEventHandler

for (RoomMember member : activeMembers) {
   Long otherUserId = member.getUser().getId();

  if (otherUserId.equals(senderId)) {
                    continue; }

  boolean isMention = mentionedUserIds.contains(otherUserId);
                connectionService.addChatInteraction(senderId, otherUserId, locationId, roomType, isMention);
}

addChatInteraction() を追っていくと

以下のように双方向で互いにブロックしているかどうかを確認するために、クエリが2回発行されている
ループ前にsender関連のブロック関係を一度にまとめて取得する

  // Before: 49 × 2 = 98クエリ
  for (member : activeMembers) {
      blockValidator.isBlockedEitherWay(senderId, otherUserId);
  }
  // After: 1クエリ
  Set<Long> blockedUserIds = userBlockRepository
      .findAllBlockedPairs(senderId, memberIds);
  // → SELECT * FROM user_blocks
  //   WHERE (blocker_id = :senderId AND blocked_id IN (:memberIds))
  //      OR (blocker_id IN (:memberIds) AND blocked_id = :senderId)


        Connection connection = connectionRepository
                .findByUserIdSmallAndUserIdLarge(smallId, largeId)
                .orElse(null);

このクエリもforループの外に出すことで、49回呼び出していたものを1回で取得できる

3. RoomListEventPublisher

ここも同様の流れである

calculateUnreadCount()

private int calculateUnreadCount(Long roomId, Long userId, Message newMessage) {
      if (newMessage.getSender().getId().equals(userId)) return 0;  // senderはクエリしない
      Long count = messageRepository.countUnreadMessages(roomId, userId);  // 残りの49人
  }

SELECT count(messages) LEFT JOIN user_blocks — 4テーブルJOINする重いクエリ
- senderは0を返すためクエリなし、残り49人 × 1クエリ = 49クエリ
- 解決：ルーム全体のunread countを一度にまとめて照会する
buildSnapshot() → roomMemberRepository.findById()

// RoomListEventPublisher.java:168-171
  RoomMember member = roomMemberRepository.findById(
      new RoomMemberId(room.getId(), userId)
  ).orElse(null);  // isPinned, sortOrderを取得するために

50人全員 × 1クエリ = 50クエリ
しかしループの外側48行目で既にfindAllActiveByRoomId()で全員を照会していた
同じデータを既に持っているのに、また個別に照会している
解決策：既に照会したメンバーリストをMapに変換して再利用する

  // Before: 50クエリ
  for (RoomMember member : members) {
      roomMemberRepository.findById(new RoomMemberId(roomId, userId));
  }
  // After: 0クエリ（既存データを再利用）
  Map<Long, RoomMember> memberMap = members.stream()
      .collect(Collectors.toMap(m -> m.getUser().getId(), m -> m));

改善まとめ

ループの外に出す — 毎回同じ値（sender）を照会 → 1回照会して変数に格納
IN句で一括照会 — 49回の個別SELECT → WHERE id IN (...) 1クエリ
既存データの再利用 — 照会済みなのにまた照会 → Mapに変換

1次改善後の結果

同じbaselineテストを再度実行した

k6

指標	Before	After	基準	判定
RTT Avg	6,410ms	10,610ms	< 500ms	FAIL
RTT Med	-	10,200ms	-	-
RTT P95	9,680ms	13,330ms	< 1,000ms	FAIL
RTT Max	10,050ms	13,750ms	-	-
Error Rate	24%	0%	< 1%	PASS
Messages Sent	50件	50件	-	-
Messages Received	38件	50件	50件	消失0件
Connection Time	233ms	744ms	-	-

エラー率が24% → 0%、メッセージ消失が12件 → 0件に完全に解消された。TaskRejectedExceptionによるブロードキャスト漏れがなくなった
しかしRTTが6.4秒 → 10.6秒とむしろ悪化した。原因は2つある：
1. 計測範囲の変化：Beforeでは遅いメッセージ12件がタイムアウトで消失し、RTT計測から除外されていた。Afterでは50件すべてが最後までキューで待機するためRTTに含まれ、平均が上がった
2. サーバー処理時間自体の悪化：消失がなくなったことで非同期処理がすべて実行され、HikariCPコネクションプールが飽和（Active 10/10、Avg Acquire 133µs→602ms）した。コネクション待機時間が同期経路（893ms→1.29s）と非同期経路（313ms→2.44s）の両方を遅くした（下記詳細分析）

Grafanaサーバーメトリクス

同期経路 — ユーザーが待つ区間

同期処理パイプライン — 平均所要時間

Name	Before Mean	Before Max	After Mean	After Max
chat.ws.send（全体）	893 ms	1.12 s	1.29 s	1.29 s
chat.message.send（トランザクション）	788 ms	1.01 s	350 ms	350 ms
chat.message.read（既読処理）	45.2 ms	47.1 ms	188 ms	188 ms
chat.message.response.build（レスポンスビルド）	352 µs	446 µs	3.14 ms	3.14 ms
chat.hashtag.process（ハッシュタグ）	95.2 µs	121 µs	114 µs	114 µs

After列でMean=Maxになっている理由：Grafanaのscrapeインターバル（15秒）内にデータポイントが1つしかなかったためだ。約10秒のテストでは十分に起こりうる現象であり、厳密には「平均」ではなくそのインターバルの単一計測値だ。したがって、Before（複数データポイントの実際の平均）とAfter（単一計測値）の比較は信頼度が同一ではない。 変化の方向（改善／悪化）は参考にできるが、正確な比率として解釈すべきではない。

同期処理 — Max所要時間（スパイク検出）

Name	Before Mean	Before Max	After Mean	After Max
chat.ws.send MAX	185 ms	1.78 s	3.71 s	3.71 s
chat.message.send MAX	121 ms	1.19 s	962 ms	962 ms
chat.message.send MAX (TaskRejected!)	157 ms	1.51 s	-	-
chat.message.response.build MAX	209 µs	2.03 ms	20.3 ms	22.7 ms
chat.hashtag.process MAX	118 µs	1.15 ms	4.61 ms	4.61 ms
chat.message.read MAX	35.2 ms	340 ms	460 ms	460 ms

非同期経路（ブロードキャスト）

非同期処理 — 平均所要時間

Name	Before Mean	Before Max	After Mean	After Max
chat.event.message.sent（イベントハンドラ）	313 ms	401 ms	2.44 s	2.44 s
chat.broadcast.room（ブロードキャスト）	202 ms	255 ms	928 ms	928 ms

サーバースループット

Name	Before Mean	Before Max	After Mean	After Max
メッセージ処理/s	0.0261 ops/s	2.33 ops/s	0.300 ops/s	1.20 ops/s
ブロードキャスト/s	0.0261 ops/s	2.33 ops/s	0.417 ops/s	1.67 ops/s
TaskRejected/s	0.00825 ops/s	0.800 ops/s	0 ops/s	0 ops/s

インフラ — JVM / DB / CPU

JVM Heap Memory

	After
Used	136 MiB
Committed	287 MiB
Max	512 MiB

前回のテストで欠測

GC Pause Time

	After
GC Time/s (G1 Evacuation Pause)	3.30 ms
GC Max Pause (G1 Evacuation Pause)	40 ms

前回のテストで欠測

HikariCPコネクションプール

Active	Idle	Pending	Total	Avg Acquire	Max Acquire
Before: 7	3	0	10	56.6ms	600ms
After: 10	0	0	10	602ms	3.18s

CPU

	Before	After
JVM	62.1%	77.0%
System	99.9%	99.1%

JVM Threads

	Before	After
Live	67	73
Peak	76	73
Daemon	32	39

Hibernate Query

	Before	After
Queries/s	919 ops/s	181 ops/s
Inserts/s	105 ops/s	75.5 ops/s
Loads/s	1.22K ops/s	657 ops/s
Statements/s	-	287 ops/s

DB Connection Acquire Time

	Before	After
Avg Acquire	133 µs	602 ms
Max Acquire	600 ms	3.18 s
Max Usage	-	3.76 s

hibernateログ分析

テスト条件

ルームメンバー：50人
sender 1人、listener 2人（オンライン3人 / オフライン47人）
メッセージ3件送信
前回と同じテストでhibernateログを抽出して分析した

| | Before | After | 変化 |
|--|--------|-------|------|
| 総クエリ数 | 1,926 | 582 | -70% |
| 1件あたりクエリ数 | 642 | 194 | -70% |
| クエリ | Before合計 | After合計 | Before 1件あたり | After 1件あたり | 変化 |
|------|------------|-----------|-------------|------------|------|
| SELECT users WHERE id=? | 297 | 3 | 99 | 1 | -98 |
| SELECT count(*) FROM user_blocks | 294 | 9 | 98 | 3 | -95 |
| SELECT count(messages) LEFT JOIN user_blocks | 153 | 12 | 51 | 4 | -47 |
| SELECT user_devices | 147 | 3 | 49 | 1 | -48 |
| UPDATE user_devices (badge++) | 147 | 3 | 49 | 1 | -48 |
| SELECT global_notification_settings | 147 | 3 | 49 | 1 | -48 |
| SELECT room_notification_mutes | 147 | 3 | 49 | 1 | -48 |
| SELECT user_location_history | 147 | 150 | 49 | 50 | 1次未改善対象。49→50はsender含有有無の差（2〜3次で解決） |
| SELECT connections | 147 | 150 | 49 | 50 | 1次未改善対象。49→50はsender含有有無の差（2〜3次で解決） |
| INSERT INTO notifications | 147 | 147 | 49 | 49 | 同一 |
| SELECT room_members JOIN users | 12 | 12 | 4 | 4 | 同一 |
| SELECT room_members (unread count) | - | 12 | - | 4 | 新規 |
| SELECT rooms | 14 | 12 | ~5 | 4 | ほぼ同じ |
| INSERT INTO messages | 3 | 3 | 1 | 1 | 同一 |
| UPDATE rooms | 3 | 3 | 1 | 1 | 同一 |
| UPDATE room_members | 3 | 3 | 1 | 1 | 同一 |
| その他 | ~118 | ~54 | ~39 | ~18 | 減少 |
7つのクエリがIN句への移行で大幅に減少したが、3つのループ内繰り返しクエリパターンがそのまま残っている：
SELECT connections（50/msg）：メンバーごとの接続関係を個別SELECT（N+1）
SELECT user_location_history（50/msg）：メンバーごとの位置確認を個別SELECT（N+1）
INSERT INTO notifications（49/msg）：メンバーごとの通知を個別INSERT（ループ内個別INSERT）
582クエリのうち**447クエリ（77%）**がこの3つのパターンだ。

1次改善後の結果分析

何が改善されたか？

	Before	After	変化
クエリ/メッセージ	642	194	-70%
Hibernate Queries/s	919 ops/s	181 ops/s	-80%
エラー率	24%	0%	解決
リアルタイム配信漏れ	12件	0件	解決
TaskRejected	発生	0	解決

まずクエリが大幅に改善された
1次改善の核心的な成果は安定性だ
7つのループ内繰り返しクエリ（N+1 SELECT + 個別INSERT/UPDATE）をIN句での一括照会に移行したことでクエリ数が70%減少し、非同期スレッドプールの飽和が解消されてメッセージ消失が完全になくなった

何が改善されなかったか

	Before	After
RTT Avg	6.4s	10.6s
同期経路（ws.send）	893ms	1.29s
非同期経路（event.sent）	313ms	2.44s
HikariCP Avg Acquire	133µs	602ms
CPU（System）	99.9%	99.1%

After列は単一scrapeポイント（Mean=Max）のため、正確な比率比較よりも変化の方向（改善／悪化）を把握する用途で読むべきだ。
RTTがむしろ悪化した。
消失がなくなったことですべてのメッセージがキューで待機するようになったことが直接的な原因と考えられる
根本的には依然としてサーバーが入力速度に追いつけていない状態だ（HikariCPの飽和、非同期経路の悪化がこれを裏付けている）

コネクションプールの飽和：Beforeより深刻になった

最も目立つ悪化指標はHikariCPだ

	Before	After
Active	7/10	10/10
Idle	3	0
Avg Acquire	133µs	602ms
Max Acquire	600ms	3.18s

BeforeではActive 7、Idle 3と余裕があったが、AfterではActive 10/10、Idle 0だ。コネクションプールが完全に飽和した。Avg Acquireが133µs → 602msと約4,500倍遅くなった
Beforeでは非同期処理の多くがTaskRejectedExceptionで即座に破棄されていたため、コネクションを確保しなかった。Afterでは非同期処理がすべて実行され、コネクション10本を同時に占有するようになった。消失をなくした代わりに、コネクションプールがボトルネックとして浮上した。

残りのN+1がボトルネックの77%

582クエリのうち447クエリ（77%）が3つのループ内繰り返しクエリパターンだ：

SELECT connections（50/msg）：メンバーごとの接続関係を個別SELECT（N+1）
SELECT user_location_history（50/msg）：メンバーごとの位置共有を個別SELECT（N+1）
INSERT INTO notifications（49/msg）：メンバーごとの通知を個別INSERT（ループ内個別INSERT — 従来のN+1と異なり、SELECTではなくINSERTが繰り返されるパターン）
この3つはすべてConnectionMessageEventHandlerとNotificationFallbackHandlerで発生している。コードを追跡してみた。

1. connectionsの個別SELECT（147件）

ConnectionMessageEventHandlerでは既に1次改善でbatch INクエリを追加していた：

// ConnectionMessageEventHandler.java:82-87 — 1次改善で追加したbatch照会
Map<Long, Connection> connectionMap = connectionRepository
        .findAllByUserIdAndTargetIds(senderId, otherMemberIds).stream()
        .collect(Collectors.toMap(c -> c.getOtherUserId(senderId), Function.identity()));

ログでもこのbatchクエリが実行されていることを確認できる：

Hibernate: select ... from connections c1_0 where (c1_0.user_id_small=? and c1_0.user_id_large in (49個)) or ...

しかしループ内でaddChatInteractionWithConnection()を呼び出す際、connectionMap.get(otherUserId)がnullの場合（connectionが存在しないユーザー）、existingパラメータにnullが渡される：

// ConnectionMessageEventHandler.java:99-101
Connection existing = connectionMap.get(otherUserId); // null（connectionなし）
connectionService.addChatInteractionWithConnection(
        senderId, otherUserId, locationId, roomType, isMention, existing); // nullを渡す

するとConnectionService.addChatInteractionInternal()で

// ConnectionService.java:155-156
Connection connection = existing != null ? existing
        : connectionRepository.findByUserIdSmallAndUserIdLarge(smallId, largeId).orElse(null);
        // ↑ existingがnullのため個別クエリを再実行！

batchで既に「存在しない」と確認した結果を渡す手段がないため、再び個別クエリで確認するという完全な重複クエリだ。
テストユーザー49人のほとんどがsenderとのconnectionを持っていないため、49件 × 3メッセージ = 147件発生。

2. user_location_historyの個別SELECT（147件）

1でconnectionがnullと確定した後、新しいconnectionを作るかどうか決めるために共有位置を確認する：

// ConnectionService.java:159-160
if (connection == null) {
    List<Long> sharedLocationIds = userLocationHistoryRepository.findSharedLocationIds(smallId, largeId);
    // ↑ メンバーごとにサブクエリを1件ずつ実行

このクエリは2人のユーザーが共通して訪れた位置を探すサブクエリだ：

Hibernate: select ulh1_0.location_id from user_location_history ulh1_0 where ulh1_0.user_id=? and ulh1_0.location_id in (select ulh2_0.location_id from user_location_history ulh2_0 where ulh2_0.user_id=?)

connectionが存在しないユーザー49人 × 3メッセージ = 147件発生。

3. INSERT notifications 個別INSERT（147件）

NotificationFallbackHandlerでsaveAll()を呼び出す：

// NotificationFallbackHandler.java:158-163
List<Notification> notifications = finalRecipients.stream()
        .map(user -> Notification.createMessageNotification(...))
        .toList();
notificationRepository.saveAll(notifications); // バッチに見えるが…

コードはバッチのように見えるが、NotificationエンティティのID戦略がIDENTITYだ：

// Notification.java:21-23
@Id
@GeneratedValue(strategy = GenerationType.IDENTITY)
private Long id;

MySQLのAUTO_INCREMENTに依存するIDENTITY戦略では、HibernateがINSERT後に生成されたIDを即座に受け取る必要があるため、JDBC batch insertを使用できない。saveAll()を呼び出しても、実際のHibernateログでは49件の個別INSERTが観測された。

次の改善方針

connectionsの重複排除：batchで「存在しない」と確認した結果を渡せるようシグニチャを変更。existingがnullの場合に再クエリしないよう修正
user_location_historyのバッチ化：connectionが存在しないユーザーリストに対して共有位置を一括照会するバッチクエリを導入
notificationsのバッチINSERT：IDENTITY戦略ではHibernateバッチが不可能なため、native SQL INSERT INTO ... VALUES (...), (...), (...) またはSEQUENCE戦略への移行
コネクションプールのボトルネック解消：クエリ数の減少により自然に解消される見込み
非同期経路自体の最適化：ブロードキャストのRedis pipeline化、シリアライズの1回化など

2次改善 — SEQUENCE戦略の試み

1次で残ったループ内繰り返しクエリのうち、最もクエリ数が多いINSERT notifications（49件/msg）を先に解決しようとした。NotificationFallbackHandlerでnotificationRepository.saveAll()を呼び出しているが、NotificationエンティティのID戦略がGenerationType.IDENTITYのため、HibernateのJDBC自動バッチングが動作せず、実際のHibernateログでも49件の個別INSERTが観測されていた。

なぜIDENTITYではHibernateの自動batch insertができないのか？

MySQLのAUTO_INCREMENTを使用するIDENTITY戦略では、INSERTを実行してはじめてDBがIDを生成する。Hibernateは永続性コンテキストにエンティティを登録するためにIDが必要なため、INSERT → ID返却 → 永続性コンテキスト登録を1件ずつ行わなければならない。そのためsaveAll()を呼び出してもHibernateログ上で個別INSERTがN回実行されることが確認される。（Hibernateを迂回したnative/JDBC bulk INSERTは可能であり、後の3次ではこの方法で解決した。）

SEQUENCE戦略を試みた — そして失敗

「IDENTITYではbatch insertができない」とわかったので、次の疑問は「では何に変えるべきか？」だった。調べてみるとどこでも同じ答えが出てきた：
Vlad Mihalceaブログ（Hibernateコアコントリビューター）

How to batch INSERT statements with MySQL and Hibernate

"the entity identifier is assigned when calling persist by firing the INSERT statement right away, so when the Persistence Context is flushed and the ActionQueue attempts to batch the pending statements, there won't be any INSERT statement to be batched."

"MySQL doesn't support SEQUENCE objects, so using IDENTITY is the only reasonable option."

IDENTITYがなぜ機能しないかを内部動作まで説明しながら、同時に**「MySQLにはSEQUENCEがないのでIDENTITYが唯一の合理的な選択」**とも述べている。正確には、MySQL + IDENTITY戦略ではHibernateの自動JDBC batchingを期待しにくいという意味だ。（TABLE generator、assigned ID、またはHibernateを迂回したnative/JDBC bulk INSERTを使えばMySQLでもバッチは可能だ。このプロジェクトでは後の3次でJdbcTemplate bulk INSERTによって解決した。）

3. Baeldung — Batch Insert/Update with Hibernate/JPA

Batch Insert/Update with Hibernate/JPA

batch insertの設定方法を説明しながら、IDENTITY戦略では動作しないと明記。SEQUENCE戦略のサンプルを提示
これらの資料を見て、IDENTITY → SEQUENCEへの移行が正解だと判断した。SEQUENCEはINSERT前にIDを事前に払い出せるため、Hibernateが複数エンティティのIDをまとめて取得してbatch INSERTを実行できる。
しかしMySQLには本物のSEQUENCEが存在しない。
PostgreSQLやOracleはCREATE SEQUENCE構文をネイティブにサポートしているが、MySQLはサポートしていない。Hibernateはこれをテーブルエミュレーションで代替する：

-- Hibernateが内部的に実行するもの
CREATE TABLE notification_seq (next_val BIGINT);
-- IDが必要なたびに：
SELECT next_val FROM notification_seq FOR UPDATE;  -- 行ロック
UPDATE notification_seq SET next_val = next_val + 50;  -- allocationSize分増加

MySQLでSEQUENCEをテーブルベースでエミュレーションする過程で、今回の環境（Hibernate 6 + HikariCP 10個）ではID払い出し時に追加のコネクション競合が発生した。allocationSize=50の初期大量割り当てが重なり、コネクション待機が連鎖的に発生したと推定される。

2次結果：1次改善より深刻な後退

指標	1次改善	2次改善（SEQUENCE）
Error Rate	0%	70〜76%
Messages Received	50件	12〜15件
RTT Max	13,750ms	33,220ms
エラーログを確認すると、すべて同一だった：

HikariCP Connection is not available, request timed out after 30001ms

エラーログがすべてrequest timed out after 30001msであるため、コネクションプールの枯渇（pool exhaustion）によるresource starvationと考えられる。thread dumpやSQL traceで内部メカニズムを直接確認したわけではないため、以下はあくまで仮説だ：

スレッド1：[コネクションA占有] → notification_seqの払い出しのためコネクション待機
スレッド2：[コネクションB占有] → notification_seqの払い出しのためコネクション待機
...
スレッド10：[コネクションJ占有] → notification_seqの払い出しのためコネクション待機

このモデルが正しければ、各スレッドが既に確保しているコネクションを返却するにはシーケンス払い出しが完了する必要があり、シーケンス払い出しが完了するには別のスレッドがコネクションを返却する必要がある。現時点の証拠（エラーログ）だけでは、この追加コネクション待機型デッドロックまで断定することはできないが、テーブルベースSEQUENCEの動作特性とエラーパターンがこのシナリオと一致している。
allocationSize=50を使用しているため、正常状態では50回のINSERTごとに1回だけシーケンステーブルを照会する。しかしテスト開始時点で10以上のスレッドが同時に最初のシーケンス範囲を割り当てようとすると、初期バーストで競合が集中する。
IDENTITYでHibernateの自動JDBC batchingを期待しにくいためSEQUENCEを試みたが、MySQLではテーブルベースのエミュレーションとコネクション競合が重なり、むしろ状況が悪化した。

解決策：native SQL bulk INSERT

Hibernateを迂回してJDBCで直接multi-values INSERTを実行すれば、IDENTITY戦略を維持したまま1クエリですべて挿入できる

// NotificationBulkRepositoryImpl.java — JdbcTemplateを使用
String sql = "INSERT INTO notifications " +
    "(recipient_id, sender_id, type, title, body, ...) VALUES " +
    "(?,?,?,?,?,...), (?,?,?,?,?,...), ...";  // 49件を1文で
jdbcTemplate.update(sql, ps -> {
    int idx = 1;
    for (Notification n : notifications) {
        ps.setLong(idx++, n.getRecipient().getId());
        // ...
    }
});

IDENTITY戦略を維持 → 追加コネクション不要
HibernateのsaveAll()の代わりにbulkInsert()を呼び出す → 今回のテストでは49件が1つのmulti-row INSERTで送信される
デメリット：INSERT後にエンティティへ生成されたIDがセットされない。しかし通知保存後にIDを使用するロジックがないため問題なし
SEQUENCE戦略を試みる → 失敗 → IDENTITY + native bulk INSERTで最終解決。

3次改善 — bulkInsert + 残りの繰り返しクエリの解決

改善内容

2次でSEQUENCEが失敗したため、HibernateをJdbcTemplate bulkInsertで迂回する方式に切り替え、同時に1次で残っていたループ内繰り返しクエリ3つをすべて解決した

1. notifications → JdbcTemplate bulkInsert（49件 → 1件）

2次で説明した通り、Hibernateを迂回してJdbcTemplate.batchUpdate()でINSERTする。JDBC URLにrewriteBatchedStatements=trueを設定することで、MySQL JDBCドライバが個別のINSERT文をmulti-row VALUES形式に書き換える。今回のテストでは49件が実際に1つのINSERTとして送信された（ドライバ内部のbatch sizeによって分割される場合がある）。

@RequiredArgsConstructor
public class NotificationBulkRepositoryImpl implements NotificationBulkRepository {

    private final JdbcTemplate jdbcTemplate;

    @Override
    public void bulkInsert(List<Notification> notifications) {
        if (notifications.isEmpty()) {
            return;
        }

        String sql = "INSERT INTO notifications " +
                "(recipient_id, sender_id, type, title, body, title_key, body_key, body_params, " +
                "extra_data, room_id, message_id, reference_id, is_read, created_at, updated_at) " +
                "VALUES (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)";

        LocalDateTime now = LocalDateTime.now();
        Timestamp ts = Timestamp.valueOf(now);

        jdbcTemplate.batchUpdate(sql, notifications, 1000, (ps, n) -> {
            ps.setLong(1, n.getRecipient().getId());
            setNullableLong(ps, 2, n.getSender() != null ? n.getSender().getId() : null);
            ps.setString(3, n.getType().name());
            ps.setString(4, n.getTitle());
            setNullableString(ps, 5, n.getBody());
            setNullableString(ps, 6, n.getTitleKey());
            setNullableString(ps, 7, n.getBodyKey());
            setNullableString(ps, 8, n.getBodyParams());
            setNullableString(ps, 9, n.getExtraData());
            setNullableLong(ps, 10, n.getRoomId());
            setNullableLong(ps, 11, n.getMessageId());
            setNullableLong(ps, 12, n.getReferenceId());
            ps.setBoolean(13, Boolean.FALSE);
            ps.setTimestamp(14, ts);
            ps.setTimestamp(15, ts);
        });
    }
}

2. connectionsの重複SELECT排除（50件 → 1件）

ConnectionMessageEventHandlerでbatch INクエリによって既に「存在しない」と確認したconnectionを、ConnectionService.addChatInteractionInternal()で再び個別SELECTしていた問題。

addChatInteractionWithConnection()のシグニチャにList<Long> precomputedSharedLocationIdsを追加
addChatInteractionInternal()にconnectionPreloadedフラグを追加 — trueの場合は個別クエリをスキップ

3. user_location_historyの個別SELECT排除（50件 → 2件）

connectionが存在しないユーザー49人に対して、共有位置を個別サブクエリで確認していた問題。

ConnectionMessageEventHandlerでforループ進入前にsenderの位置リストを1クエリで照会
該当位置にいるメンバーの位置履歴をfindByUserIdInAndLocationIdIn()バッチクエリ1件で照会
結果をMap<Long, List<Long>>に変換してforループ内で渡す

k6結果

指標	Before	1次	2次（SEQUENCE）	3次（bulkInsert）
Error Rate	24%	0%	70〜76%	0%
RTT Avg	6,410ms	10,610ms	-	6,980ms
RTT P95	9,680ms	13,330ms	-	11,460ms
RTT Max	10,050ms	13,750ms	33,220ms	11,940ms
RTT Min	-	-	-	1,510ms
Messages Sent	50件	50件	-	50件
Messages Received	38件	50件	12〜15件	50件
リアルタイム配信漏れ	12件	0件	35〜38件	0件
Connection Time	233ms	744ms	-	422ms

Before・1次のRTTは、後に発見されたk6イベントループバグが含まれた値だ。3次のRTTはバグを修正したスクリプトで再計測した値のため、Before・1次と3次のRTT数値の比較は成立しない。エラー率・消失件数はk6バグと無関係のため比較可能だ

Grafanaサーバーメトリクス

同期経路 — ユーザーが待つ区間

同期処理パイプライン — 平均所要時間

Name	Before Mean	Before Max	1次 Mean	1次 Max	3次 Mean	3次 Max
chat.ws.send（全体）	893 ms	1.12 s	1.29 s	1.29 s	104 ms	104 ms
chat.message.send（トランザクション）	788 ms	1.01 s	350 ms	350 ms	56.7 ms	56.7 ms
chat.message.read（既読処理）	45.2 ms	47.1 ms	188 ms	188 ms	34.7 ms	34.7 ms
chat.message.response.build（レスポンスビルド）	352 µs	446 µs	3.14 ms	3.14 ms	148 µs	148 µs
chat.hashtag.process（ハッシュタグ）	95.2 µs	121 µs	114 µs	114 µs	31.1 µs	31.1 µs

1次と同様、3次列もMean=Maxであり単一scrapeポイントだ。特にchat.message.sendの56.7msは、その後の再計測（Prometheusカウンターベース、50件全体集計）では1,389msという結果になった。元の56.7msはテストの特定15秒区間に記録されたスナップショットに過ぎず、実際の負荷中の平均は再計測の1,389msに近い。本文で56.7msを引用している箇所はこの限界を踏まえて読む必要がある。

同期処理 — Max所要時間（スパイク検出）

Name	Before Mean	Before Max	1次, Mean	1次, Max	3次 Mean	3次 Max
chat.ws.send MAX	185 ms	1.78 s	3.71 s	3.71 s	52.9 ms	182 ms
chat.message.send MAX	121 ms	1.19 s	962 ms	962 ms	26.0 ms	81.9 ms
chat.message.response.build MAX	209 µs	2.03 ms	20.3 ms	22.7 ms	88.2 µs	299 µs
chat.hashtag.process MAX	118 µs	1.15 ms	4.61 ms	4.61 ms	39.3 µs	160 µs
chat.message.read MAX	35.2 ms	340 ms	460 ms	460 ms	29.9 ms	104 ms

非同期経路（ブロードキャスト）

非同期処理 — 平均所要時間

Name	Before Mean	Before Max	1次 Mean	1次 Max	3次 Mean	3次 Max
chat.event.message.sent（イベントハンドラ）	313 ms	401 ms	2.44 s	2.44 s	83.0 ms	83.0 ms
chat.broadcast.room（ブロードキャスト）	202 ms	255 ms	928 ms	928 ms	15.8 ms	15.8 ms

サーバースループット

Name	Before Mean	Before Max	1次 Mean	1次 Max	3次 Mean	3次 Max
メッセージ処理/s	0.0261 ops/s	2.33 ops/s	0.300 ops/s	1.20 ops/s	0.0952 ops/s	3.33 ops/s
ブロードキャスト/s	0.0261 ops/s	2.33 ops/s	0.417 ops/s	1.67 ops/s	0.0952 ops/s	3.33 ops/s
TaskRejected/s	0.00825 ops/s	0.800 ops/s	0 ops/s	0 ops/s	0 ops/s	0 ops/s

インフラ — JVM / DB / CPU

JVM Heap Memory

	Before	1次	3次
Used	-	136 MiB	263 MiB
Committed	-	287 MiB	288 MiB
Max	-	512 MiB	512 MiB

GC Pause Time

	Before	1次	3次
GC Time/s	-	3.30 ms	1.04 ms
GC Max Pause	-	40 ms	29 ms

HikariCPコネクションプール

	Before	1次	3次
Active	7	10	0
Idle	3	0	10
Pending	0	0	0
Total	10	10	10
Avg Acquire	56.6ms	602ms	167 µs
Max Acquire	600ms	3.18s	11.1 ms
Max Usage	-	3.76s	91 ms

CPU

	Before	1次	3次
JVM	62.1%	77.0%	14.1%
System	99.9%	99.1%	39.6%

JVM Threads

	Before	1次	3次
Live	67	73	57
Peak	76	73	66
Daemon	32	39	38

Hibernateクエリ

	Before	1次	3次
Queries/s	919 ops/s	181 ops/s	70.0 ops/s
Inserts/s	105 ops/s	75.5 ops/s	6.66 ops/s
Loads/s	1.22K ops/s	657 ops/s	1.53K ops/s
Statements/s	-	287 ops/s	150 ops/s

Queries/sが70に減ったのにLoads/sが1.53Kとむしろ2.3倍増加した理由：IN句バッチクエリ1件が50件のエンティティを一括ロードするためだ。クエリの「件数」は減ったが、クエリの「結果行数」（= entity loads）は増えた。1次キャッシュにより多くのエンティティが乗ることで、JVMヒープ使用量の増加（136→263 MiB）にも寄与した

DB Connection Acquire Time

	Before	1次	3次
Avg Acquire	133 µs	602 ms	167 µs
Max Acquire	600 ms	3.18 s	11.1 ms
Max Usage	-	3.76 s	91 ms

hibernateログ分析

同一条件（ルーム50人、sender 1人、listener 2人、メッセージ3件）でhibernateログを分析した。

	Before	1次	3次	変化
総クエリ数	1,926	582	138	-93%
1件あたりクエリ数	642	194	46	-93%
クエリ	Before 1件あたり	1次 1件あたり	3次 1件あたり	変化
`SELECT users`	99	1	1	同一
`SELECT user_blocks`	98	3	3	同一
`SELECT count(messages) LEFT JOIN`（unread）	51	4	0	削除
`SELECT user_location_history`	49	50	2	-48
`SELECT user_devices`	49	1	1	同一
`UPDATE user_devices (badge++)`	49	1	1	同一
`SELECT global_notification_settings`	49	1	1	同一
`SELECT room_notification_mutes`	49	1	1	同一
`SELECT connections`	49	50	1	-49
`INSERT INTO notifications`	49	49	0	-49（JdbcTemplate）
`SELECT room_members`	4	4	8	+4
`SELECT rooms`	~5	4	4	同一
`SELECT messages`	-	-	6	新規
`SELECT message_media`	-	-	2	新規
`SELECT user_suspensions`	-	-	1	新規
`SELECT user_location`（IN句）	-	-	1	新規
`INSERT message_read_receipts`	-	-	2	新規
その他	~5	~14	8	減少
`INSERT messages`	1	1	1	同一
`UPDATE rooms`	1	1	1	同一
`UPDATE room_members`	1	1	1	同一

1次で残っていたループ内繰り返しクエリ3つの解決

1次以降、582クエリの77%を占めていた3つの残存パターンがすべて解決された

INSERT notifications 49/msg → 0：JdbcTemplate batchUpdate()でHibernate外から1回実行。Hibernateログに記録されない
SELECT connections 50/msg → 1：batchで「存在しない」と確認されたnullを再度個別照会していた問題を修正
SELECT user_location_history 50/msg → 2：個別SELECTをuser_location IN句バッチ照会に置き換え

新たに追加されたクエリ

1次→3次の間に機能追加・変更によって生じたクエリだ。すべて固定回数（メンバー数に比例しない）のためN+1ではない

SELECT user_suspensions（1/msg）：セキュリティ監査後に追加。メッセージ送信時に停止ユーザーかどうかをチェック
SELECT message_media（2/msg）：メディア添付のlazy loading
INSERT message_read_receipts（2/msg）：既読処理がUPDATE room_membersから別テーブル（message_read_receipts）へ変更
SELECT messages（6/msg）：レスポンスビルド（サブタイプfull fetch）、unread count、最新メッセージ照会など
SELECT user_location IN句（1/msg）：user_location_historyの個別50件を置き換えるバッチ照会
SELECT room_members（4→8/msg）：unread count bulkクエリ、findById追加呼び出し

3次改善まとめ

何をしたか

1次で残っていたループ内繰り返しクエリ3つを解決した

INSERT notifications 49件/msg → JdbcTemplate batchUpdate() 1回
SELECT connections 50件/msg → nullの重複照会を排除
SELECT user_location_history 50件/msg → IN句バッチ照会に置き換え
加えてJDBC URLにrewriteBatchedStatements=trueを設定し、batchUpdate()が内部的にmulti-row INSERTとして書き換えられるようにした

何が改善されたか

以下の3次数値はGrafanaの単一scrapeスナップショットだ。その後、同一条件での再計測ではchat.message.send avg=1,389msと確認されているため、絶対的な平均値というよりボトルネックの変化方向を示す参考値として読むべきだ。

	Before	1次	3次（Grafanaスナップショット）	3次（再計測）
クエリ/メッセージ	642	194	46（-93%）	—
Error Rate	24%	0%	0%	0%
リアルタイム配信漏れ	12件	0件	0件	0件
同期経路（chat.message.send avg）	893ms	1.29s	104ms（スナップショット）	1,389ms
非同期経路（chat.event.message.sent avg）	313ms	2.44s	83ms	—
CPU（System）	99.9%	99.1%	39.6%	—
HikariCP Avg Acquire	133µs	602ms	167µs	—
Hibernate Inserts/s	105	75.5	6.66（-94%）	—

同期経路：Grafanaスナップショット104msと再計測1,389msの乖離が大きい。スナップショットはテスト後半に負荷が抜けた15秒区間の単一ポイントであり、再計測は50件全体処理のPrometheusカウンターベースの平均だ。実際の負荷中の性能は再計測の1,389msに近い
コネクションプールの飽和が完全に解消（Active 10/10 → 0/10）
CPU 60%の余裕
クエリ数93%削減、安定性確保

しかし問題がある

RTTが依然として7秒だ

	Before	1次	3次
RTT Avg	6,410ms	10,610ms	6,980ms

当時のGrafanaスナップショットだけを見ると、同期104ms・非同期83msと処理区間が数百ms程度まで下がったように見えた。しかしその後の再計測では3次のchat.message.send avgが1,389msと出ており、3次時点でも同期経路のボトルネックが完全に解消されたわけではなかった。ただし、クエリ数の削減と安定性の改善が大幅に進んだことは明らかだった。実測RTTは6,980msで、大部分がキュー積滞・待機遅延と見るのが合理的だ

入力速度：   5 msg/s（200ms間隔で50件）
サーバーピーク：   3.33 msg/s
→ 毎秒1.67件ずつ積み残し
→ 50件目のメッセージは前49件が終わるまで待機

クエリを93%削減してサーバー処理自体は速くなったが、スループット（throughput）が入力速度に追いつけていない
当時のGrafanaスナップショットだけを見ると同期経路が数百ms程度まで縮小したように見えたが、その後の再計測では3次のchat.message.send avgが1,389msと確認され、同期経路のボトルネックが依然として残っていた

ボトルネックの転換：Before〜3次の主なボトルネックはDB/N+1クエリ（642→46件/msg）だった。4次からはクエリ自体よりも同期経路の構造的占有、イベントfan-outパターン、キューイングがボトルネックの中心となる。以降の改善は「クエリを減らすこと」から「アーキテクチャを変えること」へと性格が変わる

4次改善 — 非同期ハンドラのオンラインフィルタリング + Passive Session

計測条件の注意：4次の元のk6テストではlistener 19人が/app/room/enterを送信せずpassiveとして処理された。後半の再計測（3次〜6次比較表）は全員activeの条件で統一しているため、4次本文の数値と再計測の数値を直接紐付けて読んではいけない

なぜ必要か

3次までクエリを93%削減してサーバー処理自体は速くなったが、RTTは依然として7秒だ。残るボトルネックはすべてのオンラインユーザーに同じようにフルメッセージを送る構造だ。
例えば渋谷ルームにメッセージが届いたとき

ユーザーA：渋谷ルームでチャット中（このルームを見ている）→ 全メッセージが必要（画面に表示する必要がある）
ユーザーB：アプリは起動しているが1:1チャットを見ている（渋谷ルームは見ていない）→ unread count +1だけ必要
ユーザーC：アプリがバックグラウンド（オフライン）→ プッシュ通知だけ必要
しかし現在のサーバーはユーザーAとBを区別しない。どちらも「オンライン」のため、同じようにフルメッセージペイロードをシリアライズして送信する。

状態	条件	必要なデータ
Active	WebSocket接続 + 該当ルームを見ている	全メッセージ + unread count
Passive	WebSocket接続 + 別のルームを見ている	unread countのみ
Offline	WebSocket未接続	プッシュ通知 + DB保存

大規模リアルタイムサービスでもactive/passive区別によって不要なfan-outを削減するパターンが使われている。Discordエンジニアリングブログによると、100万人以上が接続したサーバーで90%以上の接続がpassiveであり、これを識別してgatewayトラフィックを削減したとのことだ。規模とアーキテクチャ（sharding、gateway fanoutなど）はこのプロジェクトと大きく異なるが、「見ていないユーザーには軽いデータだけ送る」というアイデアを参考にした。

既存インフラ：RoomPresenceService

このプロジェクトには既にルームごとのactiveユーザー追跡インフラが存在する。
現在RoomPresenceServiceがRedis SETで管理している。

Redis Key	タイプ	用途	TTL
`ws:room:{roomId}`	SET	該当ルームを現在見ているユーザーID一覧	1時間
`ws:user:{userId}:rooms`	SET	ユーザーが現在見ているルームID一覧	1時間

クライアントがルームを開くと/app/room/enter → enterRoom() → Redis SETに追加
ルームを閉じると/app/room/leave → leaveRoom() → Redis SETから削除
TTL 1時間：RedisのTTLはキー単位で適用されるため、他のユーザーの活動によってキーのTTLが更新されると、異常終了したユーザーのIDがSET内により長く残る可能性がある。heartbeatベースの個別メンバー削除は未実装であり、キー期限切れ時に一括削除される構造だ

このインフラをブロードキャストに活用すればよい。

改善内容

1. Passive Session

RoomPresenceService.getActiveUserIds(roomId)で現在ルームを見ているユーザーを照会し、activeユーザーにのみ全メッセージを送信する。

// ChatEventHandler.java:63-78
Set<Long> activeUserIds = roomPresenceService.getActiveUserIds(roomId);
boolean hasActiveUsers = !activeUserIds.isEmpty();
broadcastHelper.broadcastToRoomMembers(roomId, QUEUE_MESSAGES, memberId -> {
    // unread countは全員に常に送信
    broadcastHelper.sendToUser(memberId, QUEUE_UNREAD, unreadCountResponse);
    // activeユーザーがいるのにこのメンバーがactiveでない → passive → fullメッセージをスキップ
    if (hasActiveUsers && !activeUserIds.contains(memberId)) {
        return null;
    }
    // activeユーザーのみ全メッセージを受信
    return WebSocketMessageResponse.of(personalizedMessage, unreadCount);
});

デプロイ後に発覚：ensureActiveInRoom()
初回デプロイ時にすべてのメッセージがpassiveとして処理される問題が発生した。activeUserIdsが常に空だった。

原因 k6テストでlistener 19人はWebSocket接続のみ行い、/app/room/enterを送信しない。senderも同様だった。誰もenterRoom()を呼び出さないため、ws:room:{roomId} SETが空のままだった
防御ロジック（hasActiveUsersがfalseの場合は全員に送信）は機能していたが、これではpassive sessionの効果がない
解決策ChatWebSocketService.sendMessage()でメッセージ送信時にroomPresenceService.ensureActiveInRoom(senderId, roomId)を呼び出すよう追加した。メッセージを送信するユーザーは必ずそのルームを見ているため、送信時点で自動的にactive登録するのが適切だ

// ChatWebSocketService.java:54
roomPresenceService.ensureActiveInRoom(senderId, request.roomId());

防御ロジック：activeUserIdsが空の場合（誰もroom enterしていない状態）は全員に送信

2. NotificationFallbackHandler — オンラインユーザーのフィルタリング

// NotificationFallbackHandler.java:96
.filter(m -> !broadcastHelper.isUserOnline(m.getUser().getId()))

オンラインユーザーはWebSocketで既に受信しているため、オフラインユーザーにのみプッシュ通知を送信
50人中20人オンライン → プッシュ対象が30人に縮小

3. RoomListEventPublisher — オンラインユーザーにのみルームリスト更新

// RoomListEventPublisher.java:54
.filter(m -> broadcastHelper.isUserOnline(m.getUser().getId()))

オフラインユーザーにリアルタイムのルームリスト更新を送っても意味がない
50人 → 20人にイベント対象を縮小

テスト条件

既存のblogテストと完全に同一ではない

同一の条件

ルームメンバー：50人
同時接続：20人（sender 1 + listener 19）
メッセージ：50件、200ms間隔
k6スクリプト：同一
インフラ：同一EC2（2コアARM)

変わった条件（サーバーコード変更）

項目	Before（元のテスト）	After（4次改善）
fullメッセージブロードキャスト	20人全員	sender 1人のみ（19人はpassive → unreadのみ）
プッシュ通知対象	49人（sender除く全員）	30人（オフラインのみ）
ルームリスト更新対象	50人全員	20人（オンラインのみ）
Connectionクエリ	49 × 2 = 98クエリ（N+1）	2クエリ（batch IN）
Notification INSERT	49 × 個別INSERT	1 bulk INSERT
Redisキャッシュ	なし	依然としてなし
Virtual Threads	なし	依然としてなし
Hibernate batch	なし	依然としてなし

listener 19人は/app/room/enterを送信しないためpassiveユーザーとして処理される。senderのみensureActiveInRoom()でactive登録される。そのためサーバーがメッセージ1件あたりに行う作業量自体が以前のテストより少ない。 以前のテストと同一条件で比較するには、listenerもroom enterを行う必要がある

k6結果

指標	Before	1次	3次	4次
RTT Avg	6,410ms	10,610ms	6,980ms	7,780ms
RTT P95	9,680ms	13,330ms	11,460ms	12,760ms
RTT Max	10,050ms	13,750ms	11,940ms	13,010ms
RTT Min	-	-	1,510ms	1,730ms
Error Rate	24%	0%	0%	0%
Messages Sent	50件	50件	50件	50件
Messages Received	38件	50件	50件	50件
Connection Time	233ms	744ms	422ms	858ms

Before・1次はk6バグが含まれたスクリプトの値だ。3次・4次はバグを修正したスクリプトでall-active条件（listenerもroom enter）で再計測した値だ。本文で説明したpassive sessionは4次で導入したサーバー側の改善であり、上記のk6数値はその効果を計測したものではなく、同一条件での再計測結果だ。Before・1次と3次・4次のRTT数値の比較は成立しない

分析

安定性：維持

エラー率0%、消失0件。1次改善以降、安定性は継続して維持されている
TaskRejectedExceptionの発生なし

RTT：数値上は1次より低くなったが、条件が異なる

4次再計測のRTT（7.78s）は以前の次数と直接数値比較が難しい。Before・1次はk6バグが含まれたスクリプトベースであり、4次はバグを修正したスクリプトでall-active条件で再計測した値だ。計測ツールとテスト条件の両方が異なるため、RTTの変化率を算出することに意味はない。確実なのは、エラー率0%・消失0件が維持されているという点と、RTT 7.78sという値自体が依然として目標（500ms）に大きく届いていないという点だ。

なぜRTTが依然として7〜8秒なのか

サーバーの処理量が減ったにもかかわらずRTTが依然として高い理由は、根本的なボトルネックが解決されていないからだ。 同期経路ではRedisキャッシュなしに毎回DBを照会し、非同期経路ではisUserOnline()をメンバーごとに個別のRedis RTTで叩いており、スレッドプールも固定サイズ（core=5、max=20）のためメッセージごとに4つのハンドラが競合する。まだ手をつけていない部分が多い。

キュー積滞 — 根本原因

入力：200ms間隔（5 msg/s）
メッセージ1件あたりのサーバー処理：
  同期経路：DBクエリ10件、キャッシュなし
  非同期ハンドラ4つ：
    ├─ ChatEventHandler：             50人を巡回、hasKey() × 50
    ├─ NotificationFallbackHandler：  30人プッシュ
    ├─ ConnectionMessageEventHandler： batchクエリ
    └─ RoomListEventPublisher：       20人 × unread countクエリ

サーバーの1件あたりの処理速度が入力間隔（200ms）を超えるとキューが積み上がる。k6のRTTがmin 1,730msからmax 13,010msまで開いているのが、このキュー積滞の結果だ
非同期スレッドプール（core=5、max=20、queue=200）がハンドラを並列処理するが、DBコネクションプール（HikariCP 10個）を共有するため、実際の並列性は限定的だ

passive sessionの効果はどこに？

注意：4次テストではlistener 19人が/app/room/enterを送信せずpassiveとして処理された。つまりsender 1人だけがactiveな状態でテストが進行したため、構造改善の効果とテスト負荷削減の効果が混在している。以前の次数（全員にfullメッセージをブロードキャスト）との定量比較指標として使いにくいという限界がある。

4次再計測のRTTは7.78sだ。1次（10.61s）と直接比較はできないが（計測ツール・条件が異なる）、passive sessionでサーバー負荷自体は減少した：
- fullメッセージのシリアライズ：20回 → 1回（JSON シリアライズのCPU節約）
- messagingTemplate.convertAndSendToUser()：20回 → 1回（STOMPフレーム送信の節約）
しかしbroadcastToRoomMembersのforループ自体は依然として50人を巡回し、hasKey() 50回、sendToUser(QUEUE_UNREAD) 20回はそのまま実行される

5次改善 — Virtual Threads + Redis @Cacheable

仮説

4次改善までの分析で残ったボトルネックは2つだった：

非同期スレッドプールの競合：AsyncConfigのThreadPoolTaskExecutor(core=5、max=20)でメッセージ1件あたり@Asyncハンドラが4つトリガーされる。50件連続送信では200個の非同期タスクが5〜20スレッドで競合する。CPUは42%と余裕があるのに、スレッドプールのせいでリソースを使いきれていない
DBクエリの繰り返し：同期経路でUser/Room/RoomMemberをメッセージごとにDB照会。非同期経路でもfindAllActiveByRoomId()を再度呼び出している
Virtual Threadsでスレッドプールのボトルネックを排除し、Redis @Cacheableで繰り返しDBクエリをキャッシュすることが目標だった。

改善内容

1. Virtual Threads — スレッドプールのボトルネック排除

// AsyncConfig.java — Before
@Override
public Executor getAsyncExecutor() {
    ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
    executor.setCorePoolSize(5);
    executor.setMaxPoolSize(20);
    executor.setQueueCapacity(200);
    return executor;
}

// AsyncConfig.java — After
@Override
public Executor getAsyncExecutor() {
    return Executors.newVirtualThreadPerTaskExecutor();
}

@Asyncハンドラが仮想スレッドで即座に実行。I/O待機時に仮想スレッドがpark
- キャリアスレッドを他の作業に譲渡
application-server-prod.ymlにspring.threads.virtual.enabled: trueは既に存在していたが、このプロジェクトではAsyncConfigがカスタムexecutorを登録しているため、@AsyncはSpring Bootのauto-configurationではなく当該executorを使用していた。つまりvirtual thread設定の効果を@Asyncが受けていなかった

2. Redis `@Cacheable` — 繰り返しDBクエリのキャッシュ

JPAエンティティ（RoomMember → lazy Room、User）を直接キャッシュするとLazyInitializationExceptionが発生するため、軽量DTOを作成してキャッシュした

// RoomMemberCacheInfo.java — シリアライズ安全なDTO
public record RoomMemberCacheInfo(
    Long userId, Long roomId, MemberRole role,
    String nickname, String profilePictureUrl,
    String nicknameAdjectiveKey, String nicknameNounKey,
    String displayProfileImageUrl, Long lastReadMessageId
) implements Serializable {
    public static RoomMemberCacheInfo from(RoomMember member) { ... }
}

// RoomMemberCacheService.java
@Cacheable(value = "activeRoomMembers", key = "#roomId")
public List<RoomMemberCacheInfo> getActiveRoomMembers(Long roomId) { ... }

@Cacheable(value = "activeRoomMemberIds", key = "#roomId")
public List<Long> getActiveRoomMemberIds(Long roomId) { ... }

TTL 30秒。メンバー変更（入室/退室/追放/ブロック）時に@CacheEvictで即時無効化
消費者の切り替え：WebSocketBroadcastHelper、MessageService.getOtherActiveMemberIds()などでroomMemberRepository → roomMemberCacheServiceに置き換え

3. RedisConfig — キャッシュマネージャーの登録

@Bean
@ConditionalOnProperty(name = "spring.cache.type", havingValue = "redis")
public RedisCacheManager cacheManager(RedisConnectionFactory connectionFactory) {
    GenericJackson2JsonRedisSerializer serializer = new GenericJackson2JsonRedisSerializer();
    // activeRoomMembers, activeRoomMemberIds: TTL 30秒
    // デフォルト: TTL 60秒
}

@ConditionalOnPropertyでテストプロファイル（cache.type: none）ではBean未登録
application-redis.yml：cache.type: none -> cache.type: redis

シリアライズ問題 — テスト後に発覚

初回デプロイ後のテストで**エラー率98%**が出た。

SerializationException: Could not read JSON:
Unexpected token (START_ARRAY), expected VALUE_STRING:
need String, Number of Boolean value that contains type id

原因：ObjectMapper.DefaultTyping.NON_FINALで設定していたが、RoomMemberCacheInfoはJava record = finalクラスだ。NON_FINALはfinal型に型情報を記録しないため、デシリアライズ時に型が不明となり失敗した
修正：

GenericJackson2JsonRedisSerializer()デフォルトコンストラクタを使用 → 内部的にDefaultTyping.EVERYTHING + As.PROPERTYが適用される
.toList() -> .collect(Collectors.toList()) — ArrayList（non-final）で返す

テスト条件

ルームメンバー：50人、同時接続20人（sender 1 + listener 19）
メッセージ：50件、200ms間隔
20人全員がroom enter（active） — listenerも/app/room/enterを送信してサーバーでactiveメンバーとしてカウント。4次の元のテストではlistenerがpassiveだったが、5次からall-activeに変更した
k6スクリプト：同一

k6結果

指標	Before	1次	4次	5次
RTT Avg	6,410ms	10,610ms	7,780ms	9,110ms
RTT P95	9,680ms	13,330ms	12,760ms	15,010ms
RTT Max	10,050ms	13,750ms	13,010ms	15,400ms
RTT Min	-	-	1,730ms	1,630ms
Error Rate	24%	0%	0%	0%
Messages Sent	50件	50件	50件	50件
Messages Received	38件	50件	50件	50件
Messages Lost	12件	0件	0件	0件
Connection Time	233ms	744ms	858ms	970ms

Before・1次はk6バグが含まれたスクリプトの値だ。4次・5次はバグを修正したスクリプトでall-active条件で再計測した値のため、Before・1次とのRTT数値の比較は成立しない。
安定性（エラー0%、消失0件）は維持。しかしRTTが4次（7,780ms）よりむしろ上昇した（9,110ms）。Virtual Threads + Redisキャッシュを適用したのに遅くなった。

Grafanaサーバーメトリクス

5次表の比較基準が1次である理由：3次と4次の間にGrafanaダッシュボードの構成が変更され、一貫したスクリーンショットが残っているのが1次のみだったためだ。

核心比較：4次 vs 5次（再計測基準、同一条件）

メトリクス	4次	5次	変化
chat.message.send avg	1,507ms	1,691ms	+12%（悪化）
chat.broadcast avg	188ms	133ms	-29%（改善）
hibernate entity loads	26,900	17,450	-35%（改善）
RTT avg	7,780ms	9,110ms	+17%（悪化）

非同期経路（broadcast、entity loads）は改善されたが、同期経路（message.send）が悪化し全体のRTTが上昇した。ただしRTTの悪化だけで原因を特定したわけではない
— サーバーのLoggingAspectがpublishMessageSent() 1,170msをWARNログとして直接記録しており（サーバーログ分析）、このメトリクスが同期ブロッキング問題を確認した直接的な根拠だ。

同期経路

同期処理パイプライン — 平均所要時間

Name	1次改善 Mean	5次改善 Mean	変化
chat.ws.send（全体）	1.29 s	1.30 s	同一
chat.message.send（トランザクション）	350 ms	1.14 s	+226%
chat.message.read（既読処理）	188 ms	99.3 ms	-47%
chat.message.response.build（レスポンスビルド）	3.14 ms	2.60 ms	-17%
chat.hashtag.process（ハッシュタグ）	114 µs	43.2 µs	-62%

同期処理 — Max所要時間（スパイク検出）

Name	1次改善 Max	5次改善 Max	変化
chat.ws.send MAX	3.71 s	2.00 s	-46%
chat.message.send MAX	962 ms	1.67 s	+74%
chat.message.response.build MAX	22.7 ms	25.8 ms	同一
chat.hashtag.process MAX	4.61 ms	2.15 ms	-53%
chat.message.read MAX	460 ms	578 ms	+26%

非同期経路

非同期ブロードキャスト — 平均所要時間

Name	1次改善 Mean	5次改善 Mean	変化
chat.event.message.sent（イベントハンドラ）	2.44 s	330 ms	-86%
chat.broadcast.room（ブロードキャスト）	928 ms	98.4 ms	-89%

サーバースループット

Name	1次改善	5次改善	変化
メッセージ処理/s（Max）	1.20 ops/s	0.933 ops/s	-22%
ブロードキャスト/s（Max）	1.67 ops/s	1.00 ops/s	-40%

インフラ

JVM Heap Memory

	5次改善
Used	248 MiB
Committed	298 MiB
Max	512 MiB

GC Pause Time

	1次改善	5次改善
GC Time/s（G1 Evacuation Pause）	3.30 ms	3.78 ms
GC Max Pause（G1 Evacuation Pause）	40 ms	100 ms

CPU

	Before（元）	1次改善	5次改善	変化（1次->5次）
JVM	62.1%	77.0%	53.4%	-31%
System	99.9%	99.1%	88.8%	-10%

HikariCPコネクションプール

	Before（元）	1次改善	5次改善	変化（1次->5次）
Active	7	10	7	-30%
Idle	3	0	3	余裕回復
Avg Acquire	133 µs	602 ms	16.8 ms	-97%
Max Acquire	600 ms	3.18 s	291 ms	-91%
Max Usage	-	-	1.70 s

Hibernateクエリ

	Before（元）	1次改善	5次改善	変化（1次->5次）
Queries/s	919 ops/s	181 ops/s	46.8 ops/s	-74%
Inserts/s	105 ops/s	75.5 ops/s	5.03 ops/s	-93%
Loads/s	1.22K ops/s	657 ops/s	795 ops/s	+21%
Statements/s	-	287 ops/s	104 ops/s	-64%

JVM Threads

	Before（元）	1次改善	5次改善	変化（1次->5次）
Live	67	73	40	-45%
Peak	76	73	40	-45%
Daemon	32	39	-

観測時点のliveスレッド数は減少したが、Virtual Threadは短く生成・消滅し、JVMのliveスレッドカウンターに含まれない。この数値の減少はThreadPoolTaskExecutor（core=5、max=20）がなくなりVirtual Thread executorに置き換えられた影響であり、「より少ないスレッドで処理している」という直接的な性能根拠として解釈するのは難しい

分析 — Virtual Threadsは非同期経路に効果があったが、核心ボトルネックは同期経路に残っていた

サーバーログ：真のボトルネックが見える

サーバーにはLoggingAspect（AOP）が実装されており、サービスメソッドの実行時間が1000msを超えるとWARNレベルで自動出力される。

{"timestamp":"2026-03-09T09:33:12.732Z","message":"[SERVICE] RoomListEventPublisher.publishMessageSent() SLOW | duration=1004ms","thread_name":"clientInboundChannel-2","level":"WARN"}
{"timestamp":"2026-03-09T09:33:12.732Z","message":"[SERVICE] MessageService.sendMessage() SLOW | duration=1114ms","thread_name":"clientInboundChannel-4","level":"WARN"}
{"timestamp":"2026-03-09T09:33:13.013Z","message":"[SERVICE] RoomListEventPublisher.publishMessageSent() SLOW | duration=1004ms","thread_name":"clientInboundChannel-2","level":"WARN"}
{"timestamp":"2026-03-09T09:33:13.013Z","message":"[SERVICE] MessageService.sendMessage() SLOW | duration=1044ms","thread_name":"clientInboundChannel-2","level":"WARN"}
{"timestamp":"2026-03-09T09:33:13.318Z","message":"[SERVICE] RoomListEventPublisher.publishMessageSent() SLOW | duration=1003ms","thread_name":"clientInboundChannel-1","level":"WARN"}
{"timestamp":"2026-03-09T09:33:13.319Z","message":"[SERVICE] MessageService.sendMessage() SLOW | duration=1043ms","thread_name":"clientInboundChannel-1","level":"WARN"}
{"timestamp":"2026-03-09T09:33:13.613Z","message":"[SERVICE] RoomListEventPublisher.publishMessageSent() SLOW | duration=1042ms","thread_name":"clientInboundChannel-3","level":"WARN"}
{"timestamp":"2026-03-09T09:33:13.614Z","message":"[SERVICE] MessageService.sendMessage() SLOW | duration=1091ms","thread_name":"clientInboundChannel-3","level":"WARN"}
{"timestamp":"2026-03-09T09:33:13.967Z","message":"[SERVICE] RoomListEventPublisher.publishMessageSent() SLOW | duration=1112ms","thread_name":"clientInboundChannel-4","level":"WARN"}
{"timestamp":"2026-03-09T09:33:13.968Z","message":"[SERVICE] MessageService.sendMessage() SLOW | duration=1142ms","thread_name":"clientInboundChannel-4","level":"WARN"}
{"timestamp":"2026-03-09T09:33:15.578Z","message":"[SERVICE] RoomListEventPublisher.publishMessageSent() SLOW | duration=1150ms","thread_name":"clientInboundChannel-2","level":"WARN"}
{"timestamp":"2026-03-09T09:33:15.579Z","message":"[SERVICE] MessageService.sendMessage() SLOW | duration=1190ms","thread_name":"clientInboundChannel-2","level":"WARN"}
{"timestamp":"2026-03-09T09:33:15.978Z","message":"[SERVICE] RoomListEventPublisher.publishMessageSent() SLOW | duration=1293ms","thread_name":"clientInboundChannel-1","level":"WARN"}
{"timestamp":"2026-03-09T09:33:15.979Z","message":"[SERVICE] MessageService.sendMessage() SLOW | duration=1327ms","thread_name":"clientInboundChannel-1","level":"WARN"}
{"timestamp":"2026-03-09T09:33:16.334Z","message":"[SERVICE] RoomListEventPublisher.publishMessageSent() SLOW | duration=1307ms","thread_name":"clientInboundChannel-3","level":"WARN"}
{"timestamp":"2026-03-09T09:33:16.335Z","message":"[SERVICE] MessageService.sendMessage() SLOW | duration=1338ms","thread_name":"clientInboundChannel-3","level":"WARN"}
…（以下、同じパターンの繰り返し）

2つが目を引く

sendMessage()が約1,044〜1,338msで、その中のpublishMessageSent()が約1,003〜1,307msだ。同期経路の時間の95〜97%がpublishMessageSent()という1つのメソッドで消費されている
thread_nameがclientInboundChannel-1, 2, 3, 4だ。非同期ハンドラのvirtual-XXXXではなく、WebSocket STOMPインバウンドチャネルのプラットフォームスレッドだ

publishMessageSent()は同期だ

MessageService.sendMessage()の中でroomListEventPublisher.publishMessageSent()が直接呼び出されている。@Asyncではない。そのためclientInboundChannelスレッドで同期実行され、このメソッドが終わるまで当該スレッドはブロッキングされる
3次ではなぜ遅くなかったのか？ 3次の元のGrafanaでchat.message.send avgは56.7msだった。ただしこの値は単一scrapeスナップショットであり、再計測（Prometheusカウンターベース）では1,389msと出ている。56.7msをそのまま受け入れることはできないが、publishMessageSent()は3次でも同期呼び出しであり、当時の内部ロジ

クライアント -> ChatWebSocketController -> ChatWebSocketService
  -> MessageService.sendMessage() [@Transactional、clientInboundChannelスレッド]
    ├─ メッセージ保存、ハッシュタグ、既読処理、レスポンスビルド -> 約50ms（キャッシュのおかげで高速）
    └─ roomListEventPublisher.publishMessageSent() -> 約1,170ms ← ここが96%
        ├─ roomRepository.findById()
        ├─ roomMemberRepository.findAllActiveByRoomId()  ← キャッシュ未適用（直接repo呼び出し）
        ├─ broadcastHelper.isUserOnline() × N人           ← Redis個別呼び出し
        ├─ messageRepository.findUnreadCountsByRoomId()   ← 4テーブルJOIN
        └─ eventPublisher.publishEvent() × N人

今回の構成でVirtual Threadsが同期経路に適用されなかった理由

今回のプロジェクトではAsyncConfig.getAsyncExecutor()で@Async executorのみをVirtual Threadに置き換えた。publishMessageSent()は@Asyncではなく同期呼び出しのため、この変更の影響を受けなかった。

clientInboundChannelはSpring STOMPのthread-pool backed channelであり、configureClientInboundChannel()で個別にカスタマイズできる。しかし今回のプロジェクトではこのチャネルのexecutorを変更しなかったため、プラットフォームスレッドのままだった。サーバーログでclientInboundChannel-1, 2, 3, 4が観測され、この4つのプラットフォームスレッドがpublishMessageSent()の約1,170msのブロッキングに縛られていた。

spring.threads.virtual.enabled=true  -> auto-config対象のexecutorに適用
AsyncConfig（カスタムexecutor）        -> @Asyncを上書きするため、5次前はvirtual thread未適用
AsyncConfig（Virtual Threads、5次〜） -> @Asyncハンドラのみ適用
clientInboundChannel                 -> 今回の構成では個別カスタマイズせずプラットフォームスレッドのまま  <- ここがボトルネック

Redisキャッシュが同期経路に効果がなかった理由

Redis @CacheableはRoomMemberCacheServiceを通じてのみ動作する。WebSocketBroadcastHelperとMessageServiceはroomMemberCacheServiceに切り替えたが、RoomListEventPublisherは依然としてroomMemberRepositoryを直接呼び出している
またpublishMessageSent()内で最も重いクエリであるfindUnreadCountsByRoomId()は4テーブルJOINであり、キャッシュ対象ではない。

キュー積滞の計算

clientInboundChannel：4スレッド
publishMessageSent()：約1,170ms/msg（同期ブロッキング）
処理容量：4スレッド ÷ 1.17s = 3.4 msg/s
入力速度：1 msg / 200ms = 5.0 msg/s
超過分：5.0 - 3.4 = 1.6 msg/s -> キューに積み上がる

50件送信（10秒）の間のキュー積滞：

最初の4件：即時処理（4スレッド同時）
5件目から待機開始
4件まとめ（800ms）ごとに処理時間の超過分（T - 800ms）がキューに累積
msg[i]のRTT ≈ T + ⌊i/4⌋ × (T - 800)、ここでT = メッセージ1件の処理時間

単純モデル（T=1,170ms）ではavg RTT ≈ 3.3秒だが、負荷が増えるほどHikariCPの競合（7コネクションを約200 Virtual Threadが共有）によりTが増加する。サーバーメトリクスの実測T=1,691msを代入するとavg RTT ≈ 6.8秒となり、観測値（旧スクリプト7,350ms / 再計測9,110ms）の傾向とおおむね一致する。推定より観測値が高いのは、後半のメッセージほどTが非線形に増加する効果が単純モデルに反映されていないためだ。

しかし非同期ハンドラは速くなった

サーバーログの非同期ハンドラのスレッド名を見ると

thread_name: "virtual-1388"  ← ChatEventHandler（ブロードキャスト）
thread_name: "virtual-1391"  ← RoomListWebSocketHandler（ルームリスト更新）
thread_name: "virtual-1410"  ← ChatEventHandler（ブロードキャスト）

Virtual Threadsが正常に動作している。@Asyncハンドラはスレッドプールの競合なしに即座に実行される。4次までの非同期経路で発生していたThreadPoolTaskExecutorのキュー問題は解決された。
しかし非同期経路がいくら速くなっても、その前の同期経路で1,170msをブロッキングしていればRTTは減らない。

まとめ

成果

項目	効果
リアルタイム配信漏れ	0件維持（1次以降継続）
エラー率	0%維持
`@Async`スレッドプールのボトルネック	解決 — Virtual Threadsで競合を排除
繰り返しDBクエリ（broadcastHelper、MessageService）	解決 — Redis `@Cacheable`キャッシュヒット
シリアライズ問題	解決 — `DefaultTyping.EVERYTHING` + `collect(Collectors.toList())`

未解決

項目	現状
RTT	9,110ms — 目標（500ms）の18.2倍
publishMessageSent()の同期ブロッキング	1,170ms — 同期経路の96%
clientInboundChannel	4スレッド、今回の構成でプラットフォームスレッドのまま

今回の改善の本当の成果はボトルネックの正体を明らかにしたことだ

4次までは「非同期経路が遅い」->@Asyncスレッドプールの競合を原因と考えていた
5次では非同期経路をVirtual Threadsで解消しようとしたが、RTTに変化がなかった
真のボトルネックは同期経路の**publishMessageSent()**だと推論できた
次の改善でpublishMessageSent()を非同期に分離することが急務だと判断した

6次改善

今回の最適化の大部分は、クエリチューニングではなく、同期経路に潜んでいたpublishMessageSent()のボトルネックを除去したことから生まれた。再計測基準でchat.message.send avgが3次1,389ms -> 6次46msと30倍改善されたことがその証拠だ

原因分析

5次改善（Virtual Threads + Redis @Cacheable）後もRTTが9,110msとむしろ悪化した。サーバーログとGrafanaメトリクスを分析した結果、3つのボトルネックを発見した。

1. `clientInboundChannel`の同期ブロッキング

thread_name: "clientInboundChannel-2"  <- Spring STOMP内部スレッドプール
[SERVICE] RoomListEventPublisher.publishMessageSent() SLOW | duration=1170ms

RoomListEventPublisher.publishMessageSent()が同期的にclientInboundChannelスレッドで実行され、約1,000〜1,300msを要していた。
clientInboundChannelはSpring STOMPの内部スレッドプールだ。今回の環境ではclientInboundChannel-1..4と4スレッドが観測された。@Asyncではなく同期呼び出しのため、Virtual Threadsの適用対象ではない。

処理能力：4スレッド ÷ 1.17s/メッセージ = 3.4 msg/s
負荷テストの入力：5 msg/s
-> 入力 -> 処理 -> キュー積滞 -> RTT急増

2. HikariCPコネクションプールの枯渇

HikariPool-1 - Pool stats (total=7, active=7, idle=0, waiting=37)

この数値は6次改善前のテスト中にHikariCPが定期的に出力するサーバーログからキャプチャしたものだ。Grafana（15秒scrapeインターバル）のPending=0スナップショットよりもリアルタイムの状態をより正確に反映している

メッセージ1件あたり4つの@Asyncハンドラが同時にDBコネクションを占有する。200ms間隔で50件が送られると、200個のVirtual Threadが7個のコネクションを奪い合う。

3. 非同期タスクの爆発（キューイング）

50メッセージ × 4ハンドラ = 200個の非同期タスクが同時実行され、DB/CPUを競合する。

メッセージ1件 -> AFTER_COMMITイベント
  ├─ ChatEventHandler（300〜500ms） — ブロードキャスト、メンバー20人に順次送信
  ├─ ConnectionMessageEventHandler — 縁スコア計算、batchクエリ
  ├─ RoomListEventPublisher（50〜150ms） — ルームリスト更新、DBクエリ5件
  └─ NotificationFallbackHandler（500〜2000ms） — プッシュ通知、DBクエリ10件以上

サーバーログでブロードキャスト時間が徐々に遅くなるパターンが観測される：

序盤のメッセージ：約200ms
中盤のメッセージ：約500ms
後半のメッセージ：約1,500ms
同じルームにメッセージが50件連続で届くと、RoomListEventPublisherが50回、NotificationFallbackHandlerが50回実行される。ルームリスト更新は最後のメッセージ基準で1回あれば十分であり、プッシュ通知も50個の個別通知より1個の方がUX上優れている。

改善内容

1. `publishMessageSent()`の非同期化

重い同期呼び出しを@Async @TransactionalEventListener(AFTER_COMMIT)パターンに切り替えた。

// Before：同期メソッド、clientInboundChannelで直接実行
public void publishMessageSent(Long roomId, Message message) {
    // 約1,170msブロッキング
}
// After：非同期イベントハンドラ、Virtual Threadで実行
@Async
@TransactionalEventListener(phase = TransactionPhase.AFTER_COMMIT)
public void handleMessageSent(RoomListMessageSentEvent event) {
    // ...
}

MessageServiceでの直接呼び出しの代わりにイベント発行に切り替えた

// Before
roomListEventPublisher.publishMessageSent(roomId, savedMessage);

// After
eventPublisher.publishEvent(RoomListMessageSentEvent.of(roomId, savedMessage.getId()));

同期経路の占有時間

Before（5次）：
clientInboundChannelスレッド：
  sendMessage()【約50ms】+ publishMessageSent()【約1,170ms】= 約1,220ms/メッセージ
  -> スループット：4 / 1.22 = 3.3 msg/s < 入力5 msg/s -> キュー積滞
After（6次）：
clientInboundChannelスレッド：
  sendMessage()【約50ms】+ イベント発行【約0ms】= 約50ms/メッセージ
  -> 理論上のinboundボトルネック上限：4 / 0.05 = 80 msg/s >> 入力5 msg/s -> キューなし
  （実際のシステム全体のスループットはDB、Redis、ブロードキャストなどdownstreamによって制限される）

2. 重複クエリのキャッシュ

ChatEventHandlerとRoomListEventPublisherがそれぞれ呼び出していたfindUnreadCountsByRoomId()をRoomMemberCacheServiceの@Cacheableに統合

@Cacheable(value = "roomUnreadCounts", key = "#roomId")
public Map<Long, long[]> getUnreadCountsByRoomId(Long roomId) { ... }

RoomListEventPublisherに早期リターンの最適化も適用

List<Long> allMemberIds = roomMemberCacheService.getActiveRoomMemberIds(roomId);  // キャッシュ
Set<Long> onlineIds = broadcastHelper.filterOnlineUserIds(allMemberIds);           // Pipeline 1回
if (onlineIds.isEmpty()) return;  // オンラインメンバーがいなければDBクエリを完全スキップ

3. ブロードキャストの並列化 — `WebSocketBroadcastHelper`

SimpMessagingTemplateは共有Beanとして一般的に使用され、今回の実装では別途mutable stateなしに並列送信を試みた。順次forループをVirtual Thread並列送信に変更した。

private static final ExecutorService BROADCAST_EXECUTOR =
        Executors.newVirtualThreadPerTaskExecutor();

public <T> void broadcastToRoomMembers(Long roomId, String destination,
                                        Function<Long, T> messageBuilder) {
    // … メンバー照会、オンラインフィルタリング …
    AtomicInteger sentCount = new AtomicInteger();

    List<CompletableFuture<Void>> futures = members.stream()
            .map(RoomMemberCacheInfo::userId)
            .filter(onlineIds::contains)
            .map(memberId -> CompletableFuture.runAsync(() -> {
                T message = messageBuilder.apply(memberId);
                if (message != null) {
                    messagingTemplate.convertAndSendToUser(
                            memberId.toString(), destination, message);
                    sentCount.incrementAndGet();
                }
            }, BROADCAST_EXECUTOR))
            .toList();

    CompletableFuture.allOf(futures.toArray(new CompletableFuture[0])).join();
}

Grafana計測：chat.broadcast.room avg 98.4ms（5次）→ 62.5ms（6次）、-37%

順序保証について：並列化の単位はユーザーだ（同じメッセージをユーザーA、B、Cに並列送信する）。そのため、listener間の受信タイミングの差（fanout skew）は発生しうる。一方、同一受信者に対するメッセージの順序は構造的に保証される：broadcastToRoomMembers()はCompletableFuture.allOf().join()で完了を待ってからリターンし、次のメッセージはclientInboundChannelで順次ディスパッチされるため、MSG[1]のbroadcastが終わってからMSG[2]のbroadcastが始まる。同じユーザーにMSG[2]がMSG[1]より先に届く順序逆転は、この構造では発生しない

4. イベントハンドラのデバウンス — `RoomListEventPublisher`、`NotificationFallbackHandler`

同じルームにメッセージが50件連続で届いた場合、ルームリスト更新とプッシュ通知は最後のメッセージ基準で1回だけ処理する。これは単なるパフォーマンストリックではなく、ドメインポリシーの変更だ — 「メッセージごとに即時通知」から「一定時間内の最後のメッセージのみ通知」へとUX要件を再定義したものだ。チャットの連打状況では50件の個別通知より1件の最新通知の方がユーザー体験として適切だと判断した

private final ConcurrentHashMap<Long, RoomListMessageSentEvent> pendingEvents = new ConcurrentHashMap<>();
private final ConcurrentHashMap<Long, ScheduledFuture<?>> scheduledTasks = new ConcurrentHashMap<>();
private final ScheduledExecutorService debounceScheduler =
        Executors.newSingleThreadScheduledExecutor(
                Thread.ofVirtual().name("room-list-debounce-", 0).factory());

private static final long DEBOUNCE_DELAY_MS = 300;

@Async
@TransactionalEventListener(phase = TransactionPhase.AFTER_COMMIT)
public void handleMessageSent(RoomListMessageSentEvent event) {
    Long roomId = event.roomId();
    pendingEvents.put(roomId, event);

    scheduledTasks.compute(roomId, (key, existingFuture) -> {
        if (existingFuture != null) existingFuture.cancel(false);
        return debounceScheduler.schedule(() -> {
            RoomListMessageSentEvent latestEvent = pendingEvents.remove(roomId);
            if (latestEvent != null) processMessageSent(latestEvent);
        }, DEBOUNCE_DELAY_MS, TimeUnit.MILLISECONDS);
    });
}

デバウンスされたコールバックはSpringプロキシを経由しないため@Transactionalが動作しない。実際の処理ロジックであるprocessMessageSent()ではTransactionTemplateで直接トランザクションを管理する。
NotificationFallbackHandlerにも同じパターンを適用した（デバウンス500ms — 通知はより緩くても問題ない）。ただし、メンション（@）通知はデバウンス対象ではない。メンションはMentionNotificationEventという別のイベントタイプで発行され、NotificationFallbackHandler.handleMentionNotification()でデバウンスなしに即時処理される。連打中にメンションが含まれたメッセージが握りつぶされることはない

効果：50回実行 -> 各1回（DBクエリ750件以上 -> 15件）

5. HikariCPコネクションプール調整

5次でVirtual Threads導入後、@Asyncハンドラが無制限にスポーンされ、HikariCP maximum-pool-size=10設定下で観測時点にtotal=7, active=7, waiting=37の枯渇状態が現れた。6次ではHikariCP maximum-pool-sizeを7、minimum-idleを7に明示設定した。プールサイズはむしろ縮小したが（10->7）、待機スレッドは37個->0個に解消された。これは同期経路の非同期化、デバウンス、並列ブロードキャストによって同時DBアクセス自体が減ったためだ。決定的な効果はプールの拡張ではなく、同時アクセスを減らした構造変更から生まれた。

ここで5次のtotal=7, active=7はmax=10設定下での観測時点のランタイム状態であり、6次のmax=7は設定値自体を調整したものだ。つまり5次の7は観測値、6次の7は設定値だ

デバウンスのトレードオフ

デバウンス300ms/500msはタダではない

ルームリスト更新の遅延（300ms）：メッセージ送信後、ルームリストの「最後のメッセージ」プレビューが最大300ms遅れて反映される。しかしユーザーがチャット中にルームリストを同時に見ることは稀であり、300msは体感しにくいレベルだ。
通知の遅延（500ms）：連打時は最後のメッセージのみ通知が届く。一般的なメッセンジャー（KakaoTalk、LINE）でも連打中に毎件通知が来るわけではないため、この動作は自然だ。
サーバー障害時のイベント消失：デバウンス待機中のイベントはConcurrentHashMapにインメモリで保持される。デバウンスウィンドウ（300〜500ms）内にサーバーがダウンすると最後のイベントが消失する。ルームリスト更新や通知は次回接続時にDBから復元されるため致命的ではないが、リアルタイム反映が欠落する可能性がある
なぜこの値か：200ms間隔で50件連打する極端なシナリオでもデバウンスが有効であるためには、送信間隔（200ms）より大きくなければならない。300msは間隔の1.5倍であり、連打中の中間実行を確実に抑制しつつ、体感遅延のない下限値だ

k6結果

サーバーログでデバウンスと並列ブロードキャストが正常に動作していることを確認した

room-list-debounce-0：50回 -> 1回実行
notif-debounce-0：50回 -> 1回実行
ブロードキャスト：Virtual Thread（virtual-504、virtual-509…）で並列送信

k6測定スクリプトのバグ発見

Grafanaで同期経路が1.14s -> 24msと98%速くなったことを確認した。ところがk6を実行するとRTT avgが5,150ms — サーバーが30倍速くなったのにRTTは30%しか減っていない。この不一致が不自然だったのでk6スクリプト自体を調査した。
既存のk6スクリプトはsendAllMessages()関数をon('message')ハンドラのCONNECTED分岐の中で呼び出していた

socket.on('message', function (data) {
    if (frame.command === 'CONNECTED') {
        // ...subscriptions...
        sleep(1);
        sendAllMessages(socket);  // ← ここで10秒間ブロッキング！
    }
    if (frame.command === 'MESSAGE') {
        // RTT計測ロジック
    }
});

既存のスクリプトはon('message')コールバック内部で長時間実行される送信ループを回しており、この構造のせいで受信イベントの処理タイミングが後ろにずれる計測歪みが発生していた。sendAllMessages()がsleep(200ms) × 50件 = 10秒間実行される間、サーバーから返ってくるブロードキャストメッセージの受信処理が遅延する現象が観測された。
その結果、RTTが以下のように歪んだ：

MSG[0]は送信直後にサーバーが応答したが、送信ループ完了後にやっと受信処理された → RTT = 約10,000ms
MSG[49]は9.8秒に送信され直後に受信 → RTT = 約200ms
既存のRTT数値はサーバーレイテンシではなく、スクリプト構造による受信遅延の産物だった。 socket.setInterval()ベースに再構成した後、この現象が消えた。setIntervalコールバックの間に受信イベントが正常に処理され、各メッセージの実際のサーバーRTTが計測されるようになった。

修正後、3次〜6次を同一条件（ルーム50人、同時接続20人全員active、50件 × 200ms）で再計測した。既存の4次テストではlistenerが/app/room/enterを送信せずpassive状態だったが、再計測では3次〜6次すべてlistenerがroom enterを送信するall-active条件に統一した。したがって再計測表の次数間比較はテスト条件が同一だ。このブログの3次〜6次のk6数値はすべて修正されたスクリプトの結果だ。既存のRTT avgに加えて3つのメトリクスも追加した

メトリクス	意味
`first_5 avg`	メッセージ0〜4番のRTT平均。サーバーウォームアップ（JIT + キャッシュcold）を含む
`last_5 avg`	メッセージ45〜49番のRTT平均。サーバーがキューを消化した程度
`total_duration`	最初の送信〜最後の受信。サーバーが入力に追いついたかどうか

指標	3次	4次	5次	6次
first_5 avg	2,044ms	2,225ms	2,188ms	1,156ms
last_5 avg	11,596ms	12,804ms	15,052ms	132ms
total_duration	21,907ms	22,948ms	25,402ms	10,143ms
RTT avg	6,980ms	7,780ms	9,110ms	386ms
RTT min	1,510ms	1,730ms	1,630ms	117ms
RTT max	11,940ms	13,010ms	15,400ms	1,430ms
RTT p95	11,460ms	12,760ms	15,010ms	1,070ms
Error Rate	0%	0%	0%	0%
Messages Lost	0件	0件	0件	0件

3次〜5次はRTTが線形増加するキュー積滞パターンだ。6次で平均RTT目標（500ms以下）を達成した（avg 386ms）。P95は1,070msで安定性目標（1,000ms以下）を70ms超過して未達だ。 first_5 avg（1,156ms）がlast_5 avg（132ms）の9倍である点から、JITウォームアップ + キャッシュcold startの影響が大きいと推定されるが、ウォームアップ区間を除いたP95を別途算出していないため、この推定は検証されていない。

キューイングパターン（per-message RTT）

メッセージごとのRTTを計測すると、次数別のサーバー処理パターンが明確に見える

3次：MSG[0]=1,578ms -> RTT線形増加 -> MSG[49]=11,906ms

キューが積み上がり続ける。サーバーが入力速度（5 msg/s）に追いつけていない
4次：MSG[0]=1,739ms -> RTT線形増加 → MSG[49]=12,947ms
3次と同じパターンだがやや悪化。再計測はall-active条件のためpassive sessionの恩恵がなく、4次で追加されたisUserOnline() × 50人のRedis個別呼び出しが純粋なオーバーヘッドとして作用したためと推定される。つまりpassive sessionはオンライン:オフライン比率が低いとき（passiveユーザーが多いとき）のみ有効な条件付き最適化であり、全員active状態ではRedis個別呼び出しのコストだけが追加される
5次：MSG[0]=1,636ms -> RTT線形増加 -> MSG[49]=15,402ms
全次数中で最悪。publishMessageSent()の同期ブロッキングにより処理量3.4 msg/s < 入力5 msg/s
6次：MSG[0]=1,436ms（ウォームアップ） -> MSG[15]=361ms -> MSG[20]=227ms -> MSG[49]=143ms
MSG[15]以降200ms以下で安定。サーバーが入力より速く処理してキューを完全消化

サーバーメトリクス比較（actuator/prometheus、per 50 messages）

メトリクス	3次	4次	5次	6次
chat.message.send avg	1,389ms	1,507ms	1,691ms	46ms
chat.message.send max	1,723ms	1,769ms	2,175ms	312ms
chat.broadcast avg	163ms	188ms	133ms	117ms
chat.broadcast max	610ms	522ms	600ms	547ms
hibernate queries（per 50msg）	1,174	1,174	1,093	653
hibernate entity loads（per 50msg）	26,900	26,900	17,450	6,443

再計測表と以下のGrafana表の数値の差について：上の表は再計測時にPrometheusカウンター（/actuator/prometheus）から収集した値であり、以下のGrafana表は6次改善当時のGrafanaダッシュボードパネルから読み取った値だ。それぞれ異なるテストセッションのデータのため、例えばchat.message.send avgが再計測では46ms、Grafanaでは24.3msと異なり、chat.broadcast.room avgが117ms vs 62.5msと異なる。両方の値とも実測であり、テスト実行時点のサーバー状態（キャッシュウォームアップ、GC、ネットワーク）によって変化する

Grafanaサーバーメトリクス

同期経路

同期処理パイプライン — 平均所要時間

Name	5次改善 Mean	6次改善 Mean	変化
chat.ws.send（全体）	1.30 s	161.7 ms	-88%
chat.message.send（トランザクション）	1.14 s	24.3 ms	-98%
chat.message.read（既読処理）	99.3 ms	93.9 ms	-5%
chat.message.response.build（レスポンスビルド）	2.60 ms	0.6 ms	-77%
chat.hashtag.process（ハッシュタグ）	43.2 µs	0.2 ms	同一水準

同期処理 — Max所要時間（スパイク検出）

≤ 表記はGrafanaグラフで正確な数値を読み取りにくいため、目盛りベースで上限値を記録したものだ。実際の値はこれより低い可能性がある

Name	5次改善 Max	6次改善 Max	変化
chat.ws.send MAX	2.00 s	≤984 ms	-51%
chat.message.send MAX	1.67 s	≤224 ms	-87%
chat.message.response.build MAX	25.8 ms	≤11 ms	-57%
chat.hashtag.process MAX	2.15 ms	≤8 ms	同一水準
chat.message.read MAX	578 ms	≤716 ms	同一水準

非同期経路

非同期ブロードキャスト — 平均所要時間

Name	5次改善 Mean	6次改善 Mean	変化
chat.event.message.sent（イベントハンドラ）	330 ms	126.7 ms	-62%
chat.broadcast.room（ブロードキャスト）	98.4 ms	62.5 ms	-37%

非同期ブロードキャスト — Max所要時間

Name	6次改善 Max
chat.event.message.sent MAX	≤1,432 ms
chat.broadcast.room MAX	≤537 ms

サーバースループット

Name	5次改善	6次改善	変化
メッセージ処理/s（Max）	0.933 ops/s	1.11 ops/s	+19%
ブロードキャスト/s（Max）	1.00 ops/s	1.11 ops/s	+11%

GrafanaのOps/sパネルは15秒scrapeベースのため、10秒以内のburst負荷の瞬間スループットを正確に反映しない。6次でops/sが1.11と入力速度（5 msg/s）より低く見えるが、実際の処理可否はtotal_duration（10.1s ≈ 入力時間）とper-message RTTの安定化（後半132ms）で判断した

インフラ

CPU

	5次改善	6次改善	変化
JVM	53.4%	26.7%	-50%
System	88.8%	37.7%	-58%

HikariCPコネクションプール

	5次改善	6次改善	変化
Active	7	0（scrapeインターバル内に返却）	即時返却
Idle	3	7	余裕回復
Pending	0	0
Total	10（max=10）	7（max=7）	6次でmax pool sizeを10（デフォルト値）-> 7に縮小した。非同期化 + デバウンスにより同時DBアクセスが減り、7個でも待機なしで十分だった
Avg Acquire	16.8 ms	3.7 ms	-78%
Max Acquire	291 ms	2.0 ms	-99%
Max Usage	1.70 s	22 ms	-99%

JVM Heap Memory

	5次改善	6次改善
Used	248 MiB	107 MiB
Max	512 MiB	512 MiB

GC Pause Time

	5次改善	6次改善	変化
GC Max Pause（G1 Evacuation Pause）	100 ms	31 ms	-69%

JVM Threads

	5次改善	6次改善	変化
Live	40	30	-25%
Peak	40	40	同一

HibernateクエリとEntity loadsの5次 vs 6次比較は、上記の再計測サーバーメトリクス比較表（per 50 messages、Prometheusカウンターベース）を参照。6次Grafanaセッションで別途収集したper 100 messagesのカウンター累積値は基準が異なるため、混乱を避けるために除外した

分析

`total_duration`が核心だ

3次/4次：total_duration 22〜23秒。入力時間（10秒）の2倍以上。サーバーが最後までキューを消化できていない
5次：total_duration 25.4秒。全次数中で最悪。publishMessageSent()の同期ブロッキングによりむしろ悪化
6次：total_duration 10.1秒。入力時間（10秒）と同一。サーバーが入力速度に完全に追いついた

`chat.message.send avg`が決定的な証拠だ

3次：1,389ms → 5次：1,691ms（+22%、むしろ悪化） → 6次：46ms（-97%、30倍改善）
publishMessageSent()の非同期化が同期経路を50ms以下にし、inboundボトルネック基準の理論上の上限を3.3 msg/s → 80 msg/sに引き上げた根本原因

5次のパラドックスが明確に浮き彫りになった

5次は非同期経路（broadcast avg 163ms→133ms、-18%）とDB負荷（entity loads 26,900→17,450、-35%）は確実に改善した。しかし同期経路（chat.message.send avg）が1,389ms→1,691msと**+22%悪化した。Virtual Threads + Redisキャッシュの非同期効果がpublishMessageSent()の同期ブロッキングに完全に相殺**された。これが6次で非同期化を決定した直接的な根拠だ。

`last_5 avg = 132ms`の意味

6次の最後の5件のRTT平均が132msで、MSG[49]のRTTは143msだ

サーバーが50件送信（10秒）完了前にキューを完全に消化した
キューが空の状態での純粋なend-to-endレイテンシが約130msだ
この130msにはネットワーク往復（日本→韓国）、同期経路（chat.message.send）、非同期ブロードキャスト（chat.broadcast.room）、STOMPフレーミング、クライアントdispatchオーバーヘッドが含まれる。各構成要素の寄与度を正確に分離して合算はしていない
RTT平均目標（500ms）は達成した。P95（1,070ms）は安定性目標（1,000ms）を70ms超過して未達だ。 first_5 avg（1,156ms）vs last_5 avg（132ms）の差からウォームアップ（JIT、キャッシュcold start）の寄与が疑われるが、ウォームアップ区間を除いたP95を別途算出していないため、未達は未達だ。定常状態（last_5 avg）での130msは参考指標としてのみ記録する。

成果

項目	5次	6次	変化
`clientInboundChannel`占有時間	約1,220ms/msg	約50ms/msg	-96%
`clientInboundChannel`理論上の上限	3.3 msg/s	80 msg/s	24倍
非同期タスク数/50msg	200個	102個	-49%
DBクエリ/50msg（Hibernateクエリ）	1,093件	653件	-40%
ブロードキャスト時間（`chat.broadcast.room avg`）	約98ms（順次）	約63ms（並列）	-37%
HikariCP待機スレッド（上記改善の結果）	37	0	解消

全体最適化結果（Before -> 6次）

サーバー内部指標

指標	Before（Grafana）	6次（再計測Prometheus）	変化
リアルタイム配信漏れ	12件/50件	0件	解決
エラー率	24%	0%	解決
chat.message.send avg	約788ms	46ms	-94%
chat.broadcast.room avg	約202ms	117ms	-42%

Beforeはgrafanaダッシュボード、6次はPrometheusカウンターベースの再計測であり、収集方式が異なる。6次のGrafana値（24.3ms / 62.5ms）は別途テストセッションで観測されたが、同一ソースの比較ではないため、ここでは保守的な再計測値を使用した。HibernateクエリとEntity loadsは再計測基準（per 50 messages）でのみ比較可能であり、Beforeには同じ基準がないため除外した。3次〜6次の一貫した比較は上記の再計測サーバーメトリクス比較表を参照

クライアントRTT（修正済みk6スクリプト・同一条件再計測）

Beforeは修正前スクリプトで計測されており、同一条件の比較に含めることができない。同一スクリプト・同一条件の3次〜6次の比較は上記の再計測結果表を参照。

指標	6次	目標	判定
RTT avg	386ms	500ms以下	達成
RTT p95	1,070ms	1,000ms以下	70ms超過、未達
last_5 avg（定常状態）	132ms	—	キュー完全消化
total_duration	10.1s	—	入力時間（10s）と同一

改善項目別まとめ

改善	解決したボトルネック	効果
同期→非同期化	`clientInboundChannel`ブロッキング	理論上の上限3.3→80 msg/s
Unread countキャッシュ	4テーブルJOIN重複呼び出し	コネクション占有時間50%↓
ブロードキャスト並列化	順次送信O(N)	98ms→63ms（Grafana基準）
イベントデバウンス	不要な繰り返し実行	非同期タスク49%↓、DBクエリ40%↓

学んだこと

1. 計測ツール自体を疑え

k6スクリプトのイベントループブロッキングバグにより、全次数のfirst_5 avgが約9,650msで同一になっていた。この数値をそのまま信じると「サーバー性能に差がない」という誤った結論に至る。修正後の実際のfirst_5は3次2,044ms / 6次1,156msと差が明らかになり、RTT avgは3次6,980ms / 6次386msと18倍の差があった。計測スクリプトもコードだ

バグがある可能性があり、結果が疑わしければ計測ツールから検証すべきだ

2. 処理速度を上げることだけが答えではない

「メッセージ1件の処理を速く」することに集中すると、次のボトルネックが際限なく現れる。同じルームにメッセージが50件連続で届いた場合、ルームリスト更新とプッシュ通知は最後の1件だけ処理すればよい。デバウンス一つで非同期タスク数が49%減り、これは個別タスクをいくら最適化しても達成できないレベルだ。

つまり、コードレベルの作業も大切だが、より俯瞰的に考えながらドメインレベルで解決するのが最善

3. Virtual Threadsは諸刃の剣だ

5次でVirtual Threadsを導入したとき、@Asyncスレッドプールの競合は解消されたが、RTTはむしろ悪化した（7,780ms → 9,110ms）。これには2つの問題があった。

今回の構成における適用範囲：Virtual Threadsの効果は今回の構成で@Async executorにのみ反映された。clientInboundChannelは別途executor構成でプラットフォームスレッドのままだったため、そこで同期メソッド（publishMessageSent()）を呼び出すとブロッキングがそのままRTTに反映された。5次の本当の成果は、この隠れた同期ボトルネックの正体を明らかにしたことだった
downstreamリソースの飽和：スレッド数の制限がなくなったことで@Asyncタスクが爆発的に増加し、観測時点のHikariCP total=7, active=7状態が新たなボトルネックとして浮上した

Virtual Threadsを導入する際は必ず適用範囲とdownstreamリソースのサイズを再算定しなければならない。

限界と改善点

1. Before（元）を修正済みk6スクリプトで再計測しなかった

最終比較表でのBefore RTT（6,410ms）はバグがあったスクリプトの値であり、6次RTT（386ms）は修正済みスクリプトの値だ。「サーバーが実際に遅かったので再計測しても似たような値になるだろう」と推定したが、Beforeの6,410msのうちどれだけがサーバーレイテンシでどれだけがk6バグの産物かを正確に分離できていない。全体の旅の出発点の数値が不確かであるため、RTT基準の「94%改善」は正確な数値ではなく推定だ。

一貫した比較が可能なのはサーバー側メトリクスだ。再計測Prometheus基準のchat.message.send avg 3次1,389ms → 6次46ms（-97%）が同一収集方式で確認された。BeforeのGrafana値（788ms）と6次Prometheus（46ms）を比較すると-94%だが、収集方式が異なるため参考レベルだ。

2. テスト条件が次数ごとに異なり、変数の分離ができていない区間がある

4次でlistenerがroom enterを送信せずpassiveとして処理され、5次から全員activeに変わった。4次→5次のRTT悪化（7,780ms → 9,110ms）がVirtual Threadsの副作用なのか、テスト条件（passive → active）変更のためなのかが分離されていない。「変数を一つだけ変えて計測する」という原則がこの区間で守られなかった。

再計測では3次〜6次を全部all-active条件で統一したため、再計測表基準の次数間比較は公平だ。ただし4次本文のpassive session分析は元のテスト（passive listener）基準のため、再計測のk6数値とは条件が異なる点を踏まえる必要がある。

3. Redisキャッシュのヒット率を計測しなかった

5次で@Cacheableを導入したが、実際のキャッシュヒット率が何%か、cold startでのキャッシュミスがRTTにどれほど影響するかのデータがない。6次再計測でfirst_5 avgが1,156msとlast_5 avg（132ms）より8.8倍高いが、この差がキャッシュウォームアップのためなのかJITコンパイルのためなのかを検証する数値が抜けている。Spring Boot Actuatorのcache.gets{result=hit|miss}メトリクスを有効化していれば、この仮説を検証できた。
これは知らなかった部分のため、今後勉強しながらテストしてみるつもりだ

4. Connection Time（WebSocketハンドシェイク）の変動が分析されなかった

次数別のConnection Timeが233ms → 744ms → 422ms → 858ms → 970msと不安定だ。WebSocketハンドシェイク時間はサーバー負荷よりもネットワーク条件（日本→韓国間のTCP RTT変動）に影響を受けるものと思われる。RTT計測はハンドシェイク完了後に開始されるため、Connection Timeの変動がRTT比較に直接影響を与えるわけではないが、テスト間のネットワーク条件が同一でなかった可能性があるという限界を示している。

5. インメモリデバウンスは単一インスタンスでのみ動作する

現在のデバウンスはConcurrentHashMapで実装されているため、サーバーが2台以上に水平スケールすると各インスタンスが独立してデバウンスする。同じルームのメッセージがインスタンスAとBに分散されると、デバウンスの効果が半減する。水平スケール時はRedisベースのデバウンス（RedissonのRScheduledExecutorServiceなど）に切り替えるか、同じルームのメッセージを同じインスタンスにルーティングするsticky sessionが必要だ。現在は単一インスタンス運用のため問題ないが、スケールアウト時に再設計が必要な部分だ。

6. デバウンススケジューラーがシングルスレッドだ

Executors.newSingleThreadScheduledExecutor()でデバウンスコールバックを実行するため、ルームAのprocessMessageSent()（DBクエリ + トランザクション含む）が実行中だとルームBのコールバックが詰まる。現在は単一ルームのテストのため問題はなかったが、複数ルーム同時アクティブシナリオではボトルネックになりうる。「次にやること」に複数ルームのテストを計画しており、このタイミングでスケジューラーをマルチスレッドプールまたはルームごとの独立スケジューラーに切り替える必要があるかもしれない。

7. Virtual ThreadsのPinning検証を行わなかった

5次でVirtual Threadsを導入したが、Hibernate内部とHikariCP内部にsynchronizedブロックが存在する。Virtual Threadがsynchronized内でI/O待機すると、キャリアスレッドを占有したままparkできないPinningが発生する。2コアEC2でキャリアスレッドが2つしかないため、Pinningが頻発すると事実上プラットフォームスレッドプールと変わらない。-Djdk.tracePinnedThreads=shortで確認しなかったため、5次でRTTが悪化した原因の中にPinningが寄与していたかどうかは不明だ。

8. 単一senderのテストのみ実施した

すべてのテストがsender 1人が200ms間隔で50件を送るシナリオだ。実際のチャットルームは複数人が同時に送信しており、sender 5人がそれぞれ1秒間隔で送るのはサーバー負荷パターンが異なる。特にデバウンス（300ms）は同じルームに複数senderが同時に送信する場合でも最後のメッセージ基準で1回だけ処理するため、複数senderシナリオでのデバウンスの動作が意図通りかどうか別途検証が必要だ。

9. Listener側の受信遅延とfanoutの完全性を計測しなかった

k6で計測したRTTと「消失0件」は、senderが自分のメッセージをechoとして受け取った基準だ。listener 19人それぞれが50件をすべて受信したか、受信遅延がsender echo RTTと同一かどうかは別途検証していない。ブロードキャストを並列化した6次ではlistener別の受信タイミングの差（fanout skew）が発生しうるため、これを計測するにはlistener別のp50/p95受信遅延とordering violation検査が必要だ。

振り返り

今回の作業は実際のデプロイを前にした検証であり、勉強でもあった。

私はDDDを強く信じている。すべてのソフトウェアは結局、人のために存在する。消費者のニーズを素早く捉え、間違っていれば素早く解体し、また次のニーズを捉える。それがソフトウェアの本質だと思っている。そしてそのスピードを出すためにAIは強力なツールだ。

最初はAIに依存すると自分の実力が伸びないと思っていた。今は違う見方をしている。AIで速く実装しつつ、そのコードの質と性能は人間が判断しなければならない。プロジェクト初期はAIを単純にアルゴリズム作成用としてのみ使っていたが、Claude Opus 4.1以降は設計と実装全般に積極的に活用している。

しかし今回の計測が示すように、AIが作ったコードもテストを通過して正常動作しながらRTT 6,410msになりうる。通過するコードと良いコードは違う。その差を発見するのは、Grafanaの前で「なぜ?」を繰り返す人間の仕事だった。AIが提案したSEQUENCE戦略は失敗し、6次でHikariCP max pool sizeを10（デフォルト値）→7にむしろ縮小したにもかかわらずコネクション待機が解消されたのは、プールの拡張ではなく同時アクセス自体を減らした構造変更のおかげだった。核心はリソースの拡張ではなくボトルネックの除去だった。結局、データで検証して判断するのは自分がやらなければならなかった。

またAIは分析のスピードと深さが自分より優れているため、ある瞬間にすべてを任せてしまう瞬間が訪れる。

しかしすべてに「なぜ」という疑問をつければ、AIを使って速く開発しながらも、それを信頼できるソフトウェアにできると信じている。

定量的な指標を持って分析し、勉強しながら、自分のプロジェクトを改善していくこの経験は本当に価値あるものだった。実際、もっと成長すればこの文章に多くの問題点が見えてくるかもしれない。それは成長痛だと思っている。

これからもAIを積極的に活用しつつ、常に根拠を持ち、常に「なぜ」を問いながら、人のためのソフトウェアを作る開発者になりたい。

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up