Oracle strace output - detail

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