RE: Oracle strace output - detail
- From: Herring Dave - dherri <Dave.Herring@xxxxxxxxxx>
- To: "steve.gardiner@xxxxxxxxxx" <steve.gardiner@xxxxxxxxxx>, "oracle-l@xxxxxxxxxxxxx" <oracle-l@xxxxxxxxxxxxx>
- Date: Thu, 12 Jan 2012 21:35:15 +0000
Steve,
I can't help with strace, but can give a suggestion with "regexp_like". Try
adding in the beginning-of-line and end-of-line anchors:
regexp_like(index_name,'^.*(COL)+.*$')
That *shouldn't* make a difference, but it does, at least under 10.2.0.2. I
had great intentions 3 yrs ago to performance test various options with REGEXP
functions in Oracle but unfortunately didn't find the time to make it happen.
If you figure out why the line anchors make it so much faster than please
share, as I've love to know.
DAVID HERRING
DBA
Acxiom Corporation
EML dave.herring@xxxxxxxxxx
TEL 630.944.4762
MBL 630.430.5988
1501 Opus Pl, Downers Grove, IL 60515, USA
WWW.ACXIOM.COM
The information contained in this communication is confidential, is intended
only for the use of the recipient named above, and may be legally privileged.
If the reader of this message is not the intended recipient, you are hereby
notified that any dissemination, distribution or copying of this communication
is strictly prohibited. If you have received this communication in error,
please resend this communication to the sender and delete the original message
or any copy of it from your computer system. Thank you.
-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx] On
Behalf Of Steve Gardiner
Sent: Thursday, January 12, 2012 8:40 AM
To: oracle-l@xxxxxxxxxxxxx
Subject: Oracle strace output - detail
Oracle-l readers,
Does anyone have an idea how to decode this strace entry? Or where to
look for more info?
0.000222 read(11,
"\1w\0\0\6\0\0\0\0\0\20\27\0\0\0\307+\337\201\340\37\314\300\177p\334f\1
6-d\303x"..., 8208) = 375 <4.694759>
Steve Gardiner
Details:
On our 11.2 database I came across a significant performance issue when
using REGEXP_LIKE vs. LIKE.
I profiled the following statements and saw that the statement using
LIKE took about ten times longer, versus the REGEXP_LIKE.
select COUNT(*) from SYS.DBA_INDEXES t WHERE INDEX_NAME LIKE '%COL%';
The above statement takes .4 seconds
select COUNT(*) from SYS.DBA_INDEXES t WHERE
regexp_like(index_name,'.*COL.*');
The above statement takes 4.6 seconds
Doing a sql trace
select COUNT(*) from SYS.DBA_INDEXES t WHERE INDEX_NAME LIKE '%COL%'
STAT #2 id cnt20 pid pos=1 obj op='TABLE ACCESS FULL OBJ$
(cr-3 pr-0 pw=0 time811 us costC size230 cardd1)'
select COUNT(*) from SYS.DBA_INDEXES t WHERE
regexp_like(index_name,'.*COL.*');
STAT #3 id cnt20 pid pos=1 obj op='TABLE ACCESS FULL OBJ$
(cr-3 pr-0 pw=0 time722785 us costC size230 cardd1)'
Notice the differences in time811 vs time722785. Everything else
looks the same.
strace it
Session 1 as oracle
[oracle@localhost sql]$ sqlplus / as sysdba
SQL*Plus: Release 11.2.0.1.0 Production on Fri Dec 30 22:22:48 2011
Copyright (c) 1982, 2009, Oracle. All rights reserved.
Connected to:
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit
Production
With the Partitioning, OLAP, Data Mining and Real Application Testing
options
Session 2 as root
[root@localhost gardiner]# ps -ef | grep sqlplus
oracle 8065 7621 0 22:22 pts/2 00:00:00 sqlplus as sysdba
root 8097 3879 0 22:22 pts/3 00:00:00 grep sqlplus
[root@localhost gardiner]# strace -r -v -p 8065 -T -o strace.out
Process 8065 attached - interrupt to quit
Session 1 as oracle
SQL> select COUNT(*) from SYS.DBA_INDEXES t WHERE INDEX_NAME LIKE
'%COL%';
COUNT(*)
----------
134
SQL> select COUNT(*) from SYS.DBA_INDEXES t WHERE
regexp_like(index_name,'.*COL.*');
COUNT(*)
----------
134
SQL> exit
vi strace.out
read(0, "select COUNT(*) from SYS.DBA_IND"..., 1024) = 70 <27.718485>
27.719176 write(10,
"\1I\0\0\6\0\0\0\0\0\3^\10a\200\0\0\0\0\0\0\376\377\377\377\377\377\377\
377D\0\0"..., 329) = 329 <0.000058>
0.000237 read(11,
"\1\215\0\0\6\0\0\0\0\0\20\27\0\0\0){\277\26\335\2
\246T\306\351\274\3211f`x"..., 8208) = 397 <0.132226>
0.132932 write(10, "\0\25\0\0\6\0\0\0\0\0\3\5\t\1\0\0\0\17\0\0\0",
21) = 21 <0.000056>
0.000200 read(11,
"\0\254\0\0\6\0\0\0\0\0\4\1\0\0\0\6\0\1\1\0\0\0{\5\0\0\0\0\1\0\0\0"...,
8208) = 172 <0.000062>
0.000384 write(1, "\n", 1) = 1 <0.000250>
0.000411 write(1, " COUNT(*)\n", 11) = 11 <0.000166>
0.000313 write(1, "----------\n", 11) = 11 <0.000118>
0.000247 write(1, " 134\n", 11) = 11 <0.000112>
0.000246 write(1, "\n", 1) = 1 <0.000117>
0.000323 write(1, "SQL> ", 5) = 5 <0.000124>
0.000271 read(0, "select COUNT(*) from SYS.DBA_IND"..., 1024) = 80
<11.945245>
11.945649 write(10,
"\1j\0\0\6\0\0\0\0\0\21i\n\376\377\377\377\377\377\377\377\1\0\0\0\0\0\0
\0\1\0\0"..., 362) = 362 <0.000057>
0.000222 read(11,
"\1w\0\0\6\0\0\0\0\0\20\27\0\0\0\307+\337\201\340\37\314\300\177p\334f\1
6-d\303x"..., 8208) = 375 <4.694759>
4.695180 write(10, "\0\25\0\0\6\0\0\0\0\0\3\5\f\1\0\0\0\17\0\0\0",
21) = 21 <0.000054>
0.000204 read(11,
"\0\254\0\0\6\0\0\0\0\0\4\1\0\0\0\t\0\1\1\0\0\0{\5\0\0\0\0\1\0\0\0"...,
8208) = 172 <0.000042>
0.000258 write(1, "\n", 1) = 1 <0.000260>
0.000424 write(1, " COUNT(*)\n", 11) = 11 <0.000161>
0.000314 write(1, "----------\n", 11) = 11 <0.000164>
0.000303 write(1, " 134\n", 11) = 11 <0.000120>
0.000266 write(1, "\n", 1) = 1 <0.000120>
0.000304 write(1, "SQL> ", 5) = 5 <0.000119>
0.000261 read(0, "exit\n", 1024) = 5 <4.047721>
4.048128 write(10, "\0\r\0\0\6\0\0\0\0\0\3\t\r", 13) = 13
<0.000055>
0.000198 read(11, "\0\21\0\0\6\0\0\0\0\0\t\1\0\0\0\0\0", 8208) = 17
<0.001380>
0.001638 lseek(4, 4608, SEEK_SET) = 4608 <0.000040>
0.000180 read(4,
"\17\0\240\0\0\0b\0\241\0\0\0v\0\242\0\0\0\211\0\253\0\0\0\236\0\254\0\0
\0\271\0"..., 512) = 512 <0.000057>
0.000236 lseek(4, 4608, SEEK_SET) = 4608 <0.000034>
0.000136 read(4,
"\17\0\240\0\0\0b\0\241\0\0\0v\0\242\0\0\0\211\0\253\0\0\0\236\0\254\0\0
\0\271\0"..., 512) = 512 <0.000036>
0.000226 write(1, "Disconnected from Oracle Databas"..., 95) = 95
<0.000195>
0.000353 write(1, "With the Partitioning, OLAP, Dat"..., 78) = 78
<0.000158>
0.000386 write(10, "\0\n\0\0\6\0\0\0\0@", 10) = 10 <0.000049>
0.000212 close(10) = 0 <0.000045>
0.000135 close(11) = 0 <0.000042>
0.000495 close(8) = 0 <0.000039>
0.000243 close(5) = 0 <0.000037>
0.000209 close(3) = 0 <0.000040>
0.000146 close(4) = 0 <0.000039>
0.000226 munmap(0x2b2430ac0000, 143360) = 0 <0.000090>
0.000470 exit_group(0) = ?
select COUNT(*) from SYS.DBA_INDEXES t WHERE INDEX_NAME LIKE '%COL%';
generates this read that takes 0.132226 seconds
0.000237 read(11, "\1\215\0\0\6\0\0\0\0\0\20\27\0\0\0){\277\26\335\2
\246T\306\351\274\3211f`x"..., 8208) = 397 <0.132226>
select COUNT(*) from SYS.DBA_INDEXES t WHERE
regexp_like(index_name,'.*COL.*');
generates this read that takes 4.694759 seconds
0.000222 read(11,
"\1w\0\0\6\0\0\0\0\0\20\27\0\0\0\307+\337\201\340\37\314\300\177p\334f\1
6-d\303x"..., 8208) = 375 <4.694759>
Again my question is 'where can I find info about how to decode the
strace output'?
It's a read. It's taking 4.6 seconds. What the info between the " "
mean?
0.000222 read(11,
"\1w\0\0\6\0\0\0\0\0\20\27\0\0\0\307+\337\201\340\37\314\300\177p\334f\1
6-d\303x"..., 8208) = 375 <4.694759>
Steve Gardiner
Hotsos Enterprises, Ltd.
The speakers have been chosen for Hotsos Symposium '12.
Please visit:
http://www.hotsos.com/sym12/sym_speakers.html
<http://www.hotsos.com/sym12/sym_speakers.html>
--
//www.freelists.org/webpage/oracle-l
--
//www.freelists.org/webpage/oracle-l
Other related posts:
