閱讀430 返回首頁    go 微軟 go windows

Clojure世界：利用HouseMD診斷clojure

  HouseMD是淘寶的聚石寫的一個非常優秀的Java進程運行時診斷和調試工具，如果你接觸過btrace，那麼HouseMD也許你應該嚐試下，它比btrace更易用，不需要寫腳本，類似strace的方式attach到jvm進程做跟蹤調試。

    基本的安裝和使用請看這篇文檔《UserGuide》，恕不重複。以下內容都假設你正確安裝了housemd。

    本文主要介紹下怎麼用housemd診斷跟蹤clojure進程。Clojure的java實現也是跑在JVM裏，當然也可以用housemd。

    我們以一個簡單的例子開始，假設我們有如下clojure代碼：
(loop [x 1]
  (Thread/sleep 1000)
  (prn x)
  (recur (inc x)))

    這段很簡單，隻是間隔一秒不斷地打印遞增的數字x。我們準備用housemd跟蹤這個程序的運行，首先運行這個程序，你可以用lein，也可以直接java命令運行：
java -cp clojure.jar clojure.main test.clj

    運行時不斷地在控製台打印數字，通過jps或者ps查詢到該進程的id，假設為pid，使用housemd連接到該進程：
housemd <pid>
    順利進入housemd的交互控製台，通過help命令可以查詢支持的命令：

housemd> help

quit      terminate the process.
help      display this infomation.
trace     display or output infomation of method invocaton.
loaded    display loaded classes information.

    要用housemd調試clojure，你需要對clojure的實現有一點點了解，有興趣可以看過去的一篇blog《clojure hacking guide》，簡單來說，clojure的編譯器會將clojure代碼編譯成java類並運行。對於JVM來說，clojure生成的類，跟java編譯器生成類沒有什麼不同。
    具體到上麵的clojure代碼，會生成一個名為user$eval1的類，user是默認的namespace，而eval1是clojure編譯器自動生成的一個標示類名，通過loaded命令查詢類的加載情況：
housemd> loaded user$eval1 -h
user$eval1 -> null
    - clojure.lang.DynamicClassLoader@1d25d06e
        - clojure.lang.DynamicClassLoader@1d96f4b5
            - sun.misc.Launcher$AppClassLoader@a6eb38a
                - sun.misc.Launcher$ExtClassLoader@69cd2e5f

    通過-h選項打印了加載user$eval1的類加載器的層次關係，因為user$eval1是動態生成的（clojure啟動過程中），因此它不在任何一個class或者jar文件中。除了查詢user namespace的類之外，你還可以查詢clojure.core,clojure.lang,clojure.java等任何被加載進來的類，例如查詢clojure.core.prn的類,在clojure裏這是一個函數，在jvm看來這隻是一個類：
housemd> loaded -h core$prn
clojure.core$prn -> /Volumes/HDD/Users/apple/clojure/clojure.jar
    - sun.misc.Launcher$AppClassLoader@a6eb38a
        - sun.misc.Launcher$ExtClassLoader@69cd2e5f
   注意，不需要完整的namespace——clojure.core，直接core$prn即可。其他也是類似。小技巧：如果你實在不知道clojure編譯器生成的類名，你可以利用jvm自帶的jmap命令來查詢。

   接下來，我們嚐試用trace命令跟蹤方法的運行，例如例子中的clojure代碼用到了loop和recur兩個sepcial form，我們跟蹤下loop:
housemd> trace -t 5 core$loop
INFO : probe class clojure.core$loop
core$loop.doInvoke(Object, Object, Object, Object)    sun.misc.Launcher$AppClassLoader@a6eb38a            0            -ms    null
core$loop.getRequiredArity()                          sun.misc.Launcher$AppClassLoader@a6eb38a            0            -ms    null

core$loop.doInvoke(Object, Object, Object, Object)    sun.misc.Launcher$AppClassLoader@a6eb38a            0            -ms    null
core$loop.getRequiredArity()                          sun.misc.Launcher$AppClassLoader@a6eb38a            0            -ms    null

core$loop.doInvoke(Object, Object, Object, Object)    sun.misc.Launcher$AppClassLoader@a6eb38a            0            -ms    null
core$loop.getRequiredArity()                          sun.misc.Launcher$AppClassLoader@a6eb38a            0            -ms    null

core$loop.doInvoke(Object, Object, Object, Object)    sun.misc.Launcher$AppClassLoader@a6eb38a            0            -ms    null
core$loop.getRequiredArity()                          sun.misc.Launcher$AppClassLoader@a6eb38a            0            -ms    null

core$loop.doInvoke(Object, Object, Object, Object)    sun.misc.Launcher$AppClassLoader@a6eb38a            0            -ms    null
core$loop.getRequiredArity()                          sun.misc.Launcher$AppClassLoader@a6eb38a            0            -ms    null

INFO : Ended by timeout
INFO : reset class clojure.core$loop

    在5秒內，clojure.core$loop類有兩個方法各被調用了5次，doInvoke是實際的調用，而getRequiredArity用來查詢loop所需要的參數個數。trace還可以跟蹤到具體的方法，例如我們跟蹤prn函數的調用情況：
housemd> trace -t 5 core$prn.doInvoke
INFO : probe class clojure.core$prn
core$prn.doInvoke(Object)    sun.misc.Launcher$AppClassLoader@a6eb38a            1            1ms    clojure.core$prn@3e4ac866

core$prn.doInvoke(Object)    sun.misc.Launcher$AppClassLoader@a6eb38a            2           <1ms    clojure.core$prn@3e4ac866

core$prn.doInvoke(Object)    sun.misc.Launcher$AppClassLoader@a6eb38a            3           <1ms    clojure.core$prn@3e4ac866

core$prn.doInvoke(Object)    sun.misc.Launcher$AppClassLoader@a6eb38a            4           <1ms    clojure.core$prn@3e4ac866

core$prn.doInvoke(Object)    sun.misc.Launcher$AppClassLoader@a6eb38a            5           <1ms    clojure.core$prn@3e4ac866

INFO : Ended by timeout
INFO : reset class clojure.core$prn
  
   trace打印了方法的調用次數（5秒內）和每次調用的時間（毫秒級別），以及調用的target object。小技巧：沒有可變參數的函數生成類最終調用的是invoke方法（參數個數可能重載），有可變參數的函數調用的是doInvoke方法。

   trace命令還支持打印調用堆棧到文件，例如：
trace -t 5 -d -s  core$prn.doInvoke

   利用-s和-d命令會將詳細的調用信息輸出到臨時目錄，臨時目錄的路徑可以通過trace help命令查詢到，在我的機器上是/tmp/trace/<pid>@host目錄下。調用堆棧的輸出類似：
example$square.invoke(Long) call by thread [main]
    example$eval9.invoke(test.clj:11)
    clojure.lang.Compiler.eval(Compiler.java:6465)
    clojure.lang.Compiler.load(Compiler.java:6902)
    clojure.lang.Compiler.loadFile(Compiler.java:6863)
    clojure.main$load_script.invoke(main.clj:282)
    clojure.main$script_opt.invoke(main.clj:342)
    clojure.main$main.doInvoke(main.clj:426)
    clojure.lang.RestFn.invoke(RestFn.java:421)
    clojure.lang.Var.invoke(Var.java:405)
    clojure.lang.AFn.applyToHelper(AFn.java:163)
    clojure.lang.Var.applyTo(Var.java:518)
    clojure.main.main(main.java:37)

   上麵這個簡單的例子展示了使用housemd跟蹤診斷clojure進程的方法。

   自定義ns和函數的調試與此類似，假設我們有下麵的clojure代碼：
(ns example)
(defn square [x]
  (* x x))

(loop [x 1]
  (Thread/sleep 1000)
  (square x)
  (recur (inc x)))
 
   ns為example，自定義函數square並定期循環調用。使用housemd診斷這段代碼：
loaded -h example$square     #查詢square的加載情況
trace -t 10 -d -s example$square.invoke  #跟蹤10秒內square的調用情況

文章轉自莊周夢蝶  ，原文發布時間 2012-06-15

最後更新：2017-05-18 20:37:05

  上一篇：go  《軟件架構模式》-第一章分層架構（上）
  下一篇：go  分布式消息中間件Metaq發布1.4.3