...
- Change Oracle's statistics gathering function to run between 04:00 - 05:00 instead at 22:00
- Oracle assumes to be the only active user during stats gathering
- All the tables, indexes, views need to be created in the same order via scripts
- Switch to RBO (Rule Based Optimizer) for certain views
- Eventual deterministic/stable performance after queries have been tuned
- Keep in mind after rebuilding the CM tables there are only 2 tables and 2 queries that run into trouble regularly. We should be careful not to implement DB wide strategies to attack these 2 problems. We need to understand why they differ and see if they can be tuned. (KA)
Activity Log
Wednesday 10-10-2007
...
- 22:04 (Kirk) Seeing full table scans. (Thomas) Running FullTableAccess.grooy shows:
No Format TIMESTAMP: 10-09-2007 22:04:46 OPERATION: TABLE ACCESS OPTIONS: FULL OBJECT_OWNER: SAKAI_EXTERNAL OBJECT_TYPE: TABLE TIME: 77 COST: 6366 CARDINALITY: 457617 BYTES: 198605778 CPU_COST: 375633528 IO_COST: 6339 SQL_FULLTEXT: /* Formatted on 2007/10/06 22:27 (Formatter Plus v4.8.6) */SELECT sectioncmi0_.eid AS eid248_, sectioncmi0_.CATEGORY AS category248_, sectioncmi0_.title AS title248_, sectioncmi0_.description AS descript4_248_, sectioncmi0_.createdby AS createdby248_, sectioncmi0_.createddate AS createdd6_248_, sectioncmi0_.lastmodifiedby AS lastmodi7_248_, sectioncmi0_.lastmodifieddate AS lastmodi8_248_, sectioncmi0_.courseoffering_eid AS courseof9_248_, sectioncmi0_.enrollmentset_eid AS enrollm10_248_, sectioncmi0_.PARENT AS parent248_, sectioncmi0_.MAXSIZE AS maxsize248_ FROM coursemanagement_section sectioncmi0_, coursemanagement_instructors instructor1_ WHERE instructor1_.section_eid = sectioncmi0_.eid AND instructor1_.person_eid = '00125158' TIMESTAMP: 10-09-2007 22:04:46 OPERATION: TABLE ACCESS OPTIONS: FULL OBJECT_OWNER: SAKAI_EXTERNAL OBJECT_TYPE: TABLE TIME: 77 COST: 6366 CARDINALITY: 457617 BYTES: 198605778 CPU_COST: 375633528 IO_COST: 6339 SQL_FULLTEXT: /* Formatted on 2007/10/06 22:27 (Formatter Plus v4.8.6) */SELECT sectioncmi0_.eid AS eid248_, sectioncmi0_.CATEGORY AS category248_, sectioncmi0_.title AS title248_, sectioncmi0_.description AS descript4_248_, sectioncmi0_.createdby AS createdby248_, sectioncmi0_.createddate AS createdd6_248_, sectioncmi0_.lastmodifiedby AS lastmodi7_248_, sectioncmi0_.lastmodifieddate AS lastmodi8_248_, sectioncmi0_.courseoffering_eid AS courseof9_248_, sectioncmi0_.enrollmentset_eid AS enrollm10_248_, sectioncmi0_.PARENT AS parent248_, sectioncmi0_.MAXSIZE AS maxsize248_ FROM coursemanagement_section sectioncmi0_, coursemanagement_instructors instructor1_ WHERE instructor1_.section_eid = sectioncmi0_.eid AND instructor1_.person_eid = '00125158'
- 18:00 (Patrick) Recreated 5 CM tables
- 11:30 (Thomas) Finding average cpu_time for queries that run longer than one second
No Format select cpu_time / 1000000 / executions as average_cpu_time, executions, first_load_time, last_load_time, last_active_time, sql_text from v$sql where parsing_schema_name = 'SAKAI_EXTERNAL' and cpu_time / 1000000 / executions > 1 and sql_text like 'select %' order by cpu_time desc;
- 10:00 (Prabhu) AWR Report
- 08:52 (Kirk)
- Drew, What else could the statistics run be doing to slow down our queries? To recover should we
have also deleted the stats on the indexes for the tables involved? All we know for sure is
that the queries run find when the tables have been built from scratch and no stats have been run.
Prabhu, I see you get better output from your sqlplus when you do the autotrace traceonly.
Is this based on your version of sqlplus or is there something else I need to do to get
the display of the %CPU cost that I see in your traces?
- Drew, What else could the statistics run be doing to slow down our queries? To recover should we
- 06:47 (Drew)
No Format I don't think I am convinced the delete stats is working according your results. Yes, the query uses indexes after deleting the stats. However, from the stats and the Elapsed time I know the query performance is not improving. Even though the query is using the index, it's performance may not improving. The Elapsed time 1s still 19 seconds. Also, the consistent gets and physical read are too high and the query is still slow. You second AWR did not covered long enough and would not catch the query. In the first AWR report, it covered 47 minutes and the slow query (looks like a different one based on the sql_id) was executed only 2 times. The second report's 2.7 minutes may not catch the slow query at all. You need a longer period between the snapshots for the report. Go back to the trace, the one I said Yes, you will see the difference. Please don't just see if the index is used, you need to see how fast you can get the data. I copy the one I say worked fine here to save your time going back. You can comparing the two and see the difference. Thanks, Drew Look at the difference: 13 rows selected. Elapsed: 00:00:00.01 58 consistent gets 0 physical reads <good one> I ran the trace for this query now and seems indexex are being used. I also attached a awr between 8:00 am and 9:00 am, which is after rebuilding the tables. I am also planing to take awr before and after 10:00 pm and see show these plans are changing. if it not in relation with stats, we can focus on HWM and think of segment shrinking. select sectioncmi0_.EID as EID248_, sectioncmi0_.CATEGORY as 2 CATEGORY248_, sectioncmi0_.TITLE as TITLE248_, sectioncmi0_.DESCRIPTION 3 as DESCRIPT4_248_, sectioncmi0_.CREATEDBY as CREATEDBY248_, 4 sectioncmi0_.CREATEDDATE as CREATEDD6_248_, sectioncmi0_.LASTMODIFIEDBY 5 as LASTMODI7_248_, sectioncmi0_.LASTMODIFIEDDATE as LASTMODI8_248_, 6 sectioncmi0_.COURSEOFFERING_EID as 7 COURSEOF9_248_,sectioncmi0_.ENROLLMENTSET_EID as ENROLLM10_248_, 8 sectioncmi0_.PARENT as PARENT248_, sectioncmi0_.MAXSIZE as MAXSIZE248_ 9 from sakai_external.COURSEMANAGEMENT_SECTION sectioncmi0_, sakai_external.COURSEMANAGEMENT_INSTRUCTORS 10 instructor1_ 11 where instructor1_.SECTION_EID=sectioncmi0_.EID and 12 instructor1_.PERSON_EID='00125158'; 13 rows selected. Elapsed: 00:00:00.01 Execution Plan ---------------------------------------------------------- Plan hash value: 616479917 -------------------------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | -------------------------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 23 | 56051 | 66 (0)| 00:00:01 | | 1 | TABLE ACCESS BY INDEX ROWID | COURSEMANAGEMENT_SECTION_TB | 2 | 4758 | 4 (0)| 00:00:01 | | 2 | NESTED LOOPS | | 23 | 56051 | 66 (0)| 00:00:01 | | 3 | TABLE ACCESS BY INDEX ROWID| COURSEMANAGEMENT_INSTRUCT_TB | 13 | 754 | 14 (0)| 00:00:01 | |* 4 | INDEX RANGE SCAN | CM_INST_TB_PERSON_IDX | 13 | | 3 (0)| 00:00:01 | |* 5 | INDEX RANGE SCAN | CM_SECTION_TB_EID_IDX | 2 | | 2 (0)| 00:00:01 | -------------------------------------------------------------------------------------------------------------- Predicate Information (identified by operation id): --------------------------------------------------- 4 - access("INSTRUCTOR1_"."PERSON_EID"='00125158') 5 - access("INSTRUCTOR1_"."SECTION_EID"="SECTIONCMI0_"."EID") Note ----- - dynamic sampling used for this statement Statistics ---------------------------------------------------------- 0 recursive calls 0 db block gets 58 consistent gets 0 physical reads 0 redo size 11946 bytes sent via SQL*Net to client 400 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 13 rows processed ------------------------------------------------------------------------ </good one>
- 06:00 (Patrick) Recreated 5 CM tables
- 00:18 (Kirk)
No Format Verified that only the 2 tables have lost their stats: SQL Statement which produced this data: select table_name, to_char(last_analyzed,'mm/dd/yyyy hh24:mi:ss') from user_tables where lower(table_name) like 'coursemanagement_%' TABLE_NAME TO_CHAR(LAST_ANALYZED,'MM/DD/YYYYHH24:MI:SS') COURSEMANAGEMENT_ENROLLMENT_TA 10/08/2007 22:01:33 COURSEMANAGEMENT_ENROLLMENT_TB 10/08/2007 22:01:47 COURSEMANAGEMENT_INSTRUCT_TA NULL COURSEMANAGEMENT_INSTRUCT_TB 10/08/2007 22:01:10 COURSEMANAGEMENT_MEMBERSHIP_TA 10/08/2007 22:00:39 COURSEMANAGEMENT_MEMBERSHIP_TB 10/08/2007 22:00:18 COURSEMANAGEMENT_OFFERING_TA 10/08/2007 22:00:11 COURSEMANAGEMENT_OFFERING_TB 10/08/2007 22:00:08 COURSEMANAGEMENT_SECTION_TA NULL COURSEMANAGEMENT_SECTION_TB 10/08/2007 22:02:05 and none of the indexes lost theirs: SQL Statement which produced this data: select index_name, to_char(last_analyzed,'mm/dd/yyyy hh24:mi:ss') from user_indexes where lower(index_name) like '%cm_enroll_t%' INDEX_NAME TO_CHAR(LAST_ANALYZED,'MM/DD/YYYYHH24:MI:SS') CM_ENROLL_TA_EID_IDX 10/08/2007 22:01:33 CM_ENROLL_TA_ES_IDX 10/08/2007 22:01:34 CM_ENROLL_TA_PERSON_IDX 10/08/2007 22:01:37 CM_ENROLL_TB_EID_IDX 10/08/2007 22:01:50 CM_ENROLL_TB_ES_IDX 10/08/2007 22:01:51 CM_ENROLL_TB_PERSON_IDX 10/08/2007 22:01:55
Monday 10-08-2007
- 23:42 (Prabhu)
No Format Here is what I have done. 1. ran our problem query(section) at 10:30pm after stats. Noticed full scans. 2. took AWR 3. dropped stats for the two tables involved in the query. 4. ran the query again. Noticed idexes being used. 5. took AWR 6. reran the query to make sure indexes are in place PS: cron job will be switching tables from "A" to "B" tomorrow at 06:00 hrs.- AWR 2007-10-08 22:00
- AWR 2007-10-08 23:19
- 22:39 (Thomas) Detected Full Table Access
No Format TIMESTAMP: 10-08-2007 22:39:25 OPERATION: TABLE ACCESS OPTIONS: FULL OBJECT_OWNER: SAKAI_EXTERNAL OBJECT_TYPE: TABLE TIME: 79 COST: 6506 CARDINALITY: 456438 BYTES: 199463406 CPU_COST: 379747898 IO_COST: 6479 SQL_FULLTEXT: SELECT sectioncmi0_.eid AS eid248_, sectioncmi0_.CATEGORY AS category248_,sectioncmi0_.title AS title248_,sectioncmi0_.description AS descript4_248_,sectioncmi0_.createdby AS createdby248_,sectioncmi0_.createddate AS createdd6_248_,sectioncmi0_.lastmodifiedby AS lastmodi7_248_,sectioncmi0_.lastmodifieddate AS lastmodi8_248_,sectioncmi0_.courseoffering_eid AS courseof9_248_,sectioncmi0_.enrollmentset_eid AS enrollm10_248_,sectioncmi0_.PARENT AS parent248_, sectioncmi0_.MAXSIZE ASmaxsize248_FROM sakai_external.coursemanagement_section sectioncmi0_,sakai_external.coursemanagement_instructors instructor1_WHERE instructor1_.section_eid = sectioncmi0_.eidAND instructor1_.person_eid = '00125158'
- 22:23 (Thomas) Detected Full Table Access
No Format TIMESTAMP: 10-08-2007 22:23:00 OPERATION: TABLE ACCESS OPTIONS: FULL OBJECT_OWNER: SAKAI_EXTERNAL OBJECT_TYPE: TABLE TIME: 79 COST: 6506 CARDINALITY: 456438 BYTES: 199463406 CPU_COST: 379747898 IO_COST: 6479 SQL_FULLTEXT: /* Formatted on 2007/10/08 22:22 (Formatter Plus v4.8.6) */SELECT sectioncmi0_.eid AS eid248_, sectioncmi0_.CATEGORY AS category248_, sectioncmi0_.title AS title248_, sectioncmi0_.description AS descript4_248_, sectioncmi0_.createdby AS createdby248_, sectioncmi0_.createddate AS createdd6_248_, sectioncmi0_.lastmodifiedby AS lastmodi7_248_, sectioncmi0_.lastmodifieddate AS lastmodi8_248_, sectioncmi0_.courseoffering_eid AS courseof9_248_, sectioncmi0_.enrollmentset_eid AS enrollm10_248_, sectioncmi0_.PARENT AS parent248_, sectioncmi0_.MAXSIZE AS maxsize248_ FROM coursemanagement_section sectioncmi0_, coursemanagement_instructors instructor1_ WHERE instructor1_.section_eid = sectioncmi0_.eid AND instructor1_.person_eid = :1
...
- 08:57 (Drew)
No Format After reading how the tables are created and the synonyms are used in the database, I start to think the execution plan mess could be caused by the use of synonyms (just think). Please read the following two articles/email regarding the synonym and performance. http://expertanswercenter.techtarget.com/eac/knowledgebaseAnswer/0,295199,sid63_gci977691,00.html http://www.freelists.org/archives/oracle-l/11-2004/msg00075.html In the first article, it says "The use of private synonyms can cause multiple versions of the same SQL text to be maintained in the library cache, thus reducing the sharing of SQL". I would think this is even true when we have different table definitions. I am thinking if you can test a procedure without using synonyms like the following: One set of script will cover all the reload. The "alter table rename" is as fast as you create the synonym. <> --The table coursemanagement_section_new and all it's indexes have been created. --Two set of the tables are used. Only one reload script is needed. INSERT INTO coursemanagement_section_new SELECT * FROM coursemanagement_section_v; commit; alter table coursemanagement_section rename to coursemanagement_section_old; alter table coursemanagement_section_new rename to coursemanagement_section; analyze table coursemanagement_section compute statistics; alter table coursemanagement_section_old rename to coursemanagement_section_new; truncate table coursemanagement_section_new; --repeat the above in each relaod. --That will get rid of the synonym. </> This is just some thoughts based on the articles on synonyms and I don't know if this can resolve the problem. I think it worth of trying if other options cannot resolve the problem. In case you don't have access to the first website listed above, I copy the text and attach it at the end of this note (see below).
- 05:05 (Patrick) At of 5:05 am, Monday, 10/8, the "B" set of external tables are current and in production.
...