Javaアプリケーションをstraceで追う

最近、ちょっとずつstraceを使ってデバッグしたりすることがあって、今回Javaアプリケーションをstraceで追おうとするとどうするのかな？ということで少し調べてみました。

Javaアプリケーションをstraceで追う時は、少なくとも「-f」オプションはあった方が良さそうですね。その他、使いそうなオプションを。

-f … fork(2)/vfork(2)/clone(2)された子プロセスもトレースする
-t … タイムスタンプを表示（秒まで）
-tt … タイムスタンプを表示（マイクロ秒まで）

また、すでに起動中のアプリケーションをトレースするには、以下を付けるそうです。

-p [PID] … トレースしたいプロセスのPIDを指定する

その他、-oでファイル出力、-eでトレースしたいシステムコールをフィルタできるようです。

実際に使って、ちょっと確認してみましょう。

Javaアプリケーション起動時に指定する

最初は、Javaアプリケーション起動時にstraceコマンドを一緒に仕込んでみましょう。

こんなプログラムを用意します。
HelloWorld.java

public class HelloWorld {
    public static void main(String... args) throws InterruptedException {
        System.out.println("Hello World!!");

        Thread thread = new ChildThread();
        thread.start();

        thread.join();
    }

    static class ChildThread extends Thread {
        @Override
        public void run() {
            System.out.println("Hello Child Thread!!");
        }
    }
}

子スレッドも作成するようにしています。

コンパイル。

$ javac HelloWorld.java

まずは普通に実行。

$ java HelloWorld
Hello World!!
Hello Child Thread!!

では、straceをつけて実行してみます。

$ strace java HelloWorld

ですが、これだとJavaアプリケーション側で発行されたシステムコールが表示されません。最初にも書きましたが、「-f」が必要なようです。

というわけで、気を取り直して「-f」、それからタイムスタンプを表示する「-tt」を付けて実行。

$ strace -f -tt java HelloWorld 2>&1 | grep Hello
22:44:55.047220 execve("/usr/lib/jvm/java-8-oracle/bin/java", ["java", "HelloWorld"], [/* 76 vars */]) = 0
[pid 21076] 22:44:55.234833 stat("/path/to/HelloWorld.class",  <unfinished ...>
[pid 21076] 22:44:55.236497 open("/path/to/HelloWorld.class", O_RDONLY) = 4
[pid 21076] 22:44:55.237557 stat("/path/to/HelloWorld.class", {st_mode=S_IFREG|0664, st_size=649, ...}) = 0
[pid 21076] 22:44:55.254010 stat("/path/to/HelloWorld$ChildThread.class", {st_mode=S_IFREG|0664, st_size=481, ...}) = 0
[pid 21076] 22:44:55.254094 open("/path/to/HelloWorld$ChildThread.class", O_RDONLY) = 4
[pid 21076] 22:44:55.254186 stat("/path/to/HelloWorld$ChildThread.class", {st_mode=S_IFREG|0664, st_size=481, ...}) = 0
[pid 21076] 22:44:55.255142 write(1, "Hello World!!", 13Hello World!!) = 13
[pid 21095] 22:44:55.256713 write(1, "Hello Child Thread!!", 20Hello Child Thread!!) = 20

結果は標準エラー出力に吐き出されますが、今回は標準出力にマージしてgrepで絞り込んでいます。
※もしくは、「-o」でファイルに出力するとか

これで、確認できましたね。

Tomcatなどのdaemonに対してトレースしてみる

先ほどの例はjavaコマンドでの起動時に一緒にstraceを仕込んでいましたが、今度はTomcatのように起動済みのアプリケーションに対してトレースしてみましょう。

というわけで、Tomcatを起動します。サンプルとしてManagerアプリケーションを使うので、conf/tomcat-users.xmlを編集してtomcatユーザーでアクセス可能にしています。

$ bin/startup.sh

で、TomcatのPIDに対して、straceを適用してみます。

$ strace -f -tt -p [PID] 2>&1
strace: attach: ptrace(PTRACE_ATTACH, ...): Operation not permitted
Could not attach to process.  If your uid matches the uid of the target
process, check the setting of /proc/sys/kernel/yama/ptrace_scope, or try
again as the root user.  For more details, see /etc/sysctl.d/10-ptrace.conf

…コケました。

うーん、rootでやれって？

気を取り直してsudoで。今度は成功します。

$ sudo strace -f -tt -p [PID] 2>&1

…何もしなくても、ものすごい勢いでトレース結果が流れます。

このままだと追いにくいので、「-e」でトレースするシステムコールを絞るか、grepなどで絞り込んだりするとよさそうです。

まずは、「-e」で絞り込み。

$ sudo strace -f -tt -p [PID] -e trace=stat 2>&1
Process [PID] attached with 39 threads

curlでアクセスしてみます。ちょっと結果がわかりにくかったので、ここではわざと存在しないURLでアクセスしてみます。

$ curl -u tomcat:tomcat http://localhost:8080/manager/html/notfound

すると、こんな感じで表示されます。

[pid 22222] 23:05:39.440735 --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_ACCERR, si_addr=0x7f8e299c0400} ---
[pid 22359] 23:05:39.442587 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.442698 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.442750 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.442798 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.442833 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.442870 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.442922 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.442963 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.442996 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.443041 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.443085 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.443122 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.443212 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.443294 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.443372 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.443405 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22359] 23:05:39.443803 stat("/path/to/apache-tomcat-8.0.36/work/Catalina/localhost/manager/org/apache/jsp/WEB_002dINF/jsp/_403_jsp.class", {st_mode=S_IFREG|0664, st_size=9590, ...}) = 0
[pid 22359] 23:05:39.443970 stat("/path/to/apache-tomcat-8.0.36/work/Catalina/localhost/manager/org/apache/jsp/WEB_002dINF/jsp/_403_jsp.class", {st_mode=S_IFREG|0664, st_size=9590, ...}) = 0

grepとかで絞り込んでもいいでしょう。

$ sudo strace -f -tt -p 22207 2>&1 | grep manager

curlでアクセス。

$ curl -u tomcat:tomcat http://localhost:8080/manager/html/notfound

結果。

[pid 22457] 23:08:06.607899 read(79, "GET /manager/html/notfound HTTP/"..., 8192) = 142
[pid 22457] 23:08:06.609213 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp",  <unfinished ...>
[pid 22457] 23:08:06.609436 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.609517 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.609549 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.609594 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.609677 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.609720 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.609784 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.609836 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.609867 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.609909 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.609956 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.610042 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.610107 open("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", O_RDONLY) = 81
[pid 22457] 23:08:06.610192 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.610237 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.610277 stat("/path/to/apache-tomcat-8.0.36/webapps/manager/WEB-INF/jsp/403.jsp", {st_mode=S_IFREG|0644, st_size=4065, ...}) = 0
[pid 22457] 23:08:06.610547 stat("/path/to/apache-tomcat-8.0.36/work/Catalina/localhost/manager/org/apache/jsp/WEB_002dINF/jsp/_403_jsp.class", {st_mode=S_IFREG|0664, st_size=9590, ...}) = 0
[pid 22457] 23:08:06.610600 stat("/path/to/apache-tomcat-8.0.36/work/Catalina/localhost/manager/org/apache/jsp/WEB_002dINF/jsp/_403_jsp.class", {st_mode=S_IFREG|0664, st_size=9590, ...}) = 0