[#QA-13] Dumping a stack trace is too slow in 10g.

Questions & Answers

Dumping a stack trace is too slow in 10g.

Created: 15/Jul/07 01:45 PM Updated: 16/Sep/07 04:29 PM

Return to search

Fix Version/s:

None

Product Version:	10.1.0.2
Operating System:	Generic

Description

« Hide

Error code:

ORA-4031 (may not be seen by end users).

Error code definition:

The CPU usage reaches 98% in KERNEL mode. strace utility on linux reports that the process spins on read() system call.

System calls:

An excerpt from strace -p <OSPID> output:

 
read(29, "<\345&\0\1\0\21\0\330Wk\10\0\0\0@\30\0\0\0\0\0\0\0", 24) = 24
read(29, "I\345&\0\1\0\22\0\230\226\217\10\0\0\0@\30\0\0\0\0\0\0"..., 24) = 24
read(29, "\20\1\0\0\1\0\24\0\260\n3\0\0\0\0`\20\0\0\0\0\0\0\0", 24) = 24
read(29, "\34\1\0\0\1\0\34\0`\200\353\0\0\0\0`\10\0\0\0\0\0\0\0", 24) = 24
read(29, "\'\1\0\0\1\0\34\0h\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24
read(29, "3\1\0\0\1\0\34\0l\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24
read(29, "V\345&\0\4\0\361\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 24) = 24
read(29, "`\345&\0\1\0\f\0\300XF\4\0\0\0@\4\0\0\0\0\0\0\0", 24) = 24
read(29, "k\345&\0\1\0\21\0\20Xk\10\0\0\0@\30\0\0\0\0\0\0\0", 24) = 24
read(29, "y\345&\0\1\0\22\0\260\226\217\10\0\0\0@\30\0\0\0\0\0\0"..., 24) = 24
read(29, "\20\1\0\0\1\0\24\0\300\n3\0\0\0\0`\20\0\0\0\0\0\0\0", 24) = 24
read(29, "\34\1\0\0\1\0\34\0p\200\353\0\0\0\0`\10\0\0\0\0\0\0\0", 24) = 24
read(29, "\'\1\0\0\1\0\34\0x\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24
read(29, "3\1\0\0\1\0\34\0|\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24

The file descriptor is 29(the first argument in read() system call). By linux lsof command, the descriptor#29 is 1081732 /oracle/product/10.1.0/bin/oracle. In other words, the process is reading Oracle executable.

strace -c -p <OSPID> output for 1 minute:

 
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00 21.570914 40 543060 read
0.00 0.000016 2 7 lseek
0.00 0.000003 3 1 getpid
0.00 0.000001 1 1 open
0.00 0.000001 1 1 readlink
------ ----------- ----------- --------- --------- ----------------
100.00 21.570935 543070 total

read() system call had been called 543,060 times per minute. That's why CPU utilization in KERNEL mode is high.

An excerpt from stack trace by OS debugger:

 
#0 0x200000000137fa81 in read () from /lib/tls/libpthread.so.0
#1 0x4000000004d7a7e0 in sskgds_getsnm ()
#2 0x4000000002766160 in skdsttpcs ()
#3 0x4000000001131920 in ksedst ()
#4 0x40000000011b0140 in ksm_4031_dump ()

ksm_4031_dump() function of Oracle dumps ORA-4031 traces. The top of the stack includes read() system calls.

Problem interpretation:

The process gets ORA-4031 error, then tries to dump trace file for this error. But, while dumping the trace, it spins on read() system calls.

Workaround:

Set the following parameters in pfile/spfile:

 
_4031_dump_bitvec        = 0
_4031_max_dumps         = 0

Bug:

Ref: Oracle Note:3964602 DUMPING A CALL STACK TRACE IS SLOW.

Description

Error code:

ORA-4031 (may not be seen by end users).

Error code definition:

The CPU usage reaches 98% in KERNEL mode. strace utility on linux reports that the process spins on read() system call.

System calls:

An excerpt from strace -p <OSPID> output:

 
read(29, "<\345&\0\1\0\21\0\330Wk\10\0\0\0@\30\0\0\0\0\0\0\0", 24) = 24
read(29, "I\345&\0\1\0\22\0\230\226\217\10\0\0\0@\30\0\0\0\0\0\0"..., 24) = 24
read(29, "\20\1\0\0\1\0\24\0\260\n3\0\0\0\0`\20\0\0\0\0\0\0\0", 24) = 24
read(29, "\34\1\0\0\1\0\34\0`\200\353\0\0\0\0`\10\0\0\0\0\0\0\0", 24) = 24
read(29, "\'\1\0\0\1\0\34\0h\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24
read(29, "3\1\0\0\1\0\34\0l\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24
read(29, "V\345&\0\4\0\361\377\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", 24) = 24
read(29, "`\345&\0\1\0\f\0\300XF\4\0\0\0@\4\0\0\0\0\0\0\0", 24) = 24
read(29, "k\345&\0\1\0\21\0\20Xk\10\0\0\0@\30\0\0\0\0\0\0\0", 24) = 24
read(29, "y\345&\0\1\0\22\0\260\226\217\10\0\0\0@\30\0\0\0\0\0\0"..., 24) = 24
read(29, "\20\1\0\0\1\0\24\0\300\n3\0\0\0\0`\20\0\0\0\0\0\0\0", 24) = 24
read(29, "\34\1\0\0\1\0\34\0p\200\353\0\0\0\0`\10\0\0\0\0\0\0\0", 24) = 24
read(29, "\'\1\0\0\1\0\34\0x\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24
read(29, "3\1\0\0\1\0\34\0|\200\353\0\0\0\0`\4\0\0\0\0\0\0\0", 24) = 24

 
% time seconds usecs/call calls errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00 21.570914 40 543060 read
0.00 0.000016 2 7 lseek
0.00 0.000003 3 1 getpid
0.00 0.000001 1 1 open
0.00 0.000001 1 1 readlink
------ ----------- ----------- --------- --------- ----------------
100.00 21.570935 543070 total

read() system call had been called 543,060 times per minute. That's why CPU utilization in KERNEL mode is high. An excerpt from stack trace by OS debugger:

 
#0 0x200000000137fa81 in read () from /lib/tls/libpthread.so.0
#1 0x4000000004d7a7e0 in sskgds_getsnm ()
#2 0x4000000002766160 in skdsttpcs ()
#3 0x4000000001131920 in ksedst ()
#4 0x40000000011b0140 in ksm_4031_dump ()

ksm_4031_dump() function of Oracle dumps ORA-4031 traces. The top of the stack includes read() system calls.

Problem interpretation:

The process gets ORA-4031 error, then tries to dump trace file for this error. But, while dumping the trace, it spins on read() system calls.

Workaround:

Set the following parameters in pfile/spfile:

 
_4031_dump_bitvec        = 0
_4031_max_dumps         = 0

Bug:

Ref: Oracle Note:3964602 DUMPING A CALL STACK TRACE IS SLOW.

Show »

All

Comments

Change History

Sort Order:

Ascending order - Click to sort in descending order

There are no comments yet on this issue.