Hello,
I am trying to investigate some "performance issues" on one of our
sparc server. I used term "performance issues" because it is not
a typical load but anyway I would like to know what is going on ?
Please look below:
[ output of sar ]
...
08:00:00 71 22 0 6
08:10:01 71 23 0 6
08:20:00 71 23 0 6
08:30:00 70 21 0 9
08:40:00 61 20 0 19
08:50:01 64 20 0 16
09:00:00 56 22 0 23
09:10:00 50 25 0 25
09:20:00 57 23 0 20
09:30:00 57 23 0 20
Average 67 22 0 11
What is using so much syscalls ?
bash-3.00# dtrace -n ''syscall::: { @[execname] = count (); }''
dtrace: description ''syscall::: '' matched 460 probes
^C
sshd 36
...
nscd 8608
tnslsnr 9085
sendmail 10584
xntpd 12272
sadc 17968
vxsvc 31096
dtrace 1354522
oracle 147541421
What syscalls is doing oracle ?
bash-3.00# dtrace -n ''syscall::: /execname == "oracle"/ {
@[probefunc] = count (); }''
dtrace: description ''syscall::: '' matched 460 probes
^C
connect 4
so_socket 4
pipe 6
waitsys 6
....
stat 1578
mmap 1926
open 2144
close 2692
write 18966
read 21104
semsys 37571
pread 44805
pwrite 118022
lwp_park 169225
kaio 268228
times 9870413
>From the manual:
NAME
times - get process and child process times
SYNOPSIS
#include <sys/times.h>
#include <limits.h>
clock_t times(struct tms *buffer);
DESCRIPTION
The times() function fills the tms structure pointed to by
buffer with time-accounting information. The tms structure,
defined in <sys/times.h>, contains the following members:
....
I am stuck here. :-(
Can anybody help and show me where should I dig now ? How can I check
what is causing ''times'' syscall and why ?
Regards
przemol
Roch Bourbonnais - Performance Engineering
2006-May-12 08:55 UTC
[dtrace-discuss] ''times'' syscall
So Oracle is calling times; Probably no worries there.
You could track this down further with
dtrace -n ''syscall::times:entry /execname == "oracle"/ {
@[ustack(100)] = count ();}''
-r
przemolicc at poczta.fm writes:
> Hello,
>
> I am trying to investigate some "performance issues" on one of
our
> sparc server. I used term "performance issues" because it is
not
> a typical load but anyway I would like to know what is going on ?
> Please look below:
>
> [ output of sar ]
> ...
> 08:00:00 71 22 0 6
> 08:10:01 71 23 0 6
> 08:20:00 71 23 0 6
> 08:30:00 70 21 0 9
> 08:40:00 61 20 0 19
> 08:50:01 64 20 0 16
> 09:00:00 56 22 0 23
> 09:10:00 50 25 0 25
> 09:20:00 57 23 0 20
> 09:30:00 57 23 0 20
>
> Average 67 22 0 11
>
> What is using so much syscalls ?
>
> bash-3.00# dtrace -n ''syscall::: { @[execname] = count ();
}''
> dtrace: description ''syscall::: '' matched 460 probes
> ^C
>
> sshd 36
> ...
> nscd 8608
> tnslsnr 9085
> sendmail 10584
> xntpd 12272
> sadc 17968
> vxsvc 31096
> dtrace 1354522
> oracle 147541421
>
> What syscalls is doing oracle ?
>
> bash-3.00# dtrace -n ''syscall::: /execname == "oracle"/
{ @[probefunc] = count (); }''
> dtrace: description ''syscall::: '' matched 460 probes
> ^C
>
> connect 4
> so_socket 4
> pipe 6
> waitsys 6
> ....
> stat 1578
> mmap 1926
> open 2144
> close 2692
> write 18966
> read 21104
> semsys 37571
> pread 44805
> pwrite 118022
> lwp_park 169225
> kaio 268228
> times 9870413
>
> >From the manual:
>
> NAME
> times - get process and child process times
>
> SYNOPSIS
> #include <sys/times.h>
> #include <limits.h>
>
> clock_t times(struct tms *buffer);
>
> DESCRIPTION
> The times() function fills the tms structure pointed to by
> buffer with time-accounting information. The tms structure,
> defined in <sys/times.h>, contains the following members:
> ....
>
> I am stuck here. :-(
> Can anybody help and show me where should I dig now ? How can I check
> what is causing ''times'' syscall and why ?
>
> Regards
> przemol
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
On Fri, May 12, 2006 at 10:55:43AM +0200, Roch Bourbonnais - Performance Engineering wrote:> > So Oracle is calling times; Probably no worries there. > > You could track this down further with > > dtrace -n ''syscall::times:entry /execname == "oracle"/ { @[ustack(100)] = count ();}''dtrace -n ''syscall::times:entry /execname == "oracle"/ { @st[ustack()] = count (); } END {trunc(@st,10);}'' libc.so.1`times+0x4 oracle`ksuprc+0x3fc oracle`opiodr+0x44c oracle`rpidrus+0x90 oracle`skgmstack+0x9c oracle`rpidru+0xa0 oracle`rpiswu2+0x180 oracle`rpidrv+0x5b8 oracle`psddr0+0x9c oracle`psdnal+0x16c oracle`pevm_EXECC+0x140 oracle`pfrrun+0x65b8 oracle`peicnt+0x10c oracle`kkxtexe+0x194 oracle`kxtex1+0x10c oracle`rpiswu2+0x180 oracle`kxtexe+0x180 oracle`insbrp+0x924 oracle`insrow+0xbc oracle`insdrv+0x428 90148 libc.so.1`times+0x4 oracle`ksupop+0x374 oracle`opiodr+0x768 oracle`rpidrus+0x90 oracle`skgmstack+0x9c oracle`rpidru+0xa0 oracle`rpiswu2+0x180 oracle`rpidrv+0x5b8 oracle`psddr0+0x9c oracle`psdnal+0x16c oracle`pevm_EXECC+0x140 oracle`pfrrun+0x65b8 oracle`peicnt+0x10c oracle`kkxtexe+0x194 oracle`kxtex1+0x10c oracle`rpiswu2+0x180 oracle`kxtexe+0x180 oracle`insbrp+0x924 oracle`insrow+0xbc oracle`insdrv+0x428 90148 libc.so.1`times+0x4 oracle`opifch2+0xd50 oracle`opifch+0x3c oracle`opiefn0+0x114 oracle`opipls+0xa94 oracle`opiodr+0x6a0 oracle`rpidrus+0x90 oracle`skgmstack+0x9c oracle`rpidru+0xa0 oracle`rpiswu2+0x180 oracle`rpidrv+0x5b8 oracle`psddr0+0x9c oracle`psdnal+0x16c oracle`pevm_EXECC+0x140 oracle`pfrrun+0x65b8 oracle`peicnt+0x10c oracle`kkxtexe+0x194 oracle`kxtex1+0x10c oracle`rpiswu2+0x180 oracle`kxtexe+0x180 90148 libc.so.1`times+0x4 oracle`opifch2+0xd70 oracle`opifch+0x3c oracle`opiefn0+0x114 oracle`opipls+0xa94 oracle`opiodr+0x6a0 oracle`rpidrus+0x90 oracle`skgmstack+0x9c oracle`rpidru+0xa0 oracle`rpiswu2+0x180 oracle`rpidrv+0x5b8 oracle`psddr0+0x9c oracle`psdnal+0x16c oracle`pevm_EXECC+0x140 oracle`pfrrun+0x65b8 oracle`peicnt+0x10c oracle`kkxtexe+0x194 oracle`kxtex1+0x10c oracle`rpiswu2+0x180 oracle`kxtexe+0x180 90148 libc.so.1`times+0x4 oracle`opiexe+0x1b30 oracle`opiefn0+0xe0 oracle`opipls+0xa94 oracle`opiodr+0x6a0 oracle`rpidrus+0x90 oracle`skgmstack+0x9c oracle`rpidru+0xa0 oracle`rpiswu2+0x180 oracle`rpidrv+0x5b8 oracle`psddr0+0x9c oracle`psdnal+0x16c oracle`pevm_EXECC+0x140 oracle`pfrrun+0x65b8 oracle`peicnt+0x10c oracle`kkxtexe+0x194 oracle`kxtex1+0x10c oracle`rpiswu2+0x180 oracle`kxtexe+0x180 oracle`insbrp+0x924 90148 libc.so.1`times+0x4 oracle`opiexe+0x1b50 oracle`opiefn0+0xe0 oracle`opipls+0xa94 oracle`opiodr+0x6a0 oracle`rpidrus+0x90 oracle`skgmstack+0x9c oracle`rpidru+0xa0 oracle`rpiswu2+0x180 oracle`rpidrv+0x5b8 oracle`psddr0+0x9c oracle`psdnal+0x16c oracle`pevm_EXECC+0x140 oracle`pfrrun+0x65b8 oracle`peicnt+0x10c oracle`kkxtexe+0x194 oracle`kxtex1+0x10c oracle`rpiswu2+0x180 oracle`kxtexe+0x180 oracle`insbrp+0x924 90148 Any explanation what oracle is doing ? Or any documents/docs which will help me how to interpret ustack output ? Regards przemol
If timed_statistics is set to TRUE for Oracle (which is TRUE by default), it will cause Oracle to make times(2) system call. It has low performance overhead (1% to 2%) and not to worry about. --Ravi. przemolicc at poczta.fm wrote On 05/12/06 14:19,:> Hello, > > I am trying to investigate some "performance issues" on one of our > sparc server. I used term "performance issues" because it is not > a typical load but anyway I would like to know what is going on ? > Please look below: > > [ output of sar ] > ... > 08:00:00 71 22 0 6 > 08:10:01 71 23 0 6 > 08:20:00 71 23 0 6 > 08:30:00 70 21 0 9 > 08:40:00 61 20 0 19 > 08:50:01 64 20 0 16 > 09:00:00 56 22 0 23 > 09:10:00 50 25 0 25 > 09:20:00 57 23 0 20 > 09:30:00 57 23 0 20 > > Average 67 22 0 11 > > What is using so much syscalls ? > > bash-3.00# dtrace -n ''syscall::: { @[execname] = count (); }'' > dtrace: description ''syscall::: '' matched 460 probes > ^C > > sshd 36 > ... > nscd 8608 > tnslsnr 9085 > sendmail 10584 > xntpd 12272 > sadc 17968 > vxsvc 31096 > dtrace 1354522 > oracle 147541421 > > What syscalls is doing oracle ? > > bash-3.00# dtrace -n ''syscall::: /execname == "oracle"/ { @[probefunc] = count (); }'' > dtrace: description ''syscall::: '' matched 460 probes > ^C > > connect 4 > so_socket 4 > pipe 6 > waitsys 6 > .... > stat 1578 > mmap 1926 > open 2144 > close 2692 > write 18966 > read 21104 > semsys 37571 > pread 44805 > pwrite 118022 > lwp_park 169225 > kaio 268228 > times 9870413 > >>From the manual: > > NAME > times - get process and child process times > > SYNOPSIS > #include <sys/times.h> > #include <limits.h> > > clock_t times(struct tms *buffer); > > DESCRIPTION > The times() function fills the tms structure pointed to by > buffer with time-accounting information. The tms structure, > defined in <sys/times.h>, contains the following members: > .... > > I am stuck here. :-( > Can anybody help and show me where should I dig now ? How can I check > what is causing ''times'' syscall and why ? > > Regards > przemol > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org
G''Day, On Fri, 12 May 2006, Ravindra Talashikar wrote:> > If timed_statistics is set to TRUE for Oracle (which is TRUE by default), > it will cause Oracle to make times(2) system call. > > It has low performance overhead (1% to 2%) and not to worry about.Perhaps measuring the CPU-consumed time by those times() system calls would be helpful. A script in the DTraceToolkit will do this, http://www.opensolaris.org/os/community/dtrace/dtracetoolkit # ./procsystime -oT -n oracle it will measure on-CPU time in nanoseconds (or use several lines of DTrace). I imagine the CPU time will indeed be small, but it''s great to be able to confirm these assumptions... no worries, Brendan> > --Ravi.[...]> > What syscalls is doing oracle ? > > > > bash-3.00# dtrace -n ''syscall::: /execname == "oracle"/ { @[probefunc] = count (); }'' > > dtrace: description ''syscall::: '' matched 460 probes > > ^C > > > > connect 4 > > so_socket 4 > > pipe 6 > > waitsys 6 > > .... > > stat 1578 > > mmap 1926 > > open 2144 > > close 2692 > > write 18966 > > read 21104 > > semsys 37571 > > pread 44805 > > pwrite 118022 > > lwp_park 169225 > > kaio 268228 > > times 9870413 > >
On Fri, May 12, 2006 at 03:22:18PM +0530, Ravindra Talashikar wrote:> > If timed_statistics is set to TRUE for Oracle (which is TRUE by default), > it will cause Oracle to make times(2) system call. > > It has low performance overhead (1% to 2%) and not to worry about.I asked our DBA and he turned the timed_statistics off for a while: bash-3.00# dtrace -n ''syscall::: /execname == "oracle"/ { @[probefunc] = count (); }'' dtrace: description ''syscall::: '' matched 462 probes ^C pipe 44 waitsys 44 connect 54 so_socket 54 ... close 22156 pollsys 23554 yield 42150 readv 51927 write 158584 read 174879 semsys 500094 pread 816890 pwrite 2354951 lwp_park 4289370 kaio 5093254 There are no more ''times'' syscall on top of the list. But sar didn''t change a lot, just "stabilize" (12:10:00 is the time when timed_statistics was turned off): ... 10:50:00 58 24 0 18 11:00:01 53 26 0 21 11:10:00 52 26 0 21 11:20:00 53 28 0 18 11:30:00 55 30 0 15 11:40:00 57 27 0 16 11:50:01 60 23 0 16 12:00:00 56 24 0 20 12:10:00 53 25 0 22 12:20:00 52 24 0 24 12:30:00 53 24 0 24 12:40:00 50 24 0 26 12:50:00 53 24 0 23 13:00:00 56 24 0 20 13:10:00 57 23 0 20 13:20:01 58 23 0 19 Anyway, thanks Ravindra for the information. Regards przemol
We don''t expect sar(1) to show much difference. As Ravi said the cost of timed stats is about 1-2% (in controlled tests). However, we do have much lighter weight alternatives to times(2) -- for example, gethrtime(3C). 1-2% is not to be sneezed at if it is easy to do. Several 1-2% gains soon add up to something significant. Phil przemolicc at poczta.fm wrote:> On Fri, May 12, 2006 at 03:22:18PM +0530, Ravindra Talashikar wrote: > >> If timed_statistics is set to TRUE for Oracle (which is TRUE by default), >> it will cause Oracle to make times(2) system call. >> >> It has low performance overhead (1% to 2%) and not to worry about. >> > > I asked our DBA and he turned the timed_statistics off for a while: > > bash-3.00# dtrace -n ''syscall::: /execname == "oracle"/ { @[probefunc] = count (); }'' > dtrace: description ''syscall::: '' matched 462 probes > ^C > > pipe 44 > waitsys 44 > connect 54 > so_socket 54 > ... > close 22156 > pollsys 23554 > yield 42150 > readv 51927 > write 158584 > read 174879 > semsys 500094 > pread 816890 > pwrite 2354951 > lwp_park 4289370 > kaio 5093254 > > There are no more ''times'' syscall on top of the list. But sar didn''t change a lot, > just "stabilize" (12:10:00 is the time when timed_statistics was turned off): > ... > 10:50:00 58 24 0 18 > 11:00:01 53 26 0 21 > 11:10:00 52 26 0 21 > 11:20:00 53 28 0 18 > 11:30:00 55 30 0 15 > 11:40:00 57 27 0 16 > 11:50:01 60 23 0 16 > 12:00:00 56 24 0 20 > 12:10:00 53 25 0 22 > 12:20:00 52 24 0 24 > 12:30:00 53 24 0 24 > 12:40:00 50 24 0 26 > 12:50:00 53 24 0 23 > 13:00:00 56 24 0 20 > 13:10:00 57 23 0 20 > 13:20:01 58 23 0 19 > > Anyway, thanks Ravindra for the information. > > Regards > przemol > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org >-------------- next part -------------- A non-text attachment was scrubbed... Name: smime.p7s Type: application/x-pkcs7-signature Size: 3383 bytes Desc: S/MIME Cryptographic Signature URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20060512/f3a0e4a6/attachment.bin>
This is correct except if the times() calls are coming from the Oracle listener(s). In that case, this is a sign of an application connecting/disconnecting all the times and a classic problem of scalability as the Oracle listener is single threaded. regards benoit Ravindra Talashikar wrote:> > If timed_statistics is set to TRUE for Oracle (which is TRUE by default), > it will cause Oracle to make times(2) system call. > > It has low performance overhead (1% to 2%) and not to worry about. > > --Ravi. > > przemolicc at poczta.fm wrote On 05/12/06 14:19,: >> Hello, >> >> I am trying to investigate some "performance issues" on one of our >> sparc server. I used term "performance issues" because it is not >> a typical load but anyway I would like to know what is going on ? >> Please look below: >> >> [ output of sar ] >> ... >> 08:00:00 71 22 0 6 >> 08:10:01 71 23 0 6 >> 08:20:00 71 23 0 6 >> 08:30:00 70 21 0 9 >> 08:40:00 61 20 0 19 >> 08:50:01 64 20 0 16 >> 09:00:00 56 22 0 23 >> 09:10:00 50 25 0 25 >> 09:20:00 57 23 0 20 >> 09:30:00 57 23 0 20 >> >> Average 67 22 0 11 >> >> What is using so much syscalls ? >> >> bash-3.00# dtrace -n ''syscall::: { @[execname] = count (); }'' >> dtrace: description ''syscall::: '' matched 460 probes >> ^C >> >> sshd 36 >> ... >> nscd 8608 >> tnslsnr 9085 >> sendmail 10584 >> xntpd 12272 >> sadc 17968 >> vxsvc 31096 >> dtrace 1354522 >> oracle 147541421 >> >> What syscalls is doing oracle ? >> >> bash-3.00# dtrace -n ''syscall::: /execname == "oracle"/ { >> @[probefunc] = count (); }'' >> dtrace: description ''syscall::: '' matched 460 probes >> ^C >> >> connect 4 >> so_socket 4 >> pipe 6 >> waitsys 6 >> .... >> stat 1578 >> mmap 1926 >> open 2144 >> close 2692 >> write 18966 >> read 21104 >> semsys 37571 >> pread 44805 >> pwrite 118022 >> lwp_park 169225 >> kaio 268228 >> times 9870413 >> >>> From the manual: >> >> NAME >> times - get process and child process times >> >> SYNOPSIS >> #include <sys/times.h> >> #include <limits.h> >> >> clock_t times(struct tms *buffer); >> >> DESCRIPTION >> The times() function fills the tms structure pointed to by >> buffer with time-accounting information. The tms structure, >> defined in <sys/times.h>, contains the following members: >> .... >> >> I am stuck here. :-( >> Can anybody help and show me where should I dig now ? How can I check >> what is causing ''times'' syscall and why ? >> >> Regards >> przemol >> _______________________________________________ >> dtrace-discuss mailing list >> dtrace-discuss at opensolaris.org > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org