【Tomcat】Tomcat ログあれこれ

Tomcatログについて

`#`ログファイル`説明`設定箇所
1catalina.out標準出力・標準エラー出力catalina.sh
2catalina.YYYY-MM-DD.logTomcat自体のログlogging.properties
3localhost.YYYY-MM-DD.loghost(VirtualHost)のログlogging.properties
4manager.YYYY-MM-DD.logmanager webapp ののログlogging.properties
5host-manager.YYYY-MM-DD.loghost-manager webapp ののログlogging.properties
6localhost_access_log.YYYY-MM-DD.txtアクセスログserver.xml

参考文献

https://qiita.com/hidekatsu-izuno/items/ab604b6c764b5b5a86ed
http://johonet.ddo.jp/b/?p=536

Tomcatアクセスログのファイル名を変更する

修正例

修正前
<!-- Access log processes all example.
     Documentation at: /docs/config/valve.html
     Note: The pattern used is equivalent to using pattern="common" -->
<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
       prefix="localhost_access_log" suffix=".txt"
       pattern="%h %l %u %t "%r" %s %b" />
修正後
<!-- Access log processes all example.
     Documentation at: /docs/config/valve.html
     Note: The pattern used is equivalent to using pattern="common" -->
<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
       prefix="localhost_access_log" suffix=".log"
       rotatable="false" fileDateFormat=""
       pattern="%h %l %u %t "%r" %s %b" />

参考文献

http://www.siva-jp.com/2012/01/22/tomcat_log/
http://www.m-bsys.com/code/tomcat-accesslog

Tomcatアクセスログの処理時間を出力するには

 * server.xmlのAccessLogValveの部分のpatternに、処理時間%D(マイクロ秒)または処理時間%T(秒)を追加

修正例

修正前
<!-- Access log processes all example.
     Documentation at: /docs/config/valve.html
     Note: The pattern used is equivalent to using pattern="common" -->
<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
       prefix="localhost_access_log" suffix=".txt"
       pattern="%h %l %u %t "%r" %s %b" />
修正後
<!-- Access log processes all example.
     Documentation at: /docs/config/valve.html
     Note: The pattern used is equivalent to using pattern="common" -->
<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
       prefix="localhost_access_log" suffix=".txt"
       pattern="%h %l %u %t "%r" %s %b (%T)" />

出力結果例

「(1.162)」が処理時間
127.0.0.1 - - [11/Jan/2018:21:29:40 +0900] "GET / HTTP/1.1" 200 11458 (1.162)

参考文献

http://server-helper.doorblog.jp/archives/3234773.html
「処理時間」について詳細に言及
http://dev.ariel-networks.com/Members/inoue/response-time/

TomcatGCログを出力する

 * CATALINA_OPTS に指定する
  => 具体的には、$CATALINA_HOME/bin/setenv.bat (Windows)、setenv.sh (Linux) に指定
 * Linux の場合、「sudo chmod 750 setenv.sh」
 * GCログ出力については、以下の関連記事を参照のこと。
https://blogs.yahoo.co.jp/dk521123/37328410.html

設定例

$CATALINA_HOME/bin/setenv.bat (Windows)
set CATALINA_OPTS=-verbose:gc -Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:GCLogFileSize=100M -XX:NumberOfGCLogFiles=5
$CATALINA_HOME/bin/setenv.sh (Linux)
#!/bin/sh

CATALINA_OPTS="-verbose:gc -Xloggc:${CATALINA_BASE}/logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseGCLogFileRotation -XX:GCLogFileSize=100M -XX:NumberOfGCLogFiles=5"

GCログを参照:GCViewer

設定
[1] 以下のサイトから、GCViewer をダウンロードする(今回は「gcviewer-1.36-SNAPSHOT.jar」)
https://github.com/chewiebug/GCViewer/wiki/Changelog
[2] ダウンロードしたJARファイルをダブルクリックする
使い方
 * GCのログファイルをドラッグ&ドロップする
見方
 * 赤:最大のヒープサイズ
 * 青:使用中のヒープサイズ
参考文献
https://qiita.com/watanata/items/6d74823832882685d7bc
http://www.atmarkit.co.jp/ait/articles/0703/22/news138_2.html
http://www.atmarkit.co.jp/ait/articles/0711/27/news122.html

Tomcatでヒープ統計情報を出力する

 * 「TomcatGCログを出力する」と同様
 * PrintClassHistogramオプションを使う

ヒープ統計情報

 * 以下を出力される
  + ヒープ中のオブジェクトのインスタンス数
  + サイズ一覧

設定例

$CATALINA_HOME/bin/setenv.sh (Linux)
#!/bin/sh

CATALINA_OPTS="-verbose:gc -XX:+PrintClassHistogram"

出力方法

[1] jpsコマンドで「Bootstrap(Tomcat)」のJavaプロセスのIDを特定
jps

36631 Jps
34175 Bootstrap
[2] SIGQUITシグナルを送信するために「kill -3 <Java PID>」を実行する
jps -3 34175

# 「jps | grep -v Jps | awk '{print $1}' | xargs kill -3」で実行する
[3] 「catalina.out」を確認すると、各クラスのインスタンスの個数および全インスタンスの合計サイズを、GCログとともに出力する
18-Jan-2018 22:10:11.015 情報 [main] org.apache.catalina.startup.Catalina.start Server startup in 11135 ms
2018-01-18 22:11:08
Full thread dump OpenJDK 64-Bit Server VM (25.151-b12 mixed mode):

"http-nio-8080-exec-1" #19 daemon prio=5 os_prio=0 tid=0x00007ff5e46418a0 nid=0x9435 waiting on condition [0x00007ff5c0bea000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000e4025178> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:103)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:31)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)

"VM Thread" os_prio=0 tid=0x00007ff5e407b030 nid=0x93f9 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007ff5e401b500 nid=0x9401 waiting on condition 

JNI global references: 319

Heap
 def new generation   total 49152K, used 11547K [0x00000000e3800000, 0x00000000e6d50000, 0x00000000ed000000)
  eden space 43712K,  26% used [0x00000000e3800000, 0x00000000e4346c18, 0x00000000e62b0000)
  from space 5440K,   0% used [0x00000000e62b0000, 0x00000000e62b0000, 0x00000000e6800000)
  to   space 5440K,   0% used [0x00000000e6800000, 0x00000000e6800000, 0x00000000e6d50000)
 tenured generation   total 109076K, used 65443K [0x00000000ed000000, 0x00000000f3a85000, 0x0000000100000000)
   the space 109076K,  59% used [0x00000000ed000000, 0x00000000f0fe8ff8, 0x00000000f0fe9000, 0x00000000f3a85000)
 Metaspace       used 27722K, capacity 28250K, committed 28544K, reserved 1075200K
  class space    used 3239K, capacity 3402K, committed 3456K, reserved 1048576K
【補足】cronを使って定期的に出力する
https://blogs.yahoo.co.jp/dk521123/36463384.html
で記載しているcronで以下のシェルを実行
~~~~~
#!/bin/sh

jps | grep -v Jps | awk '{print $1}' | xargs kill -3
~~~~~

参考文献

http://www.atmarkit.co.jp/ait/articles/0711/27/news122_2.html
https://qiita.com/setoazusa/items/ee0a7d795c2687b80817

Tomcatのログをローテーションさせる

 * 以下の関連記事を参照のこと。
https://blogs.yahoo.co.jp/dk521123/37407399.html

関連記事

Tomcat】設定ファイル server.xml ~ Valve 編~

https://blogs.yahoo.co.jp/dk521123/37348697.html

Javaガベージコレクション ( Barbage Collection; GC )

https://blogs.yahoo.co.jp/dk521123/37328410.html

Linux】 cronデーモン / crontabコマンド

https://blogs.yahoo.co.jp/dk521123/36463384.html

Linux】ログ世代管理 ~ logrotate ~

https://blogs.yahoo.co.jp/dk521123/37407399.html