Re: intermittent long "log file sync" waits
From: Chris Stephens <cstephens16_at_gmail.com>
Date: Thu, 30 Jan 2020 07:57:14 -0600
Message-ID: <CAEFL0sxoooae+f7j_NbyWu009jEMpzOtupHyvJ2Fr+mVn5Jrpw_at_mail.gmail.com>
_inmemory_ext_roarea 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
_inmemory_ext_rwarea 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
7 where first_time > trunc(sysdate-5) 8 and dest_id = (select dest_id from V$ARCHIVE_DEST_STATUS where status='VALID' and type='LOCAL')
9 group by thread#, trunc(completion_time) 10 order by 2,1
11 ;
THREAD# DATE NUM GB MB KB
__________ ______________ _______ ______ _________ ______________
Date: Thu, 30 Jan 2020 07:57:14 -0600
Message-ID: <CAEFL0sxoooae+f7j_NbyWu009jEMpzOtupHyvJ2Fr+mVn5Jrpw_at_mail.gmail.com>
Hey Mark,
Sorry for delayed response. I saw this on my phone over lunch and forgot to reply when I got back to work.
No resource manager plan in place (which i think i need to correct when we want to enable PQ right?)
SQL> _at_pd resource_manager_plan
Show all parameters and session values from x$ksppi/x$ksppcv...
NUM N_HEX PD_NAME PD_VALUE
PD_DESCR
______ ________ _________________________ ___________
_________________________________________
453 1C5 _resource_manager_plan resource mgr top plan
for internal use
454 1C6 resource_manager_plan resource mgr top plan
I have an SR open and Oracle has filed unpublished bug 30235630.
No resize ops since Jan 17:
SQL> _at_sgares
SGARES_COMPONENT OPER_TYPE OPER_MODE
SGARES_PARAMETER INITIAL_SIZE TARGET_SIZE FINAL_SIZE STATUS
START_TIME END_TIME
______________________________ _______________ ____________
___________________________ _______________ ______________ ______________
___________ ______________________ ______________________
shared pool STATIC
shared_pool_size 0 6845104128 6845104128
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
In Memory RO Extension Area STATIC
_inmemory_ext_roarea 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
java pool STATIC java_pool_size
0 671088640 671088640 COMPLETE
2020-01-17 16:20:48 2020-01-17 16:20:48
streams pool STATIC
streams_pool_size 0 268435456 268435456
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
unified pga pool STATIC
_unified_pga_pool_size 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
DEFAULT buffer cache STATIC db_cache_size
0 45365592064 45365592064 COMPLETE
2020-01-17 16:20:48 2020-01-17 16:20:48
ASM Buffer Cache STATIC db_cache_size
0 0 0 COMPLETE
2020-01-17 16:20:48 2020-01-17 16:20:48
DEFAULT buffer cache INITIALIZING db_cache_size
45365592064 45365592064 45365592064 COMPLETE
2020-01-17 16:20:48 2020-01-17 16:20:52
DEFAULT 2K buffer cache STATIC
db_2k_cache_size 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
DEFAULT 4K buffer cache STATIC
db_4k_cache_size 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
DEFAULT 8K buffer cache STATIC
db_8k_cache_size 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
DEFAULT 16K buffer cache STATIC
db_16k_cache_size 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
DEFAULT 32K buffer cache STATIC
db_32k_cache_size 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
KEEP buffer cache STATIC
db_keep_cache_size 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
RECYCLE buffer cache STATIC
db_recycle_cache_size 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
memoptimize buffer cache STATIC
memoptimize_pool_size 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
Shared IO Pool STATIC
_shared_io_pool_size 0 134217728 134217728
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
Data Transfer Cache STATIC
data_transfer_cache_size 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
In-Memory Area STATIC inmemory_size
0 0 0 COMPLETE
2020-01-17 16:20:48 2020-01-17 16:20:48
In Memory RW Extension Area STATIC
_inmemory_ext_rwarea 0 0 0
COMPLETE 2020-01-17 16:20:48 2020-01-17 16:20:48
large pool STATIC large_pool_size
0 268435456 268435456 COMPLETE
2020-01-17 16:20:48 2020-01-17 16:20:48
huh...maybe log file switches is exacerbating and/or causing the issue:
THREAD# date Day total h00 h01 h02 h03
h04 h05 h06 h07 h08 h09 h10 h11 h12 h13 h14
h15 h16 h17 h18 h19 h20 h21 h22 h23
__________ ______________ ______ ________ ______ ______ ______ ______
______ ______ ______ ______ ______ ______ ______ ______ ______ ______
______ ______ ______ ______ ______ ______ ______ ______ ______ ______
1 25 JAN 2020 Sat 798 0 3 14 11
13 15 17 22 26 27 29 34 38 39 41
43 45 47 49 51 53 58 59 64
2 25 JAN 2020 Sat 849 0 3 14 11
13 15 17 22 26 30 31 36 40 41 43
45 50 51 56 57 59 61 63 65
3 25 JAN 2020 Sat 997 0 6 18 16
17 19 24 28 32 36 37 42 46 47 49
51 56 57 62 63 68 72 73 78
1 26 JAN 2020 Sun 2558 68 69 151 79
84 88 89 91 93 98 102 103 108 112 113
115 117 119 121 123 125 127 129 134
2 26 JAN 2020 Sun 2464 67 69 146 77
79 84 85 87 92 93 95 100 104 105 110
111 113 115 117 119 121 123 125 127
3 26 JAN 2020 Sun 2950 82 86 183 95
100 104 105 107 109 111 116 117 122 123 128
129 131 133 138 142 143 145 150 151
1 27 JAN 2020 Mon 3990 135 137 282 145 147 149 151 153 155 157 159 161 163 139 161 161 170 163 194 168 178 186 189 187
2 27 JAN 2020 Mon 3821 129 131 270 139 141 143 145 150 151 153 155 160 161 139 161 159 161 171 181 167 163 165 151 175
3 27 JAN 2020 Mon 4687 153 158 322 168 172 173 178 182 183 185 190 194 195 160 189 181 206 209 211 214 203 217 221 223
1 28 JAN 2020 Tue 5550 122 276 311 298 232 205 175 247 213 219 187 245 225 221 223 239 235 225 219 239 245 243 251 255
2 28 JAN 2020 Tue 5367 156 220 269 304 222 185 189 219 201 211 209 219 219 219 215 230 228 217 229 237 237 241 244 247
3 28 JAN 2020 Tue 6373 138 315 367 333 242 245 244 253 252 255 246 275 264 255 189 271 275 275 246 279 284 279 290 301
1 29 JAN 2020 Wed 2444 249 255 261 518
265 267 269 271 84 0 0 0 1 0 0
0 0 0 1 0 2 0 1 0
2 29 JAN 2020 Wed 2405 248 255 315 454
264 268 271 273 42 0 1 0 1 0 1
0 0 1 3 0 4 0 4 0
3 29 JAN 2020 Wed 2864 278 301 326 588
312 315 317 320 102 0 0 0 0 0 1
0 0 0 1 0 1 0 2 0
1 30 JAN 2020 Thu 5 1 0 1 0
1 1 0 1 0 0 0 0 0 0 0
0 0 0 0 0 0 0 0 0
2 30 JAN 2020 Thu 15 3 1 2 1
2 2 2 2 0 0 0 0 0 0 0
0 0 0 0 0 0 0 0 0
3 30 JAN 2020 Thu 5 1 0 1 0
1 0 1 1 0 0 0 0 0 0 0
0 0 0 0 0 0 0 0 0
18 rows selected.
SQL> select THREAD#, trunc(completion_time) as "DATE"
2 , count(1) num 3 , trunc(sum(blocks*block_size)/1024/1024/1024) as GB 4 , trunc(sum(blocks*block_size)/1024/1024) as MB 5 , sum(blocks*block_size)/1024 as KB6 from v$archived_log
7 where first_time > trunc(sysdate-5) 8 and dest_id = (select dest_id from V$ARCHIVE_DEST_STATUS where status='VALID' and type='LOCAL')
9 group by thread#, trunc(completion_time) 10 order by 2,1
11 ;
THREAD# DATE NUM GB MB KB
__________ ______________ _______ ______ _________ ______________
1 25 JAN 2020 798 4 4927 5045460
2 25 JAN 2020 849 2 2945 3016640.5
3 25 JAN 2020 997 9 10194 10439208.5
1 26 JAN 2020 2558 14 15170 15534632.5
2 26 JAN 2020 2464 8 8839 9052122
3 26 JAN 2020 2950 30 30994 31737893
1 27 JAN 2020 3990 22 22801 23348572.5
2 27 JAN 2020 3821 66 67974 69605574.5
3 27 JAN 2020 4687 45 46557 47675299.5
1 28 JAN 2020 5550 29 30308 31036136
2 28 JAN 2020 5367 293 300736 307953909.5
3 28 JAN 2020 6373 55 57085 58455647.5
1 29 JAN 2020 2444 17 18256 18694448
2 29 JAN 2020 2405 205 210578 215632638.5
3 29 JAN 2020 2864 24 24660 25252497
1 30 JAN 2020 5 0 49 50711.5
2 30 JAN 2020 15 12 12716 13021758.5
3 30 JAN 2020 5 0 124 126987.5
18 rows selected.
I have 10 1GB redo logs / instance:
SQL> _at_log
Show redo log layout from V$LOG, V$STANDBY_LOG and V$LOGFILE...
GROUP# THREAD# SEQUENCE# BYTES BLOCKSIZE MEMBERS ARCHIVED STATUS FIRST_CHANGE# FIRST_TIME NEXT_CHANGE# NEXT_TIME CON_ID
_________ __________ ____________ _____________ ____________ __________
___________ ___________ ________________ ______________
_______________________ ______________ _________
201 1 5808 1073741824 512 1 YES INACTIVE 977176498 29 JAN 2020 977270909 30 JAN 2020 0 202 1 5809 1073741824 512 1 YES INACTIVE 977270909 30 JAN 2020 977391147 30 JAN 2020 0 203 1 5810 1073741824 512 1 YES INACTIVE 977391147 30 JAN 2020 977493024 30 JAN 2020 0 204 1 5811 1073741824 512 1 YES INACTIVE 977493024 30 JAN 2020 977568300 30 JAN 2020 0 205 1 5812 1073741824 512 1 YES INACTIVE 977568300 30 JAN 2020 977658325 30 JAN 2020 0 206 1 5813 1073741824 512 1 NO CURRENT 977658325 30 JAN 2020 18446744073709551615 0 207 1 5804 1073741824 512 1 YES INACTIVE 976026050 29 JAN 2020 976861880 29 JAN 2020 0 208 1 5805 1073741824 512 1 YES INACTIVE 976861880 29 JAN 2020 976962754 29 JAN 2020 0 209 1 5806 1073741824 512 1 YES INACTIVE 976962754 29 JAN 2020 977038519 29 JAN 2020 0 210 1 5807 1073741824 512 1 YES INACTIVE 977038519 29 JAN 2020 977176498 29 JAN 2020 0 211 2 5765 1073741824 512 1 YES INACTIVE 977568233 30 JAN 2020 977611133 30 JAN 2020 0 212 2 5766 1073741824 512 1 YES INACTIVE 977611133 30 JAN 2020 977627280 30 JAN 2020 0 213 2 5767 1073741824 512 1 YES INACTIVE 977627280 30 JAN 2020 977658278 30 JAN 2020 0 214 2 5768 1073741824 512 1 YES INACTIVE 977658278 30 JAN 2020 977686371 30 JAN 2020 0 215 2 5769 1073741824 512 1 NO CURRENT 977686371 30 JAN 2020 18446744073709551615 0 216 2 5760 1073741824 512 1 YES INACTIVE 977415597 30 JAN 2020 977446081 30 JAN 2020 0 217 2 5761 1073741824 512 1 YES INACTIVE 977446081 30 JAN 2020 977491939 30 JAN 2020 0 218 2 5762 1073741824 512 1 YES INACTIVE 977491939 30 JAN 2020 977509788 30 JAN 2020 0 219 2 5763 1073741824 512 1 YES INACTIVE 977509788 30 JAN 2020 977538906 30 JAN 2020 0 220 2 5764 1073741824 512 1 YES INACTIVE 977538906 30 JAN 2020 977568233 30 JAN 2020 0 221 3 5038 1073741824 512 1 YES INACTIVE 977126597 29 JAN 2020 977206443 29 JAN 2020 0 222 3 5039 1073741824 512 1 YES INACTIVE 977206443 29 JAN 2020 977300069 30 JAN 2020 0 223 3 5040 1073741824 512 1 YES INACTIVE 977300069 30 JAN 2020 977415692 30 JAN 2020 0 224 3 5041 1073741824 512 1 YES INACTIVE 977415692 30 JAN 2020 977511539 30 JAN 2020 0 225 3 5042 1073741824 512 1 YES INACTIVE 977511539 30 JAN 2020 977612291 30 JAN 2020 0 226 3 5043 1073741824 512 1 YES INACTIVE 977612291 30 JAN 2020 977686425 30 JAN 2020 0 227 3 5044 1073741824 512 1 NO CURRENT 977686425 30 JAN 2020 18446744073709551615 0 228 3 5035 1073741824 512 1 YES INACTIVE 976434830 29 JAN 2020 976889647 29 JAN 2020 0 229 3 5036 1073741824 512 1 YES INACTIVE 976889647 29 JAN 2020 976981047 29 JAN 2020 0 230 3 5037 1073741824 512 1 YES INACTIVE 976981047 29 JAN 2020 977126597 29 JAN 2020 0
with that frequency of log file switches, does it make sense to increase redo log size to 10x10GB?
"I guaranteed you this is not magic." ... that's what i keep telling myself. was pretty burned out yesterday feeling like i was out of ideas but ready to get back at it today.
Chris
On Wed, Jan 29, 2020 at 10:55 AM Mark W. Farnham <mwf_at_rsiz.com> wrote:
> Do all y’all have some consumer group limits running? > > > > Your trouble with Tanel’s script “ERROR at line 14: > > ORA-12850: Could not allocate slaves on all specified instances: 3 needed, > 1 allocated” > > > > makes me suspect this. > > > > I have seen severe intermittent problems associated with DBRM and parallel > slaves reaching impossible solution spaces, often associated with the CPU > starvation problems that JL mentioned. > > > > And even though it was not a silver bullet in this case, I want to mention > that I endorse highly the nano-second look aside Tim mentioned to check for > resize ops. That’s on my list of “so cheap to check, so disruptive to all > other metrics” things that I consider worthwhile. (That’s a mutating list > that started somewhere around 1984, and a lot has aged out based on better > instrumentation and Oracle actually has fixed a **lot** of stuff since > then.) > > > > Good luck. Also compare the time of day/date with your log > archiving/remote site transmissions and any “backups” done by sysadmins > that you can’t see in the Oracle consumption metrics. Is there a pattern > for the 25 second problems that screams to be checked? I guaranteed you > this is not magic. > > > > *From:* oracle-l-bounce_at_freelists.org [mailto: > oracle-l-bounce_at_freelists.org] *On Behalf Of *Cary Millsap > *Sent:* Tuesday, January 28, 2020 4:04 PM > *To:* Stefan Koehler > *Cc:* Chris Stephens; oracle-l > *Subject:* Re: intermittent long "log file sync" waits > > > > And Chris, MRPROF-ERROR-0004 is a known bug in Workbench 8.1.2.1 that is > fixed in 9.0. If you'd like to send me your trace file directly, I'll be > happy to profile it for you with 9.0. > > > > > > Cary Millsap > Method R Corporation > > Author of *Optimizing Oracle Performance <http://amzn.to/OM0q75>* > > and *The Method R Guide to Mastering Oracle Trace Data, 3rd edition > <https://amzn.to/2IhhCG6+-+Millsap+2019.+Mastering+Oracle+Trace+Data+3ed>* > > > > > > > > On Tue, Jan 28, 2020 at 2:59 PM Stefan Koehler <contact_at_soocs.de> wrote: > > Hello Chris, > it seems like it is accounted as "MRPROF-ERROR-0004" in the Method-R > report. > > Can you possibly send the raw trace file as a compressed file? :) > > Thanks. > > Best Regards > Stefan Koehler > > Independent Oracle performance consultant and researcher > Website: http://www.soocs.de > Twitter: _at_OracleSK > > > Chris Stephens <cstephens16_at_gmail.com> hat am 28. Januar 2020 um 21:49 > geschrieben: > > > > man, all the Heavy Weights from oracle-l! (Stefan/JL/Tim/Noveljic) > > > > I'm not exactly sure what is going on here. attached is method r report > corresponding to call profile of trace file (log file sync doesn't show up > prominently in report) > > > > Duration by call name > > mrskew "/Users/cs2018/no_keep/lsst2db2_ora_8486.trc" > > Run began 2020-01-28T14:44:09, lasted 3.435000 seconds > > > > input files: > > '/Users/cs2018/no_keep/lsst2db2_ora_8486.trc' > > > > where expression: > > ((1) and ($dep==$depmin)) and ($nam=~/(?^:(?i).+)/) > > > > group expression: > > $nam > > > > matched call names: > > 'CLOSE' > > 'DLM cross inst call completion' > > 'Disk file operations I/O' > > 'EXEC' > > 'FETCH' > > 'IPC group service call' > > 'KJC: Wait for msg sends to complete' > > 'PARSE' > > 'PGA memory operation' > > 'SQL*Net message from client' > > 'SQL*Net message to client' > > 'SQL*Net more data from client' > > 'XCTEND' > > 'enq: FB - contention' > > 'enq: TM - contention' > > 'enq: TS - contention' > > 'enq: TT - contention' > > 'gc current grant 2-way' > > 'gc current multi block request' > > 'ges resource directory to be unfrozen' > > 'index (re)build lock or pin object' > > 'library cache lock' > > 'library cache pin' > > 'log file sync' > > 'reliable message' > > 'row cache lock' > > > > CALL-NAME DURATION % CALLS MEAN > MIN MAX > > ------------------------------ ---------- ------ ------ -------- > -------- -------- > > log file sync 79.291166 76.0% 150 0.528608 > 0.000264 2.986575 > > SQL*Net message from client 22.090587 21.2% 9,886 0.002235 > 0.000216 7.900402 > > EXEC 2.537643 2.4% 9,702 0.000262 > 0.000000 0.221403 > > row cache lock 0.068551 0.1% 124 0.000553 > 0.000209 0.001036 > > PARSE 0.056969 0.1% 4,778 0.000012 > 0.000000 0.001996 > > FETCH 0.055241 0.1% 1,029 0.000054 > 0.000000 0.003969 > > CLOSE 0.042863 0.0% 4,784 0.000009 > 0.000000 0.000180 > > DLM cross inst call completion 0.030066 0.0% 211 0.000142 > 0.000005 0.000590 > > library cache lock 0.024349 0.0% 61 0.000399 > 0.000160 0.000728 > > library cache pin 0.019441 0.0% 48 0.000405 > 0.000157 0.000672 > > 16 others 0.076164 0.1% 10,726 0.000007 > 0.000000 0.001792 > > ------------------------------ ---------- ------ ------ -------- > -------- -------- > > TOTAL (26) 104.293040 100.0% 41,499 0.002513 > 0.000000 7.900402 > > > > > > I will check on lgwr / scalable log writer mode. > -- > http://www.freelists.org/webpage/oracle-l > >
-- http://www.freelists.org/webpage/oracle-lReceived on Thu Jan 30 2020 - 14:57:14 CET