Go to Qiita Advent Calendar Top
LoginSignup
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

@th4nk_y0u_y0sh1

Springboot でehcache3.Xを実装してみる

Last updated at Posted at 2025-07-30

cacheとは

IEC（国際電気標準会議）の定義

buffer storage that contains data likely to be used later (あとで使うためのデータを含むバッファ記憶域）

ISO/IEC/IEEE 24765の定義

  1. temporary storage in computer memory, to improve operations by having frequently used data readily available for retrieval　（頻繁に使うデータをすぐ取り出せるようにするためのコンピュータの一時記憶領域）
  2. RAM（Random Access Memmory) with very high operating speed used for data storage within a processor　（プロセッサー内でものすごく速いスピードで使われるデータ領域をもつRAMのこと）

一般的なCacheの認識は以上のようだ

Ehcacheとは

今回、扱うEhcacheというプラグインはJVM (Java Virtual Machine)上で動作するアプリケーション層のキャッシュライブラリ／フレームワーク

JVMのヒープ領域上にキャッシュをEhcacheが独立して管理する

Ehcacheのキャッシュは
→OSのfree memmoryで管理されるものではない
→JVM上のヒープ領域(young gen/old gen)で管理されるものではない

Ehcacheは単独でキャッシュを定義できる

  • TTL(Time To Live)というキャッシュが保持される有効期限
  • Ehcacheの使うヒープメモリの上限値
  • etc.

非機能テスト

非機能テストとは、システムの 機能そのもの ではなく、性能や品質特性 を検証するテスト

今回は、EhcacheのTTLの設定がGCへどのように影響を与えるかを検証する

これは、ISO 25010でいう性能効率性の非機能テストに参照されるもの

一般的には機能ではないもの、負荷テスト、性能テストと言われるもので間違いなさそうだ

検証＃１

TTLを３秒に設定してみる

３秒ルールが切れたら回復ポイント（fallback)を参照するように設計した

キャッシュに参照しようとしてなかったら外部サービスのMongoDBを参照するようにした

ehcache.xmlでコンフィグを設定する

  • Javaで呼び出す名前空間の定義
  • キャッシュの有効期限
  • ヒープ領域で確保できるエントリー数　(←理論値）
ehcache.xml
<!--getCache configuration-->
 <cache alias="getCache">
    <key-type>java.lang.String</key-type>
    <value-type>java.lang.Object</value-type>
    <expiry><ttl unit="seconds">3</ttl></expiry>
    <resources><heap unit="entries">21</heap></resources>
 </cache>
  • ２回目以降の呼び出しでキャッシュの有効期限が切れるまでキャッシュが呼び出されているか
  • ３秒後に回復ポイントのMongoDBにクエリして思い出しているか

実装＃１

まず、ABCを呼び出す

これは、１回目の呼び出しなのでABCはキャッシュにない

１秒後（１０００ミリ秒後）

Aを呼び出してみる

これは、先ほど呼び出したものなので
あとで使うようにキャッシュに残したAが使われる

１秒後（１０００ミリ秒後）

初回の呼び出しから２秒経った
Bでもキャッシュに残っているはず

１秒後（１０００ミリ秒後）

初回の呼び出しから３秒後
TTLの３秒を超えた
もう忘れてキャッシュに何も残ってないはず
Cを呼び出してもキャッシュにない

１秒後（１０００ミリ秒後）

初回の呼び出しから４秒後
ABCを呼び出してみる
さて、キャッシュに残っているのはどれだろうか？

.java
for (String k : new String[] { "A", "B", "C" }) {
    cacheService.getFromCache(k);
}

// A, B, C: hot → cache hits
cacheService.getFromCache("A");
cacheService.getFromCache("B");
cacheService.getFromCache("C");

Thread.sleep(1000);
// stales after TTL?
cacheService.getFromCache("A");
cacheService.getFromCache("A");

Thread.sleep(1000);
cacheService.getFromCache("B");
cacheService.getFromCache("B");

Thread.sleep(1000);
cacheService.getFromCache("C");
cacheService.getFromCache("C");

Thread.sleep(1000);
// wrap up
cacheService.getFromCache("A");
cacheService.getFromCache("B");
cacheService.getFromCache("C");

結果＃1

catalinaのログからわかったこと

  • キャッシュを参照したときは速い(0ms以下)
  • ２回目の呼び出しからキャッシュを参照している
  • TTLの３秒後にはちゃんとMongoDBを参照している
catalina.log
springboot-app    | 2025-07-30 10:04:52.410  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'A': MongoDBから取得したA
springboot-app    | 2025-07-30 10:04:52.418  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'A' took 178 ms
springboot-app    | 2025-07-30 10:04:52.419  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'B', falling back to MongoDB
springboot-app    | 2025-07-30 10:04:52.423  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'B': MongoDBから取得したB
springboot-app    | 2025-07-30 10:04:52.424  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'B' took 5 ms
springboot-app    | 2025-07-30 10:04:52.424  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'C', falling back to MongoDB
springboot-app    | 2025-07-30 10:04:52.429  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'C': MongoDBから取得したC
springboot-app    | 2025-07-30 10:04:52.430  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'C' took 6 ms
springboot-app    | 2025-07-30 10:04:52.432  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'A' (2 ms)
springboot-app    | 2025-07-30 10:04:52.433  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'B' (1 ms)
springboot-app    | 2025-07-30 10:04:52.433  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'C' (0 ms)
springboot-app    | 2025-07-30 10:04:53.435  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'A' (0 ms)
springboot-app    | 2025-07-30 10:04:53.436  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'A' (0 ms)
springboot-app    | 2025-07-30 10:04:54.438  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'B' (0 ms)
springboot-app    | 2025-07-30 10:04:54.439  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'B' (0 ms)
springboot-app    | 2025-07-30 10:04:55.442  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'C', falling back to MongoDB
springboot-app    | 2025-07-30 10:04:55.448  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'C': MongoDBから取得したC
springboot-app    | 2025-07-30 10:04:55.449  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'C' took 8 ms
springboot-app    | 2025-07-30 10:04:55.449  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'C' (0 ms)
springboot-app    | 2025-07-30 10:04:56.450  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'A', falling back to MongoDB
springboot-app    | 2025-07-30 10:04:56.453  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'A': MongoDBから取得したA
springboot-app    | 2025-07-30 10:04:56.454  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'A' took 4 ms
springboot-app    | 2025-07-30 10:04:56.454  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'B', falling back to MongoDB
springboot-app    | 2025-07-30 10:04:56.459  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'B': MongoDBから取得したB
springboot-app    | 2025-07-30 10:04:56.459  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'B' took 5 ms
springboot-app    | 2025-07-30 10:04:56.459  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'C' (0 ms)

上のログは読みましたでしょうか？

目を凝らして読んでみてください

読みづらいですね

正解は、最後はCだけキャッシュに残る！でした。

検証＃２

ヒープ領域で確保できるエントリー数を超えるオブジェクトがキャッシュに登録されるとどうなるのか？

デフォルトでheapメモリの管理方法はLRU(Least Recently Used)方式を採る

ヒープ上限を超えた分は LRU（最も長く参照されていないもの）から自動的に退避（Eviction）される

なので、キャッシュの有効期限が切れてないのにも関わらずキャッシュされるはずのものがキャッシュから消えてしまうことが予想される

実装＃２

3秒待機するのでキャッシュの有効期限が切れる

先ほどの試行の後にA〜V(22)まで追加でデータを呼び出す

A〜Cの３つにさらにD〜Vの１９コを足すと２２コ

これはヒープ上限エントリー数に設定した２１コを超える

２２コのオブジェクトを呼び出す試行を5回繰り返す

さてどのキャッシュから先に退避されるでしょう

.java
Thread.sleep(3000);
// wrap up
int l = 0;
while (l < 5) {
    for (String key : new String[] {
        "A", "B", "C", "D", "E", "F", "G", "H", "I", "J",
        "K", "L", "M", "N", "O", "P", "Q", "R", "S", "T", "U", "V"
    }) {
        cacheService.getFromCache(key);
        System.out.println("Loop " + l + ": Accessing key " + key);
    }
    Thread.sleep(1000);  // Simulate time delay to test TTL and GC impact
    l++;
}

結果＃２

LRUで使われないキャッシュが退避される

最大エントリー数を21に設定している

１秒後の２回目の呼び出しで超過分の一個だけキャッシュされないのだと予想していたが
実際にキャッシュされなかったのは「AGHQR」だった

１秒後の３回目の試行でキャッシュされなかったのは、「ABCDOP」

１秒後の4回目の試行でキャッシュされなかったのは、「EFIJKLMNSTUV」

１秒後の5回目の試行でキャッシュされなかったのは、「GHIJKQR」

catalina.log
2025-07-31 10:06:41.809  INFO 1 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 3 ms
2025-07-31 10:06:41.887  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'A', falling back to MongoDB
2025-07-31 10:06:42.002  INFO 1 --- [nio-8080-exec-1] org.mongodb.driver.connection            : Opened connection [connectionId{localValue:3, serverValue:7}] to mongo-fallback:27017
2025-07-31 10:06:42.110  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'A': MongoDBから取得したA
2025-07-31 10:06:42.124  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'A' took 238 ms
2025-07-31 10:06:42.125  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'B', falling back to MongoDB
2025-07-31 10:06:42.130  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'B': MongoDBから取得したB
2025-07-31 10:06:42.131  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'B' took 6 ms

(...)

2025-07-31 10:06:48.166  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'A', falling back to MongoDB
2025-07-31 10:06:48.176  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'A': MongoDBから取得したA
2025-07-31 10:06:48.177  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'A' took 11 ms
Loop 0: Accessing key A
2025-07-31 10:06:48.195  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'B', falling back to MongoDB
2025-07-31 10:06:48.200  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'B': MongoDBから取得したB
2025-07-31 10:06:48.201  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'B' took 6 ms
Loop 0: Accessing key B
2025-07-31 10:06:48.201  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'C', falling back to MongoDB
2025-07-31 10:06:48.206  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'C': MongoDBから取得したC
2025-07-31 10:06:48.206  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'C' took 5 ms
Loop 0: Accessing key C

(...)

2025-07-31 10:06:49.407  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'R', falling back to MongoDB
2025-07-31 10:06:49.414  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'R': MongoDBから取得したR
2025-07-31 10:06:49.414  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'R' took 7 ms
Loop 1: Accessing key R
2025-07-31 10:06:49.415  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'S' (0 ms)
Loop 1: Accessing key S
2025-07-31 10:06:49.415  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'T' (0 ms)
Loop 1: Accessing key T
2025-07-31 10:06:49.415  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'U' (0 ms)
Loop 1: Accessing key U
2025-07-31 10:06:49.415  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'V' (0 ms)
Loop 1: Accessing key V

(...)

2025-07-31 10:06:52.591  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'P' (0 ms)
Loop 4: Accessing key P
2025-07-31 10:06:52.592  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'Q', falling back to MongoDB
2025-07-31 10:06:52.596  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'Q': MongoDBから取得したQ
2025-07-31 10:06:52.597  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'Q' took 6 ms
Loop 4: Accessing key Q
2025-07-31 10:06:52.599  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache miss for key 'R', falling back to MongoDB
2025-07-31 10:06:52.604  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : MongoDB hit for key 'R': MongoDBから取得したR
2025-07-31 10:06:52.605  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : getFromCache execution for key 'R' took 6 ms
Loop 4: Accessing key R
2025-07-31 10:06:52.605  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'S' (0 ms)
Loop 4: Accessing key S
2025-07-31 10:06:52.605  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'T' (0 ms)
Loop 4: Accessing key T
2025-07-31 10:06:52.605  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'U' (0 ms)
Loop 4: Accessing key U
2025-07-31 10:06:52.605  INFO 1 --- [nio-8080-exec-1] c.example.cacheapp.service.CacheService  : Cache hit for key 'V' (0 ms)
Loop 4: Accessing key V

キャッシュされたりされんかったり読みづらい挙動をすることがわかった

TTL切れ + LRUの複合作用が起きていることがわかった

GCへの影響

  • JVMヒープ領域の逼迫(Full GC)は起きていない
  • TTL切れによりヒープに残された短命オブジェクトが大量にGCされる(Young GC)

TTL切れが頻繁に起こるために短命のオブジェクトが大量にできた

JVMは使わないオブジェクトを自動的に掃除する機能であるGC(Garbage Collector)を持っている

GC(15) Pause Young (Normal) (G1 Evacuation Pause) 123M->28M(183M) 10.855ms

GCによりヒープ領域で短命のオブジェクトの領域のYoung Genで大量にオブジェクトが破棄される

GCが起きているおかげでOOM(Out Of Memmory)を防ぐことができている

この Young GCの間、アプリは10.855ms停止

Stop-The-World(STW) が発動する

0.011秒の停止はcatalina.logでは見れない

まさに 五条悟の「無量空処」 のように、

外界では一瞬、内部では膨大な処理が行われる

という状態です。

gc.log
[2025-07-31T10:06:52.491+0000][info] GC(15) Pause Young (Normal) (G1 Evacuation Pause)
[2025-07-31T10:06:52.491+0000][info] GC(15) Using 6 workers of 8 for evacuation
[2025-07-31T10:06:52.501+0000][info] GC(15)   Pre Evacuate Collection Set: 0.0ms
[2025-07-31T10:06:52.502+0000][info] GC(15)   Evacuate Collection Set: 7.8ms
[2025-07-31T10:06:52.502+0000][info] GC(15)   Post Evacuate Collection Set: 2.2ms
[2025-07-31T10:06:52.502+0000][info] GC(15)   Other: 0.9ms
[2025-07-31T10:06:52.502+0000][info] GC(15) Eden regions: 99->0(96)
[2025-07-31T10:06:52.502+0000][info] GC(15) Survivor regions: 10->13(14)
[2025-07-31T10:06:52.502+0000][info] GC(15) Old regions: 16->18
[2025-07-31T10:06:52.502+0000][info] GC(15) Humongous regions: 0->0
[2025-07-31T10:06:52.502+0000][info] GC(15) Metaspace: 53409K->53409K(1097728K)
[2025-07-31T10:06:52.502+0000][info] GC(15) Pause Young (Normal) (G1 Evacuation Pause) 123M->28M(183M) 10.855ms
[2025-07-31T10:06:52.502+0000][info] GC(15) User=0.05s Sys=0.01s Real=0.01s

まとめ

今回、EhcacheのTTL設定で遊んでみて学んだこと

  • TTL切れはEhcacheのキャッシュ領域から退避(Evict)される
  • TTL切れの使われないオブジェクトはJVMヒープのYoung Genに生成されYoung GCが起きる。この間にStop-The-World(STW)が発動する。OOM(OutOfMemory)は発生しない。
  • Ehcacheでヒープ上限を超えたオブジェクトのエントリーはキャッシュされない。LRUにしたがってキャッシュされたオブジェクトから退避される。

画面を実装した様子

image.png
フロントエンドがあると映えるのか

それは、さておき

見栄えより大きなメリットがあります

  • リバースプロキシを実装すればDDoS対策もすることができる
  • レイトリミットを実装すればユーザーに遅延を感じさせない
  • フォームバリデーションによりバックエンドへの無効なリクエストを防ぐことができる

例えば、AからCまでのデータしかないときはそれ以外の入力を防ぐことができる

一回クリックしたら処理が終わるまでもう一回クリックさせないこともできる

背景のアニメーションがあると注意を逸らすことができ、待機時間を心理的効果で短くすることができる

次回、フロントエンドの実装についてまとめる

引用

グロッサリー

  • ISO (International Organization for Standardization）国際標準化機構
  • IEC（International Electrotechnical Commision) 国際電気標準会議
  • IEEE (Institute of Electrical and Electronics Engineers) I-triple-E、 米国電気電子技術者協会
0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?