消えるStackTrace

こんにちは　マネックスラボのMです。

ラボではJavaを使用したシステムが多いです
先日とある不具合が発生してしまいまして
ログを調査していたところ
この事象が発生していましたので紹介したいと思います。

事象

Javaのログで例外が出たとなるとこのようなStackTraceの出力を期待するかと思います。

2023-08-25 10:00:00.000 ERROR 11111 --- [http-nio-8080-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.NullPointerException] with root cause

java.lang.NullPointerException: null
    at abc.logic.AbcLogic.addParams(AbcLogic.java:111)
    at abc.controller.AbcController.getItems(AbcController.java:222)
    at abc.controller.AbcController.getGroups(AbcController.java:333)
    at abc.controller.AbcController.index(AbcController.java:444)
    ...

このようにStackTraceが出力されることで原因行の特定ができるのですが
今回紹介する事象が発生すると以下のようにStackTrace部分が出なくなってしまいます

2023-08-25 10:00:00.000 ERROR 11111 --- [http-nio-8080-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.NullPointerException] with root cause

何が起きているか

どうやらJava7頃からこの機能が実装されたようですが
高速パスと言われる、ループ処理や、頻繁に呼び出されるメソッド の中で
特定の例外（NullPointerException や ArrayIndexOutOfBoundsException など）が発生すると
StackTraceの出力を省略するそうです
これはStackTraceの取得に負荷がかかるためパフォーマンスを改善する目的のものとのことです

どのくらい省略されるのか

今わかっていることは以下です

  • 一度省略が発生すると、JVM起動中はずっと省略される
  • JVMを再起動すると（おそらく）省略前の状態になる＝しばらく出力される
  • 省略されはじめる例外の発生回数は決まっていない？
    • 検証したところ、同じロジックでも2回で省略される場合もあれば、2万回で省略される場合もある

対応方法はあるか

-XX:-OmitStackTraceInFastThrow

上記の起動オプションをJVMに与えて起動することで省略されなくなります
ただし、元々パフォーマンスを改善する目的のものなので注意が必要とのことです
が、実際にはこの機能に該当するような例外がパフォーマンスに影響するほど頻発する
状態で機能をリリースするようなことはないんじゃないかと個人的には思います

人材募集