時々Thread.dumpStackデバッグ

# TL;DR

Javaでデバッグの方法はいろいろあるけど、`Thread#dumpStack`を使う（スタックトレースを表示する）、みたいなことも知っておくと便利ですよ、ということで。


# デバッグ方法？

Javaアプリケーションのデバッグって、どんな感じでやっているでしょうか？

- `System.out.println`でしょ
- 各種ログライブラリで、ふつうにログ埋め込みますよ
- IDEのデバッガー使ってます

まあ、いろいろあるんじゃないかと思います。

デバッガーも使うけど、めんどうな時は`System.out.println`してる、みたいなこともあるでしょう。


# スタックトレースを使う

確認したい内容によっては、スタックトレースを表示すると楽に情報が見れることがあります。

たとえば、

- ある処理の呼び出しを、どういう経路で、誰が行っているか知りたい
- 共通的な処理を入れ込んだ時に、ちゃんと呼び出しが行われているか知りたい

などなど。

前者は、「これ、誰が呼び出してるんだろう？」とか「なんでこの処理が呼び出されたんだろう？」ということを確認したい時などに。後者は、AOPやサーブレットフィルターなどを追加した時に、「本当に組み込まれているか？」を確認したい時などに。

ログや処理結果に反映されるなどで、デバッグをするための処理を仕込まなくてもわかるのが1番ですけどね。それがわからない時、確認しなくてはいけない時、トレースしなくてはいけない時などに知っておくと便利です。


# 例外のインスタンスは必ずスローしなければならない、というわけでもない

Javaで例外（`Exception`）を目にする機会というのは

- なにかしら問題が起こった時に、スタックトレースとともに表示される
- try-catchと`printStackTrace`を知り、「これでスタックトレースというものが表示される」と覚える
- 例外というものを覚え、`throw`で例外をスローできることを知る（で、`catch`する）

という感じで、およそ「エラーの発生」、「エラーハンドリング」と合わせて意識に刷り込まれます。

なので「エラーが起こるとスタックトレースが出る」とか、スタックトレースを見ると「エラーになった」みたいな拒絶反応に近いことになる人も、まあまあ見ます。

ですが、`Exception`（というか、その上位の`Throwable`）もインスタンスですし、`throw`できるだけであってここからスタックトレースをオブジェクトとして取得することもできます。

[Throwable#getStackTrace](https://docs.oracle.com/javase/jp/11/docs/api/java.base/java/lang/Throwable.html#getStackTrace())

これを標準エラー出力に書き出しているのが、おなじみ`printStackTrace`です。

[Throwable#printStackTrace](https://docs.oracle.com/javase/jp/11/docs/api/java.base/java/lang/Throwable.html#printStackTrace())

https://github.com/openjdk/jdk/blob/jdk-11+9/src/java.base/share/classes/java/lang/Throwable.java#L638-L673

なので`catch`を使わずともスタックトレースを出力することができます。

こんな感じですね。

```java
        new Exception().printStackTrace();
```

とはいえ、例外を`new`して`throw`しないのはちょっと気持ち悪いかもしれません。

こんな時には`Thread#dumpStack`を使ってみるとよいでしょう。

```java
        Thread.dumpStack();
```

まあ、実際の中身はこんな感じなんですが。

```java
    public static void dumpStack() {
        (new Exception("Stack trace")).printStackTrace();
    }
```

https://github.com/openjdk/jdk/blob/jdk-11+9/src/java.base/share/classes/java/lang/Thread.java#L1423-L1425

結局は、`Exception`のインスタンスを生成しているんですけどね。


# サンプル

実際に、例を見てみましょう。

確認環境はこちらです。

```java
$ java --version
openjdk 11.0.9.1 2020-11-04
OpenJDK Runtime Environment (build 11.0.9.1+1-Ubuntu-0ubuntu1.20.04)
OpenJDK 64-Bit Server VM (build 11.0.9.1+1-Ubuntu-0ubuntu1.20.04, mixed mode, sharing)


$ mvn --version
Apache Maven 3.6.3 (cecedd343002696d0abb50b32b541b8a6ba2883f)
Maven home: /home/charon-r13b/.sdkman/candidates/maven/current
Java version: 11.0.9.1, vendor: Ubuntu, runtime: /usr/lib/jvm/java-11-openjdk-amd64
Default locale: ja_JP, platform encoding: UTF-8
OS name: "linux", version: "5.4.0-56-generic", arch: "amd64", family: "unix"
```

お題は、簡単にSpring Bootでいきます。

```shell
$ curl https://start.spring.io/starter.tgz -d dependencies=web,jdbc,h2 \
           -d bootVersion=2.4.0 -d baseDir=demo | tar -xzvf -
$ cd demo
```

こんな`RestController`を作成。

`src/main/java/com/example/demo/HelloController.java`

```java
package com.example.demo;

import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RestController
public class HelloController {
    @GetMapping("hello")
    public String hello() {
        return "Hello World!!";
    }
}
```

起動。

```shell
$ mvn spring-boot:run
```

確認。

```shell
$ curl localhost:8080/hello
Hello World!!
```

まずは動いているのが確認できたので、`RestController`を以下のように修正してみます。

```shell
@RestController
public class HelloController {
    public HelloController() {
        Thread.dumpStack();
    }

    @GetMapping("hello")
    public String hello() {
        Thread.dumpStack();
        return "Hello World!!";
    }
}
```

コンストラクタと、リクスエストを受け付けるメソッドに`Thread#dumpStack`を仕込みました。

すると、`mvn spring-boot:run`（というかアプリケーションの起動時）に、こんな内容が標準エラー出力に書き出されます。

```java
java.lang.Exception: Stack trace
	at java.base/java.lang.Thread.dumpStack(Thread.java:1388)
	at com.example.demo.HelloController.<init>(HelloController.java:9)
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
	at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:212)
	at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:87)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateBean(AbstractAutowireCapableBeanFactory.java:1310)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1216)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:571)
	at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:531)
	at org.springframework.beans.factory.support.AbstractBeanFactory.lambda$doGetBean$0(AbstractBeanFactory.java:335)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:234)
	at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:333)
	at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:208)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:944)
	at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:925)
	at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:588)
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:144)
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:767)
	at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:759)
	at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:426)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:326)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1309)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1298)
	at com.example.demo.DemoApplication.main(DemoApplication.java:10)
```

今回のコードだと、アプリケーションの`main`メソッドからの呼び出し先の時点で、すでに`RestController`のインスタンスが作成されていることがわかります。

```java
	at com.example.demo.DemoApplication.main(DemoApplication.java:10)
```

また、リクエストを送ってみると

```shell
$ curl localhost:8080/hello
Hello World!!
```

こんなスタックトレースが得られます。

```java
java.lang.Exception: Stack trace
	at java.base/java.lang.Thread.dumpStack(Thread.java:1388)
	at com.example.demo.HelloController.hello(HelloController.java:14)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:893)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:807)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1061)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:961)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:626)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.base/java.lang.Thread.run(Thread.java:834)
```

ちょっと長いので、まあまあ見そうな部分を残すと、こんなところでしょうか。


```java
java.lang.Exception: Stack trace
	at java.base/java.lang.Thread.dumpStack(Thread.java:1388)
	at com.example.demo.HelloController.hello(HelloController.java:14)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:893)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:807)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1061)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:961)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:626)
```

Spring FrameworkがどのようなクラスをたどってControllerを呼び出しているかの雰囲気が、少しわかります。

では、次に`@Transactional`アノテーションを付けてみましょう。

```java
    @Transactional
    @GetMapping("hello")
    public String hello() {
        Thread.dumpStack();
        return "Hello World!!";
    }
```

すると、スタックトレースがこう変化します。

```java
java.lang.Exception: Stack trace
	at java.base/java.lang.Thread.dumpStack(Thread.java:1388)
	at com.example.demo.HelloController.hello(HelloController.java:16)
	at com.example.demo.HelloController$$FastClassBySpringCGLIB$$71860334.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:771)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:371)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:134)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
	at com.example.demo.HelloController$$EnhancerBySpringCGLIB$$84c39e5d.hello(<generated>)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:893)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:807)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1061)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:961)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:626)
```

リフレクションでの呼び出しを抜粋すると、`@Transactional`がない時はこれくらいシンプルだったのが

```java
java.lang.Exception: Stack trace
	at java.base/java.lang.Thread.dumpStack(Thread.java:1388)
	at com.example.demo.HelloController.hello(HelloController.java:14)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
```

一気に呼び出し階層が増えます。

```java
java.lang.Exception: Stack trace
	at java.base/java.lang.Thread.dumpStack(Thread.java:1388)
	at com.example.demo.HelloController.hello(HelloController.java:16)
	at com.example.demo.HelloController$$FastClassBySpringCGLIB$$71860334.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:771)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:371)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:134)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:749)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:691)
	at com.example.demo.HelloController$$EnhancerBySpringCGLIB$$84c39e5d.hello(<generated>)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
```

トランザクションに関係しそうな処理が織り込まれているのが確認できますね。

```java
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:371)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:134)
```

わかりやすい例として、AOPを使用したわけですが。

`@Transactional`の場合はコミット、ロールバックの実際の結果で確認すればよい、という話はもちろんあります。ですが、「そもそも呼ばれてる？」とか「なにが変わるんだろう？」みたいな疑問にはこういう視点で確認することもできるかな、と。


# 注意点

こういうスタックトレースを扱う方法を知ると、`Exception`のインスタンスを作ってスタックトレースを得ればメソッド名とかソースコードの行番号をログに出力できるのでは？とか思うことがあります。

ですが、これはやらない方が懸命です。

`Exception`のインスタンスの生成は重い処理になるため、ログ出力の高頻度で使われる用途に組み込んでしまうとパフォーマンスがとても悪くなります。

あくまで、例外は「例外的な状況で使いましょう」、という原則は変わりません。

今回のような使い方は、一時的なデバッグ用途のため、知りたい情報が確認できたら削除されるような代物のはずです。


# というわけで

使えそうなところがあれば、デバッグの手段としておひとつどうぞ。

あと、自分たちが作るクラスもスタックトレースに含まれることになるので、「なにをするためのクラスやメソッドなのか、名前から推測がしやすいもの」とすることを心がけたいですね。

そうすれば、スタックトレースを見るとだいたいどんな処理が行われていそうか、雰囲気をつかみやすくなるでしょう。