Performance Tuning :: Elapsed Time In Trace File Output
Nov 16, 2011
I executed a query which executed quickly (1.7 seconds) but since its output took time in displaying on the console the time shown by 'set timing on was 39.5 seconds
also I took trace (tkprof) for the same.My query is why the timings under 'Total Waited' (43.19 and 1.69) are not added to the elapsed time 1.83 seconds
On AWR, I see two script that are out of ordinary, and I want to make sure that I interpret them correctly.
1) "Elap per Exec (s)" shows 3263.49 with 1 "Executions". 2) "Elap per Exec (s)" shows 3180.17 each execution with 2 "Executions".
Does this mean that this script ran for ~ 54 minutes (3263.49 / 60 seconds) for 1 "Execution" and ~ 53 minutes (3180.17 / 60 seconds) per each execution? I need to understand "Elapsed Time (s),CPU Time (s),Executions ,Elap per Exec (s), % Total DB Time" represent.
Elapsed Time (s) CPU Time (s) Executions Elap per Exec (s) % Total DB Time SQL Id SQL Module SQL Text 2,423 1 3,919 0.62 1.83 gt49gg0fnc5x8 srv_dr@ahs (TNS V1-V3) UPDATE /*+ CCL<OENDB_FILE... 2,227 14 1 2227.16 1.68 bggfx8a04prj9 SQL*Plus select * from (select n.source... .........
On [SQL ordered by Elapsed Time], [SQL Module] shows an indication that a SQL was executed by which process (i.e. srv_dr@ahs)outside of SQL*PLUS.If [SQL Modeule] shows as [SQL*Plus], does it mean the query was run in SQL*PLUS manually or directly?I have the SQL ID. How do I find out who, how, and exactly what time it was run?
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 1 0.00 0.00 db file sequential read 85704 0.31 460.55 latch free 1 0.00 0.00 SQL*Net message from client 1 14.98 14.98
[code]...
Why the elasped time changed when data and plan hasn't changed at all? Also why the plan has different stats for round 1 and 2 on db1 and db2?
I ran it 2 times each round each database so hard parsing shall not be issue.Also why the number of rows accessed are different in db1,db2 and db3,db4 especially for step1 when count of crt.qtn_cun_id is similar?
In fact when the query was taking long I was the only user on the system Also I used hard coded value (no bind variables at all)
I checked num_rows, distinct keys as well which are quite similar across all 4 databases Also no stats where gather during the query execution
I need to take the database trace of each page of my web application. I am giving the following commands.
BEGIN dbms_monitor.session_trace_enable(session_id=>122, serial_num=>NULL, waits=>true, binds=>true); END;
Accessing the web application. Once it renders completely, I am executing the following command.
BEGIN dbms_monitor.session_trace_disable(session_id=>122); END;
In the user_dump_dest folder, I am expecting to see a new trace whenever I execute these commands. But the same trace file is getting updated. How do I make oracle to create a new trace for each iteration. I am using Oracle 11g Release on CentOS 5.x
I've got a query running a select count (*) over a table. The default plan takes in the order of 15 minutes to return, a hinted plan to use a different index takes 3 minutes to return.
Unfortunately I cant get at the index stats and a few other areas which I suspect may be key here.When running autotrace against the two queries I see fairly different values as one would expect.
Query
select count (*) from fulfilmentitem bfi where created >= sysdate-30 AND bfi.status = 'FA' AND bfi.fulfilmentmethod = 'D' Slow run PLAN_TABLE_OUTPUT ----------------------------------------------------------------------------------------------- ---------------------------------------------------------------------------------------------- | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| ---------------------------------------------------------------------------------------------- | 0 | SELECT STATEMENT | | 1 | 15 | 33119 (1)| | 1 | SORT AGGREGATE | | 1 | 15 | | |* 2 | TABLE ACCESS BY INDEX ROWID| FULFILMENTITEM | 12525 | 183K| 33119 (1)| |* 3 | INDEX RANGE SCAN | IDX_FULFIL_METHODSTATUS | 250K| | 1786 (1)| ---------------------------------------------------------------------------------------------- [code]....
IDX_FULFIL_METHODSTATUS is across FULFILMENTMETHOD & STATUS in that order. IDX_BFI_CREATED is on CREATED and is approx 70% of the size of the other index
The row counts estimated in the explain plan are out, the count(*) comes in at 32.8k rows.As you will have seen, the fast run shows a pretty significant consistent get increase compared to the slow run and a decent though not dramatic physical read drop.
My uncertainty is around if these changes in consistent get/phys read values would typically be enough to suggest the real time improvements I'm observing or if other (albeit perhaps temporary) factors are involved. It is a prod OLTP environment so the data will be rapidly changing and that may be a factor.
I know it can never be an exact science without intimately knowing the hardware/current loads etc but I also know that there's enough experience on these boards to have a loose handle on if the time shifts between queries are likely (or not) to be reflective of the stat changes or if those differences alone shouldn't (or typically wouldn't account) for it.
I'm thinking about instructing the query to ignore its original plan but am hesitant to do so without being a little more confident that it's not just a timing thing or something other than the change of index approach which may be causing the improvement. the autotrace stat changes observed I couldn't put my hand on heart say "yup - that change is good, ignore the default index all the time for this job".
I've been searching the web for examples of how to run a trace.It's needed for a session different then current in trace LEVEL 4 (I need the bind variables values in the trace).
Unfortunately, I couldn't trace with DBMS_SUPPORT.START_TRACE_IN_SESSION, I understand that this is because it was only introduced in Oracle 11g.
how can i trace a session in level 4 on Oracle 10g for another session?
I have just migrated database to 11.2 ..Migration is successfull and now database is in open mode working fine.BUT i m getting following mesage in alert log file
"Time drift detected. Please check VKTM trace file for more details."I m using windows platform.
understanding the TKPROF output for the session that was executing an insert statement(inserting 70 lakh data) on which a row level trigger get fired and select from following table.The trace was run for 1 hour.
Table name - > GS_MAP_RCC_CCIT
This table is having 37 rows as in on single block and having primary key index on RCC_NUM that is also contained on single block.We are getting maximum wait events on db_file_sequential_read.
As per my understanding this is due to the contention for the same block because for each row these queries get fired.
Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 13 0.00 0.00 SQL*Net more data to client 24 0.00 0.00 SQL*Net message from client 13 5.33 5.47
Misses in library cache during parse: 1 Optimizer mode: ALL_ROWS Parsing user id: 3139
No Row Source Operation information here Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 1 0.00 0.00 db file sequential read 73062 0.25 692.23 db file scattered read 16099 0.18 76.65 latch: shared pool 4 0.02 0.03 latch: cache buffers chains 3 0.04 0.04 latch free 16 0.00 0.00
I have an AWR report based on two snapshots one an one hour time window, under the "SQL ordered by Elapsed Time" section, there is a query having Elapsed Time = 7012 seconds, which is almost two hours, how is this possible? I have been told that this i aggregate value of all sessions.
I am executing below two SQL's at a time in a .sql file and I want the total execution time of these two queries:-
set timing on; select 1 from dual; select 2 from dual;
The output of the above sql file is returning the results like below which is expected:-
1 ---------- 1
Elapsed: 00:00:00.01
2 ---------- 2
Elapsed: 00:00:00.00
I want the total execution time of the two SQL queries at a time, I mean post execution of the two queries I want to know the total execution time, in this case is execution case will be 00:00:00.01.
How can i check the avg time taken by an execution plan. Actually i have a very big query and it changes its execution plan very often, we would like to lock the best execution plan and to find it , i would like to know the Average Execution Time the query takes when it runs using different different execution plans.
elapsed time = time spent on waits + time CPU was used
Total time during snaps = Elapsed time + (may be) time waited for CPU...In AWR is it possible to draw such equation? I can see that the AWR report has following elements
1) End Snap time - Begin Snap time 2) DB time - as mentioned at the top of AWR report 3) DB CPU - in "Top 5 Timed Foreground Events" (I assume this is 'CPU used by sesson timing' in statspack) 4) Total of time for all Statistics in "Time Model Statistics" 5) BUSY_TIME + IDLE_TIME - "Operating System Statistics"
Time between 2 snapshots? or what else? Also for which seconds to multiply to 'DB Time(s)' per second and 'DB CPU(s)' per second in Load Profile to get the db time and CPU time?
For example, we have a table ACCOUNT (snowflake dimension containing other dimension keys) and I have many fact tables based on this dimension. Normally data warehouse load happens like first dimensions needs to be loaded and then facts. Our frequency of loads is 30 mins.
To increase the rate in which the data will be available in the facts (as its a financial application), am considering to have two batches one with dimension and another one with fact (came to this conclusion as there is no dependency like first dimensions to be loaded then only fact) just the update might get missed sometimes. But if I do that, when dimension gets loaded, it will be read in the facts in another session. Will this affect the performance ?
LOADING (insert/update) and selecting data from table at the same time. Will it affect the performance in any way.
I understand that when data is read from the disk, I/O is done..And When computations are done then CPU is used..Then where the following equation fits?
I have a table which contains 8,21,177 amount of data totally.Now I am trying to delete around 4,84,000 of data from this table by using just one filter i.e. my query is something like below
DELETE /*+ parallel(resource,4) */ FROM resource where created_by = 'MIGN'
This is going to delete 4,84,000 rows of data . But my current issue is this is taking lots of time to delete the data . To be precise , its almost taking 25 hours to delete this data..The created_by column is indexed .
Execution Plan ---------------------------------------------------------- Plan hash value: 2389236532
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | --------------------------------------------------------------------------------
- First time to execute: Using all indexes on 2 tables
- Second time to execute: Using only indexes on first table, full table scan on the other
- Third time to execute: Do FTS on both of tables.
Now, I show the objects and relate information here:
The Tables:
system@dbwap> select count(*) from my_wap.news_relation;
COUNT(*) ---------- 272708
system@dbwap> select count(*) from my_wap.news_content;
COUNT(*) ---------- 95092
system@dbwap> desc my_wap.news_content; Name Null? Type ----------------------------------------------------- -------- ---------------- ID NOT NULL NUMBER(11) SUBJECT NOT NULL VARCHAR2(500) TITLE VARCHAR2(4000) STATE NUMBER(1) IMGPATH VARCHAR2(500) ALIGN VARCHAR2(10)
Yesterday, there were performance issue at server. So today, when i am generating report for that particular period, found snapshot id sequence is serially but with skipped hourly timed. Instead of generating report at 15:30, it generated at 16:30.
Enter value for num_days: 2
Listing the last 2 days of Completed Snapshots Snap Instance DB Name Snap Id Snap Started Level ------------ ------------ --------- ------------------ ----- tagidev TAGIDEV 2857 10 Sep 2013 00:30 1 2858 10 Sep 2013 01:30 1 2859 10 Sep 2013 02:30 1 2860 10 Sep 2013 03:30 1 2861 10 Sep 2013 04:30 1 2862 10 Sep 2013 05:31 1
[code]....
Below are the details at alert log -
Tue Sep 10 14:28:20 2013 Thread 1 cannot allocate new log, sequence 7029 Checkpoint not complete Current log# 2 seq# 7028 mem# 0: E:APPORACLEORADATATAGIDEVREDO02.LOG Thread 1 advanced to log sequence 7029 (LGWR switch)
[code]....
1) why snap didn't started at 15:30?
2) since database just started at the scheduled time of AWR snap time. But generated at 16:32 instead of 16:30, though last services "SMCO" is started at 16:42. How it snap id generated for this particular time?
3) what does "kewastUnPackStats(): bad magic 1 (0x000000001B3CE48D, 0)" mean?
Is there any way to reduce the index creation time. I have one table which has 7700000 records and every day this table get truncate and we create with create table as select statement and then create the 4 indexes and each index took 5 minutes so in totality it took 20 minutes in index creation.
In my insert query, Window sort takes longer time i.e. 93% of total execution time, How do i reduce this time? are there any tuning parameters availabe for this?
In my code I am using delete statement which is taking too much time to execute.
Statement is as follow:
DELETE FROM TRADE_ORDER_EMP_ALLOCATION T WHERE (ARTEMIS_SOURCE_SYSTEM_ID,NM_ARTEMIS_SOURCE_SYSTEM,CD_BOOK_KEY,ACTIVITY_DT) IN (SELECT ARTEMIS_SOURCE_SYSTEM_ID,NM_ARTEMIS_SOURCE_SYSTEM,CD_BOOK_KEY,ACTIVITY_DT FROM LOAD_TRADE_ORDER WHERE IND_IS_BAD_RECORD='N');
Every column in "IN" clause and select clause is containing index on it
Every time no of rows which to be deleted is vary (May be in hundred ,thousand or hundred thousand )so that I am Unable to use "BITMAP" index on the table "LOAD_TRADE_ORDER" column "IND_IS_BAD_RECORD" though it is containing distinct record in it.
Even table "TRADE_ORDER_EMP_ALLOCATION" is containing "RANGE" PARTITION over it on the column "ARTEMIS_SOURCE_SYSTEM_ID". With this I am enclosing table scripts with Indexes and Partitions over it.
way for fast execution in of above delete statement?
