Vishal desai’s Oracle Blog

May 11, 2015

Filter predicates after MIN aggregation

Filed under: Performance Tuning, SQL — vishaldesai @ 8:41 pm

One of OLTP SQL on Exadata was consuming lot of CPU and was running for about 8 seconds per execution. Most of CPU activity was towards bottom half of the SQL as shown in real time SQL monitoring report below.

 

image 

image

To demonstrate this I will created simple test case using following code. PCTFREE, c3 and 90000 rows for multiple iterations are used to create large table:

SQL> drop table tab purge;
drop table tab purge
           *
ERROR at line 1:
ORA-00942: table or view does not exist


SQL> create table tab (c1 number, c2 date, c3 char(2000)) pctfree 50;

Table created.

SQL> insert into tab select rownum, sysdate-rownum, 'X' from dual connect by level <=90000;

90000 rows created.

SQL> insert into tab select rownum, sysdate-rownum-3, 'X' from dual connect by level <=90000;

90000 rows created.

SQL> insert into tab select rownum, sysdate-rownum-2, 'X' from dual connect by level <=90000;

90000 rows created.

SQL> insert into tab select rownum, sysdate-rownum-1, 'X' from dual connect by level <=90000;

90000 rows created.

SQL> insert into tab select rownum, sysdate-rownum+2, 'X' from dual connect by level <=90000;

90000 rows created.

SQL> insert into tab select rownum, sysdate-rownum+2, 'X' from dual connect by level <=90000;

90000 rows created.

SQL> commit;

Commit complete.

SQL> create index i_c1 on tab(c1);

Index created.

SQL> create index i_c2 on tab(c2);

Index created.

SQL> exec dbms_stats.gather_table_stats(USER,'TAB',cascade=>true,estimate_percent=>100);

PL/SQL procedure successfully completed.

Original SQL was calculating MIN of date column grouped by column c1 and then was applying filter against MIN column for narrow date range. So majority of rows were filtered out after full table scan and aggregation. As you can see it was doing 540k buffer gets to return 5 records. As this database is on Exadata, it does 540K physical reads very fast due to smart scan but in original SQL 43% of CPU activity was against full table scan operation.

 

SQL> alter session set statistics_level=all;
SQL>
SQL> select c1, c2 from
  2  (select c1,min(c2) c2
  3  from tab
  4  group by c1)
  5  where c2>=sysdate-15 and c2<=sysdate-10
  6  order by 1,2;

        C1 C2
---------- ---------
         7 01-MAY-15
         8 30-APR-15
         9 29-APR-15
        10 28-APR-15
        11 27-APR-15
SQL>
SQL> select * from table(dbms_xplan.display_cursor(format=>'allstats last'));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  58qhpx48c18v9, child number 0
-------------------------------------
select c1, c2 from (select c1,min(c2) c2 from tab group by c1) where
c2>=sysdate-15 and c2<=sysdate-10 order by 1,2

Plan hash value: 443431404

-----------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |      |      1 |        |      5 |00:00:00.69 |     540K|    540K|       |       |          |
|   1 |  SORT ORDER BY               |      |      1 |   4500 |      5 |00:00:00.69 |     540K|    540K|  2048 |  2048 | 2048  (0)|
|*  2 |   FILTER                     |      |      1 |        |      5 |00:00:00.69 |     540K|    540K|       |       |          |
|   3 |    HASH GROUP BY             |      |      1 |   4500 |  90000 |00:00:00.68 |     540K|    540K|    31M|  8462K| 5717K (0)|
|   4 |     TABLE ACCESS STORAGE FULL| TAB  |      1 |    540K|    540K|00:00:00.47 |     540K|    540K|  1025K|  1025K| 7199K (0)|
-----------------------------------------------------------------------------------------------------------------------------------

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

   2 - filter((MIN("C2")>=SYSDATE@!-15 AND MIN("C2")<=SYSDATE@!-10))

 

Column C1 was not unique so we cannot just apply filter prior to MIN. As you can see from below that consistent gets have gone down significantly due to index range scan but SQL is not returning same output. If filter predicate is applied first its returning records that we need and records that we don’t (false positives).

SQL> select c1,min(c2)
  2  from tab
  3  where c2>=sysdate-15 and c2<=sysdate-10
  4  group by c1
  5  order by 1,2;

        C1 MIN(C2)
---------- -----------------
         7 05/01/15 18:42:40
         8 04/30/15 18:42:40
         9 04/29/15 18:42:40
        10 04/28/15 18:42:40
        11 04/27/15 18:42:40
        12 04/27/15 18:43:15
        13 04/27/15 18:43:50
        14 04/27/15 18:42:04
        15 04/28/15 18:44:25
        16 04/27/15 18:44:25
SQL> select * from table(dbms_xplan.display_cursor(format=>'allstats l

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------
SQL_ID  7fwwz4v1a9fx4, child number 0
-------------------------------------
select c1,min(c2) from tab where c2>=sysdate-15 and c2<=sysdate-10
group by c1 order by 1,2

Plan hash value: 1451778582

-------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |      |      1 |        |     10 |00:00:00.01 |      33 |
|   1 |  SORT ORDER BY                 |      |      1 |     32 |     10 |00:00:00.01 |      33 |
|   2 |   HASH GROUP BY                |      |      1 |     32 |     10 |00:00:00.01 |      33 |
|*  3 |    FILTER                      |      |      1 |        |     30 |00:00:00.01 |      33 |
|   4 |     TABLE ACCESS BY INDEX ROWID| TAB  |      1 |     32 |     30 |00:00:00.01 |      33 |
|*  5 |      INDEX RANGE SCAN          | I_C2 |      1 |     32 |     30 |00:00:00.01 |       3 |
-------------------------------------------------------------------------------------------------

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

   3 - filter(SYSDATE@!-10>=SYSDATE@!-15)
   5 - access("C2">=SYSDATE@!-15 AND "C2"<=SYSDATE@!-10)

For such construct of SQL, we can still apply filter predicates first and remove records that should not be returned (false positives) using sub query as shown below. As you can see from below the consistent gets have gone down, indexes are being used, response time has improved, CPU activity has also gone down and we are getting same output.

 

SQL> select  t1.c1, t1.c2 from
  2  (select c1,min(c2) c2
  3  from tab
  4  where c2>=sysdate-15 and c2<=sysdate-10
  5  group by c1) t1
  6  where not exists (select c1 from tab t2 where t1.c1 = t2.c1 and t1.c2 > t2.c2 and t2.c2<=sysdate-10)
  7  order by 1,2;

        C1 C2
---------- -----------------
         7 05/01/15 18:42:40
         8 04/30/15 18:42:40
         9 04/29/15 18:42:40
        10 04/28/15 18:42:40
        11 04/27/15 18:42:40
SQL>
SQL> select * from table(dbms_xplan.display_cursor(format=>'allstats last'));

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------------------------------------------
SQL_ID  g0agfd3mm02qk, child number 0
-------------------------------------
select  t1.c1, t1.c2 from (select c1,min(c2) c2 from tab where
c2>=sysdate-15 and c2<=sysdate-10 group by c1) t1 where not exists
(select c1 from tab t2 where t1.c1 = t2.c1 and t1.c2 > t2.c2 and
t2.c2<=sysdate-10) order by 1,2

Plan hash value: 327191261

-------------------------------------------------------------------------------------------------------------------
| Id  | Operation                        | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem |
-------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                 |      |      1 |        |      5 |00:00:00.01 |      84 |    	  |       |
|   1 |  SORT ORDER BY                   |      |      1 |     30 |      5 |00:00:00.01 |      84 |  2048 |  2048 |
|   2 |   NESTED LOOPS ANTI              |      |      1 |     30 |      5 |00:00:00.01 |      84 |       |       |
|   3 |    VIEW                          |      |      1 |     32 |     10 |00:00:00.01 |      33 |       |       |
|   4 |     HASH GROUP BY                |      |      1 |     32 |     10 |00:00:00.01 |      33 |  3331K|  3331K|
|*  5 |      FILTER                      |      |      1 |        |     30 |00:00:00.01 |      33 |       |       |
|   6 |       TABLE ACCESS BY INDEX ROWID| TAB  |      1 |     32 |     30 |00:00:00.01 |      33 |       |       |
|*  7 |        INDEX RANGE SCAN          | I_C2 |      1 |     32 |     30 |00:00:00.01 |       3 |  1025K|  1025K|
|*  8 |    TABLE ACCESS BY INDEX ROWID   | TAB  |     10 |  26996 |      5 |00:00:00.01 |      51 |       |       |
|*  9 |     INDEX RANGE SCAN             | I_C1 |     10 |      6 |     38 |00:00:00.01 |      13 |  1025K|  1025K|
-------------------------------------------------------------------------------------------------------------------

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

   5 - filter(SYSDATE@!-10>=SYSDATE@!-15)
   7 - access("C2">=SYSDATE@!-15 AND "C2"<=SYSDATE@!-10)
   8 - filter(("T2"."C2"<=SYSDATE@!-10 AND "T1"."C2">"T2"."C2"))
   9 - access("T1"."C1"="T2"."C1")

April 24, 2015

Wait Chain analysis using Tanel’s awesome ash_wait_chains script

Filed under: Oracle Database, Troubleshooting — Tags: — vishaldesai @ 7:14 pm

Our database performance engineering team was trying to troubleshoot high wait time on enq:SQ – contention and was working with Oracle support. Snippet from Active Sessions and AWR report is shown below:

 

image

image

image

I thought it could be classic case of Sequence concurrency in RAC environment. I started looking as dba_hist_active_sess_history and found all the sessions were waiting on same sequence object id (p2=362). Object id 362 belongs to sequence AUDSES$ which is used by AUD$ and sequence cache size was already set to 10000. In previous releases there were couple of bugs where sequence cache for AUDSES$ was not high enough and workaround was to fix cache size but this particular database is on 11.2.0.4 and cache size is also 10000 so there was no reason to believe we were hitting those bugs.

image

I manually started mining ASH for sample session that led me all the way from one instance to another instance’s lgwr session.

image

image

image

image

So for given session 1286 and few others wait chain was as follows:

image

Then I realized, instead of doing this manually, I could use Tanel’s ash_wait_chains.sql to see the overall impact. As you can see from top of the output that more than 70% of impact was along the same line.

 

@dash_wait_chains username||':'||event  1=1 1596 1596

%This     SECONDS WAIT_CHAIN
------ ---------- ----------------------------------------------------------------------------------------------------------------------------------------------------
  70%   105023520 -> SYS:enq: SQ - contention -> SYS:row cache lock -> SYS:log file switch (archiving needed) -> SYS:control file sequential read
   9%    13698720 -> SYS:enq: SQ - contention -> SYS:row cache lock -> SYS:log file switch (archiving needed) -> SYS:Disk file Mirror Read
   6%     9803520 -> SYS:enq: SQ - contention -> SYS:log file switch (archiving needed) -> SYS:control file sequential read
   6%     9132480 -> SYS:enq: SQ - contention -> SYS:row cache lock -> SYS:log file switch (archiving needed) -> SYS:
   3%     4566240 -> SYS:enq: SQ - contention -> SYS:row cache lock -> SYS:log file switch (archiving needed) -> SYS:enq: CF - contention
   1%     1887840 -> SYS:buffer busy waits -> SYS:log file switch (archiving needed) -> SYS:control file sequential read
   1%     1278720 -> SYS:enq: SQ - contention -> SYS:log file switch (archiving needed) -> SYS:Disk file Mirror Read
   1%     1159430 -> DBFS_dbname01:buffer busy waits -> DBFS_dbname01:log file switch (archiving needed) -> SYS:control file sequential read
   1%      852480 -> SYS:enq: SQ - contention -> SYS:log file switch (archiving needed) -> SYS:
   0%      695520 -> DBSNMP:buffer busy waits -> ETL_USER:log file switch (archiving needed) -> SYS:control file sequential read
   0%      695520 -> SYS:row cache lock -> SYS:log file switch (archiving needed) -> SYS:control file sequential read
   0%      426240 -> SYS:enq: SQ - contention -> SYS:log file switch (archiving needed) -> SYS:enq: CF - contention
   0%      246240 -> SYS:buffer busy waits -> SYS:log file switch (archiving needed) -> SYS:Disk file Mirror Read
   0%      195500 -> SYS:log file switch (archiving needed) -> SYS:control file sequential read
   0%      182160 -> ETL_USER:log file switch (archiving needed) -> SYS:control file sequential read
   0%      164160 -> SYS:buffer busy waits -> SYS:log file switch (archiving needed) -> SYS:
   0%      151230 -> DBFS_dbname01:buffer busy waits -> DBFS_dbname01:log file switch (archiving needed) -> SYS:Disk file Mirror Read
   0%      100820 -> DBFS_dbname01:buffer busy waits -> DBFS_dbname01:log file switch (archiving needed) -> SYS:
   0%       90720 -> SYS:row cache lock -> SYS:log file switch (archiving needed) -> SYS:Disk file Mirror Read
   0%       90720 -> DBSNMP:buffer busy waits -> ETL_USER:log file switch (archiving needed) -> SYS:Disk file Mirror Read
   0%       82080 -> SYS:buffer busy waits -> SYS:log file switch (archiving needed) -> SYS:enq: CF - contention
   0%       60480 -> SYS:row cache lock -> SYS:log file switch (archiving needed) -> SYS:
   0%       60480 -> DBSNMP:buffer busy waits -> ETL_USER:log file switch (archiving needed) -> SYS:
   0%       50410 -> DBFS_dbname01:buffer busy waits -> DBFS_dbname01:log file switch (archiving needed) -> SYS:enq: CF - contention
   0%       32660 -> DBFS_dbname01:log file switch (archiving needed) -> SYS:control file sequential read
   0%       30240 -> SYS:row cache lock -> SYS:log file switch (archiving needed) -> SYS:enq: CF - contention
   0%       30240 -> DBSNMP:buffer busy waits -> ETL_USER:log file switch (archiving needed) -> SYS:enq: CF - contention
   0%       25500 -> SYS:log file switch (archiving needed) -> SYS:Disk file Mirror Read
   0%       23760 -> ETL_USER:log file switch (archiving needed) -> SYS:Disk file Mirror Read
   0%       17000 -> SYS:log file switch (archiving needed) -> SYS:
   0%       15840 -> ETL_USER:log file switch (archiving needed) -> SYS:
   0%       13590 -> SYS:enq: SQ - contention -> ETL_USER:
   0%        8500 -> SYS:log file switch (archiving needed) -> SYS:enq: CF - contention
   0%        7920 -> ETL_USER:log file switch (archiving needed) -> SYS:enq: CF - contention
   0%        5520 -> DBSNMP:log file switch (archiving needed) -> SYS:control file sequential read
   0%        4260 -> DBFS_dbname01:log file switch (archiving needed) -> SYS:Disk file Mirror Read
   0%        3600 -> ETL_USER:
   0%        3020 -> SYS:enq: SQ - contention -> ETL_USER:cell single block physical read
   0%        2840 -> DBFS_dbname01:log file switch (archiving needed) -> SYS:
   0%        1420 -> DBFS_dbname01:log file switch (archiving needed) -> SYS:enq: CF - contention
   0%         970 -> SYS:
   0%         870 -> GGADMIN:SQL*Net more data from client
   0%         720 -> DBSNMP:log file switch (archiving needed) -> SYS:Disk file Mirror Read
   0%         600 -> ETL_USER:cell single block physical read
   0%         480 -> DBSNMP:log file switch (archiving needed) -> SYS:
   0%         240 -> DBSNMP:log file switch (archiving needed) -> SYS:enq: CF - contention
   0%         230 -> SYS:control file sequential read
   0%         160 -> SYS:gc current request
   0%          90 -> SYS:flashback log file write
   0%          90 -> SYS:db file parallel write
   0%          80 -> ETL_USER:log file sync -> SYS:
   0%          80 -> ETL_USER:log file sync -> SYS:log file parallel write
   0%          80 -> GGADMIN:cell single block physical read
   0%          80 -> GGADMIN:
   0%          70 -> SYS:reliable message
   0%          70 -> SYS:log file sequential read
   0%          70 -> SYS:JS kgl get object wait
   0%          60 -> ETL_USER:resmgr:cpu quantum
   0%          40 -> SYS:log file parallel write
   0%          40 -> ETL_USER:cell multiblock physical read
   0%          30 -> SYS:ges lms sync during dynamic remastering and reconfig -> SYS:
   0%          30 -> GGADMIN:gcs drm freeze in enter server mode -> SYS:ges lms sync during dynamic remastering and reconfig -> SYS:
   0%          30 -> SYS:Disk file Mirror Read
   0%          20 -> SYS:enq: CF - contention
   0%          20 -> GGADMIN:Streams miscellaneous event
   0%          10 -> ETL_USER:direct path write temp
   0%          10 -> ETL_USER:gc cr grant 2-way
   0%          10 -> DBSNMP:log file sync -> SYS:log file parallel write
   0%          10 -> SYS:change tracking file synchronous read
   0%          10 -> U002585:
   0%          10 -> ETL_USER:direct path read temp
   0%          10 -> SYS:library cache lock
   0%          10 -> DBFS_dbname01:
   0%          10 -> ETL_USER:enq: FB - contention
   0%          10 -> ETL_USER:gc current block 3-way
   0%          10 -> ETL_USER:gc current block 2-way
   0%          10 -> SYS:ASM file metadata operation
   0%          10 -> DBFS_dbname01:direct path write
   0%          10 -> DBSNMP:log file sync -> SYS:

79 rows selected.

Further from below output its also clear that the ultimate blocker was session id 1262 on instance 2 (LGWR process). Line id with 3% impact matches my manual analysis.

 

dash_wait_chains instance_number||':'||session_id  1=1 1596 1596

%This     SECONDS WAIT_CHAIN
------ ---------- -----------------------------------------------------
  24%    35955360 -> 1:3164 -> 1:654 -> 2:2540 -> 2:1262
  21%    32447520 -> 1:2533 -> 1:654 -> 2:2540 -> 2:1262
  17%    25431840 -> 1:1914 -> 1:654 -> 2:2540 -> 2:1262
  13%    19293120 -> 1:1913 -> 1:654 -> 2:2540 -> 2:1262
  10%    14908320 -> 1:6 -> 1:654 -> 2:2540 -> 2:1262
   3%     4384800 -> 1:1286 -> 1:654 -> 2:2540 -> 2:1262
   1%     1503360 -> 2:2542 -> 2:2540 -> 2:1262
   1%     1503360 -> 2:1276 -> 2:2540 -> 2:1262
   1%     1503360 -> 2:2520 -> 2:2538 -> 2:1262
   1%     1503360 -> 2:1907 -> 2:2540 -> 2:1262
   1%     1503360 -> 2:3170 -> 2:2540 -> 2:1262
   1%     1503360 -> 2:2533 -> 2:2540 -> 2:1262
   1%     1503360 -> 2:1282 -> 2:2540 -> 2:1262
   1%     1503360 -> 2:25 -> 2:2540 -> 2:1262
   1%     1503360 -> 2:3171 -> 2:2540 -> 2:1262
   1%     1461890 -> 2:1906 -> 2:1909 -> 2:1262
   1%      876960 -> 1:654 -> 2:2540 -> 2:1262
   1%      876960 -> 2:1263 -> 2:2538 -> 2:1262
   0%      709920 -> 2:650 -> 2:3169 -> 2:1262
   0%      229680 -> 2:650 -> 2:2540 -> 2:1262
   0%      167040 -> 2:645 -> 2:3169 -> 2:1262
   0%      104400 -> 2:3163 -> 2:2540 -> 2:1262
   0%       20880 -> 2:653 -> 2:1262
   0%       20880 -> 2:1908 -> 2:1262
   0%       20880 -> 2:20 -> 2:1262
   0%       20880 -> 2:2540 -> 2:1262
   0%       20880 -> 2:1281 -> 2:1262
   0%       20880 -> 2:1269 -> 2:1262
   0%       20880 -> 2:2536 -> 2:1262
   0%       20880 -> 2:649 -> 2:1262
   0%       20880 -> 2:6 -> 2:1262
   0%       20880 -> 2:3169 -> 2:1262
   0%       20880 -> 2:1284 -> 2:1262
   0%       20880 -> 2:1896 -> 2:1262
   0%       20880 -> 2:2538 -> 2:1262
   0%       20880 -> 2:17 -> 2:1262
   0%       20880 -> 2:655 -> 2:1262
   0%       20880 -> 2:1280 -> 2:1262
   0%       20880 -> 2:1895 -> 2:1262
   0%       20880 -> 2:1899 -> 2:1262
   0%       20880 -> 2:3158 -> 2:1262
   0%       20880 -> 2:3167 -> 2:1262
   0%       20880 -> 2:24 -> 2:1262
   0%       20880 -> 2:1288 -> 2:1262
   0%       20590 -> 2:1909 -> 2:1262
   0%       20590 -> 2:2541 -> 2:1262
   0%       16820 -> 2:1913 -> 2:1262
   0%        6960 -> 2:2523 -> 2:1262
   0%        4510 -> 1:3164 -> 1:654
   0%        4070 -> 1:2533 -> 1:654
   0%        3190 -> 1:1914 -> 1:654
   0%        2420 -> 1:1913 -> 1:654
   0%        1870 -> 1:6 -> 1:654
   0%         880 -> 3:3162
   0%         720 -> 2:632

Now the question is what was LGWR process doing and why was it constantly trying to read control file. If you run 10046 on LGWR process you will notice that LGWR will read control file while doing log switches.

WAIT #0: nam='control file sequential read' ela= 59 file#=0 block#=1 blocks=1 obj#=-1 tim=1429886768732384
WAIT #0: nam='control file sequential read' ela= 203 file#=0 block#=40 blocks=1 obj#=-1 tim=142988668732612
WAIT #0: nam='control file sequential read' ela= 197 file#=0 block#=42 blocks=1 obj#=-1 tim=1429886768732845
WAIT #0: nam='control file sequential read' ela= 216 file#=0 block#=1 blocks=1 obj#=-1 tim=1429886768733206
WAIT #0: nam='control file sequential read' ela= 192 file#=1 block#=1 blocks=1 obj#=-1 tim=1429886768733440
WAIT #0: nam='control file sequential read' ela= 200 file#=0 block#=40 blocks=1 obj#=-1 tim=1429886768733674
WAIT #0: nam='control file sequential read' ela= 198 file#=0 block#=42 blocks=1 obj#=-1 tim=1429886768733909

Then I checked alert log on instance 2 and found number of occurrences of following errors:

Tue Apr 21 19:59:21 2015
ORA-19815: WARNING: db_recovery_file_dest_size of 858993459200 bytes is 100.00% used, and has 0 remaining bytes available.
ARC1: Error 19809 Creating archive log file to '+RECO1'
ARCH: Archival stopped, error occurred. Will continue retrying
ORACLE Instance dbname2 - Archival Error
ORA-16038: log 21 sequence# 2506 cannot be archived
ORA-19809: limit exceeded for recovery files

Session id 1262 on instance 2 was doing number of small control file sequential read and none of single IO was stuck in large wait.

@event_hist.sql control.*read session_id=1262 1596 1596
                                 Wait time    Num ASH   Estimated    Estimated    % Event  Estimated
Wait Event                      bucket ms+    Samples Total Waits    Total Sec       Time  Time Graph
------------------------------ ----------- ---------- ----------- ------------ ---------- ------------
control file sequential read           < 1         17     66149.3         66.1       88.3 |######### |
                                      < 16          2       171.8          2.7        3.6 |          |
                                      < 32          3       128.2          4.1        5.5 |#         |
                                     < 128          1        15.6          2.0        2.7 |          |

 

image

Majority of sessions were ultimately waiting for session id 1262 on instance 2 (LGWR process). I think wait counts for control file read went up as LGWR was constantly trying to switch log file but it couldn’t as recovery destination was full. So enq: SQ – contention was the symptom of LGWR spinning on log switch due to no space in recovery destination(db_recovery_file_dest_size).

References:

Advanced Oracle Troubleshooting Guide – Part 11: Complex Wait Chain Signature Analysis

Diagnosing buffer busy waits with the ash_wait_chains.sql script (v0.2)

Update: 04/27/2015

I deliberately filled recovery destination area and then tried to switch log files. Switch log file command was hung and LGWR 10046 trace showed repeated loop of trying to read control file blocks. First two lines shows it was trying to read control file header block from multiplexed control files. Below is the excerpt from LGWR trace file.

nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 
nam='control file sequential read' file#=0 block#=40 
nam='control file sequential read' file#=0 block#=42 
nam='control file sequential read' file#=0 block#=43 
nam='control file sequential read' file#=0 block#=815 
nam='control file sequential read' file#=0 block#=46 
nam='control file sequential read' file#=0 block#=1 
nam='control file sequential read' file#=1 block#=1 

March 10, 2015

SQL Plan Tree Visualization

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

Real Time SQL Monitor Graphical plan from Cloud Control at times is not legible. Using google chart and visualization techniques that I learned from Accenture Enkitec’s and Iggy’s blog, I have create three scripts to quickly display plan in graphical Btree format. The one from real time sql monitoring displays few more metrics such as cardinality, IO and time statistics and I have added some color logic such that if time spend in one plan line id is more than 10% of total elapsed time then display Timeline in red otherwise green.

@getplan_cursor_tree.sql – Display graphical btree plan from cache based on SQL ID and plan_hash_value

@getplan_awr_tree.sql – Display graphical btree plan from AWR metadata based on SQL ID and plan_hash_value

@getplan_realsqlmonitor_tree.sql – Display graphical btree plan from Real Time SQL monitoring based on SQL ID, sql_exec_id etc.

Modify hard coded lines in script:

SPO logs\getplan_realsqlmonitor_tree_&tmenvs..html;

host start chrome C:\Users\U267399\Desktop\Tools\scripts\logs\getplan_realsqlmonitor_tree_&tmenvs..html

Sample output from OEM:

 image

 

Sample html output using getplan_realsqlmonitor_tree.sql: 

image

Full html file https://dl.dropboxusercontent.com/u/48791336/getplan_realsqlmonitor_tree_031615_170343.html

Download

References:

1) http://mauro-pagano.com/2015/03/10/trouble-reading-an-execution-plan-maybe-sqld360-can-help/

2) https://iggyfernandez.wordpress.com/2010/11/26/explaining-the-explain-plan-using-pictures/

November 5, 2014

SQL Performance changing over time

Filed under: Performance Tuning, SQL, Tools — vishaldesai @ 9:43 pm

Here is another visualization to analyze sql performance changing over period of time using Excel.

Input Screen:

image

Enter the details such as username, password, tns, Days, Interval and SQL ID and click on run button.

Output Screen:

image

As you can see from above, IO Wait times on 8/16 and 9/2 were higher compared to 8/19, 8/21 and 8/26. Number of executions were more or less same on those days. On 9/9 and 9/10, IO wait times were at peak but that could be due corresponding increase in number of executions.

image 

Data 2 worksheet will show more details about other SQL statistics. Units for other statistics are different so its difficult to show these statistics in two dimensional chart format.

Formatting for some combination by Day/Interval may not format excel chart properly. You may have to adjust chart manually to make it legible.

Download (Will be updated on 11/08)

October 3, 2014

Compare Oracle SQL Plan in Excel

Filed under: Performance Tuning, Tools — vishaldesai @ 2:36 pm

 

Input Screen:

image

 

 

Output Screen:

image

Download xlsm file, input source and target details, double click on list box to populate plan hash values and select one item and click on Run button to compare plan. The output screen will highlight first line (only first) where it finds difference in operation.

Download

Compare Oracle Database Parameters in Excel

Filed under: Performance Tuning, Tools — vishaldesai @ 2:13 pm

Input Screen:

image

Output Screen:

image

It will highlight differences in red. I have added logic to mark it blue if values are different for parameters instance_number, thread, undo_tablespace and local_listener. You can add more parameters to that logic for further customization.

Download xlsm file, add tns alias to tnsnames.ora file on your windows client and start comparing parameters.

Download

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

April 18, 2014

Database Time Viewer

Filed under: Tools — vishaldesai @ 2:31 pm

DBTimeViewer is a great standalone tool created by Dominic Giles to monitor Oracle Database Time. It requires simple configuration file update which includes database connection information such as username, password, hostname, port and service. In large enterprise environment with hundreds of thousands of databases it becomes little difficult to update database.xml file every time you have to connect to different database. I have created simple combination of batch and SQL script which will automatically create database.xml.

Scripts:

Create SQL and Batch scripts with proper path settings:

Script dbtimemonitor.sql

set head off
set feed off
set linesize 200
set pages 9999
set feedback off
set verify off
set pagesize 0


set term off

spool C:\<dbtime path>\databases.xml

select '<?xml version = ' || '''' || '1.0' || '''' || ' encoding = ' || '''' || 'UTF-8' || '''' || '?>'  from dual
union all
select '<WaitMonitor Title="Monitored Databases" xmlns="http://www.dominicgiles.com/waitmonitor">' from dual
union all
select  '<MonitoredDatabase><ConnectString>//' || a.host_name || '<domain>:<port>/' || b.name || '</ConnectString><Comment></Comment><Username>' || '&1' || '</Username><Password>' || '&2' || '</Password></MonitoredDatabase>'  from gv$instance a, v$database b
union all
select '</WaitMonitor>' from dual;

spool off
set term on
exit


Script dbtime.bat

@ECHO off
SET DBUser=%1
SET DBPass=%2
SET DBTNS=%3

sqlplus -s "%DBUser%/%DBPass%@%DBTNS%" @C:\<path>\dbtimemonitor.sql %1 %2

cd C:\<path>
dbtimemonitor.bat

Output:

C:\<path>>dbtime.bat <dbuser> <dbpassword> <dbtns>

Capture4

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.

Older Posts »

The Silver is the New Black Theme. Create a free website or blog at WordPress.com.

Follow

Get every new post delivered to your Inbox.

Join 36 other followers