Wednesday, 11 July 2018

Broken DG configuration

Few days ago I 've run into the following situation on a DG configuration:
  • the primary shipped logs to the standby properly, but reported errors if asked for status in dgmgrl
    DGMGRL> show configuration
    
    Configuration - dbd
    
      Protection Mode: MaxPerformance
      Databases:
        db1d - Primary database
        db2d - Physical standby database
    
    Fast-Start Failover: DISABLED
    
    Configuration Status:
    ORA-16610: command "Broker operation" in progress
    DGM-17017: unable to determine configuration status
    
  • the standby initially did not process archivelogs, but after configuration reset (disable and enable operations) it started to process them, but also reported errors in dgmgrl
  • it was possible to log in from the primary to the standby
  • it was possible to log in from the standby to the primary
  • I copied password file from the primary to the standby to ensure this is the same file
  • when calling show database on the primary the errors were reported for the standby
  • when calling show database on the standby the errors were reported for the primary
What was the cause?
It showed that the problem was generated by the TNS entries on the primary - apparently the TNS alias definitions for the primary and the standby there included some blank characters, which caused the alias to be read improperly in case of dgmgrl - at the same time simple call to those aliases through sqlplus went ok.
Once I removed all the formatting in the tnsnames.ora, whole thing started to work properly. What is a bit interesting is that the errors in the TNS were present only on the primary, while the dgmgrl calls malfunctioned on both ends.

Role order

Lately a colleague of mine run into the problem with too many roles - some account have them 150, while maximally allowed are 148. He wanted to establish the order in which the roles are assigned to the user as obviously only the excess over 148 was thrown away.
He has found that the roles are loaded with the following query:
select /*+ connect_by_filtering */ privilege#,level from sysauth$ connect by grantee#=prior privilege# and privilege#>0 start with grantee#=:1 and privilege#>0; 
Thus it seems as the the order may be random, though it is possible that usually the data is returned in the order of insertion.

Friday, 29 June 2018

ORA-01554: transaction concurrency limit reached reason:no undo segment found with available slot params:0, 0 :

Some time ago I found such error on one of our databases. It is a bit mysterious as there are not much about it on Metalink (few bugs) or on the internet (at least when searching by Google). But indeed the database hit a limit of concurrent transactions in some very short period of time. On the performance chart in OEM there is a high peak with an INSERT to some custom table, with waits on TX - index contention, buffer busy, enq: SQ contention and undo segment tx slot.
The database is working with UNDO_MANAGEMENT=AUTO, which is a default setting and since 10g used very widely, so the administrator may simply forget about rollback segments management. According to the docs with this setting some work parameters relevant to the rollback management are simply ignored (TRANSACTIONS, TRANSACTIONS_PER_ROLLBACK_SEGMENT), while the number of transactions is limited by the undo tablespace size.
So it seems we should not experience this error, but rather session suspension and the error about lack of space in the undo tablespace.
Yet here are are. It is clear from the numbers below, that still there is a space in the undo (up to 4598 undo blocks used
What I could check is this:
select BEGIN_TIME, UNDOTSN, UNDOBLKS, TXNCOUNT, MAXQUERYLEN, MAXQUERYID, MAXCONCURRENCY, 
ACTIVEBLKS, UNEXPIREDBLKS, EXPIREDBLKS, TUNED_UNDORETENTION 
from v$undostat 
where begin_time between to_date('2018-06-25 14', 'yyyy-mm-dd hh24') and to_date('2018-06-25 16', 'yyyy-mm-dd hh24') 
order by begin_time;

BEGIN_TIMEUNDOBLKSTXNCOUNTMAXQUERYLENMAXCONCURRENCYACTIVEBLKSUNEXPIREDBLKSEXPIREDBLKSTUNED_UNDORETENTION
2018-06-25 14:3907816520160071682372
2018-06-25 14:4914119116532160071682373
2018-06-25 14:5945981042251653131160473658882373
2018-06-25 15:092169103321933311160665643521653
2018-06-25 15:19228217341160806428162454
Since the midnight the number of undo blocks consumed was 63475 with 524416 available blocks (so ~12%) and maximum query length was below 1h. Thus definitely we were far below the undo space limit. From this figures it is clear that still it is possible to hit an error typical for MANUAL undo management scenario, while on AUTO - as here we are.

And here few words of wisdom from Jonathan Lewis:
Taking a quick guess:

An (automatic) undo segment has 34 slots in the transaction table (the thing in the undo segment header).
If you and up with a small number N of undo segments then you can't have more than 34 * N concurrent transactions active because each one needs a transaction table slot and the next attempt to start a transaction would see ORA-01554

It seems a little unlikely that this would happan in typical system since Oracle would usually end up stealing an extent from an existing undo segment to use it as the first extent of a new undo segment. But it wouldn't be hard to set up a mechanism that started with a small number of undo segments in a relatively small undo tablespace - started some transactions (then leave them idle forever after the first change - e.g. they might have come in from a remote database) that made it impossible to free any extents, then did a lot of work to allocate all the extents (but still left a little space in allocated extents for continuting transactions), then started lots of transactions until you hit the error.

And Julian Dyke's presentation:
Undo segments are allocated at instance startup.
Undo segments can be added dynamically.

Each undo segment header contains
  • Pool of free undo extents
  • Set of undo slots

One undo slot is allocated to each transaction.
Undo slot contains list of undo extents.
Extents can migrate from one undo segment to another.
Undo slots are used cyclically:
  • remain in header as long as possible
  • reduces probability of ORA-01555: Snapshot too old

With all this in mind I would say that 1000 times higher transaction rate is in this particular case the main reason for the error. Apparently the db is not able to extend its concurrent transactions rate capability fast enough to respond to extended demand. Possible action here could be initial setting of _rollback_segment_count to a higher value than 12, which are set here.

Monday, 18 June 2018

High latch free on Exadata

Today I have investigated an issue with poor performance on some processing. On the production environment the thing have been usually accomplished in some 5 minutes, while on one of test databases it took once 5h to complete.
As this was a RAC on Exadata machine, AWR report was not that much helpful, though immediately was clear the main problem was a latch free event. The problem was, which latch was responsible here.
The performance chart in OEM did not provide SQL text (as apparently those calls were one-time SQL calls - candidates for dealing with them by setting cursor_sharing to FORCE).
A good step was to call the following query:
select name, (misses/decode(gets,0,1,gets) )*100 ratio, 
       (immediate_misses/decode(immediate_gets,0,1,immediate_gets))*100 immediate_ratio,
        spin_gets, wait_time
 from v$latch
where wait_time > 0
order by 2
;
While one can not be 100% sure the query indicates the right latch, it at least gives some clues. This time the only distinctive ratio (around 40%) was Result Cache: RC Latch. The other one with around 10% was resource manager latch but there the number of gets and misses in total was fairly small, so it was not that interesting.
I've looked for this latch name and found few articles on the subject:

Friday, 8 June 2018

RMAN-3008/RMAN-3009 and RMAN-20095

Today I had the following problem:
  • initially the backup failed with
    RMAN-00571: ===========================================================
    RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
    RMAN-00571: ===========================================================
    RMAN-03008: error while performing automatic resync of recovery catalog
    RMAN-20095: invalid backup/copy control file checkpoint SCN
    
  • every next backup failed with
    RMAN-03014: implicit resync of recovery catalog failed
    RMAN-03009: failure of partial resync command on default channel at 06/07/2018 04:18:50
    RMAN-20095: invalid backup/copy control file checkpoint SCN
    
This is reported on Metalink as "Bug 19209117 RMAN-3008 RMAN-20095 while performing Automatic Resync"

How to move forward?
I found the 1st backup, which failed, then in this backup log found the place the 1st time the error occurred, then started to uncatalog since that place upward. Please note the uncataloging has to take place when connected only to the database (i.e. when working only with backaup entries stored within a control file) - otherwise rman will try as a 1st step implicitly resync the catalog which will lead to the error over and over again.
change backuppiece '/path_to_backup/cf_YYYYY_c-283029066-20180607-02' uncatalog;
The first call to uncatalog controlfile backup was enough.
In the debug of call to resync catalog during problems there is the following section:
DBGRESYNC:     channel default:   file# 0 [11:30:20.805] (resync)
DBGRPC:        krmxrpc - channel default kpurpc2 err=0 db=rcvcat proc=BSPEP.DBMS_RCVCAT.CHECKBACKUPDATAFILE excl: 0
   DBGRCVCAT: addBackupControlfile - Inside dup_val_on_index exception
DBGRESYNC:     channel default: Calling checkBackupDataFile for set_stamp 978149312 set_count 8542 recid 6038 [11:30:20.807] (resync)
DBGRESYNC:     channel default:   file# 0 [11:30:20.807] (resync)
DBGRPC:        krmxrpc - channel default kpurpc2 err=20095 db=rcvcat proc=BSPEP.DBMS_RCVCAT.CHECKBACKUPDATAFILE excl: 129
   DBGRCVCAT: addBackupControlfile - Inside dup_val_on_index exception
   DBGRCVCAT: addBackupControlfile - ckp_scn 3201066972364 ckp_time 07-JUN-18
   DBGRCVCAT: addBackupControlfile - lckp_scn 3201066972565 lckp_time 07-JUN-18
DBGRPC:        krmxrpc - channel default kpurpc2 err=0 db=rcvcat proc=BSPEP.DBMS_RCVCAT.CANCELCKPT excl: 0
   DBGRCVCAT: cancelCkpt - rollback, released all locks

-- here the moment the error 20095 is catched
DBGPLSQL:     EXITED resync with status ORA--20095 [11:30:20.992]
DBGRPC:       krmxr - channel default returned from peicnt
DBGMISC:      ENTERED krmstrim [11:30:20.992]
DBGMISC:       Trimming message: ORA-06512: at line 3401 [11:30:20.992] (krmstrim)
DBGMISC:        (24) (krmstrim)
DBGMISC:      EXITED krmstrim with status 24 [11:30:20.992] elapsed time [00:00:00:00.000]
DBGRPC:       krmxr - channel default got execution errors (step_60)
DBGRPC:       krmxr - exiting with 1
DBGMISC:      krmqexe: unhandled exception on channel default [11:30:20.992]
DBGMISC:     EXITED krmiexe with status 1 [11:30:20.992] elapsed time [00:00:01:21.889]
[..]
DBGMISC:     error recovery releasing channel resources [11:30:20.992]
DBGRPC:      krmxcr - channel default resetted
DBGMISC:     ENTERED krmice [11:30:20.993]
DBGMISC:      command to be compiled and executed is: cleanup  [11:30:20.993] (krmice)
DBGMISC:      command after this command is: NONE  [11:30:20.993] (krmice)
[..]
DBGMISC:     EXITED krmice [11:30:21.017] elapsed time [00:00:00:00.024]
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03009: failure of resync command on default channel at 06/08/2018 11:30:20
RMAN-20095: invalid backup/copy control file checkpoint SCN

Tuesday, 22 May 2018

ORA-04030 on a process with large memory requirements

Lately I've met with the following problem. The database in version 11.2.0.4, the application with an evening batch job. At some point the batch job started to fail constantly, reaching around 4500M of allocated PGA. All the efforts to increase PGA_AGGREGATE_TARGET were void, we increased 1st to 5G (from 3), then to 8, but still failed at pretty much the same allocation.
Top allocations look as follows:
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------
70% 3204 MB, 205630 chunks: "pmuccst: adt/record       "  PL/SQL
         koh-kghu call   ds=0x7f2e2ea3c938  dsprt=0xb8c04a0
30% 1356 MB, 87052 chunks: "pl/sql vc2                "  PL/SQL
         koh-kghu call   ds=0x7f2e2ea3c938  dsprt=0xb8c04a0
I've found an article on Metalink (ORA-04030 Error For Memory Allocation Type "pmuccst: adt/record" (Doc ID 1513623.1)), but there was stated that this allocation is common for PL/SQL collections and it is not possible to limit it with PGA_AGGREGATE_TARGET (or _pga_max_size) as this is a different allocation bound with the heap of the process and governed with other settings. Similarly pl/sql vc2 allocation is common for local variables like varrays (ORA-04030 Error For Memory Allocation Type "pl/sql vc2" (Doc ID 1315884.1)).

There are few solutions to the problem above - one is to rewrite the PL/SQL code to replace those large collections with GTT or another is limit collections to fetch only limited number of entries and process cursors in loops.
There is also (as it finally shows up) a possibility to deal with this threshold.
There are the following parameters, which govern this allocation:
  • vm.max_map_count, which is set to 65530 by default - on OS level
  • _use_realfree_heap - hidden db parameter (in 11.2.0.4 defaults to TRUE) - this one enables the whole feature apparently
  • _realfree_heap_pagesize_hint - hidden db parameter (in 11.2.0.4 defaults to 65536) - this one sets page size, so e.g. with increase to 262144 we can increase the memory allocation to around 16G
  • _realfree_heap_pagesize (since 12c)
  • _realfree_heap_max_size - hidden db parameter (in 11.2.0.4 defaults to 32768) - it is described as "minimum max total heap size", in Kbytes - not sure exactly what does that mean and what is controlled by that
The indication, that this is a problem with realfree heap, is present in the process map dump - in this case the dump displayed exactly maximal allowed number of entries.

In general it seems the memory available to the process is calculated as vm.max_map_count * _realfree_heap_pagesize_hint, thus one may affect one of multipliers or both of them, where max_map_count controls the number of allocations while realfree_heap_pagesize the amount of memory within one allocation.

Friday, 13 April 2018

ORA-12154 while duplicating from active database on RAC

A colleague of mine tried to rebuild a standby from some primary database. He prepared, added proper entries to tnsnames.ora on both clusters (primary and standby), then fired duplicate command. When it came to
restore clone from service  'ORCLPRIM' standby controlfile;
the command failed with:
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-03002: failure of Duplicate Db command at 04/13/2018 12:54:04
RMAN-05501: aborting duplication of target database
RMAN-03015: error occurred in stored script Memory Script
RMAN-06136: ORACLE error from auxiliary database: ORA-17629: Cannot connect to the remote database server
ORA-17627: ORA-12154: TNS:could not resolve the connect identifier specified
ORA-17629: Cannot connect to the remote database server
We checked tnsnames.ora files, connections 'standby to primary' and 'primary to standby' - all seemed ok.

Sometimes it is some 'invisible' character in tnsnames.ora, which gets in the way, sometimes simple lack of definition. But not this time, so this case is a bit more interesting...
The grid binaries and database binaries have different homes here and keep different tnsnames.ora files (as there is no shared TNS_ADMIN location).
And the solution was to add the required TNS entries also to the grid home.
My supposition is as follows:
  • the point where the command is issued is the standby instance, to which the script connects through statically registered interface.
  • the listener is fired from the grid home (and not db), so its environment is derived from grid, even though in static registration definition the db home is pointed as ORACLE_HOME
  • thus addition of TNS definitions to the grid home tnsnames.ora helped
  • I 've found also that for some static registration entries there was added additional clause ENVS (disclaimer: this parameter in not supported on Windows, any process started by the listener will simply inherit the listener's environment) in the form
    (SID_DESC =
          (SID_NAME = orclstb1)
          (ORACLE_HOME = [db home])
          (GLOBAL_DBNAME = orclstb_dgmgrl)
          (ENVS = "TNS_ADMIN=[db home]/network/admin") 
    )
    
    so seems my supposition is correct and this way is another way to get around this issue