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> @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> @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 KB
6 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> @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@xxxxxxxx> 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@xxxxxxxxxxxxx [mailto:
oracle-l-bounce@xxxxxxxxxxxxx] *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@xxxxxxxx> 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: @OracleSK
Chris Stephens <cstephens16@xxxxxxxxx> hat am 28. Januar 2020 um 21:49geschrieben:
corresponding to call profile of trace file (log file sync doesn't show up
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
prominently in report)
MIN MAX
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
------------------------------ ---------- ------ ------ ---------------- --------
log file sync 79.291166 76.0% 150 0.5286080.000264 2.986575
SQL*Net message from client 22.090587 21.2% 9,886 0.0022350.000216 7.900402
EXEC 2.537643 2.4% 9,702 0.0002620.000000 0.221403
row cache lock 0.068551 0.1% 124 0.0005530.000209 0.001036
PARSE 0.056969 0.1% 4,778 0.0000120.000000 0.001996
FETCH 0.055241 0.1% 1,029 0.0000540.000000 0.003969
CLOSE 0.042863 0.0% 4,784 0.0000090.000000 0.000180
DLM cross inst call completion 0.030066 0.0% 211 0.0001420.000005 0.000590
library cache lock 0.024349 0.0% 61 0.0003990.000160 0.000728
library cache pin 0.019441 0.0% 48 0.0004050.000157 0.000672
16 others 0.076164 0.1% 10,726 0.0000070.000000 0.001792
------------------------------ ---------- ------ ------ ---------------- --------
TOTAL (26) 104.293040 100.0% 41,499 0.0025130.000000 7.900402
--
I will check on lgwr / scalable log writer mode.
//www.freelists.org/webpage/oracle-l
