#chiroito ’s blog

Java を中心とした趣味の技術について

Java がファイルを読んでいるか strace を使って確認する

Java アプリケーションの動きを分析をしていると、javaプロセスがファイルを開いたのかどうか確認したいことがあります。自分で作成したアプリケーションがファイルを読み書きしていればログを入れて確認できますが、アプリケーションの変更が簡単に行なえない場合やファイルを読み書きしている部分がミドルウェアやライブラリの内部で行われているとファイルの読み書きを確認することは難しいです。

java プロセスは OS から見るとただのプロセスなので、ファイルの読み書きにはシステムコールを使用します。このシステムコールを監視することでアプリケーションの変更や停止をせずに java プロセスがファイルを読み書きしているかを確認できます。Linux では strace を使用してシステムコールを監視します。

次のサンプルプログラムは、第一引数に与えた引数をファイルパスとしてファイルを読み込みモードで開くアプリケーションです。

import java.io.*;
import java.nio.file.*;

public class FileOpen {
    public static void main(String[] args) {
        try(InputStream inputStream = Files.newInputStream(Paths.get(args[0]))){
            // なにもしない
        } catch (IOException e) {
            e.printStackTrace();
        }
    }
}

今回は、このサンプルプログラムのソースファイル(FileOpen.java)を読込んで動作を監視します。監視されるコマンドはjava FileOpen FileOpen.javaになります。

このアプリケーションは try-catch-resource を使用して InputStream のオブジェクトを取得しますが、try句の中では使用しません。「Javaは勝手に最適化するって聞くし、結果を使用しない処理なのでファイルの読み込みはされないのでは?」と思う方もいるかもしれません。このアプリケーションはファイルの読み込むのかシステムコールを監視してみましょう。

システムコールの監視には strace コマンドを使用します。スレッド毎(-ff)に監視結果をstrace_java という接頭辞のファイルへ出力し(-o strace_java)、ファイルディスクリプタ番号とファイルパスの対応付けて(-y)プロセス(java FileOpen FileOpen.java)を実行してシステムコールを監視します。 実行が終わった後には strace_java から始まるファイルがスレッド分作成されます。ファイルはアプリケーションが使用するスレッドだけでは無く、JVM が使用するスレッドの分まで作成されます。

> strace -ff -y -o strace_java java FileOpen FileOpen.java
> ls -w1 strace_java*
strace_java.11802
strace_java.11804
strace_java.11805
strace_java.11806
strace_java.11807
strace_java.11811
strace_java.11812
strace_java.11813
strace_java.11814
strace_java.11815
strace_java.11816
strace_java.11817

※この方法は、java プロセスの実行から終了までを監視しますが、既に起動している java プロセスを監視する場合にはコマンドの代わりにプロセス ID を-p <PID>のように指定します。

これらの結果の中から、grep コマンドを使って FileOpen.java が関わるログを探し出します。

> grep FileOpen.java strace_java*
strace_java.11802:execve("/usr/bin/java", ["java", "FileOpen", "FileOpen.java"], [/* 24 vars */]) = 0
strace_java.11804:open("FileOpen.java", O_RDONLY)         = 4
strace_java.11804:close(4</home/oracle/FileOpen.java>)    = 0

このログを確認すると、アプリケーションは読み込み専用でファイルを開いて(open("FileOpen.java", O_RDONLY))、その後クローズ(close(4</home/oracle/FileOpen.java>))しています。strace を使うことで、アプリケーションの修正無しに確認できました。

この例では、アプリケーションの実行と監視を同時に行いましたが、既に動いているプロセスに対してはstrace -ff -y -o strace_java -P <PID>で監視できます。