Drilling Deep Into Exadata Performance with ASH, SQL Monitoring and Exadata Snapper – slides and a hacking session!

The promised hacking session about Exadata performance troubleshooting will happen on Thursday 21st February 9am-11am PST (2 hours). I will show a number of examples and demos where the Exadata Snapper shows what was going on in storage cells when running Smart Scans or just doing IO.

Register here (free stuff!):

Slides:

I will post the scripts on the day of this session.

Note that you should read through the slides before the hacking session – as I’m not going to spend much time on presenting slides, as the name says – it’s a hacking session, so 95% demos. I will show a couple of important slides which explain the essence of Exadata Snapper (check slide 17, 21, 22), but otherwise it’s all demos.

This hacking session will also give a little preview of what’s going to happen in my new Advanced Exadata Performance seminars – see below ;-) As far as I know, there is no other seminar in the world (well at least available to public) where you can learn so deep knowledge about Exadata performance troubleshooting, optimization and internals – all arranged around a systematic approach for dealing with Exadata performance issues.

New Seminar – Advanced Exadata Performance: Troubleshooting and Optimization

This advanced seminar is meant for DBAs and developers who already have at least the basic experience of working with Exadata and have seen some of the common performance problems that may occur in production or performance tests. In this class we will dive deep into details of how Exadata works internally and then how to systematically troubleshoot performance problems caused either by application, database, storage cell software or Exadata hardware issues. The demos and troubleshooting examples are shown on Enkitec’s in-house Exadata X2-2 and V2 machines and we will use both standard Oracle tools and advanced Exadata troubleshooting scripts written by Tanel.

What students will learn:

  • Understand how Exadata features, the storage cell servers and the DB-cell communication work internally
  • How to use database, OS and cell metrics for systematically troubleshooting Exadata performance issues, from basic to complex problems involving multiple components, bugs and hardware issues
  • How to identify which workloads and SQL statements are not Exadata-friendly and what to do about it
  • How to design for optimal Exadata performance and avoid design and coding pitfalls

What this class is not:

  • This class is not an introductory “what is Exadata” class, but an advanced seminar about getting the most out of your Exadatas and resolving even complex performance problems systematically and fast
  • This class is not an introductory SQL or database tuning class, but focuses on troubleshooting only Exadata-related performance issues of your workloads
  • This class is not a general Exadata infrastructure troubleshooting class (like hardware, networking and Grid Infrastructure configuration problems), instead we focus entirely on performance

 

Day 1 – Exadata Internals, Systematic Troubleshooting and Smart Scans

    • Understanding the low-level internals of Exadata data flow all the way from cell disks to the database nodes – and the physics behind its performance
    • Using basic performance tools like V$SQLSTATS, ASH and SQL Monitoring views on Exadata
    • Troubleshooting why Smart Scans (and direct path reads) do not get used
    • Measuring the efficiency of Smart Scans and how much work gets offloaded to the storage cells
    • Troubleshooting advanced Smart Scan performance problems, like passthrough mode and selective fallback to block IO – with Exadata Snapper
    • Using CELLCLI and cell-level metrics where database & session metrics aren’t enough
Day 2 – Parallel Execution, Hybrid Columnar Compression and OLTP

    • PX issues, including the In-Memory Parallel Execution feature
    • Optimizing hash joins for efficient bloom filtering in the cells
    • Troubleshooting Exadata Hybrid Columnar Compression issues
    • Troubleshooting long commit and disk write latency issues on Exadata
    • Troubleshooting flash caching issues and optimizing for tiered caching
    • Learn to use the Exadata scripts, tools and OS commands Tanel regularly uses for Exadata performance troubleshooting
    • Q&A and free-form demo session and/or reviewing Exadata performance case studies

If you like this – check out my Oracle training and seminars page, the first sessions happen already in May! (And there’s even one on-site in Enkitec office in Irving, TX).

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

Posted in Exadata, Oracle | Leave a comment

Troubleshooting high CPU usage with poor-man’s stack profiler – in a one-liner!

Here’s an example of a quick’n’dirty way of profiling stack traces on your command line. This is an example from Solaris (but the script should work on Linux too plus other Unixes with minor modifications).

I created a problem case below, based on a case I once troubleshooted at a client site. Note that they had set optimizer_mode = FIRST_ROWS in their database and the optimized came up with a very inefficient execution plan for the select from DBA_LOCK_INTERNAL view below:

SQL> ALTER SESSION SET optimizer_mode = FIRST_ROWS;

Session altered.

SQL> SET TIMING ON

SQL> SELECT * FROM dba_lock_internal;
...
... the output data stripped ...
...

927 rows selected.

Elapsed: 00:23:27.14

It took over 23 minutes to return 927 rows from DBA_LOCK_INTERNAL!

I ran Snapper to see where the time is spent then:

SQL> @snapper4 all 5 1 222
Sampling SID 222 with interval 5 seconds, taking 1 snapshots...

-- Session Snapper v4.00 BETA - by Tanel Poder ( http://blog.tanelpoder.com ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet! :)

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  WAITS/SEC,   AVERAGES
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    222, SYS       , STAT, non-idle wait count                                       ,             1,        .19,         ,             ,          ,           ,          ~ per execution
    222, SYS       , TIME, DB CPU                                                    ,       6028084,      1.17s,   117.2%, [@@@@@@@@@@],          ,           ,
    222, SYS       , TIME, sql execute elapsed time                                  ,       6032677,      1.17s,   117.3%, [##########],          ,           ,
    222, SYS       , TIME, DB time                                                   ,       6032677,      1.17s,   117.3%, [##########],          ,           ,          ~ unaccounted time
    222, SYS       , WAIT, library cache: mutex X                                    ,             6,     1.17us,      .0%, [          ],         1,        .19,        6us average wait

--  End of Stats snap 1, end=2013-02-14 21:30:45, seconds=5.1

---------------------------------------------------------------------------------------------
Active% | SQL_ID          | SQL_CHILD | EVENT                               | WAIT_CLASS
---------------------------------------------------------------------------------------------
   100% | c884zcqpv9y5h   | 0         | ON CPU                              | ON CPU

--  End of ASH snap 1, end=2013-02-14 21:30:45, seconds=5, samples_taken=50

The query is apparently 100% on CPU with no significant waits. Normally I would expect some other metrics to pop up in snapper output in such high-CPU cases, like thousands of session logical reads per second, sorts (rows) showing millions of rows sorted per second or parse count (hard) number in hundreds or thousands per second. These are the “usual suspects”.

But this time none of these additional metrics were incremented by the session. So it’s time to systematically drill down by other means.

Continue reading

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

Posted in Oracle | 12 Comments

Session Snapper v4 – The World’s Most Advanced Oracle Troubleshooting Script!

Snapper V4 Webinar

Snapper V4 is out!

The major new features include:

  1. RAC support – ability to query stats from remote instances
  2. Manual Before and After snapshot support – no need to use DBMS_LOCK sleeps anymore
  3. Show useful averages and ratios *in addition to* raw metrics for faster troubleshooting
  4. And more! :)

Snapper is still a free-to-use tool and it still does NOT require any object creation nor changes in your databases for use. Now even DBMS_LOCK access isn’t needed, although it’s still useful for convenience.

I have posted the hacking session video to here:

Oh, wait, there’s more! You’re going to love this, especially if you love reverse engineering code puzzles! ;-) 

New Kind of Snapper Logo

Update: If you’re too lazy to run the code below, here’s what the logo looks like :-)

snapper_logo

I have also done major updates to Snapper logo which you should check out. If you have ever looked into the Snapper source code you know the old logo looks like this:

--    +-----=====O=== Welcome to The Session Snapper! (Yes, you are looking at a cheap ASCII
--   /                                                 imitation of a fish and a fishing rod.
--   |                                                 Nevertheless the PL/SQL code below the
--   |                                                 fish itself should be helpful for quick
--   |                                                 catching of relevant Oracle performance
--   |                                                 information.
--   |                                                 So I wish you happy... um... snapping?
--   |                                                )
--   |                       ......
--   |                       iittii,,....
--   ¿                    iiffffjjjjtttt,,
--                ..;;ttffLLLLffLLLLLLffjjtt;;..
--            ..ttLLGGGGGGLLffLLLLLLLLLLLLLLffjjii,,                        ..ii,,
--            ffGGffLLLLLLjjttjjjjjjjjffLLLLLLLLLLjjii..                ..iijj;;....
--          ffGGLLiittjjttttttiittttttttttffLLLLLLGGffii..            ;;LLLLii;;;;..
--        ffEEGGffiittiittttttttttiiiiiiiittjjjjffLLGGLLii..      iiLLLLLLttiiii,,
--      ;;ffDDLLiiiitt,,ttttttttttttiiiiiiiijjjjjjffLLLLffttiiiiffLLGGLLjjtttt;;..
--    ..ttttjjiitt,,iiiiiittttttttjjjjttttttttjjjjttttjjttttjjjjffLLDDGGLLttii..
--    iittiitttt,   ;;iittttttttjjjjjjjjjjttjjjjjjffffffjjjjjjjjjjLLDDGGLLtt;;..
--    jjjjttttii:. ..iiiiffLLGGLLLLLLLLffffffLLLLLLLLLLLLLLLLffffffLLLLLLfftt,,
--    iittttii,,;;,,ttiiiiLLLLffffffjjffffLLLLLLLLffLLffjjttttttttttjjjjffjjii..
--    ,,iiiiiiiiiittttttiiiiiiiiiijjffffLLLLLLLLffLLffttttttii;;;;iiiitttttttt;;..
--    ..iittttttffffttttiiiiiiiiiittttffjjjjffffffffttiittii::    ....,,;;iittii;;
--      ..;;iittttttttttttttttiiiiiittttttttttjjjjjjtttttt;;              ..;;ii;;..
--          ..;;;;iittttttjjttiittttttttttttttjjttttttttii..                  ....
--                ....;;;;ttjjttttiiiiii;;;;;;iittttiiii..
--                      ..;;ttttii;;....      ..;;;;....
--                        ..iiii;;..
--                          ..;;,,
--                            ....
--

As the Snapper script allows you to easily take performance snapshots of Oracle sessions and fish for solutions to your performance problems from the ocean of possible root causes, it makes sense to use a fish in the logo somewhere. I have also added sea and a cruise boat (symbolizing longer vacations thanks to Snapper!) into the new Snapper script file and and have pasted it below.

Scroll down and check it out – I’m sure you see it’s special. Does it ring a bell – what should you do with this special kind of a logo now? Of course – copy&paste it into sqlplus and run the logo! ;-) Note that you should run this on Oracle 11.2 or later.

There are actually two different logos below. The first one (cruise boat) is a low-tech one, suitable for use with Windows CMD.EXE and GUI tools like SQL*Developer.

Low-tech version:

 
SET                                                                     LiNeSiZe 10000         PageSize 5000
SET                                                                                   TrimOut ON           Head Off
                                                                  /**/
                                                                SELECT
                                                               LISTAGG
                                                             (SUBSTR(s,
                                        MOD(r2-1,115)+1,1)) WITHIN GROUP(ORDER BY r) 
                                     FROM(SELECT rownum r,RPAD(RPAD(RPAD(RPAD(LPAD(LPAD
                               ('(',x,'('),20,' '),x+20,')'),40,' '),40+y,' '),50,'W')s FROM(
                                  SELECT CEIL(ABS(SIN(rownum/30)*13))x,CEIL(ABS(COS(rownum/9)*5))y
                                     FROM dual CONNECT BY LEVEL<=115)), (SELECT rownum r2 FROM (dual)
--~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                          CONNECT BY LEVEL <= 50) GROUP BY MOD(r2-1, 115)    +1;

Hi-tech version:

This version requires a modern xterm emulator like Putty (on Windows) or iTerm2 or Terminator on Mac OSX, if your current terminal ends up showing garbage. Go ahead, make your terminal window wide enough, paste and enjoy :-)

First change the sqlplus settings if you didn’t do so already:

SET LINESIZE 10000 TRIMOUT ON TRIMSPOOL OFF HEAD OFF PAGESIZE 5000

And now paste this in:

 
                                                      SELECT                      
                                                CHR(POWER(3,3))             
                                          ||'[38;5;0m'||LISTAGG(SUBSTR(
                                    REPLACE(REPLACE(REPLACE(REPLACE(REPLACE(s ,')',
                            CHR(POWER(3,3))||'[48;5;'||TRIM(TO_CHAR((POWER(2,4)+CEIL((SIN(r2/5)                                                 +
                    SIN(ROWNUM/150)+1)*3-1)+CEIL((-SIN(ROWNUM/150)+1)*3-1)*6+CEIL((COS(ROWNUM/150)+1)*3-1)                                 *6*6),
              '099'))||'m)'),'(',CHR(POWER(3,3))||'[48;5;'||TRIM(TO_CHAR((POWER(2,4)+CEIL((SIN(r2/5)+SIN(ROWNUM/150)                   +1)*3-1)+
       CEIL((-SIN(ROWNUM   /150)+1)*3-1)*6+CEIL((COS(ROWNUM/150)+1)*3-1)*6*6),'099'))||'m('),' ',CHR(POWER(3,3))||'[48;5;'||TRIM      (TO_CHAR(
(POWER(2,4)+CEIL(4)+CEIL(4)*6+CEIL(5-(r2/8))*6*6),'099'))||'m '),'.',CHR(POWER(3,3))||'[48;5;'||TRIM(TO_CHAR((POWER(2,4)+CEIL(5)+CEIL(4)*6+CEIL
       (3)*6*6),'099'))||'m~'),'W',CHR(POWER(3,3))||'[48;5;'||TRIM(TO_CHAR((POWER(2,4)+CEIL(4+ABS(SIN(r/25)))+CEIL(2-ABS(SIN          (r/5))*2)
           *6+CEIL(2-ABS(SIN(r/5))*2)*6*6),'099'))||'m '),(MOD(r2-1,115)+1)*12+1,12))WITHIN GROUP(ORDER BY r)||CHR(POWER                  (3,3))                        
                ||'[0m' v FROM(SELECT ROWNUM r, RPAD(RPAD(RPAD(RPAD(LPAD(LPAD('(',x,'('),20,' '), x+20,')'),40,' '),                        40+y,
                      '.'),50,'W')s FROM (SELECT CEIL(ABS(SIN(ROWNUM/30)*13))x,CEIL(ABS(COS(ROWNUM                                              *
                            1/DBMS_RANDOM.VALUE(7,7.5))*7))y FROM dual CONNECT BY LEVEL<=115)),
                                    (SELECT ROWNUM r2 FROM dual CONNECT BY LEVEL<=50)
                                               GROUP BY MOD(r2-1,115)+1;

 

So, how do you like the new Snapper logo? :)

Feel free to leave a comment – and if you like this, please share it – all the billions of people of the world deserve to know how cool sqlplus is! :-)

Also, check out my upcoming Advanced Oracle Troubleshooting and Advanced Oracle SQL Tuning seminars and see you all on Wednesday at Snapper V4 Launch Party ;-)

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

Posted in Cool stuff, Oracle | 46 Comments

Sqlplus is my second home: Part 7 – Downloading files via sqlplus :-)

Some years ago I wrote about how sqlplus allows you to run sqlplus scripts directly from HTTP and FTP locations instead of the local filesystem. By the way, I didn’t even notice – my blog is over 5 years old already! :)

I a recent email thread Marco Gralike just showed the simplest way I to open a HTTP URL and download + list its contents in a CLOB datatype. It’s the HTTPURITYPE and its getCLOB (and getBLOB) methods.

So, basically if you want to download and save a (text) file like a script without a browser for some reason – and assuming that your database server can make outgoing HTTP connections, you can use this trick:

SQL> SET LINES 1000 TRIMSPOOL ON TRIMOUT ON PAGESIZE 0 LONG 99999999 LONGCHUNKSIZE 99999999 FEEDBACK OFF HEAD OFF
SQL> SPOOL $HOME/snapper_download.sql
SQL> 
SQL> select httpuritype('http://blog.tanelpoder.com/files/scripts/snapper.sql').getCLOB() from dual;
--------------------------------------------------------------------------------
--
-- File name:   snapper.sql
-- Purpose:     An easy to use Oracle session-level performance measurement tool
--              which does NOT require any database changes nor creation of any
--              database objects!
--
--              This is very useful for ad-hoc performance diagnosis in environments
--              with restrictive change management processes, where creating

... lots of output snipped ...

SQL> SPOOL OFF

Now you have to open the spool file (snapper_download.sql) and remove any garbage (sqlplus commands) from the top of the spool file and there you go:

SQL> @snapper_download all 5 1 3
Sampling SID 3 with interval 5 seconds, taking 1 snapshots...

-- Session Snapper v3.62 by Tanel Poder ( http://blog.tanelpoder.com )

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  WAITS/SEC,   AVERAGES
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
      3, SYS       , STAT, opened cursors cumulative                                 ,            43,        8.6,         ,             ,          ,           ,
      3, SYS       , STAT, recursive calls                                           ,            44,        8.8,         ,             ,          ,           ,
      3, SYS       , STAT, recursive cpu usage                                       ,             9,        1.8,         ,             ,          ,           ,
      3, SYS       , STAT, CPU used by this session                                  ,             8,        1.6,         ,             ,          ,           ,
      3, SYS       , STAT, in call idle wait time                                    ,           412,       82.4,         ,             ,          ,           ,
      3, SYS       , STAT, session uga memory                                        ,         65512,      13.1k,         ,             ,          ,           ,
      3, SYS       , STAT, session pga memory                                        ,        327680,     65.54k,         ,             ,          ,           ,
      3, SYS       , STAT, calls to get snapshot scn: kcmgss                         ,            43,        8.6,         ,             ,          ,           ,
      3, SYS       , STAT, session cursor cache hits                                 ,            43,        8.6,         ,             ,          ,           ,
      3, SYS       , STAT, session cursor cache count                                ,             1,         .2,         ,             ,          ,           ,
      3, SYS       , STAT, workarea executions - optimal                             ,            48,        9.6,         ,             ,          ,           ,
      3, SYS       , STAT, execute count                                             ,            43,        8.6,         ,             ,          ,           ,
      3, SYS       , STAT, sorts (memory)                                            ,            45,          9,         ,             ,          ,           ,
      3, SYS       , STAT, sorts (rows)                                              ,          1867,      373.4,         ,             ,          ,           ,
      3, SYS       , TIME, PL/SQL execution elapsed time                             ,          5398,     1.08ms,      .1%, [          ],          ,           ,
      3, SYS       , TIME, DB CPU                                                    ,        435933,    87.19ms,     8.7%, [@         ],          ,           ,
      3, SYS       , TIME, sql execute elapsed time                                  ,        129913,    25.98ms,     2.6%, [#         ],          ,           ,
      3, SYS       , TIME, DB time                                                   ,        449166,    89.83ms,     9.0%, [#         ],          ,           ,
      3, SYS       , WAIT, PL/SQL lock timer                                         ,       4127427,   825.49ms,    82.5%, [WWWWWWWWW ],        41,        8.2,   100.67ms

--  End of Stats snap 1, end=2013-01-24 22:45:53, seconds=5

    

--  End of ASH snap 1, end=2013-01-24 22:45:53, seconds=5, samples_taken=41
 

Of course this technique is more for fun and is not reliable for binary files (unless you use something like UTL_ENCODE.BASE64_ENCODE or UUENCODE first). But still pretty fun :) I was happy to see that accessing a HTTP resource within the database has become so simple that it’s just a one-liner (as opposed to all the UTL_HTTP code lines needed for HTTP access).

Have fun (and thanks Marco for the tip :-)

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

Posted in Cool stuff, Oracle | 5 Comments

Japanese translation of some of my blog articles

Ryota Watabe has translated some of my articles into Japanese and intends to translate more in the future (thanks for that! :)

I have added a little “translations” section to the left sidebar of the blog (scroll down). Or just go to this link:

You might also want to follow Watabe-san on Twitter to get notified of any new Japanese translations that show up.

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

Posted in Oracle | Leave a comment

What the heck is the INTERNAL_FUNCTION in execution plan predicate section?

Sometimes you see something like this in an execution plan:

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS FULL| T    |     1 |    22 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------

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

   1 - filter("B"=INTERNAL_FUNCTION("A"))

There’s quite a little information available about what the INTERNAL_FUNCTION really is and why does it show up, thus this blog entry.

There’s actually no function called INTERNAL_FUNCTION in Oracle and this is (partially) confirmed also by querying the V$SQLFN_METADATA view:

SQL> @sqlfn %internal%

no rows selected

The common understanding, coming from Oracle documentation is that the INTERNAL_FUNCTION is some sort of a special function doing (implicit) datatype conversion. This is only partially true and not the whole truth – but let’s examine the datatype conversion first and proceed to the explanation and other examples later on.

Implicit datatype conversion

I’m creating a table which stores a date in VARCHAR2 datatype in column A and a date in DATE datatype in column B:

SQL> CREATE TABLE t(a VARCHAR2(20), b DATE);

Table created.

SQL> @desc t
           Name                            Null?    Type
           ------------------------------- -------- ----------------------------
    1      A                                        VARCHAR2(20)
    2      B                                        DATE

SQL> INSERT INTO t VALUES( TO_CHAR(sysdate), sysdate) ;

1 row created.

Now let’s run a simple select query and see its execution plan:

SQL> SELECT * FROM t WHERE a = b;

A                    B
-------------------- -----------------
20130116 17:41:49    20130116 17:41:49

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR);

--------------------------------------------------------------------------
| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------
|   0 | SELECT STATEMENT  |      |       |       |     2 (100)|          |
|*  1 |  TABLE ACCESS FULL| T    |     1 |    21 |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("B"=INTERNAL_FUNCTION("A"))

What happens here is that Oracle is forced to (implicitly) add a datatype conversion function around column A, to be able to physically compare two different datatypes. Internally Oracle is not running a comparison "WHERE a = b" anymore, but rather something like "WHERE TO_DATE(a) = b". This is one of the reasons why the INTERNAL_FUNCTION shows up – the code generating the human-readable execution plan from the actual “binary” execution plan is not able to convert the internal opcode to a corresponding human-readable function name, thus shows a default “INTERNAL_FUNCTION” string there instead.

This is Oracle 10g+ behavior, in 9i and before, Oracle just printed nothing as that function name, example output from 9i is below:

1 - filter(("DUAL"."DUMMY")=:TEST_VAR)

Do you see that there are seemingly unnecessary brackets around “DUAL”.”DUMMY” above? Why not just "DUAL.DUMMY"=:TEST_VAR, is this ("DUAL"."DUMMY"):=TEST_VAR usage some typo? It’s actually not a typo, before Oracle 10g you had to be careful to spot any such “unneccesary” brackets as they really indicated there was some function called, something like F(“DUAL”.”DUMMY”), only that the “F” was never printed. In Oracle 10g onwards, a generic “INTERNAL_FUNCTION” is printed instead of nothing in such cases – at least we know there’s some function applied to the column/variable. You need to look into the code (and possibly session-level NLS_ settings) to figure out what function it could logically be (like a function casting TIMESTAMP into a DATE when comparing these datatypes).

Un-unparseable Complex Expressions

Ok, the datatype conversion reason is already covered in Oracle docs and blogosphere. But there’s more.

Check out this example with an OR clause:

SQL> CREATE TABLE t AS SELECT * FROM dba_objects;

Table created.

SQL> SELECT COUNT(*) FROM t WHERE owner = 'SYS' OR owner = 'SYSTEM';

  COUNT(*)
----------
     32272

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR);

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |   293 (100)|          |
|   1 |  SORT AGGREGATE    |      |     1 |    17 |            |          |
|*  2 |   TABLE ACCESS FULL| T    | 36652 |   608K|   293   (1)| 00:00:04 |
---------------------------------------------------------------------------

   2 - filter(("OWNER"='SYS' OR "OWNER"='SYSTEM'))

All is fine so far – the DBMS_XPLAN.DISPLAY_CURSOR function, which reads the plans directly from library cache is able to explain the predicate correctly.

Now let’s make the predicate a little more complex, I will add another OR to this predicate, but it’s against a different column:

SQL> SELECT COUNT(*) FROM t WHERE owner = 'SYS' OR owner = 'SYSTEM' OR object_id = 123;
...
SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR);

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |   293 (100)|          |
|   1 |  SORT AGGREGATE    |      |     1 |    30 |            |          |
|*  2 |   TABLE ACCESS FULL| T    | 36652 |  1073K|   293   (1)| 00:00:04 |
---------------------------------------------------------------------------

   2 - filter((INTERNAL_FUNCTION("OWNER") OR "OBJECT_ID"=123))

Now, suddenly the two conditions on the OWNER table are gone and replaced by an INTERNAL_FUNCTION?

Let’s try an IN operator instead of the OR, but wait, we are checking for values in two different columns (so we can’t put them all into the same IN clause):

SQL> SELECT COUNT(*) FROM t WHERE owner IN ('SYS','SYSTEM','SCOTT') AND object_type = 'TABLE';

  COUNT(*)
----------
      1178

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR);

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |   293 (100)|          |
|   1 |  SORT AGGREGATE    |      |     1 |    28 |            |          |
|*  2 |   TABLE ACCESS FULL| T    |   374 | 10472 |   293   (1)| 00:00:04 |
---------------------------------------------------------------------------

   2 - filter((INTERNAL_FUNCTION("OWNER") AND "OBJECT_TYPE"='TABLE'))

Still no luck.
Let’s try a logically simpler operation, with just searching for 3 values in the same column:

SQL> SELECT COUNT(*) FROM t WHERE owner IN ('SYS','SYSTEM','SCOTT');

  COUNT(*)
----------
     32278

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY_CURSOR);

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |   293 (100)|          |
|   1 |  SORT AGGREGATE    |      |     1 |    17 |            |          |
|*  2 |   TABLE ACCESS FULL| T    | 31960 |   530K|   293   (1)| 00:00:04 |
---------------------------------------------------------------------------

   2 - filter(("OWNER"='SCOTT' OR "OWNER"='SYS' OR "OWNER"='SYSTEM'))

Works! Oracle has transformed (or at least shows it in the explanation) this IN predicate to a bunch of OR-ed conditions (against the same column).

You might already see what’s going on with the earlier examples – DBMS_XPLAN.DISPLAY_CURSOR is not able to explain “complex” composite predicates applied in a single execution plan step, which include multiple different columns AND at least one of the columns has multiple values to check for (like an in-list or OR-ed predicates).

Where does DISPLAY_CURSOR get its data from and an explanation

DBMS_XPLAN.DISPLAY_CURSOR gets its plan data from V$SQL_PLAN, the predicate section comes from ACCESS_PREDICATES and FILTER_PREDICATES columns. But when I query the V$SQL_PLAN directly, I still see the same problem:

SQL> SELECT id, filter_predicates FROM v$sql_plan WHERE sql_id = 'gcqgrmtna9g1u';

        ID FILTER_PREDICATES
---------- ------------------------------------------------------------
         0
         1
         2 (INTERNAL_FUNCTION("OWNER") AND "OBJECT_TYPE"='TABLE')

And you may have noticed that there are brackets() around the raw ORed conditions above too, which in 9i meant that there was an “unexplained” internal function in the “binary” execution plan around the reported predicates, but in this case (as 10g+ supports the internal_function naming), blank function names shouldn’t occur… Not really sure why there about this, but that’s too low level little detail for this post.

The V$SQL_PLAN view itself accesses the actual “binary” child cursor in library cache (after taking appropriate latches/pins/mutexes) and UNPARSES it. Why such term – well isn’t parsing something that takes a human readable input and translates it into computer-understandable “binary” format. Thus unparsing is the opposite – V$SQL_PLAN accesses the cursor’s “binary” execution plan memory structure and translates it to human-readable execution plan output. There’s even a parameter controlling this V$SQL_PLAN behavior, if it’s set to false, the ACCESS_PREDICATES and FILTER_PREDICATES columns will be empty there:

SQL> @pd unparse
Show all parameters and session values from x$ksppi/x$ksppcv...

NAME                             VALUE                                      DESCRIPTION
----------------------------- --------- -----------------------------------------------
_cursor_plan_unparse_enabled      TRUE          enables/disables using unparse to build
                                                                  projection/predicates

By the way, why do I keep saying “binary” execution plan and in double quotes? It’s because I want to emphasize that the real execution plan that Oracle executes is not in the text form like we see on the screen, the text is just generated for humans, for troubleshooting reasons. The execution plan is not a real executable binary (as in oracle.exe) either, it’s not directly fed to the CPUs for execution. The physical execution plan in the library cache child cursor is a bunch of opcodes, object_ids and pointers for defining the hierarchy and order of rowsource execution. It’s the SQL execution engine, which then loops through these opcodes, decodes them and knows what to do (which rowsource function to call) next.

So, as we’ve seen above, some predicates with complex AND/OR conditions chained together are displayed as INTERNAL_FUNCTION() by DBMS_XPLAN.DISPLAY_CURSOR and V$SQL_PLAN as they are unable to decode (unparse) the execution plan info fully.

Using the good old EXPLAIN PLAN

There’s some good news though! The good old EXPLAIN PLAN command can unparse (some of) these complex predicates properly! As the EXPLAIN PLAN operation parses the given SQL again, in a special, more instrumented way, it has more information at hand apparently (and it uses more memory too). Or it could just be that whoever wrote V$SQL_PLAN, didn’t write the piece of code for unparsing more complex predicates :)

Check this output, where I’m using the explain plan command instead of just running the SQL:

SQL> EXPLAIN PLAN FOR 
     SELECT COUNT(*) FROM t WHERE owner IN ('SYS','SYSTEM','SCOTT') AND object_type = 'TABLE';

Explained.

SQL> SELECT * FROM TABLE(DBMS_XPLAN.DISPLAY);

---------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |     1 |    28 |   293   (1)| 00:00:04 |
|   1 |  SORT AGGREGATE    |      |     1 |    28 |            |          |
|*  2 |   TABLE ACCESS FULL| T    |   374 | 10472 |   293   (1)| 00:00:04 |
---------------------------------------------------------------------------

   2 - filter(("OWNER"='SCOTT' OR "OWNER"='SYS' OR "OWNER"='SYSTEM')
              AND "OBJECT_TYPE"='TABLE')

It’s a miracle! The INTERNAL_FUNCTION is gone and all the predicate values are shown correctly. EXPLAIN PLAN command was very useful here.

So, while I usually don’t use the EXPLAIN PLAN command as explain plan can lie to you, then whenever I see an INTERNAL_FUNCTION in the DISPLAY_CURSOR/V$SQL_PLAN/SQL Monitor output, I run an explain plan command for the same query in hope of quickly finding out what the predicates in there really are.

Ok, it’s 2:30am here yet again – off to sleep! :)

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

Posted in Oracle | 8 Comments

A tip for lazy Oracle users – type less with ANSI DATE and TIMESTAMP SQL syntax

I am lazy, therefore if I can type less, I will type less.

Often people are surprised to see that Oracle supports the ANSI DATE and TIMESTAMP syntax in the SQL code, which allows me to shorten the lengthy TO_DATE( …. , ‘YYYY-MM-DD HH24:MI:SS’) syntax a bit. You can just type this if you want to compare some field to a date (day precision):

SQL> SELECT COUNT(*) FROM dba_objects WHERE created > DATE'2012-12-01';

  COUNT(*)
----------
         0

SQL> SELECT COUNT(*) FROM dba_objects WHERE created > DATE'2012-01-01';

  COUNT(*)
----------
       804

This way you can always use the standard date format regardless of any NLS settings that may say otherwise.

Note that in above example, the date 2012-01-01 means 2012-01-01 00:00:00 really, so any objects created on that date from 00:00:01 onwards would be included in the results. If you want timestamp precision, then you can use the TIMESTAMP keyword:

SQL> SELECT COUNT(*) FROM dba_objects WHERE created > TIMESTAMP'2012-01-01 08:12:34';

  COUNT(*)
----------
       805

SQL> SELECT COUNT(*) FROM dba_objects WHERE created > TIMESTAMP'2012-01-01 08:12:34.000000000';

  COUNT(*)
----------
       805

SQL> SELECT COUNT(*) FROM dba_objects WHERE created > TIMESTAMP'2012-01-01 08:12:34.000000000 -08:00';

  COUNT(*)
----------
       805

I think this syntax works since Oracle 9i as this is where ANSI-SQL syntax was introduced into Oracle.

You can use this syntax also in some other situations, like the FLASHBACK TO TIMESTAMP and SELECT … AS OF TIMESTAMP clauses of a statement:

SQL> SELECT COUNT(*) FROM t AS OF TIMESTAMP TIMESTAMP'2012-12-29 20:00:10 +03:00';

  COUNT(*)
----------
     25237

SQL> SELECT COUNT(*) FROM t AS OF TIMESTAMP TIMESTAMP'2012-12-29 20:01:00 +03:00';

  COUNT(*)
----------
         1

SQL> ALTER TABLE t ENABLE ROW MOVEMENT;

Table altered.

SQL> FLASHBACK TABLE t TO TIMESTAMP TIMESTAMP'2012-12-29 20:00:00 +03:00';

Flashback complete.

SQL> SELECT COUNT(*) FROM t;

  COUNT(*)
----------
     25237

Note the double “TIMESTAMP TIMESTAMP …” above. This is not a typo, the first TIMESTAMP tells you want to flash back by specifying a human timestamp as opposed to Oracle transactional timestamp in which case you would have used the “SCN” keyword. And the second TIMESTAMP is the ANSI timestamp specifier (you could use the good old TO_DATE() syntax there).

Enjoy saving time every time you type a SQL command with date&time logic in it (those of you who didn’t know about this feature, you can buy me beer when we meet).

Happy new year! :)

Update: Sayan Malakshinov has added an interesting piece of information into the comments section – that there’s also an undocumented TIME keyword available. Let’s do a quick test:


SQL> SELECT TIME'12:34:56.000000' a FROM dual;

A
---------------------------------------------------------------------------
12.34.56.000000000 PM

This returns only the time-of-day component apparently, but no day, month, year info.

Let’s try to create a table to see what datatype we’ll end up with then:

SQL> CREATE TABLE t AS SELECT TIME'12:34:56.000000' a FROM dual;
CREATE TABLE t AS SELECT TIME'12:34:56.000000' a FROM dual
*
ERROR at line 1:
ORA-00902: invalid datatype

Error!
Sayan mentioned an event 10407 in the comment, which allowed the table to be created. Let’s check the oraus.msg file and see what it’s about:

10407, 00000, "enable datetime TIME datatype creation"
// *Cause:
// *Action:  set this event to enable datetime datatype creation
// *Comment: This event is set when the user wants to create
//           a datetime datatype column.  The compatible=8.1.0.0.0 parameter
//           must also be set.

Let’s use this event:

SQL> ALTER SESSION SET EVENTS '10407 trace name context forever, level 1';

Session altered.

SQL> CREATE TABLE t AS SELECT TIME'12:34:56.000000' a FROM dual;

Table created.

Ok it’s possible now (but undocumented + unsupported too).

So after disabling the event and dropping the table I tried a few more variations with casting the TIME datatype to something else:

SQL> CREATE TABLE t AS SELECT CAST(TIME'12:34:56.000000' AS DATE) a FROM dual;
CREATE TABLE t AS SELECT CAST(TIME'12:34:56.000000' AS DATE) a FROM dual
                              *
ERROR at line 1:
ORA-00932: inconsistent datatypes: expected NUMBER got TIME

Ok, can’t convert it to DATE. Let’s try TIMESTAMP:

SQL> CREATE TABLE t AS SELECT CAST(TIME'12:34:56.000000' AS TIMESTAMP) a FROM dual;

Table created.

SQL> @desc t
           Name                            Null?    Type
           ------------------------------- -------- ----------------------------
    1      A                                        TIMESTAMP(6)


SQL> SELECT * FROM t;

A
---------------------------------------------------------------------------
29-DEC-12 12.34.56.000000 PM

Converting to TIMESTAMP worked – looks like the current DATE is chosen as the date component for the result.

Hmm, I wonder if we can somehow concatenate a date component and a time component together?


SQL> SELECT TRUNC(sysdate - 100) + TIME'15:00:00' FROM dual;
SELECT TRUNC(sysdate - 100) + TIME'15:00:00' FROM dual
                            *
ERROR at line 1:
ORA-30087: Adding two datetime values is not allowed

Well, apparently not.

Anyway, my flight departs in 40 minutes, so got to get moving. Thanks Sayan for the TIME addition – it’s good to learn new stuff (every day ;-)

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

Posted in Oracle, Productivity | 32 Comments

Snapper v3.61 released – and more work is in progress!

Here’s the latest version of my Oracle session level performance Snapper tool:

I’m going to add more stuff to Snapper in coming days, but thought to release something for testing already :)

  1. There are some cosmetic changes, like printing empty lines and header lines for better readability (still controllable by the pagesize parameter, look into the scripts).
  2. I’ve made some changes in the visual “graph” column just for easier readability when glancing at a snapper report:

    the @-character is used for CPU time (@ looks like a letter C a bit, doesn’t it :)
    the #-character is for all other Time model time
    thw W-character is for wait time 

  3. Snapper now displays the SQL child cursor number by default in the “ASH” breakdown section 
  4. The main new feature is the addition of event count columns from V$SESSION_EVENT, which allows me to calculate session-level wait event duration averages too. For example, next time you see the log file sync wait event taking lots of time, you can immediately check how much these individual waits take on average instead of having to derive it from other metrics like user commits and transaction rollbacks. In the example below I’ve identified one user session performing commits (SID 298) and also LGWRs session (492) and am snapping them at the same time.

 

Scroll right in the below section to see the wait time average columns (if you want narrower output, look into the script’s “configurable stuff” section to hide individual columns):

SQL> @snapper all 5 1 298,492

Sampling SID 298,492 with interval 5 seconds, taking 1 snapshots...

-- Session Snapper v3.61 by Tanel Poder ( http://blog.tanelpoder.com )

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  WAITS/SEC,   AVERAGES
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    298, SOE       , STAT, Requests to/from client                                   ,            36,        7.2,         ,             ,          ,           ,
    298, SOE       , STAT, opened cursors cumulative                                 ,           379,       75.8,         ,             ,          ,           ,
    298, SOE       , STAT, user commits                                              ,            54,       10.8,         ,             ,          ,           ,
    298, SOE       , STAT, user calls                                                ,            72,       14.4,         ,             ,          ,           ,
    298, SOE       , STAT, recursive calls                                           ,           433,       86.6,         ,             ,          ,           ,

... lots of output removed ...

    298, SOE       , STAT, execute count                                             ,           323,       64.6,         ,             ,          ,           ,
    298, SOE       , STAT, bytes sent via SQL*Net to client                          ,          2859,      571.8,         ,             ,          ,           ,
    298, SOE       , STAT, bytes received via SQL*Net from client                    ,          6972,      1.39k,         ,             ,          ,           ,
    298, SOE       , STAT, SQL*Net roundtrips to/from client                         ,            34,        6.8,         ,             ,          ,           ,
    298, SOE       , STAT, cell flash cache read hits                                ,            44,        8.8,         ,             ,          ,           ,
    298, SOE       , TIME, parse time elapsed                                        ,          1242,    248.4us,      .0%, [          ],          ,           ,
    298, SOE       , TIME, PL/SQL execution elapsed time                             ,         39365,     7.87ms,      .8%, [#         ],          ,           ,
    298, SOE       , TIME, DB CPU                                                    ,        137978,     27.6ms,     2.8%, [@         ],          ,           ,
    298, SOE       , TIME, sql execute elapsed time                                  ,        152021,     30.4ms,     3.0%, [#         ],          ,           ,
    298, SOE       , TIME, DB time                                                   ,        690485,    138.1ms,    13.8%, [##        ],          ,           ,
    298, SOE       , WAIT, latch: cache buffers chains                               ,            27,      5.4us,      .0%, [          ],         1,         .2,       27us
    298, SOE       , WAIT, log file sync                                             ,        530709,   106.14ms,    10.6%, [WW        ],        20,          4,    26.54ms
    298, SOE       , WAIT, SQL*Net message to client                                 ,            65,       13us,      .0%, [          ],        34,        6.8,     1.91us
    298, SOE       , WAIT, SQL*Net message from client                               ,        511002,    102.2ms,    10.2%, [W         ],        34,        6.8,    15.03ms
    298, SOE       , WAIT, PL/SQL lock timer                                         ,       3589765,   717.95ms,    71.8%, [WWWWWWWW  ],       227,       45.4,    15.81ms
    298, SOE       , WAIT, cell single block physical read                           ,         30350,     6.07ms,      .6%, [W         ],        47,        9.4,   645.74us
    298, SOE       , WAIT, events in waitclass Other                                 ,            50,       10us,      .0%, [          ],         1,         .2,       50us

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                                                 ,         DELTA, HDELTA/SEC,    %TIME, GRAPH       , NUM_WAITS,  WAITS/SEC,   AVERAGES
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    492, (LGWR)    , STAT, non-idle wait time                                        ,           328,       65.6,         ,             ,          ,           ,
    492, (LGWR)    , STAT, non-idle wait count                                       ,           350,         70,         ,             ,          ,           ,
    492, (LGWR)    , STAT, in call idle wait time                                    ,           148,       29.6,         ,             ,          ,           ,
    492, (LGWR)    , STAT, messages received                                         ,           343,       68.6,         ,             ,          ,           ,
    492, (LGWR)    , STAT, background timeouts                                       ,             1,         .2,         ,             ,          ,           ,
    492, (LGWR)    , STAT, physical write total IO requests                          ,           384,       76.8,         ,             ,          ,           ,
    492, (LGWR)    , STAT, physical write total bytes                                ,       1330688,    266.14k,         ,             ,          ,           ,
    492, (LGWR)    , STAT, cell physical IO interconnect bytes                       ,       2661376,    532.28k,         ,             ,          ,           ,
    492, (LGWR)    , STAT, redo wastage                                              ,        105336,     21.07k,         ,             ,          ,           ,
    492, (LGWR)    , STAT, redo writes                                               ,           344,       68.8,         ,             ,          ,           ,
    492, (LGWR)    , STAT, redo blocks written                                       ,          2604,      520.8,         ,             ,          ,           ,
    492, (LGWR)    , STAT, redo write time                                           ,           332,       66.4,         ,             ,          ,           ,
    492, (LGWR)    , STAT, redo blocks checksummed by FG (exclusive)                 ,           200,         40,         ,             ,          ,           ,
    492, (LGWR)    , TIME, background cpu time                                       ,        117983,     23.6ms,     2.4%, [#         ],          ,           ,
    492, (LGWR)    , TIME, background elapsed time                                   ,       4282180,   856.44ms,    85.6%, [######### ],          ,           ,
    492, (LGWR)    , WAIT, rdbms ipc message                                         ,       1673152,   334.63ms,    33.5%, [WWWW      ],       261,       52.2,     6.41ms
    492, (LGWR)    , WAIT, log file parallel write                                   ,       3068565,   613.71ms,    61.4%, [WWWWWWW   ],       367,       73.4,     8.36ms
    492, (LGWR)    , WAIT, events in waitclass Other                                 ,            55,       11us,      .0%, [          ],         4,         .8,    13.75us

--  End of Stats snap 1, end=2012-12-18 20:23:18, seconds=5

---------------------------------------------------------------------------------------------
Active% | SQL_ID          | SQL_CHILD | EVENT                               | WAIT_CLASS
---------------------------------------------------------------------------------------------
    71% |                 | 0         | log file parallel write             | System I/O
     7% |                 |           | log file sync                       | Commit
     5% | c13sma6rkr27c   | 0         | ON CPU                              | ON CPU
     2% | 0y1prvxqc2ra9   | 0         | ON CPU                              | ON CPU

--  End of ASH snap 1, end=2012-12-18 20:23:18, seconds=5, samples_taken=42

PL/SQL procedure successfully completed.

Having a quick way to check session level wait event average durations can speed up your troubleshooting – as it’s an important difference whether your session is responding slowly due to 1000 x 1 ms waits or 1 x 1000 ms wait.

Of course averages may hide some detail, but with Snapper these averages are not from system wide, but from session level sources and usually calculated over a snapshot of a few seconds, not minutes or hours.

As a next step, I plan to add more helpful averages (the usual things I currently manually calculate when needed) after the TIME model and some STAT metrics in Snapper output too. This should help to save a few seconds when troubleshooting that super-critical issue next time ;-)

So please test it out and tell me what you think!

 

(P.S. I have just updated my Oracle performance online seminars page with 2013 info!)

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

Posted in Uncategorized | 17 Comments

Select statement generating redo – and lost write detection

Gwen Shapira has written a nice summary of a problem case where the classic wait interface based troubleshooting method is not always enough for troubleshooting low-level issues.

The top SQL + top wait approach should usually be used as the starting point of troubleshooting a session, workload etc, but often the troubleshooting does not stop there. So, when the wait interface and related tools don’t explain the problem well enough, then you either start guessing from there or dig deeper into performance data. And Gwen used the V$SESSTAT metrics (using my Snapper tool) to understand why was a select statement generating redo this time (there are multiple reasons for that – and V$SESSTAT tells you why).

By the way, I’ve repeated this many times, here’s the data and the order of it what I normally use when I want to understand what’s going on in a session or workload:

  1. TOP Waits / TOP SQL
  2. V$SESSTAT counters
  3. Process stack samples

Sometimes looking into #1 is enough, often I need to look into #1 and #2 and rarely, but regularly I need to look into #3 too. But I always start from #1, then #2 and then, if needed, #3. I call this the “Advanced Oracle Troubleshooting” method ;-)

Read Gwen’s article here and another recent blog entry of mine about how V$SESSTAT helps you to measure, not guess.

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

Posted in Exadata, Oracle | Leave a comment

Sqlplus is my second home: Part 6 – Colorizing sqlplus and terminal output

Jagjeet Singh mentioned that he has built a V2 of his cool SQL Dashboard sqlplus-based monitoring script, which now also shows a nice colored ASH graph output. Yes, right inside sqlplus!

This reminded me that I demoed color output in sqlplus when I delivered the Hotsos Symposium training day a few years ago, when introducing the MOATS tool the first time. I never got to colorize it as I had hoped to though… as MOATS was more of a fun project I worked on with Adrian Billington just to prove that it is possible to build a monitoring tool purely based on SQL and PL/SQL with a TOP-like self-refreshing screen output.

Anyway, Jagjeet has done this cool work now, but if you want to colorize some of your own scripts, then on XTerm-capable terminal emulators its simply done with just outputting some escape codes before the text you want to color. Most (or even all) widely used XTerm clients support 8 colors for text and 8 for background – but some terminal emulators (like putty, iTerm, Terminator) even support 256 colors!

Here’s a simple example script I demoed at the Hotsos training day too:

Just run it in sqlplus and see what happens! Note that you have to use the sqlplus in an XTerm terminal emulator (maybe ANSI terminals would work too) – this won’t work in Windows Command prompt!

Anyway, have fun and keep those cool & colorful sqlplus scripts coming! :-)

 

Note that this year’s only Advanced Oracle Troubleshooting class takes place in the end of April/May 2014, so sign up now if you plan to attend this year!

Posted in Cool stuff, Oracle | 5 Comments