Forum Stats

  • 3,757,253 Users
  • 2,251,216 Discussions
  • 7,869,779 Comments

Discussions

Oracle RAC12.2 Granule Size/Log buffer/redo log space requests - sizing

user591200
user591200 Member Posts: 41 Bronze Badge
edited Aug 30, 2021 4:38PM in General Database Discussions

Hi,

I have Oracle 12.2 RAC(3 node) in AIX/Power-7 system, I have question on whether I am seeing the correct granule size as per my system configuration,

sga_max_size * 68719476736  

sga_target * 68719476736

Since the SGA is set to 64GB , I am expecting the granule size to be reported as 128MB but actually reported by v$sgainfo as 134217728 (bytes) , I believe this is correct.

Based on gv$sysstat , I am seeing "redo log space requests" , and it seems significant.

The redo buffers is calculated as 112 MB as per v$sgainfo,

As per note : Tuning the Redolog Buffer Cache and Resolving Redo Latch Contention (Doc ID 147471.1),

The value of "redo log space requests" should be near 0. If this value increments consistently, processes have had to wait for space in the buffer. This may be caused the checkpointing or log switching. Improve thus the checkpointing or archiving process.

This system does about 600 commits per second,

Should I be increasing the sga_max_size/sga_target to a higher value so the granule size would jump to the next granule size, 256MB ?

I dont understand the reason for indicating "redo log space requests" , this system is under log file sync /log file parallel write pressure .. / the typical avg response time for log file sync is like 4 - 5 ms , on this day there were some SAN maintenance and the response time spiked. The system is very sensitive on the avg response time from SAN for redo logs.


SQL> l
 1 select * from gv$sysstat
 2*   where name= 'redo log space requests'
SQL> /

  INST_ID STATISTIC# NAME              CLASS   VALUE  STAT_ID   CON_ID
---------- ---------- ------------------------- ---------- ---------- ---------- ----------
     2    331 redo log space requests      2   39894 1985754937     3
     3    331 redo log space requests      2   40532 1985754937     3
     1    331 redo log space requests      2   38491 1985754937     3

SQL> select bytes from v$sgainfo where name like 'Granule Size';
BYTES
----------
134217728
SQL> select name,bytes/1024/1024,RESIZEABLE,CON_ID from v$sgainfo;

NAME BYTES/1024/1024 RES CON_ID
------------------------- --------------- --- ----------
Fixed SGA Size 15.2446899 No 0
Redo Buffers 112.753906 No 0
Buffer Cache Size 41728 Yes 0
In-Memory Area Size 0 No 0
Shared Pool Size 22784 Yes 0
Large Pool Size 512 Yes 0
Java Pool Size 384 Yes 0
Streams Pool Size 0 Yes 0
Shared IO Pool Size 512 Yes 0
Data Transfer Cache Size 0 Yes 0
Granule Size 128 No 0
Maximum SGA Size 65536 No 0
Startup overhead in Share 3841.97806 No 0
d Pool

Free SGA Memory Available 0 0



dlm_stats_collect * 0  
audit_file_dest * /u03/oradata/psvrdb01/adump  
audit_sys_operations * TRUE  
audit_trail * XML, EXTENDED  
background_dump_dest 1 /u03/oradata/psvrdb01/diag/rdbms/psvrdb01/trace  

background_dump_dest 
2 /u03/oradata/psvrdb01/diag/rdbms/psvrdb01/psvrdb01/trace  

background_dump_dest 
3 /u03/oradata/psvrdb01/diag/rdbms/psvrdb01/psvrdb01/trace  
cluster_database * TRUE  
compatible * 12.2.0.1.0  
connection_brokers * ((TYPE=DEDICATED)(BROKERS=1)), ((TYPE=EMON)(BROKERS=1))  
control_file_record_keep_time * 60  
control_files * +DG_DATA_P01/psvrdb01/CONTROLFILE/current.277.998742251, +DG_FLSH_P01/psvrdb01/CONTROLFILE/current.265.998742253  
cpu_count * 16  
db_block_size * 8192  
db_create_file_dest * +DG_DATA_DXX01  
db_files * 1000  
db_name * psvrdb01  
db_recovery_file_dest * +DG_FLSH_P01  
db_recovery_file_dest_size * 32212254720  
deferred_segment_creation * FALSE  
diagnostic_dest * /u03/oradata/psvrdb01  
dispatchers * (PROTOCOL=TCP) (SERVICE=psvrdb01XDB)  
dml_locks * 1000  
enable_pluggable_database * TRUE  
event * 10298 trace name context forever, level 32  
global_names * TRUE  
instance_number 1 1  

instance_number 
2 2  

instance_number 
3 3  
java_pool_size * 268435456  
job_queue_processes * 10  
listener_networks *  
local_listener 1 (ADDRESS=(PROTOCOL=TCP)(HOST=xxx.xxx.xxx.xxx)(PORT=1529))  

local_listener 
2 (ADDRESS=(PROTOCOL=TCP)(HOST=xxx.xxx.xxx.xxx)(PORT=1529))  

local_listener 
3 (ADDRESS=(PROTOCOL=TCP)(HOST=xxx.xxx.xxx.xxx)(PORT=1529))  
log_archive_dest_1 * LOCATION=+DG_FLSH_DXX  
log_archive_dest_2 *  
log_archive_format * log%s_%t_%r.arc  
log_checkpoint_interval * 1000000  
memory_max_target * 0  
memory_target * 0  
nls_language * AMERICAN  
nls_length_semantics * BYTE  
nls_territory * AMERICA  
open_cursors * 1500  
optimizer_index_caching * 0  
optimizer_index_cost_adj * 100  
os_authent_prefix * OPS$  
parallel_force_local * TRUE  
pga_aggregate_limit * 6442450944  
pga_aggregate_target * 3221225472  
plsql_warnings * DISABLE:ALL  
processes * 2000  
remote_listener * <my-scan-addr>:1527  
remote_login_passwordfile * EXCLUSIVE  
resource_limit * TRUE  
resource_manager_cpu_allocation * 80  
resource_manager_plan * DEFAULT_CDB_PLAN  
sec_max_failed_login_attempts * 10  
sec_protocol_error_trace_action * LOG  
session_cached_cursors * 150  
sessions * 3024  
sga_max_size * 68719476736  
sga_target * 68719476736  
sql92_security * TRUE  
temp_undo_enabled * TRUE  
thread 1 1  

thread 
2 2  

thread 
3 3  
undo_retention * 14400  
undo_tablespace 1 UNDOTBS1  

undo_tablespace 
2 UNDOTBS2  

undo_tablespace 
3 UNDOTBS3  
user_dump_dest 1 /u03/db01/psvrdb01/trace  

user_dump_dest 
2 /u03/oradata/db01/psvrdb/diag/rdbms/psvrdb01/psvrdb01/trace  

user_dump_dest 
3 /u03/oradata/psvrdb/diag/rdbms/psvrdb01/psvrdb02/trace 


Any feedback is appreciated.

Thanks!

Answers

  • JohnWatson2
    JohnWatson2 Member Posts: 4,315 Silver Crown

    The information you have given suggests that your performance problem (if there is a problem - you have not said that there is, or indicated that your users are complaining about something) is caused by log file sync waits, which are taking 37% of your DB time. The standard fix for this would be to set

    commit_write=batch

    commit_wait=nowait

    which will remove the problem. Though you should read up on the implications of doing this, in some circumstances it can be considered unsafe.

  • user591200
    user591200 Member Posts: 41 Bronze Badge

    @JohnWatson2

    Thanks for the quick response, appreciate on providing above parameters .. the commit_write seems to be deprecated. The current parameter seems to be COMMIT_LOGGING = { IMMEDIATE | BATCH } and COMMIT_WAIT = { NOWAIT | WAIT | FORCE_WAIT }

    but the COMMIT_WAIT = NOWAIT , seems to be none ACID compliant , so I may not be able use this. do you have any experience with commit_wait=wait and commit_logging=batch ?

    Also any thoughts "redo log space requests" ?

    select * from gv$sysstat where name= 'redo log space requests'
    

    Thanks!

  • JohnWatson2
    JohnWatson2 Member Posts: 4,315 Silver Crown

    Ah yes, I get the parameter name wrong.

    As for whether NOWAIT BATCH violates ACID, you need to think it through: is it really a problem? Theoretically, a user could COMMIT and the COMMIT COMPLETE message is returned instantly. If the database instance then crashed before the log buffer had been flushed, the user would think that the transaction had committed but it would actually be rolled back after restart. How likely is that, and would it matter? If the DB were running ATM cash machines, yes! Because I could draw out a few dollars, and in that unlikely event the database could lose the transaction. But for most applications, it isn't critical. Not compared to losing 37% of your DB time.

    As for your redo log space requests, why do you think it is a problem?

  • Jonathan Lewis
    Jonathan Lewis Member Posts: 9,753 Gold Crown

    Redo log space requests is about the log file, not about the log buffer. (In fact the start of the section you quoted from the document you cited says:

    "The statistic "redo log space requests" reflects the number of times a user process waits for space in the redo log file, not the buffer space ."

    Given that the same section says its about log the buffer you have to figure out which statement is correct. But if you check the Reference Manual for the definition of instance activity stats (e.g. https://docs.oracle.com/en/database/oracle/oracle-database/19/refrn/statistics-descriptions-2.html#GUID-2FBC1B7E-9123-41DD-8178-96176260A639) it says:

    Redo log space requests:

    Number of times the active log file is full and Oracle must wait for disk space to be allocated for the redo log entries. Such space is created by performing a log switch.

    So if you DO have a problem with redo log space requests you should be increasing either the size or the number of online redo log files. But you haven't shown us any information that suggests that it's a problem (counts since instance startup mean nothing - how many happened in the interval you reported above - is that 30 minutes, by the way.)


    You didn't say how long an interval the report covered, but you've got over 1M log file sync waits and 3.4M single block reads in the interval, so perhaps it's not surprising that the log file parallel writes are slow. The interesting thing is that the average log file sync is more than double the log file parallel write - so you need to examine the event histogram for those two events: it is possible that a relatively small number of slow writes can lead to a large number of very slow syncs; it is possible that having too many concurrent processes per CPU can lead to lost time waiting in the O/S run queues; I also notice you have wait time related to log writer slave processes, so it's possible that the log file sync time is double the log file parallel write time because ALL the public redo threads have to be cleared before the sync can complete - and in your version of ORacle they are cleared serially not concurrently. There are also some buggy bits lurking in the code that handles the dialogue between LGWR and its slaves - do some checks on MOS, but you may find that it's a good idea to disable the log writer slave mechanism.

    Another detail that hints at delay due to inter process communication is the extremely length "gc buffer busy ..." average wait. This may, however, be a side effect of slow log writer times (gc block flush time is about waitng for log writes to complete before sending a buffer across the interconnect - check what the other nodes are reporting for that to see how this node is being affected.)

    Your parameter file says CPU_COUNT = 16, but since it's AIX Power 7 there's no way we can tell what that really means. Is this 16 tiny virtual/logical CPUs, can you work out what you've got in terms of percentage of a real CPU.

    Don't mess about with the commit_logging and commit_wait parameters unless you can find a very good reason why that will solve a performance problem.

    Regards

    Jonathan Lewis

    user591200
  • user591200
    user591200 Member Posts: 41 Bronze Badge

    @Jonathan Lewis

    Hi Jonathan,

    Glad to see your response, the AWR is 30 mins, the AIX physical core utilizations is like 21 max and 9 avg (SMT-4)/across the cluster (7 max per node and 3 min per node, 3 nodes).

    Following is how the redo logs are rotating

    Date        INST_ID Day              Total  h0  h1  h2  h3  h4  h5  h6  h7  h8  h9 h10 h11 h12 h13 h14 h15 h16 h17 h18 h19 h20 h21 h22 h23       Avg
    --------- ---------- ------------ ---------- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----------
    20-AUG-21         1 Fri                 23   0   0   0   0   0   0   0   0   0   0   0   0   0   0   0   0   4   3   4   2   3   3   2   2       .96
    20-AUG-21         2 Fri                 23   0   0   0   0   0   0   0   0   0   0   0   0   0   0   0   0   3   4   4   2   3   3   2   2       .96
    20-AUG-21         3 Fri                 24   0   0   0   0   0   0   0   0   0   0   0   0   0   0   0   0   3   4   4   3   2   3   3   2         1
    21-AUG-21         1 Sat                 80   3   5   2   6   3   4   4  12   2   3   4   3   3   3   3   2   3   3   3   2   2   2   2   1      3.33
    21-AUG-21         2 Sat                 65   3   4   1   4   4   3   2   4   2   3   4   3   3   3   3   3   2   3   2   2   2   2   2   1      2.71
    21-AUG-21         3 Sat                 70   3   4   1   6   3   4   5   5   2   2   4   3   3   3   3   2   3   3   2   2   2   2   2   1      2.92
    22-AUG-21         1 Sun                 81   5   5   1   5   3   5   2   2   2   4   3   4   4   4   4   4   4   3   3   3   3   3   2   3      3.38
    22-AUG-21         2 Sun                 79   4   4   1   5   3   4   3   4   3   3   4   3   4   4   4   3   3   3   3   3   3   2   3   3      3.29
    22-AUG-21         3 Sun                 89   5   3   2   5   4   5   3   5   7   4   3   4   4   4   4   4   4   3   3   3   2   3   3   2      3.71
    23-AUG-21         1 Mon                 89   5   4   1   5   4   4   2   4   3   5   4   5   5   5   4   4   3   4   4   3   3   2   3   3      3.71
    23-AUG-21         2 Mon                 96   3   4   1   5   4   4   6   7   7   4   4   5   5   5   3   4   4   4   4   3   3   3   2   2         4
    23-AUG-21         3 Mon                 83   3   2   2   4   4   3   2   4   3   4   4   5   5   5   4   4   3   4   4   4   3   2   3   2      3.46
    24-AUG-21         1 Tue                 77   3   4   1   4   4   3   7   5   6   2   3   4   3   2   3   4   3   3   2   3   3   2   2   1      3.21
    24-AUG-21         2 Tue                 71   5   3   1   4   3   4   2   6   4   2   3   3   4   2   3   4   3   3   2   3   2   2   2   1      2.96
    24-AUG-21         3 Tue                 69   3   4   1   4   4   3   2   3   3   3   4   3   3   3   3   3   4   3   3   2   3   2   2   1      2.88
    25-AUG-21         1 Wed                 71   5   4   1   3   4   4   7   6   2   2   2   3   3   3   2   2   3   3   3   2   2   2   1   2      2.96
    25-AUG-21         2 Wed                 68   5   3   2   4   4   3   2   4   2   2   3   3   3   3   3   4   3   3   2   3   2   2   2   1      2.83
    25-AUG-21         3 Wed                 67   4   4   1   3   4   4   3   5   2   2   2   3   3   3   3   4   3   2   3   2   2   2   2   1      2.79
    26-AUG-21         1 Thu                 67   4   4   1   5   3   1   4   5   2   2   3   3   3   3   3   4   3   3   2   3   1   2   2   1      2.79
    26-AUG-21         2 Thu                 64   4   4   1   3   4   1   3   2   3   3   3   3   3   3   3   4   2   3   3   3   1   2   2   1      2.67
    26-AUG-21         3 Thu                 69   4   4   1   5   4   3   5   5   2   2   3   3   3   3   2   3   3   4   2   2   1   2   2   1      2.88
    27-AUG-21         1 Fri                 46   4   4   1   3   1   1   4   5   2   3   4   3   2   3   3   3   0   0   0   0   0   0   0   0      1.92
    27-AUG-21         2 Fri                 44   4   4   1   4   1   1   2   4   2   4   3   3   3   3   2   3   0   0   0   0   0   0   0   0      1.83
    27-AUG-21         3 Fri                 43   4   4   1   2   1   1   5   2   2   3   4   3   2   3   3   3   0   0   0   0   0   0   0   0      1.79
    


    As you have mentioned above, are you referring to below parameters?

    good idea to disable the log writer slave mechanism.

    _log_parallelism_max = 1
    _use_single_log_writer = TRUE
    

    Currently the redo logs are setup in following way,

    GROUP# THREAD# SEQUENCE# SIZE_MB BLOCKSIZE MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIM NEXT_CHANGE# NEXT_TIME CON_ID
    ---------- ---------- ---------- ---------- ---------- ---------- --- ---------------- ---------------- --------- ------------ --------- ----------
    1 1 53097 1024 512 2 NO CURRENT 95431022495 27-AUG-21 1.8447E+19 0
    2 1 53095 1024 512 2 YES INACTIVE 95426303320 27-AUG-21 9.5429E+10 27-AUG-21 0
    3 2 52861 1024 512 2 YES INACTIVE 95426287318 27-AUG-21 9.5429E+10 27-AUG-21 0
    4 2 52862 1024 512 2 YES ACTIVE 95429064637 27-AUG-21 9.5431E+10 27-AUG-21 0
    5 3 53194 1024 512 2 YES INACTIVE 95426613701 27-AUG-21 9.5430E+10 27-AUG-21 0
    6 3 53195 1024 512 2 YES ACTIVE 95429602108 27-AUG-21 9.5431E+10 27-AUG-21 0
    7 1 53096 1024 512 2 YES ACTIVE 95428828226 27-AUG-21 9.5431E+10 27-AUG-21 0
    8 2 52863 1024 512 2 NO CURRENT 95431023367 27-AUG-21 1.8447E+19 0
    9 3 53196 1024 512 2 NO CURRENT 95431022332 27-AUG-21 1.8447E+19 0
    


    Thanks!

  • Jonathan Lewis
    Jonathan Lewis Member Posts: 9,753 Gold Crown

    Just _use_single_log_writer = true should be sufficient.

    There was a MOS note (that used to relate to 12.1, but may still be true but I can't tell because it has been pulled) that highlighted problems with the multiple log writer slaves - and there are a couple more still on MOS, but the ones I've seen claim to be fixed in 12.2. However, since a lot of the time lost on things like gc buffer busy etc. MIGHT be due to delayed log writing it's worth checking.

    The log file switch summary doesn't tell me anything useful, although the numbers suggest that the files are suitably sized. You need to look at the statistcs of the AWR report you sent me. In particular you should check for "redo log space %" in the Instance Activity - this will tell you how many waits and total time spent. I don't think the numbers will be significant (or they would have appeared in the original extract).

    I don't understand how to connect the instance report of cpu_count = 16 with your comment about min and max physical CPU, and max hitting 21. Does the SMt-4 mean that you're counting SMT threads as physical CPUs. From the way you supplied the figures does that mean you've got all three RAC instances running on the same physical hardware but in three separate domans (/ logical machines.

    Depending on what the configuration is, your 7 CPU max MIGHT mean you're ckise to maximum CPU utilisation on the instance you showed. But that's if 7 CPUs = 7 threads = 1.75 CPUs. Hight CPU load always aggravates the problems of inter-process communication


    Regards

    Jonathan Lewis

  • user591200
    user591200 Member Posts: 41 Bronze Badge

    @Jonathan Lewis

    Hi Jonathan,

    The 3 instances are hosted on 3 physical hosts and the lpar is allocated with 16 vcpu capped. Each Power-7 core is capable of running 4 threads (SMT-4 mode) , as its shown below Oracle sees total number of #CPUs = 64 and #Cores=16 , but I believe it is translated by the fact that 16 x 4 = 64 threads allocated to the lpar. The lpar contains 4 db instances , normally this db instance is responsible closer to 40 - 50% of the workload. (We are in the process of migrating these to Power-9/Oracle 19.11C very soon). it will be little difficult to give the per instance utilization of CPU's. (Because I did not capture that) , it could be like 3.x - 4.x cores per node for this db. (cluster wide 9 - 12 cores been utilized), across cluster 16x 3 = 48 Power-7 CPU's are allocated.


    The redo log space requests and redo space wait time are not indicating a significant value,


    Thanks,

  • Jonathan Lewis
    Jonathan Lewis Member Posts: 9,753 Gold Crown


    The first thing to note is that Oracle reported its CPU Time as 2,957 seconds but the OS stats report between 12,500 and 16,000 seconds, depending which instance. I'd like to think that Oracle is reporting only the lpar and not the whole machine - so where is the rest of the CPU going in that lpar?

    We still need to find out EXACTLY how much CPU your lpar is allowed. You say it's capped at 16 vcpus. But that says nothing about how much real CPU (or Thread) time you are allowed. If, for example, your cap corresponds to 16 threads then the report of 64 Threads and 16 CPUs is spurious, and the 16,000 CPU seconds is 1,000 seconds out of 1,800 seconds per CPU; worse still, 16 threads equates to 4 (real, SMT-capable) hardware CPUs, then that 16,000 busy CPU seconds in 1,800 elapsed seconds is pushing you way over capacity - in a way that won't show up as a CPU problem.


    Points 2: you'll note that the "redo log space wait time" total only 1.39 seconds, so it's not worth worrying about.

    You'll also notice that the "redo buffer allocation retries" matches the "redo log space requests". This tells you that the log buffer fills during log file switches - but that still doesn't make it a problem. If you look further down your Wait time reports you'll probably find a relatively small number of waits relating to "log file switch".

    On the back of the redo space/time details you'll note that there are two histograms in the stats that align pretty well:"redo synch time overhead" AND "redo write size count". You have a small number of large write requests which lead to a small number of relatively slow writes. You should check the trace files for the log writer processes (lgwr, lg00, lg01) which started reporting any extreme cases of slow/large writes a couple of versions ago. 

    A small number of very slow writes can have a significant impact on the average redo write time. (If I wait just once for 250 ms then - given your 600 transactions per seconds - there are 150 transactions waiting behind me for the log writer to notice that it has more work to do: so their average wait time will be ca. 125 ms even though their write time (when it happens) may take only 10ms.

    Technically you MIGHT make a difference and reduce this impact if the only problem is the log file switch by increasing the NUMBER of redo log files - possibly to as many as 10 - so that log files can become free for reuse faster. (Oracle changed the algorithm of log file switches and checkpointing years ago, so most of the notes you'll find on the internet about log file switches are likely to be out of date, even some of the ones published in the last 5 years)

    My main thoughts are still:

    • How much real CPU do you actually have in the lpar - I think you're probably overloading it.
    • There may be a significant benefit is dropping to a single log writer process
    • What processing are you doing that could be changed, or re-assigned, or re-timed to avoid doing 600 commits per second - and what recursive transactions are taking place that might be exacerbating the effect (e.g. are you doing something with a nocache sequence at high speed.)

    Regards

    Jonathan Lewis

    P.S. I can't send any more replies to this thread - the constant strean of delays introduced by the forum software makes it extremely slow work to type even a short sentence.

    user591200