Spring JPAパフォーマンス診断 - 実行SQLの可視化とボトルネック特定

1
2
3
4
5
6

spring:
  jpa:
    show-sql: true
    properties:
      hibernate:
        format_sql: true

 1
 2
 3
 4
 5
 6
 7
 8
 9
10

Hibernate: 
    select
        u1_0.id,
        u1_0.email,
        u1_0.name,
        u1_0.created_at
    from
        users u1_0
    where
        u1_0.id=?

1
2
3
4

logging:
  level:
    org.hibernate.SQL: DEBUG
    org.hibernate.orm.jdbc.bind: TRACE

1
2
3
4
5

spring:
  jpa:
    properties:
      hibernate:
        use_sql_comments: true

1
2
3
4
5
6
7
8

/* select u from User u where u.id = :id */ select
    u1_0.id,
    u1_0.email,
    u1_0.name
from
    users u1_0
where
    u1_0.id=?

 1
 2
 3
 4
 5
 6
 7
 8
 9
10

spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true

logging:
  level:
    org.hibernate.stat: DEBUG
    org.hibernate.engine.internal.StatisticalLoggingSessionEventListener: DEBUG

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36

package com.example.demo.service;

import org.hibernate.SessionFactory;
import org.hibernate.stat.Statistics;
import org.springframework.stereotype.Service;

import jakarta.persistence.EntityManagerFactory;

@Service
public class StatisticsService {

    private final Statistics statistics;

    public StatisticsService(EntityManagerFactory entityManagerFactory) {
        SessionFactory sessionFactory = entityManagerFactory.unwrap(SessionFactory.class);
        this.statistics = sessionFactory.getStatistics();
        this.statistics.setStatisticsEnabled(true);
    }

    public void printStatistics() {
        System.out.println("=== Hibernate Statistics ===");
        System.out.println("Query execution count: " + statistics.getQueryExecutionCount());
        System.out.println("Query execution max time: " + statistics.getQueryExecutionMaxTime() + "ms");
        System.out.println("Slowest query: " + statistics.getQueryExecutionMaxTimeQueryString());
        System.out.println("Entity load count: " + statistics.getEntityLoadCount());
        System.out.println("Entity fetch count: " + statistics.getEntityFetchCount());
        System.out.println("Collection load count: " + statistics.getCollectionLoadCount());
        System.out.println("Collection fetch count: " + statistics.getCollectionFetchCount());
        System.out.println("Second level cache hit count: " + statistics.getSecondLevelCacheHitCount());
        System.out.println("Second level cache miss count: " + statistics.getSecondLevelCacheMissCount());
    }

    public void clearStatistics() {
        statistics.clear();
    }
}

1
2
3
4
5
6

<!-- Maven -->
<dependency>
    <groupId>net.ttddyy</groupId>
    <artifactId>datasource-proxy</artifactId>
    <version>1.11.0</version>
</dependency>

1
2

// Gradle
implementation 'net.ttddyy:datasource-proxy:1.11.0'

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35

package com.example.demo.config;

import net.ttddyy.dsproxy.listener.logging.SLF4JLogLevel;
import net.ttddyy.dsproxy.support.ProxyDataSourceBuilder;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.autoconfigure.jdbc.DataSourceProperties;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.Primary;

import javax.sql.DataSource;
import java.util.concurrent.TimeUnit;

@Configuration
public class DataSourceProxyConfig {

    @Autowired
    private DataSourceProperties dataSourceProperties;

    @Bean
    @Primary
    public DataSource dataSource() {
        DataSource originalDataSource = dataSourceProperties
            .initializeDataSourceBuilder()
            .build();

        return ProxyDataSourceBuilder.create(originalDataSource)
            .name("QueryLoggingProxy")
            .logQueryBySlf4j(SLF4JLogLevel.INFO)
            .logSlowQueryBySlf4j(100, TimeUnit.MILLISECONDS, SLF4JLogLevel.WARN)
            .countQuery()
            .multiline()
            .build();
    }
}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40

package com.example.demo.test;

import net.ttddyy.dsproxy.QueryCountHolder;
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.BeforeEach;
import org.junit.jupiter.api.Test;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.boot.test.context.SpringBootTest;

import static org.assertj.core.api.Assertions.assertThat;

@SpringBootTest
class UserServiceIntegrationTest {

    @Autowired
    private UserService userService;

    @BeforeEach
    void setUp() {
        QueryCountHolder.clear();
    }

    @AfterEach
    void tearDown() {
        QueryCountHolder.clear();
    }

    @Test
    void findAllUsersWithOrders_shouldExecuteOptimalQueries() {
        // Given: 10人のユーザーと各ユーザーに5件の注文がある状態

        // When
        userService.findAllUsersWithOrders();

        // Then: N+1問題がなければ2クエリ以下で取得できるはず
        assertThat(QueryCountHolder.getGrandTotal().getSelect())
            .as("SELECT文の実行回数が最適化されていること")
            .isLessThanOrEqualTo(2);
    }
}

1
2
3
4
5
6

<!-- Maven -->
<dependency>
    <groupId>p6spy</groupId>
    <artifactId>p6spy</artifactId>
    <version>3.9.1</version>
</dependency>

1
2

// Gradle
implementation 'p6spy:p6spy:3.9.1'

1
2
3
4
5
6

spring:
  datasource:
    # 元のURLの前に「jdbc:p6spy:」を追加
    url: jdbc:p6spy:postgresql://localhost:5432/mydb
    # P6SpyDriverに変更
    driver-class-name: com.p6spy.engine.spy.P6SpyDriver

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18

# 実際のJDBCドライバを指定
driverlist=org.postgresql.Driver

# ログ出力形式をカスタマイズ
logMessageFormat=com.p6spy.engine.spy.appender.CustomLineFormat
customLogMessageFormat=%(currentTime)|%(executionTime)ms|%(category)|%(connectionId)|%(sqlSingleLine)

# ログ出力先
appender=com.p6spy.engine.spy.appender.Slf4JLogger

# スロークエリの閾値（ミリ秒）
executionThreshold=100

# バインドパラメータを展開して表示
excludecategories=info,debug,result,resultset

# 日付フォーマット
dateformat=yyyy-MM-dd HH:mm:ss.SSS

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16

@Test
void detectN1Problem() {
    Statistics stats = entityManagerFactory.unwrap(SessionFactory.class).getStatistics();
    stats.clear();

    // 処理を実行
    List<User> users = userRepository.findAll();
    users.forEach(user -> user.getOrders().size()); // Lazy Load発生

    // N+1問題が発生している場合、クエリ数がユーザー数+1になる
    long queryCount = stats.getQueryExecutionCount();
    System.out.println("実行されたクエリ数: " + queryCount);
    
    // 期待値は2以下（ユーザー取得 + 注文一括取得）
    assertThat(queryCount).isLessThanOrEqualTo(2);
}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15

@Test
void detectN1ProblemWithDataSourceProxy() {
    QueryCountHolder.clear();

    // 処理を実行
    userService.findAllUsersWithOrderDetails();

    // SELECTクエリの実行回数を検証
    long selectCount = QueryCountHolder.getGrandTotal().getSelect();
    
    // N+1問題がない場合は2クエリ以下
    assertThat(selectCount)
        .as("N+1問題が発生していないこと")
        .isLessThanOrEqualTo(2);
}

1
2
3
4
5
6

-- N+1問題のパターン
select * from users;
select * from orders where user_id = 1;
select * from orders where user_id = 2;
select * from orders where user_id = 3;
-- ... 繰り返し

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12

// 解決策1: JOIN FETCH
@Query("SELECT u FROM User u LEFT JOIN FETCH u.orders")
List<User> findAllWithOrders();

// 解決策2: @EntityGraph
@EntityGraph(attributePaths = {"orders"})
List<User> findAll();

// 解決策3: @BatchSize（エンティティクラスに設定）
@OneToMany(mappedBy = "user", fetch = FetchType.LAZY)
@BatchSize(size = 100)
private List<Order> orders;

1
2
3
4
5
6
7
8
9

spring:
  jpa:
    properties:
      hibernate:
        # 100ミリ秒以上のクエリをログ出力
        session:
          events:
            log:
              LOG_QUERIES_SLOWER_THAN_MS: 100

1
2
3
4
5

spring:
  jpa:
    properties:
      hibernate:
        log_slow_query: 100

1
2
3
4
5
6
7

EXPLAIN ANALYZE 
SELECT u.*, o.*
FROM users u
LEFT JOIN orders o ON u.id = o.user_id
WHERE u.status = 'ACTIVE'
ORDER BY u.created_at DESC
LIMIT 100;

1
2
3
4
5
6
7

EXPLAIN ANALYZE 
SELECT u.*, o.*
FROM users u
LEFT JOIN orders o ON u.id = o.user_id
WHERE u.status = 'ACTIVE'
ORDER BY u.created_at DESC
LIMIT 100;

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12

@Repository
public class QueryAnalysisRepository {

    @PersistenceContext
    private EntityManager entityManager;

    public List<Object[]> explainQuery(String sql) {
        // PostgreSQLの場合
        String explainSql = "EXPLAIN ANALYZE " + sql;
        return entityManager.createNativeQuery(explainSql).getResultList();
    }
}

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26

@Entity
@Table(
    name = "users",
    indexes = {
        @Index(name = "idx_users_email", columnList = "email", unique = true),
        @Index(name = "idx_users_status_created", columnList = "status, created_at"),
        @Index(name = "idx_users_name", columnList = "name")
    }
)
public class User {
    @Id
    @GeneratedValue(strategy = GenerationType.IDENTITY)
    private Long id;

    @Column(nullable = false, unique = true)
    private String email;

    @Column(nullable = false)
    private String name;

    @Column(nullable = false)
    private String status;

    @Column(name = "created_at", nullable = false)
    private LocalDateTime createdAt;
}

1
2
3
4
5

// 良い例: statusで絞り込み → created_atでソート
@Index(name = "idx_status_created", columnList = "status, created_at")

// クエリ例
SELECT * FROM users WHERE status = 'ACTIVE' ORDER BY created_at DESC;

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15

-- 1. 関数を使用した場合
SELECT * FROM users WHERE LOWER(email) = 'test@example.com';
-- 解決策: 関数インデックスを作成するか、データを正規化

-- 2. LIKE検索で前方一致以外
SELECT * FROM users WHERE name LIKE '%田中%';
-- 解決策: 全文検索の導入を検討

-- 3. NULL比較（一部のDB）
SELECT * FROM users WHERE deleted_at IS NULL;
-- 解決策: 部分インデックスの作成

-- 4. 型の不一致
SELECT * FROM users WHERE id = '123';  -- idがBIGINTの場合
-- 解決策: 適切な型でバインド

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

-- PostgreSQL
SELECT
    tablename,
    indexname,
    indexdef
FROM pg_indexes
WHERE schemaname = 'public'
ORDER BY tablename, indexname;

-- MySQL
SHOW INDEX FROM users;

1
2
3
4

# 本番環境では絶対に避けるべき設定
spring:
  jpa:
    show-sql: true  # パフォーマンス低下の原因

1
2
3
4
5
6
7

// アンチパターン
@ManyToOne(fetch = FetchType.EAGER)  // 常にJOINが発生
private Department department;

// 推奨
@ManyToOne(fetch = FetchType.LAZY)
private Department department;

1
2
3
4
5
6
7

// アンチパターン: すべての列にインデックス
@Table(indexes = {
    @Index(columnList = "col1"),
    @Index(columnList = "col2"),
    @Index(columnList = "col3"),
    // ...
})

1
2
3
4
5
6

# 本番環境では負荷が高い
spring:
  jpa:
    properties:
      hibernate:
        generate_statistics: true