Search

OakieTags

Who's online

There are currently 0 users and 24 guests online.

Recent comments

Affiliations

Oakies Blog Aggregator

Append

Quick post primarily for Jeff Smith Web|Twitter (and Gary Myers Web|Twitter who already knows this stuff). It arose from this tweet. hillbillyToad @syd_oracle just seriously freaked me the heck out http://bit.ly/niyXo9 Does /* +APPEND */ automatically suspend logging? #oracle To which my answer was the classic “It Depends”, namely nlitchfield @hillbillyToad @syd_oracle It *should* depend. [...]

BLEVEL 1 => BLEVEL 2 (Teenage Wildlife)

Jonathan Lewis recently wrote a really nice blog piece blevel=1 on the dangers of an index toggling between BLEVEL 1 and BLEVEL 2. I thought it would be useful to demonstrate this issue with a quick demo (Note: this example is on 11.2.0.1, with an 8K block size).   First, create a simple little table with 336,000 rows [...]

Australia Trip Conclusion…

I’m back home from my Australia trip, so I thought I would post a brief summary post of the whole trip…

The trip out:
No major drama here. Only 1 delay, after we boarded the plane in Dubai. It turned a 14 hour flight into 15 hours on the plane, but it wasn’t a major drama. Emirates managed lose my special meal allocation, so they had to cobble together a vegetarian meal for me on both their flights. One of these contained prawns, so that got left. :)

Events:
In my brief time in Australia I managed to speak at 3 events. The main event for the trip was InSync11 of course, but the addition of the Sydney Oracle Meetup and ACTOUG events make it a lot easier to justify traveling such a long way. Three events in four days is a little crazy, but it certainly didn’t leave any time to get bored. :) Thanks to everyone involved for making this go smoothly for me.

The trip home:
No delays during the trip home. Emirates even managed to get my food almost right. One vegetarian and one vegan. :) Unfortunately, they managed to lose my seat allocation for one flight, so my 14 hour flight was not an aisle seat. This normally freaks me out, but fortunately I managed not to get out of my seat every 15 minutes or so.

I made a few single-serving friends on the way home:

  • One guy was doing the systems for theaters, which included music, lights, stage automation and back office systems. Sounded kinda cool.
  • I was sleeping on the floor near a check in desk in Dubai and a lady from my previous flight recognized me and woke me up just in time for boarding my last flight. For that she qualifies as my best single-serving friend of the trip!
  • The young guy next to me on my Dubai – Birmingham flight had won/earned a holiday in Dubai in a competition. It was all about memorizing and reciting The Koran. He won a regional heat and progressed to the UK final and won it. Pretty cool.
  • The guy next to him was on his way home after visiting his Filipino girlfriend. It turned out we liked most of the same films and were both big fans of The Dresden Files books. So sad how excited two grown men can get when discussing Harry Dresden. We swapped a few tips on authors we thought each other would like etc.

Sleep:
This was by far the most bizarre trip I have ever done where sleep is concerned. I never sleep really well on planes, which is a problem. Both trips started in the evening, so it made the total time from bed-to-bed ridiculously long. In Australia I seemed to follow a day-on/day-off sleeping pattern. I would alternate between about 6 hours sleep one night, then about 1.5-3 hours the next. By the time I was due to go home I was feeling like I was in a rather altered state.

I decided to go to Canberra airport early and slept on the floor for about 2 hours. As soon as I got to Dubai I did the same thing. I think both these sleep breaks are just about the only thing that kept me sane during the trip home.

Once home I went to bed and slept for 18 hours. I’ve just been to the gym and I think I’m going to right-off the rest of the day and try and sleep again.

So now I have 5 weeks to get myself ready for OOW11. The combination of the ACE Director meetings and OOW itself makes it a very long trip, so I need to be in top form to get through it without feeling like a zombie.

Thanks to everyone I met during the events. You all helped to make it a great trip.

Cheers

Tim…




Why is my Exadata smart scan not offloading?

After receiving the excellent “Expert Oracle Exadata” book I decided to spend some time looking into Exadata performance after I having spent most of the time previously on infrastructure related questions such as “how can I prevent someone from overwriting my DR system with UAT data”, patching etc.

Now there is one thing to keep in mind with Exadata-you need lots of data before it breaks into a little sweat. Luckily for me, one of my colleagues has performed some testing on this environment. For reasons unknown the swingbench order entry benchmark (version 2.3) has been chosen. For those who don’t know the OE benchmark: it’s a heavy OLTP style workload simulating a web shop where users browse products, place orders etc. OE is optimised for single block I/O, and despite what you may have heard, Exadata doesn’t provide a noticable benefit for these queries.

Anyway, what I liked was the fact that the order_items table had about 350 million rows organised in about 8GB. From discussions with Frits Hoogland I know that a full scan of such a table takes between 40 and 60 seconds depending on system load.

SOE.ORDER_ITEMS

Here are some of the interesting facts around the table:

SQL> select partition_name,num_rows,blocks,avg_space,chain_cnt,global_stats,user_stats,stale_stats
2  from dba_tab_statistics
3  where table_name = 'ORDER_ITEMS'
4  /

PARTITION_NAME                   NUM_ROWS     BLOCKS  AVG_SPACE  CHAIN_CNT GLO USE STA
------------------------------ ---------- ---------- ---------- ---------- --- --- ---
349990815    1144832          0          0 YES NO  NO
SYS_P341                         21866814      71297          0          0 YES NO  NO
SYS_P342                         21889112      72317          0          0 YES NO  NO
SYS_P343                         21877726      71297          0          0 YES NO  NO
SYS_P344                         21866053      71297          0          0 YES NO  NO
SYS_P345                         21870127      71297          0          0 YES NO  NO
SYS_P346                         21887971      72317          0          0 YES NO  NO
SYS_P347                         21875056      71297          0          0 YES NO  NO
SYS_P348                         21891454      72317          0          0 YES NO  NO
SYS_P349                         21883576      72317          0          0 YES NO  NO
SYS_P350                         21859704      71297          0          0 YES NO  NO
SYS_P351                         21866820      71297          0          0 YES NO  NO
SYS_P352                         21865681      71297          0          0 YES NO  NO
SYS_P353                         21865239      71297          0          0 YES NO  NO
SYS_P354                         21870373      71297          0          0 YES NO  NO
SYS_P355                         21882656      71297          0          0 YES NO  NO
SYS_P356                         21872453      71297          0          0 YES NO  NO

17 rows selected.

It has 4 indexes, out of which some are reverse key indexes:

SQL> select index_name,index_type from user_indexes where table_name = 'ORDER_ITEMS';

INDEX_NAME                     INDEX_TYPE
------------------------------ ---------------------------
ITEM_ORDER_IX                  NORMAL/REV
ORDER_ITEMS_UK                 NORMAL
ORDER_ITEMS_PK                 NORMAL
ITEM_PRODUCT_IX                NORMAL/REV

SQL>

This is going to be interesting (I have to admit I didn’t check initially for reverse key indexes). All I wanted was a huge table to see if a smart scan really is so mind blowingly fast. These examples can easily be reproduced by generating the SOE schema with the oewizard-just make sure you select the use of partitioning (you should have a license for it).

Performance Testing

My plan was to start off with a serial execution, then use parallel query and check for execution times.As with all performance tuning of this kind you should have a copy of session snapper from Tanel Poder available. At the time of this writing, the latest version was 3.52 available from Tanel’s blog.

I also wanted to see when a smart scan kicked in. Here’s the first test with serial execution:

10:44:37 SQL> select count(*) from order_items
10:44:40   2  /

COUNT(*)
----------
350749016

Elapsed: 00:00:47.54

OK, that doesn’t look like a smart scan has happened, the 47 seconds are a little too slow. As always, check using snapper to confirm:

SQL> @snapper all 5 1 243
Sampling SID 243 with interval 5 seconds, taking 1 snapshots...
setting stats to all due option = all

-- Session Snapper v3.52 by Tanel Poder @ E2SN ( http://tech.e2sn.com )

-------------------------------------------------------------------------------------------------------------------------------------
SID, USERNAME  , TYPE, STATISTIC                                                 ,     HDELTA, HDELTA/SEC,    %TIME, GRAPH
-------------------------------------------------------------------------------------------------------------------------------------
243, SOE       , STAT, session logical reads                                     ,     81.07k,     16.21k,
243, SOE       , STAT, user I/O wait time                                        ,        299,       59.8,
243, SOE       , STAT, non-idle wait time                                        ,        300,         60,
243, SOE       , STAT, non-idle wait count                                       ,      1.26k,        251,
243, SOE       , STAT, physical read total IO requests                           ,        634,      126.8,
243, SOE       , STAT, physical read total multi block requests                  ,        634,      126.8,
243, SOE       , STAT, physical read total bytes                                 ,    664.14M,    132.83M,
243, SOE       , STAT, cell physical IO interconnect bytes                       ,    664.14M,    132.83M,
243, SOE       , STAT, consistent gets                                           ,     81.07k,     16.21k,
243, SOE       , STAT, consistent gets from cache                                ,          1,         .2,
243, SOE       , STAT, consistent gets from cache (fastpath)                     ,          1,         .2,
243, SOE       , STAT, consistent gets direct                                    ,     81.07k,     16.21k,
243, SOE       , STAT, physical reads                                            ,     81.07k,     16.21k,
243, SOE       , STAT, physical reads direct                                     ,     81.07k,     16.21k,
243, SOE       , STAT, physical read IO requests                                 ,        634,      126.8,
243, SOE       , STAT, physical read bytes                                       ,    664.14M,    132.83M,
243, SOE       , STAT, calls to kcmgcs                                           ,          1,         .2,
243, SOE       , STAT, file io wait time                                         ,        395,         79,
243, SOE       , STAT, Number of read IOs issued                                 ,        635,        127,
243, SOE       , STAT, no work - consistent read gets                            ,      81.1k,     16.22k,
243, SOE       , TIME, DB CPU                                                    ,      1.19s,   237.96ms,    23.8%, |@@@       |
243, SOE       , TIME, sql execute elapsed time                                  ,      4.01s,   801.37ms,    80.1%, |@@@@@@@@  |
243, SOE       , TIME, DB time                                                   ,      4.01s,   801.37ms,    80.1%, |@@@@@@@@  |
243, SOE       , WAIT, direct path read                                          ,      2.99s,   598.63ms,    59.9%, |@@@@@@    |
243, SOE       , WAIT, kfk: async disk IO                                        ,     4.25ms,    849.4us,      .1%, |          |
--  End of Stats snap 1, end=2011-08-17 10:30:47, seconds=5

-----------------------------------------------------------------------
Active% | SQL_ID          | EVENT                     | WAIT_CLASS
-----------------------------------------------------------------------
62% | b0hcgjs21yrq9   | direct path read          | User I/O
38% | b0hcgjs21yrq9   | ON CPU                    | ON CPU

--  End of ASH snap 1, end=2011-08-17 10:30:47, seconds=5, samples_taken=42

PL/SQL procedure successfully completed.

Right-no smart scan; this puzzled me. To recap, smart scans happen only if:

  • Direct path reads are used
  • The row source can be offloaded
  • The parameter cell_offload_processing is set to true (I think it’s “always” in 11.2)
  • There are no chained or migrated rows

Now let’s check these.

I can clearly see that direct path reads have happened from the snapper output-check. It’s also worth remembering that the decision to perform direct path reads is made on a segment basis-and each partition is a segment: keep that in mind!

You can check the execution plan to find out if the row source can be offloaded as in this example:

SQL> select * from table(dbms_xplan.display(format=>'+projection'));

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2209137760

-----------------------------------------------------------------------------------------
| Id  | Operation                     | Name            | Rows  | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |                 |     1 |   249K  (1)| 00:49:52 |
|   1 |  SORT AGGREGATE               |                 |     1 |            |          |
|   2 |   INDEX STORAGE FAST FULL SCAN| ITEM_PRODUCT_IX |   349M|   249K  (1)| 00:49:52 |
-----------------------------------------------------------------------------------------

Column Projection Information (identified by operation id):

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------

1 - (#keys=0) COUNT(*)[22]

14 rows selected.

You can see that the INDEX STORAGE FAST FULL SCAN clause is used, in other words the source can be offloaded. Strange that it didn’t happen though. The parameter cell_offload_processing was set to true on my system. Do you remember that the index is a reverse key index? I’m wondering if that has anything to do with it.

To rule out that there was a problem with the direct path reads I set “_serial_direct_read”=true and tried again, but it didn’t make a difference.

Another way to check for smart scans in a live system is the use of v$sql-columns IO_CELL_UNCOMPRESSED_BYTES and  IO_CELL_OFFLOAD_RETURNED_BYTES are cumulative counters for smart scan activity. However if they are 0 like in my case, they indicate some sort of issue.

This continued with parallel query: 8 or 64 slaves and still no smart scan. I even traced the execution, but there was not a single pxxx trace file with the word “smart” in it (and I made sure I captured the waits)

What was going on?

SQL_ID  4vkkk105tny60, child number 0
-------------------------------------
select /*+parallel(64)*/ count(*) from order_items

Plan hash value: 544438321

--------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                         | Name            | Rows  | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |                 |       |  4306 (100)|          |        |      |            |
|   1 |  SORT AGGREGATE                   |                 |     1 |            |          |        |      |            |
|   2 |   PX COORDINATOR                  |                 |       |            |          |        |      |            |
|   3 |    PX SEND QC (RANDOM)            | :TQ10000        |     1 |            |          |  Q1,00 | P->S | QC (RAND)  |
|   4 |     SORT AGGREGATE                |                 |     1 |            |          |  Q1,00 | PCWP |            |
|   5 |      PX BLOCK ITERATOR            |                 |   349M|  4306   (1)| 00:00:52 |  Q1,00 | PCWC |            |
|*  6 |       INDEX STORAGE FAST FULL SCAN| ITEM_PRODUCT_IX |   349M|  4306   (1)| 00:00:52 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

1 - SEL$1
6 - SEL$1 / ORDER_ITEMS@SEL$1

Predicate Information (identified by operation id):
---------------------------------------------------

6 - storage(:Z>=:Z AND :Z<=:Z)

Column Projection Information (identified by operation id):
-----------------------------------------------------------

1 - (#keys=0) COUNT()[22]
2 - SYS_OP_MSR()[10]
3 - (#keys=0) SYS_OP_MSR()[10]
4 - (#keys=0) SYS_OP_MSR()[10]

Note
-----
- automatic DOP: Computed Degree of Parallelism is 64

Ok then I got fed up with that ITEM_PRODUCT_IX and forced a full table scan and volia-a smart scan happened.

SQL> select * from table(dbms_xplan.display_cursor('5a1x1v72ujf8s', format=>'ALL'));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  5a1x1v72ujf8s, child number 0
-------------------------------------
select /*+ full(t) parallel(t, 8) */ count(*) from order_items t

Plan hash value: 661298821

-----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name        | Rows  | Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
-----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |             |       | 43358 (100)|          |       |       |        |      |            |
|   1 |  SORT AGGREGATE                |             |     1 |            |          |       |       |        |      |            |
|   2 |   PX COORDINATOR               |             |       |            |          |       |       |        |      |            |
|   3 |    PX SEND QC (RANDOM)         | :TQ10000    |     1 |            |          |       |       |  Q1,00 | P->S | QC (RAND)  |
|   4 |     SORT AGGREGATE             |             |     1 |            |          |       |       |  Q1,00 | PCWP |            |
|   5 |      PX BLOCK ITERATOR         |             |   349M| 43358   (1)| 00:08:41 |     1 |    16 |  Q1,00 | PCWC |            |
|*  6 |       TABLE ACCESS STORAGE FULL| ORDER_ITEMS |   349M| 43358   (1)| 00:08:41 |     1 |    16 |  Q1,00 | PCWP |            |
-----------------------------------------------------------------------------------------------------------------------------------

Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

1 - SEL$1
6 - SEL$1 / T@SEL$1

Predicate Information (identified by operation id):
---------------------------------------------------

6 - storage(:Z>=:Z AND :Z<=:Z)

Column Projection Information (identified by operation id):
-----------------------------------------------------------

1 - (#keys=0) COUNT()[22]
2 - SYS_OP_MSR()[10]
3 - (#keys=0) SYS_OP_MSR()[10]
4 - (#keys=0) SYS_OP_MSR()[10]

37 rows selected.

To be sure that was correct, I retried with serial execution (check the time):

11:44:10 SQL> select /*+ full(t) single */ count(*) from order_items t;

COUNT(*)
----------
350749016

Elapsed: 00:00:12.02

@snapper all 5 1 241

Sampling SID 243 with interval 5 seconds, taking 1 snapshots...
setting stats to all due option = all

-- Session Snapper v3.52 by Tanel Poder @ E2SN ( http://tech.e2sn.com )

-------------------------------------------------------------------------------------------------------------------------------------
SID, USERNAME  , TYPE, STATISTIC                                                 ,     HDELTA, HDELTA/SEC,    %TIME, GRAPH
-------------------------------------------------------------------------------------------------------------------------------------
243, SOE       , STAT, session logical reads                                     ,    482.88k,     96.58k,
243, SOE       , STAT, application wait time                                     ,          1,         .2,
243, SOE       , STAT, user I/O wait time                                        ,        158,       31.6,
243, SOE       , STAT, non-idle wait time                                        ,        159,       31.8,
243, SOE       , STAT, non-idle wait count                                       ,      3.72k,      744.8,
243, SOE       , STAT, enqueue waits                                             ,         15,          3,
243, SOE       , STAT, enqueue requests                                          ,         14,        2.8,
243, SOE       , STAT, enqueue conversions                                       ,         21,        4.2,
243, SOE       , STAT, enqueue releases                                          ,         14,        2.8,
243, SOE       , STAT, global enqueue gets sync                                  ,         35,          7,
243, SOE       , STAT, global enqueue releases                                   ,         14,        2.8,
243, SOE       , STAT, physical read total IO requests                           ,      5.23k,      1.05k,
243, SOE       , STAT, physical read total multi block requests                  ,      4.91k,        982,
243, SOE       , STAT, physical read total bytes                                 ,      3.95G,    790.99M,
243, SOE       , STAT, cell physical IO interconnect bytes                       ,      1.72G,    343.34M,
243, SOE       , STAT, ges messages sent                                         ,         21,        4.2,
243, SOE       , STAT, consistent gets                                           ,    482.88k,     96.58k,
243, SOE       , STAT, consistent gets from cache                                ,         97,       19.4,
243, SOE       , STAT, consistent gets from cache (fastpath)                     ,         97,       19.4,
243, SOE       , STAT, consistent gets direct                                    ,    482.78k,     96.56k,
243, SOE       , STAT, physical reads                                            ,    482.78k,     96.56k,
243, SOE       , STAT, physical reads direct                                     ,    482.78k,     96.56k,
243, SOE       , STAT, physical read IO requests                                 ,      5.23k,      1.05k,
243, SOE       , STAT, physical read bytes                                       ,      3.95G,    790.99M,
243, SOE       , STAT, calls to kcmgcs                                           ,         97,       19.4,
243, SOE       , STAT, file io wait time                                         ,      19.7k,      3.94k,
243, SOE       , STAT, cell physical IO bytes eligible for predicate offload     ,      3.95G,    790.89M,
243, SOE       , STAT, cell smart IO session cache lookups                       ,          7,        1.4,
243, SOE       , STAT, cell smart IO session cache hits                          ,          7,        1.4,
243, SOE       , STAT, cell physical IO interconnect bytes returned by smart scan,      1.72G,    343.38M,
243, SOE       , STAT, table scans (long tables)                                 ,          7,        1.4,
243, SOE       , STAT, table scans (direct read)                                 ,          7,        1.4,
243, SOE       , STAT, table scan rows gotten                                    ,    147.19M,     29.44M,
243, SOE       , STAT, table scan blocks gotten                                  ,    480.07k,     96.01k,
243, SOE       , STAT, cell scans                                                ,          7,        1.4,
243, SOE       , STAT, cell blocks processed by cache layer                      ,    576.41k,    115.28k,
243, SOE       , STAT, cell blocks processed by txn layer                        ,    576.41k,    115.28k,
243, SOE       , STAT, cell blocks processed by data layer                       ,    485.06k,     97.01k,
243, SOE       , STAT, cell blocks helped by minscn optimization                 ,    576.28k,    115.26k,
243, SOE       , STAT, cell simulated session smart scan efficiency              ,      3.97G,     794.6M,
243, SOE       , STAT, cell IO uncompressed bytes                                ,      3.97G,    794.93M,
243, SOE       , TIME, DB CPU                                                    ,      2.63s,   526.72ms,    52.7%, |@@@@@@    |
243, SOE       , TIME, sql execute elapsed time                                  ,      4.01s,   801.13ms,    80.1%, |@@@@@@@@  |
243, SOE       , TIME, DB time                                                   ,      4.01s,   801.13ms,    80.1%, |@@@@@@@@  |
243, SOE       , WAIT, enq: KO - fast object checkpoint                          ,     2.19ms,    438.8us,      .0%, |          |
243, SOE       , WAIT, cell smart table scan                                     ,      1.58s,   316.49ms,    31.6%, |@@@@      |
243, SOE       , WAIT, events in waitclass Other                                 ,     8.54ms,     1.71ms,      .2%, |          |
--  End of Stats snap 1, end=2011-08-17 12:53:04, seconds=5

-----------------------------------------------------------------------
Active% | SQL_ID          | EVENT                     | WAIT_CLASS
-----------------------------------------------------------------------
66% | cfhpsq29gb49m   | ON CPU                    | ON CPU
34% | cfhpsq29gb49m   | cell smart table scan     | User I/O

--  End of ASH snap 1, end=2011-08-17 12:53:04, seconds=5, samples_taken=47

PL/SQL procedure successfully complet

Confusing, confusing. It was time to ask the experts: Frits Hoogland who reproduced the behaviour on his environment (11.2.0.1 and 11.2.0.2), as well as Kerry Osborne-both of which thought a smart scan should have happened even with the index. An Index FFS certainly used to be offloadable, and we think there is a regression bug visible with the cells. My version of the cell software is 11.2.2.2 with 11.2.0.1 BP 6. I first thought it might be a problem with 11.2.0.1 and the version of the cell software, but it probably isn’t: Kerry tested on 11.2.0.2 BP10 and cellsrv 11.2.2.3.2, Frits tested on 11.2.0.1 and 11.2.0.2 BP 6 and cellsrv 11.2.2.2.0_LINUX.X64_101206.2-1

Summary

What we are seeing isn’t something we should be seeing. I am trying to get this raised as an SR and see what happens. From my testing it seems that it potentially impacts anyone with indexes on their tables.

Cowboys & Aliens…

I’ve got a late flight home, which always presents a bit of a problem as the hotel checkout means you are hanging around with no base for most of the day. As a result I decided to go to see Cowboys & Aliens.

Let me start by saying I got 1.5 hours of sleep last night so I am insanely tired…

The film seemed OK, but I did find myself nodding off at times. I woke with a start a few times. A couple of times it was audience screams/shouts and a couple of times it was audience laughs that brought me back to the land of the living. I did see the vast majority of the film and I thought it was OK, but I really need to see it again to make any reasonable judgement on it. The feedback from the crowd would suggest the bits I missed were quite good. :)

I’m now at the airport about 3 hours early for a domestic flight from Canberra to Sydney before my proper journey begins. I think I’m going to lie on the floor somewhere and try not to swallow my tongue… :)

Cheers

Tim…




Developer Access To 10046 Trace Files

Lets suppose you are a DBA at a large company. You have some great developers, and they’re learning all about how to turn on full logging of their code through the 10046 database trace. They just learned how to use this data in summary form to find out – at a very detailed level – what’s REALLY taking up all the time during their big batch program which runs too long. They’re salivating over this trace data – but you work for a big company with security policies that can’t be easily changed, where developers rarely get any kind of shell-level or filesystem-level access to a database server. You WANT them to have the ability to profile their own database code… but every time they run a trace, you get dragged into a long email exchange to locate their tracefile and transfer it to a network drive where they can access it. We’re so close to a great situation… but this last part is such a drag!!!

However: please notice the Security Addendum at the end of this article.

Of course if you’re lucky enough that your developers use certain tools from Oracle, then there are some slick 3rd party plugins that will help download and manage tracefiles for you. But what if your developers don’t want to add a whole new environment to their already memory-bound workstations? What if there are corporate policies making this difficult – such as a time-consuming review and approval process for any new software installs?

Wouldn’t it be nice of Oracle had a system view that your developers could just QUERY to find tracefiles? Maybe something like this (which of course displayed data in real time, reflecting the current status of the filesystem):

SQL> desc all_trace_files
 Name                          Null?    Type
 ----------------------------- -------- --------------------
 DIRECTORY                              CHAR(5)
 FILE_NAME                              VARCHAR2(400)
 FILE_TIME                              DATE
 FILE_BYTES                             NUMBER
 FILE_TRACEID                           VARCHAR2(100)
 FIRST_TIME                             DATE
 FIRST_ACTION                           VARCHAR2(100)
 FIRST_MODULE                           VARCHAR2(100)
 FIRST_SERVICE                          VARCHAR2(100)
 SID                                    NUMBER
 SERIAL                                 NUMBER
 ERROR                                  VARCHAR2(400)

Sure, this looks nice – maybe in the next version of Oracle. When you upgrade to it, 10 years from now. But what about NOW – your old 10g database running on a huge mainframe?

We all know how nice it would be if your developers run a query like this… today… on almost any database:

SQL> select directory, file_name, file_traceid, first_action from all_trace_files 
  2  where first_action is not null;

DIREC FILE_NAME                                FILE_TRACE FIRST_ACTION
----- ---------------------------------------- ---------- ----------------------------------------
UDUMP ardentp1_ora_12386502.trc                           Test Window - New
UDUMP ardentp1_ora_22347974.trc                           Test Window - New
UDUMP ardentp1_ora_22675498.trc                           SQL Window - xml_file_writing_te
UDUMP ardentp1_ora_24248536.trc                           SQL Window - test_cases.sql
UDUMP ardentp1_ora_24641726.trc                           DEQ
UDUMP ardentp1_ora_2621852.trc                            Test Window - New
UDUMP ardentp1_ora_3342766.trc                            problemTbsp
UDUMP ardentp1_ora_4063428.trc                            SQL Window - New
UDUMP ardentp1_ora_45350944.trc                           Debug Test Window - New
UDUMP ardentp1_ora_45547538.trc                           Main session
UDUMP ardentp1_ora_48103606.trc                           SQL Window - SELECT * FROM ext.e
UDUMP ardentp1_ora_50593842.trc                           SQL Window - test_cases.sql
UDUMP ardentp1_ora_50790578.trc                           SQL Window - New
UDUMP ardentp1_ora_51380240.trc                           Debug Test Window - New
UDUMP ardentp1_ora_52429026.trc                           UserBlock
UDUMP ardentp1_ora_52691004.trc                           SQL Window - New
UDUMP ardentp1_ora_60817584.trc                           Test Window - New
UDUMP ardentp1_ora_61538330.trc                           Test Window - New
UDUMP ardentp1_ora_62783512_schn_02.trc        schn_02    Test Window - New
UDUMP ardentp1_ora_62783512_schn_03.trc        schn_03    Test Window - New
UDUMP ardentp1_ora_6291778.trc                            Test Window - New
UDUMP ardentp1_ora_63176754.trc                           Test Window - New
UDUMP ardentp1_ora_66388158.trc                           Test Window - New
UDUMP ardentp1_ora_8192480.trc                            Test Window - New
UDUMP ardentp1_ora_8651144.trc                            SQL Window - test_cases.sql
BDUMP ardentp1_m000_12517418.trc                          Monitor Tablespace Thresholds
BDUMP ardentp1_m000_20119784.trc                          Monitor Tablespace Thresholds
BDUMP ardentp1_m000_24248408.trc                          Monitor Tablespace Thresholds
BDUMP ardentp1_m000_45154330.trc                          Monitor Tablespace Thresholds
BDUMP ardentp1_mmnl_52560064.trc                          Monitor Tablespace Thresholds
BDUMP ardentp1_mmon_52756580.trc                          Monitor Tablespace Thresholds

31 rows selected.

And of course – last but not least, you’d like your developers to actually be able to download the tracefile themselves, right? Actually, this has already been done – Dion Cho blogged some sample code about two and a half years ago. He has a very elegant solution using a pipelined PL/SQL function and UTL_FILE.

http://dioncho.wordpress.com/2009/03/19/another-way-to-use-trace-file/

Just one minor tweak would be needed, to grab files from more than one directory. (In addition to your session traces, you might need to get logs from parallel query slaves or DBMS_JOB/SCHEDULER processes.)

Not only can you write queries to your heart’s content on this, but just about every developer environment on the planet can easily take this query output and save it to a file – then they can run the profiler of their choice on the tracefile. That would be cool, right?!

SQL> select * from table(textfile('ardentp1_ora_52691004.trc','UDUMP')) where rownum<20;

COLUMN_VALUE
-------------------------------------------------------------------------------------------
/u0001/app/oracle/admin/ardentp/udump/ardentp1_ora_52691004.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
ORACLE_HOME = /u0001/app/oracle/product/db/10.2.0/ardentp
System name:    AIX
Node name:      ardent4
Release:        1
Version:        6
Machine:        00F66BE22C00
Instance name: ardentp1
Redo thread mounted by this instance: 1
Oracle process number: 59
Unix process pid: 52691004, image: oracle@ardent4

*** ACTION NAME:(SQL Window - New) 2011-08-15 16:35:24.791
*** MODULE NAME:(PL/SQL Developer) 2011-08-15 16:35:24.791
*** SERVICE NAME:(ardentp_dba) 2011-08-15 16:35:24.791
*** SESSION ID:(572.24734) 2011-08-15 16:35:24.791

19 rows selected.

Well I AGREE that this would be cool! And as it happens, the customer I’m working with now would find it very useful. And honestly… it’s really not that complicated to code something like this. So last night I stayed late a few hours to write it up and test it. It’s mainly build on a pipelined java function, and of course a minor tweak on Dion’s code for getting the file.

Basically, every time you query the view it scans the first 30 lines of all files in the bdump and udump directories for timestamps and identification information (module, action, service, sid, serial). This information is combined with basic file stats (name, size, last-modified-date) and the tracefile_identifier is calculated from the filename. Any errors encountered are reported in the error column (file permissions, etc).

You can download the entire thing at my github repo (specifically, the files tracefile_find.txt and tracefile_get.txt). All examples in this blog post are from a real system – nothing here is cooked, except that I changed database and host names to protect the innocent.

Enjoy!

Security Addendum

As pointed out in the comments after I published this post, there are some important security considerations with allowing access to trace files. A good explanation can be found in Pete Finnigan’s blog article: Is it possible to steal data with just ALTER SESSION? To summarize: if a clever hacker is able to access tracefiles then it is possible for them to see things that the database normally protects. This certainly includes table data, and it may even include passwords for other database accounts – sometimes even in cleartext. This is very important if you’re considering any tool that grants access to tracefiles – including the scripts I’ve published here. Although he generally disapproves of any tracefile access, Pete’s comment suggested a way to reduce the risk. The second table (which actually gives tracefile contents) can be limited to DBAs and then developers can get a view which only shows files that the DBAs explicitly grant. I think that the most useful part of my program is the first view anyway, which scans tracefiles and lets you use SQL to search on module/action/service.

One further quick postscript… lest you think I was terribly irresponsible with this client, we did consider security implications before endorsing this script. Admittedly I didn’t consider every scenario that Pete has written about, but I do still think we made an appropriate decision. (Also… the script wasn’t yet installed into production when I left the client, because it had to go through an approval process itself. ) In this particular case, the small group of developers getting access to tracefiles were people who already had full access to all data in the database and they had passwords for all key application accounts. Although they didn’t have SYSDBA passwords or shell access, they essentially had everything else – including all the data. Furthermore, they were in a stage of performance troubleshooting where their productivity could be significantly increased with the ability to run many traces and quickly access the tracefiles (think Method R). And finally, these developers were on the same small, tight team as the DBAs who took care of backups and patching, all sitting together in one corner of the office building. The DBAs were involved in the decision and seemed to find their reduced workload a very positive thing – especially since they know all the developers who would get access.

One could certainly comment on the security policies of this client, and their decisions about balancing trust and productivity. But I do not think that we were circumventing the company security policies in this case. And certainly my scripts are not intended to support such activity. Nonetheless, I do think there are cases where this is a very useful script. It’s much more convenient for developers who – even if they can get shell access – may not know much about navigating unix and are more comfortable working in their SQL development environment.

Mastering Oracle Trace Data

Cary Millsap is teaching a new one day class next week in Dallas (well Southlake actually) on Oracle trace data. This is a class that he has personally been working on recently and is teaching. I am planning on attending. Here’s a link to the sign up page which has all the details:

Mastering Oracle Trace Data

Check it out.

ACTOUG – Canberra

Yesterday, Chris Muir and I drove down from Sydney to Canberra to present at an ACTOUG event organized by Marcelle Kratochvil.

The day started off with Chris introducing REST Web Services using Java. After that I did my Clonedb presentation and I didn’t stuff up my demo this time. :) This was followed with a general Q&A and lots of pizza. I like these informal events. They are cool.

Off home tomorrow…

Cheers

Tim…




InSync11 – Day 2

InSync11 day 2 was very much “the day after the night before” for me. I didn’t sleep very well at all. I think I spent most of the night winding myself up about my dodgy demo earlier in the day.

My next presentation was in the last slot on day 2, so I got to see the following presentations before I was up:

Jeremy Ashley & Chris Muir: What’s next for Oracle’s Application User Experiences?

On our first night in Sydney, Chris Muir and I were out with Jeremy Ashley and Mark Drake from Oracle. In addition to the regular geek talk, Jeremy waxed lyrical about end-to-end user experience. It’s quite an interesting subject, with a lot more to it than first springs to mind.

Graham Wood: Ashes of DBTime

I’ve seen Graham speak on this subject a number of times, but it’s always worth checking it out again. I’ll probably end up watching it again in OpenWorld in a few weeks. :)

Marcelle Kratochvil: Why you should be storing unstructured data in the Oracle database.

I have some experience of storing images and documents in the database, so I can appreciate some of the issues Marcelle was highlighting in her presentation. She’s very passionate about the subject and constantly pushing the barrier of what Oracle is capable in the multimedia field.

Connor McDonald: Managing optimizer statistics – A better way.

Management of database statistics has got to be one of the most contentious issues. Everyone seems to have a slightly different opinion and I always come away both agreeing and disagreeing with many of the points.

Connor always has great content and is renowned as an excellent presenter. This talk was no different in that respect. In fact, I would go as far as to say this is the best presentation I’ve ever seen him do, which probably means it’s one of the best Oracle presentations I’ve ever seen. If you get the chance to see Connor present, you really should take the opportunity. Of course, if you are a presenter yourself, you may want to avoid it, as it will probably make you paranoid about how bad you are in comparison.

Me: Edition-Based Redefinition.

Rule of thumb: Don’t present a database talk in the same time slot as Tom Kyte because everyone will go to his session, not yours. To be fair, if I wasn’t presenting I would have been in his session too. :)

Even so, the talk went ok and my demo worked as planned, so I slept well that night! :)

Conclusion

Pretty much everyone I spoke to said they were very impressed with the standard of the conference this year. The standard of the presentations was high and the location was cool.

Cheers

Tim…




Friday Philosophy – Dyslexia Defence League

NB This post has nothing to do with Oracle or even technology really. It’s just some thoughts about one aspect of my life.

I know I’ve mentioned this once before, though it was in an early blog post when I had a readership of about 8, but I am mildly dyslexic. If you want to know how I found out I was dyslexic then check out the original post. I’m quite fond of that post, as a non-technical one, though almost no one read it.

The thing is, I now cringe slightly when I say I am Dyslexic. I’ve sat on this post for weeks, wondering if I should post it. You see, it seems to me that dyslexia, along with some other oddities of perception, have over the last few years almost become a thing to be proud of. A banner to wave to show how great you are. “Hey, look at me, I am this good even though I have Dyslexia” or even “I am great because I have dyslexia”. Maybe I am just a little sensitive about it but it seems to me that more and more people make a thing about it. If I am being candid, I feel a little proud that I did OK academically despite it {I should point out there is no proven link between dyslexia and IQ but in exams you get marked down for spelling and slow reading speed means it takes longer to, well, read stuff!} and in the past I have been very open about mentioning it. Hey, this is my second blog on dyslexia!

However, I’ve had it suggested to me in the past that I use it as a defense for being lazy – Can I prove I am dyslexic? Does it really impact me that much? Well, actually no I cannot prove it and has it impacted me? Not a great deal I guess as I can read pretty much anything {I did say it was mild. Scientific papers and anything with very long words can be a challenge, but isn’t that true of everyone?}. My reading speed is about 120,150 words a minute. Average is about 250wpm. My wife seems to read at about 500wpm :-)

Also, don’t get me wrong, I fully appreciate that looking at a challenge you have and taking the benefits from it that you can is a very healthy attitude. If I remember right it was Oliver Sacks in one of his books (“the man who mistook his wife for a hat” maybe) who describes a man with sever Tourette’s syndrome {which is more often all about physical ticks and uncontrolled motions rather than the famous “swearing” aspect of it} who could somehow take advantage of his physical manifestations in his jazz drumming. He could just make it flow for him. But when he took treatment to control the physical issues, his jazz drumming suffered. He really wanted the benefit of the drugs for day-to-day life but keep the Tourettes for jazz. So he took the drugs during the week and came off just before the weekends when he played. Neat.

Does Dyslexia help me? I think I am more of a diagrams and pictures person than a text person because of my dyslexia and I think I maybe look at things a little differently to most people at times – because of the differences in how I perceive. That can help me see things that maybe others have missed? Maybe an advantage. I’ll take that.

Also, in my case at least, dyslexia is not an issue for me comprehending or constructing written prose. I think I write some good stuff at times.

But I don’t want to be dyslexic. Frankly, it p122es me off.

I’ll give you an example. I did a blog post a few weeks back and it had some script examples in it. I had nearly finished it when I realised I had constantly spelt one word utterly wrong. The spell checker picked it up. But just before I posted it, I realised I had also got my column aliases utterly wrong. I have a little set of rules for generating table and column aliases, it is not complex, but in my head the leading letters of a word are not always, well, the leading letters. I had to alter my scripts and then re-run them all as I knew if I tried to unpick the spelling mistakes manually I would mess it up, I’ve been there before. It took me hours. I can really do without wasting that time. {Update, since originally drafting this post the same situation with another technical post has occurred}. Then there is the embarrassment of doing something like spelling the name of a column wrong when you design and build a database. I did that in a V8 database when renaming columns was still not a simple task {was it really Oracle 9 release 2 before column rename was introduced?}. The database went live and accrued a lot of data before anyone made an issue of it. It then kept getting mentioned and I had to keep explaining.

I don’t see Dyslexia as a badge of honour and every time I see someone being proud of it (or to my odd mind it seems they are proud of it) or suggesting they are better than average for overcoming it (again, maybe it is just my perception), I just feel uncomfortable. I think all and everyone of us has something we have had to overcome to be “normal”.

Yet, on reading that above paragraph back, it is simply insulting to people who have fought and striven to overcome severe dyslexia or other issues with perception or communication. I certainly do not mean that (and I apologise unreservedly to anyone who is now fuming at me because of my callousness).

Maybe that is my issue with the whole topic – I am not uncomfortable with the notion of being proud to have overcome something like dyslexia and I admire people who cope with other conditions which make it harder for them to get by in our culture, but I just can’t see why you would be proud of the condition or want to use it as a bragging right.

I guess I want to be able to just acknowledge my dyslexia, point out it is no big deal in my case but it is why I spell like a 10 year old. It is as significant as the fact I’m scared of heights. I guess I cringe a little when I say it as I don’t want to be seen to be making excuses and I certainly do not feel, that in my case at least. I have won through against the odds. Maybe I’ve been a little hard-done-by occasionally but haven’t we all?