On Fri, Jul 6, 2012 at 3:22 PM, <przemol...@poczta.fm> wrote: > Hello, > > we have been observing some high syscalls (much higher then usually) during > fixed part of week. > DTrace shows that they mostly comes from Oracle: > ... > uname exece > 6788165162 > oracle close > 6904279356 > dtrace ioctl > 7987232206 > oracle munmap > 13857698724 > emagent fork1 > 14217339236 > oracle resolvepath > 14438549232 > oracle semsys > 16447265715 > tnslsnr fork1 > 18617374490 > oracle stat > 23129632013 > oracle exece > 23859088254 > oracle pollsys > 28102955920 > oracle pread > 32159134471 > oracle mmap > 35380305339 > oracle times > 35475706300 > oracle open > 42314061704 > oracle memcntl > 45026502910 > oracle pwrite > 51648592719 > oracle read > 72939284043 > oracle write > 95484269587 > oracle ioctl > 306634639800 > > TOTAL: > 1060934672587
What was the dtrace script you used and over what period? How many cpus in the system (according to psrinfo | wc -l)? Those numbers look suspiciously high and make me think something is wrong with the dtrace script. > > Using sar we can observe that system spends much more time in syscalls > (column 'sys') but number of syscalls is not higher then usually (column > 'scall/s'): > > server:/export/home/przemol>sar -f /var/adm/sa/sa04 -s 12:00 -e 15:30 > > SunOS server 5.10 Generic_147440-19 sun4v 07/04/2012 > > 12:00:03 %usr %sys %wio %idle > 12:10:03 42 8 0 50 > 12:20:03 37 7 0 56 > 12:30:03 37 8 0 55 > 12:40:03 37 10 0 53 > 12:50:04 40 15 0 45 > 13:00:03 37 10 0 52 > 13:10:04 35 10 0 55 > 13:20:04 38 8 0 55 > 13:30:04 35 7 0 58 > 13:40:04 38 9 0 53 > 13:50:03 37 21 0 42 > 14:00:03 36 14 0 50 > 14:10:04 33 10 0 57 > 14:20:04 36 21 0 42 > 14:30:04 36 32 0 32 > 14:40:04 28 15 0 57 > 14:50:03 32 12 0 57 > 15:00:03 30 12 0 57 > 15:10:03 32 8 0 60 > 15:20:03 31 6 0 64 > > Average 35 12 0 52 > > server:/export/home/przemol>sar -c -f /var/adm/sa/sa04 -s 12:00 -e 15:30 > > SunOS server 5.10 Generic_147440-19 sun4v 07/04/2012 > > 12:00:03 scall/s sread/s swrit/s fork/s exec/s rchar/s wchar/s > 12:10:03 107602 6567 4948 27.82 18.74 478579 4290812 > 12:20:03 96872 6411 4549 25.64 17.55 6949437 4295743 > 12:30:03 99273 6139 4792 25.69 17.76 723126 895552 > 12:40:03 95908 5950 4129 25.47 17.61 4020240 3585954 > 12:50:04 99792 5685 5319 24.52 16.69 4579288 4915466 > 13:00:03 90723 4927 3553 24.85 17.34 4490451 3330185 > 13:10:04 94744 6207 3688 25.22 17.40 6691959 3530345 > 13:20:04 93971 6105 4111 24.88 17.05 1220270 4051683 > 13:30:04 87887 6189 4418 24.45 17.15 3026237 4946326 > 13:40:04 92151 6032 4269 24.58 17.12 4982878 3595013 > 13:50:03 80146 5360 4101 23.22 16.10 448459 4052298 > 14:00:03 72998 4488 2142 23.69 16.69 4678268 3586545 > 14:10:04 76433 4031 2385 24.82 17.31 6913550 6157899 > 14:20:04 72935 4462 1994 23.49 16.25 3090017 5321098 > 14:30:04 72516 4124 1993 23.46 16.37 2942463 6993712 > 14:40:04 72057 3048 2344 23.95 16.77 3042674 2668180 > 14:50:03 73552 3370 2506 24.93 17.13 6398090 2906262 > 15:00:03 70869 3111 2049 25.39 17.55 5858628 3745978 > 15:10:03 80258 3643 2467 47.57 28.89 7126361 3621600 > 15:20:03 73211 3519 2693 24.66 16.99 4550096 2973429 > > Average 85197 4969 3423 25.91 17.72 4110499 3973336 It's averaging 85197 system calls per second. At that rate, 1 trillion system calls (1,060,934,672,587) would take around 144 CPU days of system time. Seems kinda unlikely. Perhaps the 1 trillion number is nanoseconds spent in the system calls. That would turn into about 29 minutes of system time. That could be, but whether it is bad depends a lot on the system and the duration. > > Can I conclude that system spends much more time processing more or less the > same number > of syscalls and time spent on one (statistically) syscall takes longer time ? > What is your opinion ? > > Regards > Przemek > _______________________________________________ > perf-discuss mailing list > perf-discuss@opensolaris.org -- Mike Gerdts http://mgerdts.blogspot.com/ _______________________________________________ perf-discuss mailing list perf-discuss@opensolaris.org
