Tagged: 자바 쓰레드 덤프

jstack 과 thread Id, CPU, Mem 사용량 체크.

jstack 은 자바 애플리케이션의 쓰레드(Thread) 덤프를 뜰 수 있도록 도와주는 도구 입니다. 자바 애플리케이션의 쓰레드의 상태를 상세히 알 수 있어서 자바 애플리케이션의 프로파일링을 할 수 있고 이를 통해서 성능을 개선할 수 있습니다.

예를들면 다음과 같습니다.

jstack 결과물.
Java
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
2015-01-21 21:11:12
Full thread dump OpenJDK 64-Bit Server VM (23.25-b01 mixed mode):
 
"Attach Listener" daemon prio=10 tid=0x00007fa830001000 nid=0x3c5a waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
 
   Locked ownable synchronizers:
- None
 
"ajp-bio-8309-AsyncTimeout" daemon prio=10 tid=0x00007fa85ca18000 nid=0x2e47 waiting on condition [0x00007fa8508f4000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.tomcat.util.net.JIoEndpoint$AsyncTimeout.run(JIoEndpoint.java:152)
at java.lang.Thread.run(Thread.java:701)
 
   Locked ownable synchronizers:
- None
 
"ajp-bio-8309-Acceptor-0" daemon prio=10 tid=0x00007fa85ca16000 nid=0x2e46 runnable [0x00007fa8509f5000]
   java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:375)
at java.net.ServerSocket.implAccept(ServerSocket.java:478)
at java.net.ServerSocket.accept(ServerSocket.java:446)
at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:60)
at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:220)
at java.lang.Thread.run(Thread.java:701)
 
   Locked ownable synchronizers:
- None
 
"http-bio-8380-AsyncTimeout" daemon prio=10 tid=0x00007fa85ca13800 nid=0x2e45 waiting on condition [0x00007fa850af6000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.tomcat.util.net.JIoEndpoint$AsyncTimeout.run(JIoEndpoint.java:152)
at java.lang.Thread.run(Thread.java:701)
 
   Locked ownable synchronizers:
- None
 
"http-bio-8380-Acceptor-0" daemon prio=10 tid=0x00007fa85ca12000 nid=0x2e44 runnable [0x00007fa850bf7000]
   java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:375)
at java.net.ServerSocket.implAccept(ServerSocket.java:478)
at java.net.ServerSocket.accept(ServerSocket.java:446)
at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:60)
at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:220)
at java.lang.Thread.run(Thread.java:701)
 
   Locked ownable synchronizers:
- None
 
"ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=10 tid=0x00007fa85ca0f800 nid=0x2e43 waiting on condition [0x00007fa850cf8000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.catalina.core.ContainerBase$ContainerBackgroundProcessor.run(ContainerBase.java:1513)
at java.lang.Thread.run(Thread.java:701)
 
   Locked ownable synchronizers:
- None
 
"GroupChannel-Heartbeat-1" daemon prio=10 tid=0x00007fa85ca0b800 nid=0x2e40 waiting on condition [0x00007fa85100d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.catalina.tribes.group.GroupChannel$HeartbeatThread.run(GroupChannel.java:689)
 
   Locked ownable synchronizers:
- None
 
"Tribes-MembershipSender" daemon prio=10 tid=0x00007fa85ca0a000 nid=0x2e3e waiting on condition [0x00007fa85110e000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at org.apache.catalina.tribes.membership.McastServiceImpl$SenderThread.run(McastServiceImpl.java:580)
 
   Locked ownable synchronizers:
- None
 
"Tribes-MembershipReceiver" daemon prio=10 tid=0x00007fa85ca08800 nid=0x2e3d runnable [0x00007fa85120f000]
   java.lang.Thread.State: RUNNABLE
at java.net.PlainDatagramSocketImpl.receive0(Native Method)
- locked <0x00000000a5730da0> (a java.net.PlainDatagramSocketImpl)
at java.net.AbstractPlainDatagramSocketImpl.receive(AbstractPlainDatagramSocketImpl.java:136)
- locked <0x00000000a5730da0> (a java.net.PlainDatagramSocketImpl)
at java.net.DatagramSocket.receive(DatagramSocket.java:759)
- locked <0x00000000a5803e80> (a java.net.DatagramPacket)
- locked <0x00000000a5803e48> (a java.net.MulticastSocket)
at org.apache.catalina.tribes.membership.McastServiceImpl.receive(McastServiceImpl.java:339)
at org.apache.catalina.tribes.membership.McastServiceImpl$ReceiverThread.run(McastServiceImpl.java:533)
 
   Locked ownable synchronizers:
- None
 
"NioReceiver" daemon prio=10 tid=0x00007fa85c9da800 nid=0x2e3c runnable [0x00007fa851310000]
   java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:228)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:83)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
- locked <0x00000000a57ca768> (a sun.nio.ch.Util$1)
- locked <0x00000000a57ca758> (a java.util.Collections$UnmodifiableSet)
- locked <0x00000000a57ca710> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)
at org.apache.catalina.tribes.transport.nio.NioReceiver.listen(NioReceiver.java:283)
at org.apache.catalina.tribes.transport.nio.NioReceiver.run(NioReceiver.java:433)
at java.lang.Thread.run(Thread.java:701)
 
   Locked ownable synchronizers:
- None
 
"GC Daemon" daemon prio=10 tid=0x00007fa85c934000 nid=0x2e38 in Object.wait() [0x00007fa85183a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000a55cc360> (a sun.misc.GC$LatencyLock)
at sun.misc.GC$Daemon.run(GC.java:117)
- locked <0x00000000a55cc360> (a sun.misc.GC$LatencyLock)
 
   Locked ownable synchronizers:
- None
 
"Low Memory Detector" daemon prio=10 tid=0x00007fa85c0fa000 nid=0x2e36 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
 
   Locked ownable synchronizers:
- None
 
"C2 CompilerThread1" daemon prio=10 tid=0x00007fa85c0f8000 nid=0x2e35 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
 
   Locked ownable synchronizers:
- None
 
"C2 CompilerThread0" daemon prio=10 tid=0x00007fa85c0f5000 nid=0x2e34 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
 
   Locked ownable synchronizers:
- None
 
"Signal Dispatcher" daemon prio=10 tid=0x00007fa85c0f2800 nid=0x2e33 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
 
   Locked ownable synchronizers:
- None
 
"Finalizer" daemon prio=10 tid=0x00007fa85c0a4000 nid=0x2e32 in Object.wait() [0x00007fa85254c000]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000a57188a8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133)
- locked <0x00000000a57188a8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:189)
 
   Locked ownable synchronizers:
- None
 
"Reference Handler" daemon prio=10 tid=0x00007fa85c0a2000 nid=0x2e31 in Object.wait() [0x00007fa85264d000]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000a57ff5a0> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
- locked <0x00000000a57ff5a0> (a java.lang.ref.Reference$Lock)
 
   Locked ownable synchronizers:
- None
 
"main" prio=10 tid=0x00007fa85c009000 nid=0x2e2b runnable [0x00007fa86611b000]
   java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:375)
at java.net.ServerSocket.implAccept(ServerSocket.java:478)
at java.net.ServerSocket.accept(ServerSocket.java:446)
at org.apache.catalina.core.StandardServer.await(StandardServer.java:453)
at org.apache.catalina.startup.Catalina.await(Catalina.java:777)
at org.apache.catalina.startup.Catalina.start(Catalina.java:723)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:622)
at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:321)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:455)
 
   Locked ownable synchronizers:
- None
 
"VM Thread" prio=10 tid=0x00007fa85c093000 nid=0x2e30 runnable
 
"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007fa85c016800 nid=0x2e2c runnable
 
"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007fa85c018800 nid=0x2e2d runnable
 
"GC task thread#2 (ParallelGC)" prio=10 tid=0x00007fa85c01a000 nid=0x2e2e runnable
 
"GC task thread#3 (ParallelGC)" prio=10 tid=0x00007fa85c01c000 nid=0x2e2f runnable
 
"VM Periodic Task Thread" prio=10 tid=0x00007fa85c105000 nid=0x2e37 waiting on condition
 
JNI global references: 127

문제는 이렇게 jstack 의 결과을 보면 당시 쓰레드에 OS 의 자원사용량을 알 방법이 없습니다. OS의 자원이라고 하면 CPU, MEM 등과 같은 것입니다.

jstack  의 결과에는 tid 라고 해서 Thread ID 가 헥사(16 진수)로 표시됩니다. 이는 OS상에서 자바 애플리케이션의 쓰레드의 PID 를 가리킵니다.

그래서 jstack 을 이용할때에 top 명령어를 이용해서 로그를 나기고 이둘을 스크립트를 이용해서 조합해서 가지고 올 수 있도록 누군가 만들었더군요.

stack overflow: Inspecting Java threads in Linux using top

답변을 다신분의 스크립트는 다음과 같습니다.

cpu-java.sh
Shell
1
2
3
#!/bin/sh
top -H -b -n 1 | grep java > /tmp/top.log
jstack -l `ps fax | grep java | grep tomcat | sed "s/ *\([0-9]*\) .*/\1/g"` > /tmp/jstack.log

jstack_pid.pl
Perl
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
#!/usr/bin/perl
 
my ($sec, $min, $hour, $mday, $mon, $year, $wday, $yday, $isdst) = localtime;
 
my $now = sprintf("%04d-%02d-%02d_%02d:%02d:%02d", $year + 1900, $mon + 1, $mday, $hour, $min, $sec);
 
system("sh cpu-java.sh $now");
open LOG, "/tmp/top.log" or die $!;
print "PID\tCPU\tMem\tJStack Info\n";
while ($l = <LOG>) {
    $pid = $l;
    $pid =~ s/root.*//g;
    $pid =~ s/ *//g;
    $hex_pid = sprintf("%#x", $pid);
    @values = split(/\s{2,}/, $l);
    $pct = $values[4];
    $mem = $values[5];
    open JSTACK, "/tmp/jstack.log" or die $!;  
    while ($j = <JSTACK>){
        if ($j =~ /.*nid=.*/){
            if ($j =~ /.*$hex_pid.*/){
                $j =~ s/\n//;
                $pid =~ s/\n//;
                print $pid . "\t" . $pct . "\t" . $mem . "\t" .  $j . "\n";
            }
        }
    }  
    close JSTACK;
}
close LOG;

결과는 다음과 같이 나옵니다.

jstack_pid.pl 결과
Shell
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
[instance3@localhost ~]$ ./jstsck_pid.pl
PID CPU Mem JStack Info
11819instanc+200362155611765210972S0.02.00:01.36java 0.0 2.0 "main" prio=10 tid=0x00007fa85c009000 nid=0x2e2b runnable [0x00007fa86611b000]
11820instanc+200362155611765210972S0.02.00:00.03java 0.0 2.0 "GC task thread#0 (ParallelGC)" prio=10 tid=0x00007fa85c016800 nid=0x2e2c runnable
11821instanc+200362155611765210972S0.02.00:00.04java 0.0 2.0 "GC task thread#1 (ParallelGC)" prio=10 tid=0x00007fa85c018800 nid=0x2e2d runnable
11822instanc+200362155611765210972S0.02.00:00.04java 0.0 2.0 "GC task thread#2 (ParallelGC)" prio=10 tid=0x00007fa85c01a000 nid=0x2e2e runnable
11823instanc+200362155611765210972S0.02.00:00.04java 0.0 2.0 "GC task thread#3 (ParallelGC)" prio=10 tid=0x00007fa85c01c000 nid=0x2e2f runnable
11824instanc+200362155611765210972S0.02.00:00.18java 0.0 2.0 "VM Thread" prio=10 tid=0x00007fa85c093000 nid=0x2e30 runnable
11825instanc+200362155611765210972S0.02.00:00.00java 0.0 2.0 "Reference Handler" daemon prio=10 tid=0x00007fa85c0a2000 nid=0x2e31 in Object.wait() [0x00007fa85264d000]
11826instanc+200362155611765210972S0.02.00:00.00java 0.0 2.0 "Finalizer" daemon prio=10 tid=0x00007fa85c0a4000 nid=0x2e32 in Object.wait() [0x00007fa85254c000]
11827instanc+200362155611765210972S0.02.00:00.00java 0.0 2.0 "Signal Dispatcher" daemon prio=10 tid=0x00007fa85c0f2800 nid=0x2e33 runnable [0x0000000000000000]
11828instanc+200362155611765210972S0.02.00:01.97java 0.0 2.0 "C2 CompilerThread0" daemon prio=10 tid=0x00007fa85c0f5000 nid=0x2e34 waiting on condition [0x0000000000000000]
11829instanc+200362155611765210972S0.02.00:01.52java 0.0 2.0 "C2 CompilerThread1" daemon prio=10 tid=0x00007fa85c0f8000 nid=0x2e35 waiting on condition [0x0000000000000000]
11830instanc+200362155611765210972S0.02.00:00.00java 0.0 2.0 "Low Memory Detector" daemon prio=10 tid=0x00007fa85c0fa000 nid=0x2e36 runnable [0x0000000000000000]
11831instanc+200362155611765210972S0.02.00:00.82java 0.0 2.0 "VM Periodic Task Thread" prio=10 tid=0x00007fa85c105000 nid=0x2e37 waiting on condition
11832instanc+200362155611765210972S0.02.00:00.00java 0.0 2.0 "GC Daemon" daemon prio=10 tid=0x00007fa85c934000 nid=0x2e38 in Object.wait() [0x00007fa85183a000]
11836instanc+200362155611765210972S0.02.00:00.06java 0.0 2.0 "NioReceiver" daemon prio=10 tid=0x00007fa85c9da800 nid=0x2e3c runnable [0x00007fa851310000]
11837instanc+200362155611765210972S0.02.00:00.59java 0.0 2.0 "Tribes-MembershipReceiver" daemon prio=10 tid=0x00007fa85ca08800 nid=0x2e3d runnable [0x00007fa85120f000]
11838instanc+200362155611765210972S0.02.00:00.71java 0.0 2.0 "Tribes-MembershipSender" daemon prio=10 tid=0x00007fa85ca0a000 nid=0x2e3e sleeping[0x00007fa85110e000]
11840instanc+200362155611765210972S0.02.00:00.06java 0.0 2.0 "GroupChannel-Heartbeat-1" daemon prio=10 tid=0x00007fa85ca0b800 nid=0x2e40 waiting on condition [0x00007fa85100d000]
11843instanc+200362155611765210972S0.02.00:00.98java 0.0 2.0 "ContainerBackgroundProcessor[StandardEngine[Catalina]]" daemon prio=10 tid=0x00007fa85ca0f800 nid=0x2e43 waiting on condition [0x00007fa850cf8000]
11844instanc+200362155611765210972S0.02.00:00.00java 0.0 2.0 "http-bio-8380-Acceptor-0" daemon prio=10 tid=0x00007fa85ca12000 nid=0x2e44 runnable [0x00007fa850bf7000]
11845instanc+200362155611765210972S0.02.00:00.10java 0.0 2.0 "http-bio-8380-AsyncTimeout" daemon prio=10 tid=0x00007fa85ca13800 nid=0x2e45 waiting on condition [0x00007fa850af6000]
11846instanc+200362155611765210972S0.02.00:00.00java 0.0 2.0 "ajp-bio-8309-Acceptor-0" daemon prio=10 tid=0x00007fa85ca16000 nid=0x2e46 runnable [0x00007fa8509f5000]
11847instanc+200362155611765210972S0.02.00:00.10java 0.0 2.0 "ajp-bio-8309-AsyncTimeout" daemon prio=10 tid=0x00007fa85ca18000 nid=0x2e47 waiting on condition [0x00007fa8508f4000]
15450instanc+200362155611765210972S0.02.00:00.00java 0.0 2.0 "Attach Listener" daemon prio=10 tid=0x00007fa830001000 nid=0x3c5a waiting on condition [0x0000000000000000]