t7205 t7205
2005-Dec-19 03:37 UTC
[dtrace-discuss] Dtrace indicates mutext is high than other function calls? in house application issues?
All, I am trying to learn this geat tool dtrace. While I played around with the in house app, I noticed the following: 1. top utility indicates the kernel vs user space use very close CPU utilization as shown below: last pid: 15154; load averages: 2.07, 1.82, 1.93 22:14:21 128 processes: 127 sleeping, 1 on cpu CPU states: 68.4% idle, 15.6% user, 16.0% kernel, 0.0% iowait, 0.0% swap Memory: 16G real, 9953M free, 1275M swap in use, 15G swap free the interesting part is that iowait and swap shows 0% idle. 2. then, I use dtrace (trying to learn) then I see the following: dtrace -s syscall.d -p 26442 dtrace: script ''syscall.d'' matched 227 probes ^C CPU ID FUNCTION:NAME 9 2 :END Ran for 16 seconds. lwp_mutex_wakeup 5 doorfs 108 lwp_cond_wait 615 lwp_cond_signal 880 lwp_sema_post 1299 lwp_sema_timedwait 1299 nanosleep 1543 yield 2491 ioctl 5414 sendto 5419 pollsys 5859 recvfrom 5900 gtime 30552 lwp_mutex_unlock 972407 lwp_mutex_timedlock 972408 It looks to me that for some reading we are fighting to the critial session with unlock, and timedlock but rest of the functions are within this process is low (comparing to the mutex). Any suggestion or URL that I can continue to read to understand this conditions? thanks a lot in advance. It''s a 8 CPU Sunfire 1280 box \t7205t at yahoo. com __________________________________________________ Do You Yahoo!? Tired of spam? Yahoo! Mail has the best spam protection around http://mail.yahoo.com -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20051218/632264e8/attachment.html>
Jarod Jenson
2005-Dec-19 04:22 UTC
[dtrace-discuss] Dtrace indicates mutext is high than other function calls? in house application issues?
t7205 t7205''s email at 12/18/2005 9:37 PM, said:> All, > I am trying to learn this geat tool dtrace. While I played around with the in house app, I noticed the following: > > 1. top utility indicates the kernel vs user space use very close CPU utilization as shown below: > last pid: 15154; load averages: 2.07, 1.82, 1.93 22:14:21 > 128 processes: 127 sleeping, 1 on cpu > CPU states: 68.4% idle, 15.6% user, 16.0% kernel, 0.0% iowait, 0.0% swap > Memory: 16G real, 9953M free, 1275M swap in use, 15G swap free > > the interesting part is that iowait and swap shows 0% idle. > > 2. then, I use dtrace (trying to learn) then I see the following: > > dtrace -s syscall.d -p 26442 > dtrace: script ''syscall.d'' matched 227 probes > ^C > CPU ID FUNCTION:NAME > 9 2 :END > Ran for 16 seconds. > > lwp_mutex_wakeup 5 > doorfs 108 > lwp_cond_wait 615 > lwp_cond_signal 880 > lwp_sema_post 1299 > lwp_sema_timedwait 1299 > nanosleep 1543 > yield 2491 > ioctl 5414 > sendto 5419 > pollsys 5859 > recvfrom 5900 > gtime 30552 > lwp_mutex_unlock 972407 > lwp_mutex_timedlock 972408 > > It looks to me that for some reading we are fighting to the critial session with unlock, and timedlock but rest of the functions are within this process is low (comparing to the mutex). Any suggestion or URL that I can continue to read to understand this conditions? thanks a lot in advance. > > It''s a 8 CPU Sunfire 1280 box > > \t7205t at yahoo. com >Okay, a little shake of the magic 8-ball and let''s see what we get... Looks to me like you have a Java app here - either 1.4.2 or, if we are lucky, a 1.5 JVM. I am going to guess that you have a very hot synchronized method that is routinely contended. If you are using a 1.5 VM, then grab a jstack() at lwp_mutex_timedlock to see what the method is (you can also use the DVM provider and try contended-monitor-* as hook points for the jstack(), but the former will work fine). Just for fun, I am placing my US$0.02 bet on a HashTable or a HashMap (with your own synchronization) with an implementation gone awry. An mpstat(1M) on this system will probably show a fairly high smtx rate as well. So, let me know if my 8-ball is still working or if I need to send it to the shop. Thanks, Jarod
Jim Mauro
2005-Dec-19 11:10 UTC
[dtrace-discuss] Dtrace indicates mutext is high than other function calls? in house application issues?
Please use prstat(1) instead of top. What was it that compelled you to look at PID 26442? Assuming there was a good reason to focus on this process, It would be interesting to see the microstates. Run ''prstat -Lmp <LCK>'' for a bit, and see where the process is spending time. If your speculation is correct, you''ll see a fair bit of "LCK" (user lock time). iowait is always zero in Solaris 10. It''s a meaningless metric for CPU utilization, because CPUs do not wait for IOs (threads wait for IOs). If there is significant "LCK" time, run plockstat(1) on the target process, so we can determine what the user lock situation is. /jim t7205 t7205 wrote:> All, > I am trying to learn this geat tool dtrace. While I played around > with the in house app, I noticed the following: > > 1. top utility indicates the kernel vs user space use very close CPU > utilization as shown below: > last pid: 15154; load averages: 2.07, 1.82, 1.93 > 22:14:21 > 128 processes: 127 sleeping, 1 on cpu > CPU states: 68.4% idle, *15.6% user, 16.0% kernel, 0.0% iowait, 0.0% > swap* > Memory: 16G real, 9953M free, 1275M swap in use, 15G swap free > the interesting part is that iowait and swap shows 0% idle. > > 2. then, I use dtrace (trying to learn) then I see the following: > > dtrace -s syscall.d -p 26442 > dtrace: script ''syscall.d'' match ed 227 probes > ^C > CPU ID FUNCTION:NAME > 9 2 :END > Ran for 16 seconds. > > lwp_mutex_wakeup 5 > doorfs 108 > lwp_cond_wait 615 > lwp_cond_signal & > nbsp; 880 > lwp_sema_post 1299 > lwp_sema_timedwait 1299 > nanosleep 1543 > yield 2491 > ioctl 5414 > sendto 5419 > pollsys 5859 > recvfrom 5900 > gtime 30552 > * lwp_mutex_unlock & nbsp; > 972407 > lwp_mutex_timedlock 972408 > * > It looks to me that for some reading we are fighting to the critial > session with unlock, and timedlock but rest of the functions are > within this process is low (comparing to the mutex). Any suggestion or > URL that I can continue to read to understand this conditions? thanks > a lot in advance. > > It''s a 8 CPU Sunfire 1280 box > > \t7205t at yahoo. com > > __________________________________________________ > Do You Yahoo!? > Tired of spam? Yahoo! Mail has the best spam protection around > http://mail.yahoo.com > >------------------------------------------------------------------------ > >_______________________________________________ >dtrace-discuss mailing list >dtrace-discuss at opensolaris.org > >