Vishal desai’s Oracle Blog

May 15, 2014

IO Waits, Average Wait Time and Histogram Heat maps using SQL Developer

Filed under: Tools, Troubleshooting — vishaldesai @ 11:00 pm

Jeff Smith pointed out David Mann’s blog in recent session on SQL Developer Reporting. Using David’s base code I have developed SQL developer heat map reports to visualize, troubleshoot and compare IO related waits.

 image

 

image

From above we can clearly visualize that on 11-MAY-2013 between 2:00 – 3:00 pm average wait time for log file parallel write event was 27.3 ms. The number of waits during same time slot was 10801 which is equivalent to 3 waits per second and that’s not significant. If intermittent slowness was reported by application team and if it was related to commit wait class, DBAs need to engage SA/SAN team to investigate this further.

Below are IO wait histogram reports for log file parallel write event on same database instance. For OLTP workload you want to see bright red boxes for log file parallel write between 1 and 16ms buckets for wait counts and average wait times. Such heat maps can also be used to do relative performance comparison by Day or Day/Hour.

image

 

image

 

Download (I will upload SQL developer report definition files early next week.)

Another example of vertical stacked bar chart.

IO Wait Histogram by Count – db file sequential read

image

 

IO Wait Histogram by Avg Wait Time(s) – db file sequential read

image

January 24, 2014

Build Bind Variables from v$sql_monitor binds_xml column

Filed under: SQL, Troubleshooting — vishaldesai @ 7:41 pm

One of my client had interesting SQL performance issue. Whenever client executes query from ab initio it takes forever and same SQL code from sqlplus runs in less than a minute. Both tools were producing different plan_hash_value. I looked at v$ses_optimizer_env to ensure there were no session level parameters set for ab initio session.

I wanted to run exact SQL from sqlplus, create sql plan baseline so that when SQL is submitted from AI it can use good plan. AI was generating SQL dynamically so I decided get exact SQL text, bind variables and values from v$sql_monitor. I defined bind variables, assigned values and ran SQL from sqlplus and created profile which was eventually used by AI. To automate constructing bind variables and SQL Text from v$sql_monitor, I wrote script called build_bind_sqlmontior.sql.

Script will prompt for Key, SID and SQL_ID. Enter value for at least on prompt and later on enter key value to construct bind variables and SQL Text as shown below:

SQL> @build_bind_sqlmonitor.sql
Please enter the value for Key if known       :
Please enter the value for Sid if known       : 986
Please enter the value for sql_id if known    :

             KEY STATUS              USERNAME   MODULE                      SID SQL_ID        FIRST_REFRESH_TIME   PROGRAM         SQL_TEXT
---------------- ------------------- ---------- -------------------- ---------- ------------- -------------------- --------------- --------------------
   6996503228544 DONE (ALL ROWS)     SYS        sqlplus.exe                 986 8wy5mjmh53vxf 01/24/14 10:41:56    sqlplus.exe     select /*+ monitor f
   8362302828663 DONE (ERROR)        SYS        sqlplus.exe                 986 4bkxr36kasm7s 01/24/14 10:40:51    sqlplus.exe     select /*+ monitor f
  16471201083509 DONE (ERROR)        SYS        sqlplus.exe                 986 azb329svj1ajd 01/24/14 10:39:36    sqlplus.exe     select /*+ monitor f
   7082402574450 DONE (ERROR)        SYS        sqlplus.exe                 986 3036w6mx13rq5 01/24/14 10:38:36    sqlplus.exe     select /*+ monitor f
   5845451993201 DONE (ERROR)        SYS        sqlplus.exe                 986 20fmy44010wvw 01/24/14 10:38:00    sqlplus.exe     select /*+ monitor f
  11643657842205 DONE (ALL ROWS)                                            986 bfjf698jtp6n1 01/24/14 03:10:14
   7421704990227 DONE                                                       986 2vn8ztuzaq3k4 01/24/14 03:10:11
  14856293379585 DONE (ALL ROWS)                                            986 53afdbcv9637w 01/24/14 03:10:10
.....
.....
Please enter Key from above       : 6996503228544

variable SYS_B_0 VARCHAR2(32);
variable SYS_B_1 VARCHAR2(32);
variable SYS_B_2 NUMBER;

exec :SYS_B_0 := '31-OCT-12 00.00.00';
exec :SYS_B_1 := 'DD-MON-YY HH24:MI:SS';
exec :SYS_B_2 := 30205578;

select /*+ monitor full(ism) */ *
from ism.table_name ism
where col1=to_date(:"SYS_B_0",:"SYS_B_1")
and   col2=:"SYS_B_2";

SQL> variable SYS_B_0 VARCHAR2(32);
SQL> variable SYS_B_1 VARCHAR2(32);
SQL> variable SYS_B_2 NUMBER;
SQL>
SQL> exec :SYS_B_0 := '31-OCT-12 00.00.00';

PL/SQL procedure successfully completed.

SQL> exec :SYS_B_1 := 'DD-MON-YY HH24:MI:SS';

PL/SQL procedure successfully completed.

SQL> exec :SYS_B_2 := 30205578;

PL/SQL procedure successfully completed.

SQL> select /*+ monitor full(ism) */ *
  2  from ism.table_name ism
  3  where col1=to_date(:"SYS_B_0",:"SYS_B_1")
  4  and   col2=:"SYS_B_2";

.....

1 row selected.

Download Script

If there is any data type conversion script may not produce reliable output.

January 22, 2014

Yet Another Case of multiple child cursors, BIND_MISMATCH and OPTIMIZER_MISMATCH

Filed under: Performance Tuning, Troubleshooting — vishaldesai @ 9:08 pm

One of my client had unpredictable response time for bunch of SQL statements. I did not have any sqlid or sql code to start with so I started by running Kerry’s unstable_plans.sql. As per awr_plan_stats.sql, 3799146274 was good hash and 2775678588 was bad hash.

Output from unstable_plans.sql

SQL_ID        SUM(EXECS)   MIN_ETIME   MAX_ETIME   NORM_STDDEV
------------- ---------- ----------- ----------- -------------
....
djtwm74rrch17       1709         .00       23.69    7,395.6254
..

@awr_plan_stats
Enter value for sql_id: djtwm74rrch17

SQL_ID        PLAN_HASH_VALUE        EXECS    AVG_ETIME AVG_PX_SERVERS AVG_CPU_TIME            AVG_LIO          AVG_PIO
------------- --------------- ------------ ------------ -------------- ------------ ------------------ ----------------
djtwm74rrch17      3799146274          462        1.042     .004329004         .000                7.0               .1
djtwm74rrch17      2775678588        1,250   29,602.465          .0016        2.161          157,655.3        157,725.4

SQL_TEXT for djtwm74rrch17

SELECT ...
FROM TAB1 PAL,
  TAB2 COMPANY
WHERE PAL.CPY_ID      = COMPANY.CPYID
AND ( PAL.LOAN_NUMBER = :"SYS_B_0" )
ORDER BY ...

We clearly had multiple child cursors for given hash and had two different hash values. Child 0 is the first child, Child 1 was created due to bind_mismatch, child 2 was created due to optimizer_mismatch marking child 0 as non shareable and child 3 was created due to optimizer and bind mismatch marking child 1 as non shareable..

SQL> select sql_id,plan_hash_value,child_number,is_shareable from gv$sql where sql_id='djtwm74rrch17' and inst_id=2;

SQL_ID        PLAN_HASH_VALUE CHILD_NUMBER I
------------- --------------- ------------ -
djtwm74rrch17      3799146274            0 N
djtwm74rrch17      2775678588            1 N
djtwm74rrch17      3799146274            2 Y
djtwm74rrch17      2775678588            3 Y

select * from GV$SQL_SHARED_CURSOR where sql_id='djtwm74rrch17'
and inst_id=2;

INST_ID    SQL_ID            ADDRESS                CHILD_ADDRESS    CHILD_NUMBER    OPTIMIZER_MISMATCH    BIND_MISMATCH
2        djtwm74rrch17    000000025C7B1F90    000000025C8296D0        0                        N                   N
2        djtwm74rrch17    000000025C7B1F90    000000025C6E2DF0        1                        N                   Y
2        djtwm74rrch17    000000025C7B1F90    000000025C6E4210        2                        Y                   N
2        djtwm74rrch17    000000025C7B1F90    000000025C7B90E0        3                        Y                   Y

Child cursors 2 and 3 were created due to optimizer_mismatch and parameter that caused optimizer_mismatch was _pga_max_size. But we never set or change _pga_max_size on our databases. But databases were configured with AMM. _pga_max_size is derived from pga_aggregate_target so whenever PGA was resized it was affecting _pga_max_size making existing cursors non shareable.

Based on output from gv$sql_optimizer_env
                    Child        Child        Child        Child
Parameter                0            1            2            3
_pga_max_size    229360 KB    229360 KB    239200 KB    239200 KB
SQL> show parameter memory%target

NAME                                 TYPE                             VALUE
------------------------------------ -------------------------------- ------------------------------
memory_max_target                    big integer                      8G
memory_target                        big integer                      8G

And the reason for bind mismatch was using different data types for literal values as shown below:

SQL> select sql_id,child_number,name,position,datatype,datatype_string,max_length,last_captured,value_string from GV$SQL_BIND_CAPTURE where inst_id=2 and sql_id='djtwm74rrch17'; 

SQL_ID        CHILD_NUMBER NAME                             POSITION   DATATYPE DATATYPE_STRING MAX_LENGTH LAST_CAPTURED     VALUE_STRI
------------- ------------ ------------------------------ ---------- ---------- --------------- ---------- ----------------- ----------
djtwm74rrch17            3 :SYS_B_0                                1          2 NUMBER                  22 01/22/14 08:14:14 477026652
djtwm74rrch17            2 :SYS_B_0                                1          1 VARCHAR2(32)            32 01/22/14 10:14:44 0476735873
djtwm74rrch17            1 :SYS_B_0                                1          2 NUMBER                  22 01/21/14 10:49:20 476783261
djtwm74rrch17            0 :SYS_B_0                                1          1 VARCHAR2(32)            32 01/21/14 15:45:13 0476636964 

Predicate section of plan shows to_number function used for hash 2775678588. Same information can be derived from v$sql_plan_statistics_all.

SQL_ID  djtwm74rrch17, child number 2
-------------------------------------
Plan hash value: 3799146274

-----------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name               | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                    |       |       |     6 (100)|          |
|   1 |  SORT ORDER BY                 |                    |     1 |   313 |     6  (17)| 00:00:01 |
|   2 |   NESTED LOOPS                 |                    |       |       |            |          |
|   3 |    NESTED LOOPS                |                    |     1 |   313 |     5   (0)| 00:00:01 |
|   4 |     TABLE ACCESS BY INDEX ROWID| TAB1               |     1 |   279 |     4   (0)| 00:00:01 |
|*  5 |      INDEX RANGE SCAN          | PKTAB1             |     1 |       |     3   (0)| 00:00:01 |
|*  6 |     INDEX UNIQUE SCAN          | TAB1_CPYID         |     1 |       |     0   (0)|          |
|   7 |    TABLE ACCESS BY INDEX ROWID | TAB2               |     1 |    34 |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------------

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

   5 - access("PAL"."LOAN_NUMBER"=:SYS_B_0)
   6 - access("PAL"."CPY_ID"="COMPANY"."CPYID")
   
   
SQL_ID  djtwm74rrch17, child number 3
-------------------------------------
Plan hash value: 2775678588

----------------------------------------------------------------------------------------------------
| Id  | Operation                     | Name               | Rows  | Bytes | Cost (%CPU)| Time     |
----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |                    |       |       | 44394 (100)|          |
|   1 |  SORT ORDER BY                |                    |     1 |   313 | 44394   (1)| 00:08:53 |
|   2 |   NESTED LOOPS                |                    |       |       |            |          |
|   3 |    NESTED LOOPS               |                    |     1 |   313 | 44393   (1)| 00:08:53 |
|*  4 |     TABLE ACCESS FULL         | TAB1               |     1 |   279 | 44392   (1)| 00:08:53 |
|*  5 |     INDEX UNIQUE SCAN         | TAB1_CPYID            |     1 |       |     0   (0)|          |
|   6 |    TABLE ACCESS BY INDEX ROWID| TAB2               |     1 |    34 |     1   (0)| 00:00:01 |
----------------------------------------------------------------------------------------------------


   4 - filter(TO_NUMBER("PAL"."LOAN_NUMBER")=:SYS_B_0)
   5 - access("PAL"."CPY_ID"="COMPANY"."CPYID")
   
   
SQL> l
  1   select distinct sql_id,PLAN_HASH_VALUE,id,PARENT_ID,ACCESS_PREDICATES,FILTER_PREDICATES FROM gv$sql_plan_statistics_all
  2   WHERE sql_id = 'djtwm74rrch17' and inst_id=2
  3   and (ACCESS_PREDICATES is not null or FILTER_PREDICATES is not null)
  4*  order by PLAN_HASH_VALUE
SQL> /

SQL_ID        PLAN_HASH_VALUE         ID  PARENT_ID ACCESS_PREDICATES                        FILTER_PREDICATES
------------- --------------- ---------- ---------- ---------------------------------------- ----------------------------------------
djtwm74rrch17      2775678588          5          3 "PAL"."CPY_ID"="COMPANY"."CPYID"
djtwm74rrch17      2775678588          4          3                                          TO_NUMBER("PAL"."LOAN_NUMBER")=:SYS_B_0
djtwm74rrch17      3799146274          6          3 "PAL"."CPY_ID"="COMPANY"."CPYID"
djtwm74rrch17      3799146274          5          4 "PAL"."LOAN_NUMBER"=:SYS_B_0

Unfortunately AWR does not store access_predicates and filter_predicates so if cursors have edged out it won’t be possible to troubleshoot such random behavior.

November 26, 2013

Compare IO outliers

Filed under: Performance Tuning, Tools, Troubleshooting — vishaldesai @ 9:47 pm

Oracle SQL Developer has nice reporting capability to plot charts. To compare IO outliers using db_hist_event_histogram between two periods, I have created couple of reports for quick comparison.

When you click on report, it will prompt you to select database and input event, period one start snap and end snap, period two start and end snap.

Compare IO wait count outliers by %

image

Compare IO wait count outliers by Value

image

Compare IO wait time outlier by %

image

IO latency for all snaps by Day

image

IO latency for last 24 hours

image

Download link for report definition file.

PS Current version of SQL developer supports only 5 different colors for pie charts so there is overlap of colors in first 3 charts.

October 7, 2013

SQL Developer Child Reports and Drill Down

Filed under: Tools, Troubleshooting — vishaldesai @ 10:36 pm

SQL Developer has some cool reporting capability. Using these features and some of my favorite scripts, I can now quickly troubleshoot Oracle Database related issue.

Example: For given database session, I can run Tanel’s asqlmon, look at historical SQL performance using Kerry’s AWR scripts, and drill down into IO latency with just point and click.

 

July 5, 2013

v$event_histogram – buckets of time in Nth/Snap interval

Filed under: Performance Tuning, Tools, Troubleshooting — vishaldesai @ 6:22 pm

v$event_histogram stores cumulative data since instance startup. To monitor real time events and under what latency bucket they fall under, I have written script called wait_histogram_wc_pct.sql. Script will display percentage of wait counts that falls into individual latency bucket.

Example: As shown below in last line, 25% of direct path read events waited for >32ms and <64ms (307 out of 1228  events).

SQL> @wait_histogram_wc_pct.sql 'direct path read' 10 10
---------------------------------------------------------------Percent Wait Count--------------------------------------------------------------------------|
Event               |Time                |<1    |<2    |<4    |<8    |<16   |<32   |<64   |<128  |<256  |<512  |<1024 |<2048 |<4096 |<8192 |Tot Wait Count |
-----------------------------------------------------------------------------------------------------------------------------------------------------------|
direct path read    |07/05/13 11:49:51   |     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              1|
direct path read    |07/05/13 11:50:01   |     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              1|
direct path read    |07/05/13 11:50:11   |     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              1|
direct path read    |07/05/13 11:50:21   |     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              1|
direct path read    |07/05/13 11:50:31   |     1|     2|     3|     7|    17|    38|    21|     7|     3|     0|     0|     0|     0|     0|           1212|
direct path read    |07/05/13 11:50:41   |     2|     2|     6|    11|    20|    33|    20|     5|     1|     0|     0|     0|     0|     0|           2696|
direct path read    |07/05/13 11:50:51   |     4|     3|     6|    11|    20|    29|    19|     7|     1|     0|     0|     0|     0|     0|           2492|
direct path read    |07/05/13 11:51:01   |     4|     3|     6|    11|    18|    24|    25|     9|     1|     0|     0|     0|     0|     0|           2164|
direct path read    |07/05/13 11:51:12   |     2|     2|     4|     9|    16|    23|    25|    16|     3|     0|     0|     0|     0|     0|           1588|
direct path read    |07/05/13 11:51:22   |     1|     2|     3|     7|    13|    19|    27|    21|     6|     0|     0|     0|     0|     0|           1228|

Total wait counts may not be 100% accurate if v$event_histogram gets updated between last and first sample.

To monitor historical events from AWR in similar fashion you can use awr_wait_hist_wc_pct.sql

SQL> @awr_wait_hist_wc_pct.sql
Please enter start_date(mm/dd/yy)    :07/05/13
Please enter end_date  (mm/dd/yy)    :07/05/13


     14757 05-JUL-13 09.00.57.689 AM
     14758 05-JUL-13 09.10.58.136 AM
     14759 05-JUL-13 09.20.58.580 AM
     14760 05-JUL-13 09.30.59.208 AM
     14761 05-JUL-13 09.40.59.867 AM
     14762 05-JUL-13 09.50.00.963 AM
     14763 05-JUL-13 10.00.02.200 AM
     14764 05-JUL-13 10.10.03.637 AM
     14765 05-JUL-13 10.20.04.821 AM
     14766 05-JUL-13 10.30.05.240 AM
     14767 05-JUL-13 10.40.05.723 AM
     14768 05-JUL-13 10.50.06.094 AM
     14769 05-JUL-13 11.00.06.516 AM
     14770 05-JUL-13 11.10.07.016 AM
     14771 05-JUL-13 11.20.07.402 AM
     14772 05-JUL-13 11.30.07.838 AM
     14773 05-JUL-13 11.40.08.306 AM
Enter value for start snap_id   :14757
Enter value for end snap_id     :14773
Enter wait event                :direct path read
Enter instance number for RAC   :1
---------------------------------------------------------------Percent Wait Count--------------------------------------------------------------------------|
Event               |Time                |<1    |<2    |<4    |<8    |<16   |<32   |<64   |<128  |<256  |<512  |<1024 |<2048 |<4096 |<8192 |Tot Wait Count |
-----------------------------------------------------------------------------------------------------------------------------------------------------------|
direct path read    |07/05/13 09:00      |     0|     0|    33|    33|    33|     0|     0|     0|     0|     0|     0|     0|     0|     0|              3|
direct path read    |07/05/13 09:10      |    50|     0|    50|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              2|
direct path read    |07/05/13 09:20      |     2|     3|     6|    11|    20|    36|    15|     5|     1|     0|     0|     0|     0|     0|           6002|
direct path read    |07/05/13 09:30      |     3|     3|     6|    10|    19|    33|    18|     6|     1|     0|     0|     0|     0|     0|         158867|
direct path read    |07/05/13 09:40      |     3|     3|     6|    11|    20|    30|    20|     7|     1|     0|     0|     0|     0|     0|          82122|
direct path read    |07/05/13 09:50      |     2|     3|     5|     9|    15|    22|    25|    15|     5|     0|     0|     0|     0|     0|          27698|
direct path read    |07/05/13 10:00      |     2|     2|     5|     9|    15|    24|    24|    15|     4|     0|     0|     0|     0|     0|          59854|
direct path read    |07/05/13 10:10      |     3|     3|     5|    10|    16|    24|    25|    14|     2|     0|     0|     0|     0|     0|          51421|
direct path read    |07/05/13 10:20      |     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              0|
direct path read    |07/05/13 10:30      |    20|    20|     0|    40|    20|     0|     0|     0|     0|     0|     0|     0|     0|     0|              5|
direct path read    |07/05/13 10:40      |     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              0|
direct path read    |07/05/13 10:50      |    60|     0|     0|     0|     0|    40|     0|     0|     0|     0|     0|     0|     0|     0|              5|
direct path read    |07/05/13 11:00      |    33|    33|     0|    33|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              3|
direct path read    |07/05/13 11:10      |     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              0|
direct path read    |07/05/13 11:20      |    50|     0|     0|    50|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              2|
direct path read    |07/05/13 11:30      |    50|     0|     0|    50|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              2|
direct path read    |07/05/13 11:40      |   100|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|     0|              1|

If you make any enhancements, find any bug with scripts or have any other better way to monitor this, please let me know.

Download Scripts

July 3, 2013

v$event_histogram

Filed under: Performance Tuning, Troubleshooting — vishaldesai @ 8:48 pm

Luca has written awesome script to visualize Oracle latency using Heat Maps. Many times Management appreciate numbers and percentages so my script will attempt to show those numbers since instance startup.

SQL> @wait_histogram direct%path%read

                                                                                % Wait Roll % Wait   % Wait Roll % Wait
EVENT                               WAIT_TIME_MILLI_RANGE          WAIT_COUNT    Count       Count     Time        Time LAST_UPDATE_TIME
----------------------------------- ------------------------------ ---------- -------- ----------- -------- ----------- ---------------------------------------------------
direct path read                    4096-8192                               1        0           0     0              0 02-JUL-13 03.15.05.925862 PM -05:00
direct path read                    2048-4096                              25        0           0     0              0 03-JUL-13 09.05.04.647574 AM -05:00
direct path read                    1024-2048                              54        0           0     0              0 03-JUL-13 12.40.05.158016 PM -05:00
direct path read                    512-1024                              798        0           0     1              1 03-JUL-13 01.27.50.565441 PM -05:00
direct path read                    256-512                              6775        0           0     5              6 03-JUL-13 02.35.25.224134 PM -05:00
direct path read                    128-256                             53429        3           3    18             24 03-JUL-13 02.35.30.723528 PM -05:00
direct path read                    64-128                             158033        9          12    26             50 03-JUL-13 02.35.31.271218 PM -05:00
direct path read                    32-64                              295652       17          29    25             75 03-JUL-13 02.35.31.168757 PM -05:00
direct path read                    16-32                              371819       21          50    15             90 03-JUL-13 03.17.51.706468 PM -05:00
direct path read                    8-16                               310634       18          68     6             96 03-JUL-13 03.17.36.320652 PM -05:00
direct path read                    4-8                                228440       13          81     2             98 03-JUL-13 03.17.36.327927 PM -05:00
direct path read                    2-4                                153154        9          90     1             99 03-JUL-13 03.17.06.015746 PM -05:00
direct path read                    1-2                                 89236        5          95     0             99 03-JUL-13 03.17.51.710201 PM -05:00
direct path read                    0-1                                 93204        5         100     0             99 03-JUL-13 03.35.50.715609 PM -05:00

Avg wait time ms
----------------
      32.7397445

Download

What’s wrong with the Database?

Filed under: Troubleshooting — vishaldesai @ 8:29 pm

My Development team started complaining that application startup hangs when it tries to connect to database. To verify general connectivity, I asked them to verify hostname, port and service name. I converted JDBC URL to TNS entry and verified database connectivity from SQLPLUS. While I was working on this development issue for about 15 minutes, I was asked following questions via different modes of communication:

What’s wrong with the database? What changed on database since last week? Were there any patches applied to database server? What are top wait events on database? How is the performance of oracle database? Is listener up and running? Can DBA’s restart database?

We have thousands of database running at my client site and I was overwhelmed by number and kind of questions that I was asked for this issue. My development team was not very happy as I ignored all questions except for listener question because I was able to connect using SQLPLUS from my client PC.

Verified following items:

- Can connect to database from my client laptop to database server using database host, port and service name via SQLPLUS.

- telnet dbhostname port from application server was working fine

- From database audit log, active session history and listener logs, I did not notice any session requested/established from application server.

- Application server startup just hangs. It does not throw any ORA- errors.

That tells me that issue is outside database server. I was told that SQLPLUS test is not valid as application is using JDBC thin driver. I think that was a valid concern but I ran SQLPLUS test to prove I can connect to database from other client.

I started searching Google to find sample java programs to test database connectivity using JDBC. While I was searching for sample program, development team reported that System Administrator found some issue with application server OS and they have to reboot application server.

I found following link which could be very handy to test database connectivity using oracle JDBC driver.

http://www.mkyong.com/jdbc/connect-to-oracle-db-via-jdbc-driver-java/comment-page-1/#comment-135707

Sample program: OracleJDBC.java

import java.sql.DriverManager;
import java.sql.Connection;
import java.sql.SQLException;
 
public class OracleJDBC {
    public static void main(String[] argv) {
        System.out.println("-------- Oracle JDBC Connection Testing ------");
        try {
            Class.forName("oracle.jdbc.driver.OracleDriver");
        } catch (ClassNotFoundException e) {
            System.out.println("Where is your Oracle JDBC Driver?");
            e.printStackTrace();
            return;
        }
        System.out.println("Oracle JDBC Driver Registered!");
        Connection connection = null;
        try {
            connection = DriverManager.getConnection("jdbc:oracle:thin:@xxx:port:servicename", "dbsnmp","monitor");
            connection = DriverManager.getConnection("jdbc:oracle:thin:@//xxx:port/SID", "dbsnmp","monitor");
        } catch (SQLException e) {
            System.out.println("Connection Failed! Check output console");
            e.printStackTrace();
            return;
        }
        if (connection != null) {
            System.out.println("You made it, take control your database now!");
        } else {
            System.out.println("Failed to make connection!");
        }
    }
}

Make sure JDK is installed on your client PC. Set CLASSPATH and PATH variables.

c:\oracle\product>javac OracleJDBC.java

c:\oracle\product>java -cp .;C:\oracle\product\11.2.0\client_1\jdbc\lib\ojdbc6.jar OracleJDBC
-------- Oracle JDBC Connection Testing ------
Oracle JDBC Driver Registered!
Database connectivity is fine, take control of your Application now!

In firefighting situation, DBA’s can quickly run sample program to test database connectivity from client PC or application server to prove nothing is wrong with the Database. :)

July 1, 2013

Refresh SQL output every N seconds

Filed under: Tools, Troubleshooting — vishaldesai @ 3:27 pm

In Linux there is watch command to repeat Unix Commands or Shell-Scripts every N seconds. To monitor output of SQL script at regular interval of time from sqlplus you can use refresh.sql.

Example 1: To monitor output of session_longops every 5 seconds you can run following command:

SQL> @refresh.sql session_longops 5 5

SID             % Complete Time Now        ELAPSED_SECONDS MESSAGE
--------------- ---------- --------------- --------------- ---------------------------------------------------------------
1227.1457,@1         99.99 130701 10:10:17               1 RMAN: aggregate input: backup 33: 7831 out of 7832 Blocks done

Example 2: To monitor output of Instance wait every 5 seconds you can run following command:

SQL> @refresh.sql swact 5 5

  INST_ID     SID STATE   EVENT                                          SEQ# SEC_IN_WAIT P1              P2            P3                 P1TRANSL
--------- ------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ --
        1    1179 WAITING PX Deq: Execute Reply                           320           3 sleeptime/senderid passes= 2          0
                                                                                          = 200

        1     961 WAITING Streams AQ: waiting for messages in the       23225           2 queue id= 12603    process#=          wait time= 5
                                                                                                             0x0000000C910276C0

        1    1227 WAITING control file sequential read                  45873           0 file#= 0           block#= 1          blocks= 1
        1      52 WAITING direct path read                               4197           0 file number= 156   first dba= 730752  block cnt= 128
        1      99 WAITING direct path read                               4225           0 file number= 156   first dba= 2571008 block cnt= 128
        1      25 WAITING direct path read                               3933           0 file number= 157   first dba= 1747200 block cnt= 128
        1     123 WAITING direct path read                               4167           0 file number= 158   first dba= 621824  block cnt= 128
        1      74 WAITING direct path read                               4180           0 file number= 158   first dba= 2348160 block cnt= 128
        1     146 WAITING direct path read                               4297           0 file number= 159   first dba= 2502658 block cnt= 126
        1     314 WORKING On CPU / runqueue                              4393           0
        1       1 WORKING On CPU / runqueue                              4123           0
        1     749 WORKING On CPU / runqueue                               582           0

Script:

--Usage: refresh.sql "sql script name" interval sample
set feed off
set head off
set echo off
set term off
set linesize 120
set verify off
spool refresh_1.sql
set feedback off
set feed off
set serveroutput on 
select cmd from (
select '@' || '&1'  as cmd from dual
union all
select 'exec dbms_lock.sleep(&2);' as cmd from dual
union all
select 'clear scr' as cmd from dual
) , (select rownum from dual connect by level <=&3) ;
spool off
set term on
set serveroutput on
set head on
clear scr
@refresh_1.sql

March 27, 2012

Oracle CHAR data type comparisons

Filed under: Oracle Database, SQL, Troubleshooting — vishaldesai @ 12:54 am

I received below test case from my pl/sql developer.

dev@oradb > drop table test_3;

Table dropped.

dev@oradb > create table test_3  (col1 char(2));

Table created.
 
dev@oradb > insert into test_3 values('  ');

1 row created.

dev@oradb > insert into test_3 values('~ ');

1 row created.

dev@oradb > insert into test_3 values('~');

1 row created.

dev@oradb > insert into test_3 values(' ~');

1 row created.

dev@oradb > commit;

Commit complete.

dev@oradb > select * from test_3;

CO
--

~
~
 ~


4 rows selected.

Developer wanted to find record with column value = ‘~’ and he used below query:

Test 1: --I would expect no records since it is a char field
dev@oradb > select * from test_3 where col1='~';

CO
--
~
~

2 rows selected.

Developer was expecting that above query will return 0 rows as col1 is defined as char(2) so ‘~’ will be stored as ‘~ ‘ and ‘~’ <> ‘~ ‘ but query returned 2 rows  instead of 0 rows.

As per Oracle documentation http://docs.oracle.com/cd/B28359_01/server.111/b28286/sql_elements002.htm:

With blank-padded semantics, if the two values have different lengths, then Oracle first adds blanks to the end of the shorter one so their lengths are equal. Oracle then compares the values character by character up to the first character that differs. Oracle uses blank-padded comparison semantics only when both values in the comparison are either expressions of datatype CHAR, NCHAR, text literals, or values returned by the USER function.

So now we know how CHAR data types with different lengths are compared how do we know what is the data type of ‘~’ on right side of equality operator? It’s char but lets prove it.

dba@oradb >  create table datatype_test as select '~' as db from dual;

Table created.

dba@oradb > desc  datatype_test
 Name                                            Null?    Type
 ----------------------------------------------- -------- --------------------------------
 DB                                                       CHAR(1)

dba@oradb > select col1,ora_hash(col1),ora_hash('~'),ora_hash('~ ') as "ora_hash('~ ')" from test_3;

CO ORA_HASH(COL1) ORA_HASH('~') ora_hash('~ ')
-- -------------- ------------- --------------
        190699439     216329699     4123278633
~      4123278633     216329699     4123278633
~      4123278633     216329699     4123278633
 ~      999748150     216329699     4123278633
 
4 rows selected.

From above its clear that data type of ‘~’ on right side of equality operator is CHAR and hence select query return 2 records (record 2 and record 3) instead of 0 rows. Visual comparison will look something like following:

Expected Comparison Actual Comparison
‘  ‘ ‘~’ ‘  ‘ ‘~ ‘
‘~ ‘ ‘~’ ‘~ ‘ ‘~ ‘
‘~ ’ ‘~’ ‘~ ‘ ‘~ ‘
‘ ~’ ‘~’ ‘ ~’ ‘~ ‘

Hash value returned by ora_hash function also matches as shown above.

Developer tried to use different work around which produced different results and I used same queries to prove why similar workarounds are producing different results.

Test 2: --above query works then why not this query? all im doing is replacing a ~ with nvl(trim('  '),'~')

dev@oradb > select * from test_3 where col1 =nvl(trim('  '),'~');

no rows selected

dba@oradb > select col1,ora_hash(col1),ora_hash(nvl(trim('  '),'~')) as "ora_hash(nvl(trim('  '),'~'))" from test_3;

CO ORA_HASH(COL1) ora_hash(nvl(trim('  '),'~'))
-- -------------- -----------------------------
        190699439                     216329699
~      4123278633                     216329699
~      4123278633                     216329699
 ~      999748150                     216329699

dba@oradb > create table datatype_test as select nvl(trim('  '),'~') as db from dual;

Table created.

dba@oradb > desc  datatype_test
 Name                                            Null?    Type
 ----------------------------------------------- -------- --------------------------------
 DB                                                       VARCHAR2(1)

Data type of nvl(trim(‘  ‘),’~’) is VARCHAR2 so Oracle will not pad blanks. Hash values returned are also different hence query returned 0 records.

Test 3: --works user defined function

dev@oradb > CREATE OR REPLACE FUNCTION test_fn (v_col1 VARCHAR2) RETURN VARCHAR2
  2  AS
  3   col1 CHAR(2);
  4  BEGIN
  5  col1:=  nvl(trim('  '),'~');
  6    RETURN col1;
  7  END;
  8  /

Function created.

dev@oradb > select * from test_3 where col1 =test_fn('  ');

CO
--
~
~

2 rows selected.

dba@oradb > create table datatype_test as select test_fn('  ') as dt from dual;

Table created.

dba@oradb > desc  datatype_test
 Name                                            Null?    Type
 ----------------------------------------------- -------- --------------------------------
 DT                                                       VARCHAR2(4000)

dba@oradb >  select length(dt) from datatype_test;

LENGTH(DT)
----------
         2

dba@oradb > select dt from  datatype_test;

DT
---------------------------------------------------------------
~

dba@oradb > select col1,ora_hash(col1),ora_hash(test_fn('  ')) as "ora_hash(test_fn('  '))" from test_3;

CO ORA_HASH(COL1) ora_hash(test_fn('  '))
-- -------------- -----------------------
        190699439               216329699
~      4123278633              4123278633
~      4123278633              4123278633
 ~      999748150               216329699

Data type of return variable is VARCHAR but col1 is defined as CHAR in function hence during assignment col1 will store ‘~’ as ‘~ ‘ (return value) which can also be confirmed by length function. Hash values returned for record 2 and record 3 match hence query returns 2 records.

Test 4: case also works

dev@oradb > select * from test_3 where col1 = case when trim('  ') is null then '~'   else '1' end;

CO
--
~
~

2 rows selected.

dba@oradb > select col1,ora_hash(col1),ora_hash(case when trim('  ') is null then '~'   else '1' end) as "ora_hash_on_case" from test_3;

CO ORA_HASH(COL1) ora_hash_on_case
-- -------------- ----------------
        190699439        216329699
~      4123278633        216329699
~      4123278633        216329699
 ~      999748150        216329699

 
dba@oradb > create table datatype_test as select case when trim('  ') is null then '~'   else '1' end as dt from dual;

Table created.


dba@oradb > desc  datatype_test
 Name                                            Null?    Type
 ----------------------------------------------- -------- --------------------------------
 DT                                                       CHAR(1)

Hash value doesn’t match but as the data type of return variable of CASE is CHAR oracle will pad blank and hence return 2 records.

Developer finally asked is there any way to select only record 3 using where condition? Once the data is inserted I don’t think there is way to differentiate between record 2 (‘~ ‘) and record 3 (‘~’).

Below is the data block dump of record 2 and record 3:

tab 0, row 1, @0x3f8c
tl: 6 fb: --H-FL-- lb: 0x1  cc: 1
col  0: [ 2]  7e 20
tab 0, row 2, @0x3f86
tl: 6 fb: --H-FL-- lb: 0x1  cc: 1
col  0: [ 2]  7e 20


.

The Silver is the New Black Theme. Blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.