2007-05-21

dtrace & java: part 3

My last struggles with application in java led me to the following observations (again from the very begin):

PID USERNAME SIZE RSS STATE PRI NICE TIME CPU PROCESS/NLWP
27607 inkaso 502M 436M sleep 59 0 10:59:30 5.4% java/91
517 root 3916K 3080K sleep 59 0 0:02:09 0.1% nscd/26
18198 root 2848K 2732K cpu1 59 0 0:00:00 0.0% prstat/1
18202 root 964K 676K sleep 59 0 0:00:00 0.0% sleep/1
[...]

prstat -mL -p 27607

PID USERNAME USR SYS TRP TFL DFL LCK SLP LAT VCX ICX SCL SIG PROCESS/LWPID
27607 inkaso 3.7 0.0 0.0 0.0 0.0 4.4 92 0.1 163 4 101 2 java/5142
27607 inkaso 0.8 0.0 0.0 0.0 0.0 99 0.0 0.0 7 2 15 0 java/4
27607 inkaso 0.1 0.0 0.0 0.0 0.0 0.2 100 0.0 6 0 127 0 java/5676
27607 inkaso 0.1 0.0 0.0 0.0 0.0 0.0 100 0.0 8 1 72 0 java/5679
27607 inkaso 0.1 0.0 0.0 0.0 0.0 0.0 100 0.0 4 0 52 0 java/5662
[...]

Thread id = 5142 is:

bash-3.00# grep 5142 nohup.out
S, 5142, 192.168.210.13-Connection-5122, 2007-05-21--07:24:16
S, 5162, 192.168.209.216-Connection-5142, 2007-05-21--07:33:21

bash-3.00# netstat -a|grep 192.168.210.13
inkaso220.6400 192.168.210.135.50835 5840 0 49640 0 ESTABLISHED
inkaso220.6400 192.168.210.13.51108 2144 0 49312 0 CLOSE_WAIT

It means, again, that some thread (here 5142) is doing some work instead of being already dead. The state of network connection is CLOSE_WAIT and according to: sunsolve document "indefinite CLOSE_WAIT state normally indicates some application level bug.".
And more:

bash-3.00# while true
> do
> date
> netstat -a|grep 192.168.210.13
> sleep 30
> done
Mon May 21 09:12:18 CEST 2007
inkaso220.6400 192.168.210.139.50235 5840 0 49640 0 ESTABLISHED
inkaso220.6400 192.168.210.135.50835 5840 0 49640 0 ESTABLISHED
inkaso220.6400 192.168.210.13.51108 2144 0 49312 0 CLOSE_WAIT
inkaso220.6400 192.168.210.131.59018 5840 0 49640 0 ESTABLISHED
Mon May 21 09:12:49 CEST 2007
inkaso220.6400 192.168.210.139.50235 5840 0 49640 0 ESTABLISHED
inkaso220.6400 192.168.210.135.50835 5840 0 49640 0 ESTABLISHED
inkaso220.6400 192.168.210.13.51108 2144 0 49312 0 CLOSE_WAIT
inkaso220.6400 192.168.210.131.59018 5840 0 49640 0 ESTABLISHED
Mon May 21 09:13:19 CEST 2007
inkaso220.6400 192.168.210.139.50235 5840 0 49640 0 ESTABLISHED
inkaso220.6400 192.168.210.135.50835 5840 0 49640 0 ESTABLISHED
inkaso220.6400 192.168.210.13.51108 2144 0 49312 0 CLOSE_WAIT
inkaso220.6400 192.168.210.131.59018 5840 0 49640 0 ESTABLISHED
...
Mon May 21 10:21:07 CEST 2007
inkaso220.6400 192.168.210.135.50835 5840 0 49640 0 ESTABLISHED
inkaso220.6400 192.168.210.13.51108 2144 0 49312 0 CLOSE_WAIT
Mon May 21 10:21:37 CEST 2007
inkaso220.6400 192.168.210.135.50835 5840 0 49640 0 ESTABLISHED
inkaso220.6400 192.168.210.13.51108 2144 0 49312 0 CLOSE_WAIT
...

The changes which our java programmer did last time has not helped anything. Meanwhile a new software developer took over the software (the previous one is tasked with another one) and now I am going to pass all my observations to him.

No comments: