Oracle strace output - detail
- From: "Steve Gardiner" <steve.gardiner@xxxxxxxxxx>
- To: <oracle-l@xxxxxxxxxxxxx>
- Date: Thu, 12 Jan 2012 08:40:01 -0600
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
Other related posts:
