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 Go to next message
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 #622901 is a reply to message #622900] Mon, 01 September 2014 10:11 Go to previous messageGo to next message
BlackSwan
Messages: 25797
Registered: January 2009
Location: SoCal
Senior Member
SELECT to_char(first_time, 'YYYY-MM-DD HH24:MI')
FROM V$LOG_HISTORY
WHERE FIRST_TIME > SYSDATE-2
ORDER BY 1


post results from SQL above
Re: Logging operation takes longer but no wait events [message #622903 is a reply to message #622900] Mon, 01 September 2014 10:24 Go to previous messageGo to next message
Michel Cadot
Messages: 65317
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator

http://docs.oracle.com/cd/E11882_01/server.112/e41573/instance_tune.htm#PFGRF94530

Re: Logging operation takes longer but no wait events [message #622907 is a reply to message #622903] Mon, 01 September 2014 10:43 Go to previous messageGo to next message
d_seng
Messages: 78
Registered: November 2011
Location: UK
Member
BlackSwan, please find attached the results in csv file (pre and post logging). The results were too long to post.

Total redo pre logging: 200GB
Total redo post logging: 775GB

The redo has gone up because the nologging staging area DMLs are being logged now.

Michel, I did look at the URL, but as I mentioned in my post, there are no wait events related to the redo log that are significant. The number of log switches has gone up considerably (as expected) but the AWR report doesn't seem to suggest that there were any waits caused by that...
Re: Logging operation takes longer but no wait events [message #622908 is a reply to message #622900] Mon, 01 September 2014 10:44 Go to previous messageGo to next message
John Watson
Messages: 7219
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 #622911 is a reply to message #622908] Mon, 01 September 2014 11:42 Go to previous messageGo to next message
d_seng
Messages: 78
Registered: November 2011
Location: UK
Member
John, I'm attaching the AWR report. Unfortunately I cannot isolate the reports for the SQLs as there are several jobs within the ETL process that run several (up to 6) SQLs concurrently, perhaps it wasn't clear from my post.

I stripped out the individual SQLs to keep the file within allowable size.
Re: Logging operation takes longer but no wait events [message #622913 is a reply to message #622911] Mon, 01 September 2014 12:08 Go to previous messageGo to next message
John Watson
Messages: 7219
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 #622915 is a reply to message #622913] Mon, 01 September 2014 12:16 Go to previous messageGo to next message
John Watson
Messages: 7219
Registered: January 2010
Location: Global Village
Senior Member
Sorry, not "parallel" query", I meant "direct read" - which can be parallel or serial.
Re: Logging operation takes longer but no wait events [message #622917 is a reply to message #622915] Mon, 01 September 2014 13:02 Go to previous messageGo to next message
d_seng
Messages: 78
Registered: November 2011
Location: UK
Member
Here you go...it was a bit of a struggle to keep it below 2MB, I had to get rid of the double quotes eventually. I've had to change the extension to txt, please rename.

Inappropriate DoP is a concern, the developers have probably "supercharged" each query in isolation without considering the fact that many such queries could be running simultaneously.

In fact, as a separate exercise, reducing the DoP for the concurrent SQLs has actually improved run times by approx. 30% (down to 7.5 hours from 10.5 hours), but unfortunately that piece of code is in a different baseline.

It is possible that too many parallel slaves could have an adverse impact on the additional redo logs generated, bearing in mind that too many direct reads was already a problem even when force logging was not switched on?
Re: Logging operation takes longer but no wait events [message #622918 is a reply to message #622917] Mon, 01 September 2014 13:36 Go to previous messageGo to next message
John Watson
Messages: 7219
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 #622920 is a reply to message #622918] Mon, 01 September 2014 14:55 Go to previous messageGo to next message
d_seng
Messages: 78
Registered: November 2011
Location: UK
Member
Thanks John, I'm aware of calibration, I have used Orion in the past in similar capacity. I'll try the newer method (soon I hope, as database level parameters are administered by our data centre staff) and report back the findings here.

Only two questions for now:
How/why do you reckon switching force logging on at the database level exacerbated this (parallelism) problem and increased the run times?
Will setting parallel_degree_policy to auto cause a lot of statement queuing? So will the SQLs that run concurrently at the moment end up running serially?

Cheers
Re: Logging operation takes longer but no wait events [message #622929 is a reply to message #622920] Tue, 02 September 2014 02:56 Go to previous messageGo to next message
John Watson
Messages: 7219
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 Go to previous messageGo to next message
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 Go to previous messageGo to next message
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 Go to previous messageGo to next message
John Watson
Messages: 7219
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 Go to previous message
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?
Previous Topic: Cursor: Pin S Wait on X
Next Topic: Decide on Partitioning Column/Purge Approach
Goto Forum:
  


Current Time: Fri Jan 19 23:52:02 CST 2018

Total time taken to generate the page: 0.04434 seconds