Home » RDBMS Server » Performance Tuning » Logging operation takes longer but no wait events (Oracle 11.2.0.4 EE, Linux 64 bit)
Logging operation takes longer but no wait events [message #622900] |
Mon, 01 September 2014 09:49 |
|
d_seng
Messages: 78 Registered: November 2011 Location: UK
|
Member |
|
|
Hi,
There are two monthly ETL jobs in our DWH environment, one that runs sequential SQL statements, and one that runs up to 6 concurrent SQL statements.
Targeting to move to Data Guard, we switched FORCE LOGGING on at the database level. There are 4 groups with 2 members each and the log buffer size is set at 14MB.
There was no impact on the run time of the first job (48 hours), whereas the second job degraded from 10.5 hours to 12.5 hours.
The AWR report for the second job revealed no significant waits related to redo logs, the highest one being the "log buffer space" event which was for only 15 minutes, others being "log file sync" (5 minutes), "log file switch completion" (2 minutes) and the rest being in seconds.
Although I might think that 4 groups may not be sufficient to run 6 concurrent long running DML statements, nothing in the AWR report suggests the real cause behind it.
Please let me know if you have any suggestions.
I'll happily provide any information you need from the AWR reports.
Thanks
|
|
|
|
|
|
Re: Logging operation takes longer but no wait events [message #622908 is a reply to message #622900] |
Mon, 01 September 2014 10:44 |
John Watson
Messages: 8950 Registered: January 2010 Location: Global Village
|
Senior Member |
|
|
Redo generation is the ultimate bottleneck in the Oracle environment: you cannot do DML faster than the change vectors can be streamed to disc. If it is a large operation which previously used NOLOGGING, then it is not surprising that it runs more slowly now. Possibly you could relieve the stress on the I/O system in other ways.
Can you post an AWR report covering the full 12.5 hours, and the AWR SQL reports for the 6 statements?
|
|
|
|
Re: Logging operation takes longer but no wait events [message #622913 is a reply to message #622911] |
Mon, 01 September 2014 12:08 |
John Watson
Messages: 8950 Registered: January 2010 Location: Global Village
|
Senior Member |
|
|
Man, that PDF file is really hard to read. And it doesn't have the SQL section!
However, it does appear that you need to tune away the disc I/O wait events. Without seeing the SQL and the execution plans I can't be sure, but I think you probably need to tune the use of parallel query, PGA, and the access methods and join methods. Please can you post the complete AWR report as HTML, with the SQL sections? Then we can identify the SQLs, and get the plans out.
|
|
|
|
|
Re: Logging operation takes longer but no wait events [message #622918 is a reply to message #622917] |
Mon, 01 September 2014 13:36 |
John Watson
Messages: 8950 Registered: January 2010 Location: Global Village
|
Senior Member |
|
|
As I suspected, a lot of hinted parallel query, including hitting the same tables several times. That will be the reason behind all your direct reads. I know that it is very difficult to test a process that takes twelve hours, but can you try this:
First, you must calibrate the I/O, if you haven't done it already. Are you familiar with the process? It is a low risk procedure, takes perhaps 10 minutes:
var al number
var mi number
var mm number
exec dbms_resource_manager.calibrate_io(max_iops=>:mi,max_mbps=>:mm,actual_latency=>:al)
print al
print mi
print mm
Then remove all those parallel hints from the code, and enable parallel automatic tuning, parallel statement queueing, and in-memory parallel scans:
alter system set parallel_degree_policy=auto; and run the entire workload again. The parameter can over-ride parallel degrees set per table, but not set in hints.
I strongly believe that the automatic tuning from 11.2 is far superior to anything developers try to do, but you must calibrate I/O and remove hints or it doesn't work.
If this doesn't help, there are other things to try. A nice problem.
|
|
|
|
Re: Logging operation takes longer but no wait events [message #622929 is a reply to message #622920] |
Tue, 02 September 2014 02:56 |
John Watson
Messages: 8950 Registered: January 2010 Location: Global Village
|
Senior Member |
|
|
I suspect that you have two unrelated problems. The new one, which is why you opened this topic, is that you are now generating about 1GB of redo per minute that you weren't generating before. That is going to put some strain on your I/O infrastructure. Of course your sys admins will say "the discs are fine, hardly spinning" because they always say that. In my experience, they never check the rest of the system. You are possibly flooding your fibre channels with traffic, which slows down everything else. But you can't do anything about this.
Your second problem is one you have always had: killing performance because of too much direct read related to too much parallelism. Enabling auto tuning may throttle back the parallelism to a level the system can stand. Furthermore, it permits in-memory scans which may reduce the disc I/O hugely. The queueing should help, too: better to make a process wait a short time so that it can then run with the correct DOP, then try to run it when the system is over-stretched.
All this is pure conjecture, of course.
|
|
|
Re: Logging operation takes longer but no wait events [message #626938 is a reply to message #622929] |
Wed, 05 November 2014 07:58 |
|
d_seng
Messages: 78 Registered: November 2011 Location: UK
|
Member |
|
|
Sorry for the delayed response, combination of holiday/travel/procedural delays.
Before I ventured into auto parallelism, I reduced the no. of parallel threads per concurrent SQL statement to 4 (using hints), and that resulted in an improvement from 10.5 hrs to 7.5 hrs.
The results of calibration were:
SQL> var al number
SQL> var mi number
SQL> var mm number
SQL> exec dbms_resource_manager.calibrate_io(max_iops=>:mi,max_mbps=>:mm,actual_latency=>:al)
PL/SQL procedure successfully completed.
SQL> print al
AL
----------
0
SQL> print mi
MI
----------
110245
SQL> print mm
MM
----------
1248
I then got the parameter changed:
SQL> alter system set parallel_degree_policy=auto scope=both;
Then I removed all the custom parallelism and kicked off both the jobs, one that runs SQLs serially and the other that runs concurrent SQLs. This time the runtime degraded to 11.7 hrs (from the original 10.5 hrs), and almost every SQL is marginally slower than before, adding up to the extra 1.2 hrs.
Several SQLs ran using only 2-3 threads, whereas I have seen up to 48 threads being used in some SQLs that I ran at random.
The most significant and unwanted side effect was that the number of db block changes (as shown in "Key Instance Activity Stats" in the AWR report - see attached, rename to html) increased substantially (from 166M to 1700M), and so did the redo size (from 780GB to 1000GB), although the physical reads/writes remained more or less the same.
Perhaps the extra parallel threads are creating extra extents...I'm not sure.
Overall, I'm a little disappointed with the outcome as (I thought) this feature holds a lot of potential.
[Updated on: Wed, 05 November 2014 10:26] Report message to a moderator
|
|
|
Re: Logging operation takes longer but no wait events [message #627662 is a reply to message #626938] |
Thu, 13 November 2014 15:14 |
|
d_seng
Messages: 78 Registered: November 2011 Location: UK
|
Member |
|
|
Also, index creation is taking much longer after setting PARALLEL_DEGREE_POLICY to AUTO. This is an example of the DDL not using parallel threads:
GMIS_ODS@AGMISRT> DROP INDEX IX_TransBookEarnOutw_SysPerCmp;
Index dropped.
GMIS_ODS@AGMISRT> ALTER SESSION SET PARALLEL_DEGREE_POLICY=MANUAL;
Session altered.
GMIS_ODS@AGMISRT> SET TIMING ON
GMIS_ODS@AGMISRT> CREATE INDEX IX_TransBookEarnOutw_SysPerCmp
ON TransBookedEarnedOutwards (PKSrcSystemId, CompanyCode, BranchCode, PKReportingPeriod)
NOLOGGING PARALLEL 8 COMPUTE STATISTICS;
Index created.
Elapsed: 00:00:06.17
GMIS_ODS@AGMISRT> SET TIMING OFF
GMIS_ODS@AGMISRT> select statistic, last_query from V$PQ_SESSTAT
where statistic in ('Queries Parallelized','DML Parallelized','DDL Parallelized','Server Threads');
STATISTIC LAST_QUERY
------------------------------ ----------
Queries Parallelized 0
DML Parallelized 0
DDL Parallelized 1
Server Threads 16
GMIS_ODS@AGMISRT>
GMIS_ODS@AGMISRT> DROP INDEX IX_TransBookEarnOutw_SysPerCmp;
Index dropped.
GMIS_ODS@AGMISRT> ALTER SESSION SET PARALLEL_DEGREE_POLICY=AUTO;
Session altered.
GMIS_ODS@AGMISRT> SET TIMING ON
GMIS_ODS@AGMISRT> CREATE INDEX IX_TransBookEarnOutw_SysPerCmp
ON TransBookedEarnedOutwards (PKSrcSystemId, CompanyCode, BranchCode, PKReportingPeriod)
NOLOGGING PARALLEL 8 COMPUTE STATISTICS;
Index created.
Elapsed: 00:00:35.50
GMIS_ODS@AGMISRT> SET TIMING OFF
GMIS_ODS@AGMISRT> select statistic, last_query from V$PQ_SESSTAT
where statistic in ('Queries Parallelized','DML Parallelized','DDL Parallelized','Server Threads');
STATISTIC LAST_QUERY
------------------------------ ----------
Queries Parallelized 0
DML Parallelized 0
DDL Parallelized 0
Server Threads 0
GMIS_ODS@AGMISRT>
GMIS_ODS@AGMISRT> DROP INDEX IX_TransBookEarnOutw_SysPerCmp;
Index dropped.
GMIS_ODS@AGMISRT> ALTER SESSION SET PARALLEL_DEGREE_POLICY=AUTO;
Session altered.
GMIS_ODS@AGMISRT> SET TIMING ON
GMIS_ODS@AGMISRT> CREATE INDEX IX_TransBookEarnOutw_SysPerCmp
ON TransBookedEarnedOutwards (PKSrcSystemId, CompanyCode, BranchCode, PKReportingPeriod)
NOLOGGING COMPUTE STATISTICS;
Index created.
Elapsed: 00:00:34.58
GMIS_ODS@AGMISRT> SET TIMING OFF
GMIS_ODS@AGMISRT> select statistic, last_query from V$PQ_SESSTAT
where statistic in ('Queries Parallelized','DML Parallelized','DDL Parallelized','Server Threads');
STATISTIC LAST_QUERY
------------------------------ ----------
Queries Parallelized 0
DML Parallelized 0
DDL Parallelized 0
Server Threads 0
GMIS_ODS@AGMISRT>
|
|
|
Re: Logging operation takes longer but no wait events [message #627676 is a reply to message #627662] |
Fri, 14 November 2014 03:10 |
John Watson
Messages: 8950 Registered: January 2010 Location: Global Village
|
Senior Member |
|
|
Hello again. Thank you for posting that last report, it helps a lot. The situation is more complicated than I realized. I had thought the auto PX tuning would help, but your test does seem to show that it doesn't.
You have introduced a problem with index creation. Let's try that first. You are using automatic PGA management, which has issues with memory intensive operations such as indexing. It is not surprising that auto PX tuning has downgraded it to serial. I would try this, in the session where you are generating the indexes:
alter session set workarea_size_policy=manual;
alter session set sort_area_size=2147483647; and then create your indexes, experimenting with parallel degree if you can. You have plenty of RAM, and taking PGA to the max should reduce your direct path I/O and help the indexing hugely.
|
|
|
Re: Logging operation takes longer but no wait events [message #627682 is a reply to message #627676] |
Fri, 14 November 2014 05:54 |
|
d_seng
Messages: 78 Registered: November 2011 Location: UK
|
Member |
|
|
Thank you. What you have suggested sounds very plausible, however the results are still not favourable, especially considering that the table is only 1.2GB in size and the resulting index is only 500MB in size. I'm not sure what you meant by "experimenting with parallel degree if you can", please can you clarify?
GMIS_ODS@AGMISRT> SELECT SUM(BYTES/1024/1024) FROM USER_SEGMENTS WHERE SEGMENT_NAME = UPPER('TransBookedEarnedOutwards');
SUM(BYTES/1024/1024)
--------------------
1200
GMIS_ODS@AGMISRT> ALTER SESSION SET PARALLEL_DEGREE_POLICY=AUTO;
Session altered.
GMIS_ODS@AGMISRT> ALTER SESSION SET WORKAREA_SIZE_POLICY=MANUAL;
Session altered.
GMIS_ODS@AGMISRT> ALTER SESSION SET SORT_AREA_SIZE=2147483647;
Session altered.
GMIS_ODS@AGMISRT> DROP INDEX IX_TransBookEarnOutw_SysPerCmp;
Index dropped.
GMIS_ODS@AGMISRT> SET TIMING ON
GMIS_ODS@AGMISRT> CREATE INDEX IX_TransBookEarnOutw_SysPerCmp
ON TransBookedEarnedOutwards (PKSrcSystemId, CompanyCode, BranchCode, PKReportingPeriod)
NOLOGGING PARALLEL 8 COMPUTE STATISTICS;
Index created.
Elapsed: 00:00:32.88
GMIS_ODS@AGMISRT> SET TIMING OFF
GMIS_ODS@AGMISRT> select * from V$PQ_SESSTAT where statistic in ('Queries Parallelized','DML Parallelized','DDL Parallelized','Server Threads');
STATISTIC LAST_QUERY SESSION_TOTAL
------------------------------ ---------- -------------
Queries Parallelized 0 0
DML Parallelized 0 0
DDL Parallelized 0 0
Server Threads 0 0
GMIS_ODS@AGMISRT>
GMIS_ODS@AGMISRT> DROP INDEX IX_TransBookEarnOutw_SysPerCmp;
Index dropped.
GMIS_ODS@AGMISRT> SET TIMING ON
GMIS_ODS@AGMISRT> CREATE INDEX IX_TransBookEarnOutw_SysPerCmp
ON TransBookedEarnedOutwards (PKSrcSystemId, CompanyCode, BranchCode, PKReportingPeriod)
NOLOGGING COMPUTE STATISTICS;
Index created.
Elapsed: 00:00:27.65
GMIS_ODS@AGMISRT> SET TIMING OFF
GMIS_ODS@AGMISRT> select * from V$PQ_SESSTAT where statistic in ('Queries Parallelized','DML Parallelized','DDL Parallelized','Server Threads');
STATISTIC LAST_QUERY SESSION_TOTAL
------------------------------ ---------- -------------
Queries Parallelized 0 0
DML Parallelized 0 0
DDL Parallelized 0 0
Server Threads 0 0
GMIS_ODS@AGMISRT> select BYTES/1024/1024 from USER_SEGMENTS where SEGMENT_NAME = UPPER('IX_TransBookEarnOutw_SysPerCmp');
BYTES/1024/1024
---------------
520
GMIS_ODS@AGMISRT> select * From v$pgastat;
NAME VALUE UNIT
---------------------------------------- ---------- ------------
aggregate PGA target parameter 2181038080 bytes
aggregate PGA auto target 1696306176 bytes
global memory bound 218101760 bytes
total PGA inuse 296249344 bytes
total PGA allocated 376340480 bytes
maximum PGA allocated 4356923392 bytes
total freeable PGA memory 26542080 bytes
process count 49
max processes count 497
PGA memory freed back to OS 1.6784E+13 bytes
total PGA used for auto workareas 0 bytes
maximum PGA used for auto workareas 4282433536 bytes
total PGA used for manual workareas 0 bytes
maximum PGA used for manual workareas 785932288 bytes
over allocation count 0
bytes processed 8.4548E+13 bytes
extra bytes read/written 3.4844E+13 bytes
cache hit percentage 70.81 percent
recompute count (total) 3725296
19 rows selected.
GMIS_ODS@AGMISRT> select * from v$memory_target_advice order by memory_size;
MEMORY_SIZE MEMORY_SIZE_FACTOR ESTD_DB_TIME ESTD_DB_TIME_FACTOR VERSION
----------- ------------------ ------------ ------------------- ----------
5648 .5 14142431 1.0634 0
7060 .625 13514706 1.0162 0
8472 .75 13514706 1.0162 0
9884 .875 13365754 1.005 0
11296 1 13299258 1 0
12708 1.125 13299258 1 0
14120 1.25 13299258 1 0
15532 1.375 13259360 .997 0
16944 1.5 13259360 .997 0
18356 1.625 13259360 .997 0
19768 1.75 13258030 .9969 0
21180 1.875 13258030 .9969 0
22592 2 13258030 .9969 0
13 rows selected.
GMIS_ODS@AGMISRT> show parameter memory
NAME TYPE VALUE
------------------------------------ ----------- --------
hi_shared_memory_address integer 0
memory_max_target big integer 15G
memory_target big integer 11296M
shared_memory_address integer 0
I'm not sure what we're missing?
|
|
|
Goto Forum:
Current Time: Fri Sep 20 20:10:45 CDT 2024
|