Re: sqlplus : 100% CPU usage while connecting to remote DB

From: Krivenok Dmitry <krivenok.dmitry_at_gmail.com>
Date: Mon, 25 Jun 2007 07:14:07 -0700
Message-ID: <1182780847.984649.278230@k79g2000hse.googlegroups.com>

This is a piece of strace output on my system:

...
...
...

read(6, "\337y\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512

lseek(6, 1024, SEEK_SET)                = 1024

read(6, "\25\7\'\0072\7>\7j\7\276\17$\'\6K5S\24TfT\307T(VsV\222"..., 86) = 86

brk(0x80af000)                          = 0x80af000
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839
times(NULL)                             = -2058427839

...
...
...

Compare it with another strace output (from another server where connection with MTT is established successfuly):

...
...
...

open("/usr/local/oracle/app/oracle/product/10.2.0/oracore/zoneinfo/ timezlrg.dat", O_RDONLY) = 6
fstat64(6, {st_mode=S_IFREG|0664, st_size=404884, ...}) = 0 mmap2(NULL, 404884, PROT_READ, MAP_PRIVATE|MAP_NORESERVE, 6, 0) = 0xb6cc3000

close(6)                                = 0

gettimeofday({1182779992, 205922}, NULL) = 0 open("/usr/local/oracle/app/oracle/product/10.2.0/rdbms/mesg/ ocius.msb", O_RDONLY) = 6

fcntl64(6, F_SETFD, FD_CLOEXEC)         = 0
lseek(6, 0, SEEK_SET)                   = 0

read(6, "\25\23\"\1\23\3\t\t\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 256) = 256

lseek(6, 512, SEEK_SET)                 = 512

read(6, "\337y\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512

lseek(6, 1024, SEEK_SET)                = 1024

read(6, "\25\7\'\0072\7>\7j\7\276\17$\'\6K5S\24TfT\307T(VsV\222"..., 86) = 86

brk(0x80af000)                          = 0x80af000
times(NULL)                             = 1908055079

rt_sigprocmask(SIG_BLOCK, [INT], NULL, 8) = 0 rt_sigaction(SIGINT, {0xb7bb3038, ~[ILL ABRT BUS FPE SEGV USR2 XCPU XFSZ SYS RTMIN RT_1], SA_RESTART|SA_SIGINFO}, {SIG_DFL}, 8) = 0

rt_sigprocmask(SIG_UNBLOCK, [INT], NULL, 8) = 0
gettimeofday({1182779992, 207500}, NULL) = 0
gettimeofday({1182779992, 207598}, NULL) = 0
brk(0x80d2000)                          = 0x80d2000

fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 25), ...}) = 0 mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6ed1000

write(1, "\n", 1)                       = 1
write(1, "SQL*Plus: Release 10.2.0.3.0 - P"..., 70) = 70
write(1, "\n", 1)                       = 1
write(1, "Copyright (c) 1982, 2006, Oracle"..., 56) = 56
write(1, "\n", 1)                       = 1

...
...
...

As you can see in second case

times(NULL)                             = 1908055079

positive value is returned and there is only one call of 'times' system call.

In first case

times(NULL)                             = -2058427839

negative value is returned and there are many of 'times' calls. Received on Mon Jun 25 2007 - 09:14:07 CDT