LoginSignup
7
0

More than 1 year has passed since last update.

TISAdvent Calendar 2020Day 7tis
@charoninTIS株式会社

時々Thread.dumpStackデバッグ

Last updated at Posted at 2020-12-07

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

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

Throwable#printStackTrace

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

こんな感じですね。

        new Exception().printStackTrace();

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

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

        Thread.dumpStack();

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

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

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

サンプル

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

確認環境はこちらです。

$ 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でいきます。

$ 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

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!!";
    }
}

起動。

$ mvn spring-boot:run

確認。

$ curl localhost:8080/hello
Hello World!!

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

@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.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のインスタンスが作成されていることがわかります。

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

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

$ curl localhost:8080/hello
Hello World!!

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

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.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アノテーションを付けてみましょう。

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

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

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.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.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 org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:371)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:134)

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

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

注意点

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

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

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

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

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

というわけで

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

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

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

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
What you can do with signing up
Sign upLogin
7
0