RE: Oracle strace output - detail
Date: Thu, 12 Jan 2012 21:35:15 +0000
Message-ID: <BD475CE0B3EE894DA0CAB36CE2F7DEB44550FD30_at_LITIGMBCRP02.Corp.Acxiom.net>
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_at_acxiom.com 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_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of Steve Gardiner
Sent: Thursday, January 12, 2012 8:40 AM
To: oracle-l_at_freelists.org
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_at_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_at_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_at_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_at_", 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>
-- http://www.freelists.org/webpage/oracle-l -- http://www.freelists.org/webpage/oracle-lReceived on Thu Jan 12 2012 - 15:35:15 CST