Tuesday 10-09 2007
- 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)
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>
- 00:18 (Kirk)
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)
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
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
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
- 09:15 (Prabhu) AWR Reports
- 08:57 (Drew)
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.
Sunday 10-07-2007
- 14:11 (Prabhu) Created AWR report:
- 14:09 (Drew)
If you are sure without stats will help the performance (as Prabhu as shown the table has not been analyzed), after the auto stats collection, run the following as a DBA, will delete the table stats: EXEC DBMS_STATS.delete_table_stats('SAKAI_EXTERNAL', 'COURSEMANAGEMENT_SECTION_TA'); or EXEC DBMS_STATS.delete_table_stats('SAKAI_EXTERNAL', 'COURSEMANAGEMENT_SECTION_TB'); This will remove the stats for that table and put the table into a status as of now, which makes the query perform better. Can you run a AWR report and an autotrace and make sure the non-stats table performs better (as of now)? Be careful if you remove the stats of a table because it may affect other queries.
- 13:05 (Drew)
I forgot to mention this parameter can be adjusted on line without affecting end users. When you see the full table scan (with all the stats), you adjust this parameter (as sys) and then run the plan and stats (set autotrace traceonly) in the application owner account and see if you can see the plan change. This parameter is easy to adjust without shutting down the database. When I worked at at Ford Motor company, we adjusted that parameter to achieve better performance.
- 12:51 (Drew)
Without the stats, the query will use rule-based optimizer (RBO) and will pick up all of the indexes it can find because it's one of the rules. Generally, if the tables are created correctly, the stats would certainly help. The query is a simple one and should not be difficult for CBO to find the best way. Here I think the drop and recreate table is not a good practice in that case. The two tables (before dropped and the recreated one) are different objects in the database with different object id. Oracle will gather stats for that table for sure. If you run: select table_name, to_char(last_analyzed,'mm/dd/yyyy hh24:mi:ss') from user_tables where lower(table_name)='coursemanagement_section_ta'; You will find when it's last analyzed. Have you tried to adjust this parameter, optimizer_index_cost_adj ? If not, please try to read through the following and see if that can help. To start with, you can let this parameter equals 50. http://www.dba-oracle.com/oracle_tips_cost_adj.htm
- 12:20 (Prabhu) I disable monitor when tables dropped and enable when new ones created as below.
---Enable monitoring SQL> alter index sakai_external.CM_INST_TA_PERSON_IDX monitoring usage; Index altered. SQL> alter index sakai_external.CM_SECTION_TA_EID_IDX monitoring usage; Index altered. SQL> select index_name, table_name, monitoring, used, end_monitoring from v$object_usage; no rows selected ---Disable monitoring alter index sakai_external.CM_INST_TB_PERSON_IDX nomonitoring usage; alter index sakai_external.CM_SECTION_TB_EID_IDX nomonitoring usage;
- 07:00 (Patrick) I've rebuilt the TA tables with current data and the synonyms now point there. The job completed at 7am.
Saturday 10-06-2007
- 24:00 (Oracle) run stats
- 06:58 (Patrick) I switched to the recreated TB tables. The job started at 6:58am and completed at 7:06.
- I checked the problem query on both the TA and TB tables and it looks like the indexes are still being used.
- I noticed that there are 151 pairs of duplicate EID's in the SECTION table. Have we considered changing the view to weed those out?
Friday 10-05-2007
- 22:00 (Oracle) run stats
- 14:49 (Patrick)
Thanks, Brian. I created the indexes and added these statements to the script that recreates the tables for the synonym switch. There are currently no outstanding queries in the poor performance category.
- 11:43 (Brian)
Oh, I see, I didn't put an index on it because it was all null. Okay, here are indexes for the courseset_eid and courseoffering_eid columns, both of which are all null. CREATE INDEX CM_MEMBERSHIP_TA_CS_IDX ON COURSEMANAGEMENT_MEMBERSHIP_TA (COURSESET_EID) STORAGE(INITIAL 50M NEXT 10M); CREATE INDEX CM_MEMBERSHIP_TB_CS_IDX ON COURSEMANAGEMENT_MEMBERSHIP_TB (COURSESET_EID) STORAGE(INITIAL 50M NEXT 10M); CREATE INDEX CM_MEMBERSHIP_TA_CO_IDX ON COURSEMANAGEMENT_MEMBERSHIP_TA (COURSEOFFERING_EID) STORAGE(INITIAL 50M NEXT 10M); CREATE INDEX CM_MEMBERSHIP_TB_CO_IDX ON COURSEMANAGEMENT_MEMBERSHIP_TB (COURSEOFFERING_EID) STORAGE(INITIAL 50M NEXT 10M); That will create the indexes on both tables.
- 11:18 (Patrick)
sar -q Linux 2.6.9-55.0.6.ELsmp (caje) 10/05/2007 12:00:01 AM runq-sz plist-sz ldavg-1 ldavg-5 ldavg-15 12:10:01 AM 1 1211 0.72 0.91 0.98 02:10:01 AM 0 1211 0.12 0.18 0.47 02:20:02 AM 0 1215 1.32 1.28 0.89 02:30:01 AM 0 1209 0.09 0.36 0.61 02:40:01 AM 0 1211 0.05 0.14 0.37 02:50:01 AM 0 1215 0.95 0.49 0.38 03:00:09 AM 1 1212 0.05 0.39 0.45 03:10:01 AM 0 1211 0.23 0.20 0.31 03:20:01 AM 0 1214 0.21 0.20 0.24 03:30:01 AM 1 1208 1.15 0.91 0.57 03:40:01 AM 0 1210 0.06 0.45 0.54 03:50:02 AM 0 1217 0.52 0.28 0.37 04:00:01 AM 1 1214 1.21 1.36 0.93 04:10:02 AM 0 1225 1.55 1.86 1.45 04:20:02 AM 0 1226 1.24 1.54 1.42 04:30:02 AM 0 1220 1.36 1.19 1.26 04:40:02 AM 0 1220 1.14 1.45 1.41 04:50:07 AM 0 1224 1.34 1.28 1.28 05:00:06 AM 1 1220 1.32 1.36 1.34 06:00:01 AM 0 1215 0.65 0.33 0.51 06:40:02 AM 0 1212 1.16 0.75 0.66 07:20:01 AM 0 1222 1.57 2.18 1.83 07:40:01 AM 1 1213 0.63 1.14 1.64 08:00:01 AM 5 1216 4.51 3.28 2.21 08:40:04 AM 13 1227 17.44 17.31 12.78 08:50:13 AM 14 1254 20.77 19.95 16.40 09:10:19 AM 9 1235 21.66 23.12 20.19 09:30:01 AM 0 1237 1.48 3.77 10.36 09:40:01 AM 0 1236 0.57 1.29 5.91 10:00:06 AM 2 1235 1.67 1.40 2.42 Average: 2 1220 2.89 3.01 3.01 It's really frustrating that, even at 7:40am, the system is breezing along. Prabhu and I will work to schedule a rebuild of the tables at 7:00 am each morning. That job runs about 20 minutes. We will then switch the synonyms by 7:30am. We are also opening a service request with Oracle.
- 11:17 (Drew)
If execution plan stability is an issue for you after modifying the Oracle default window, you can consider the Plan Stability specified in this Oracle document: http://download.oracle.com/docs/cd/B19306_01/server.102/b14211/outlines.htm#sthref1787
- 09:07 (Patrick)
This query is active for a number of sessions (around 10) today: 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 Here is the explain plan: SELECT STATEMENT () TABLE ACCESS (BY INDEX ROWID) COURSEMANAGEMENT_INSTRUCT_TA NESTED LOOPS () TABLE ACCESS (FULL) COURSEMANAGEMENT_SECTION_TA INDEX (RANGE SCAN) CM_INST_TA_PERSON_IDX
- 08:47 (Patrick)
Building a set of new tables after DB performance degraded
Thursday 10-04-2007
- 15:20 (Patrick) Run coursemanagement_merge_procs.sql
- coursemanagement_merge_procs.sql
- Script run fine for:
- coursemanagement_section
- coursemanagement_offering
- coursemanagement_enrollment
- Script hung during the delete records process for:
- coursemanagement_instructors
- coursemanagement_membership
- 11:35 (Patrick) Recreated the 5 CM tables after DB load increased over 20
Wednesday 10-03-2007
- ... ?
Tuesday 10-02-2007
- 2.4.x Head prod 001 Installed
Monday 10-01-2007
- ... ?
Sunday 09-30-2007
- ... ?
Saturday 09-29-2007
- ... ?