Direct Path Read Write Temp while Selecting CLOB from GV$ in RAC

I was intestigating why a simple SELECT * FROM GV$SQL started working much slower in 19c compared to 11.2.0.4. It turns out Oracle introduced some changes there in 18c. This blog post is written to demonstrate the new behavior.

A simple test case which I constructed for this example is below:

set echo on
set timing on

select banner from v$version;
alter session set events 'sql_trace wait=true';
begin
  for r in (
    select sql_fulltext
      from gv$sql)
  loop
    null;
  end loop;
end;
/
alter session set events 'sql_trace off';

select value
  from v$diag_info
 where name='Default Trace File';

I ran it in 19.10 and got the following results:

SQL> select banner from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production

Elapsed: 00:00:00.00
SQL> alter session set events 'sql_trace wait=true';

Session altered.

Elapsed: 00:00:00.00
SQL> begin
  2    for r in (
  3      select sql_fulltext
  4        from gv$sql)
  5    loop
  6      null;
  7    end loop;
  8  end;
  9  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:02.14
SQL> alter session set events 'sql_trace off';

Session altered.

Elapsed: 00:00:00.00
SQL>
SQL> select value
  2    from v$diag_info
  3   where name='Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl19/orcl191/trace/orcl191_ora_19616.trc

Elapsed: 00:00:00.00

I processed the trace file using tkprof and got the output below:

SQL ID: 250c8asaww0wz Plan Hash: 1891717107

SELECT SQL_FULLTEXT
FROM
 GV$SQL


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       21      0.44       2.13        288        288      25355        2011
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       23      0.44       2.13        288        288      25355        2011

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: SYS   (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      2011       2011       2011  PX COORDINATOR  (cr=288 pr=288 pw=2259 time=2499846 us starts=1)
         0          0          0   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=1638400 card=100)
         0          0          0    VIEW  GV$SQL (cr=0 pr=0 pw=0 time=0 us starts=0)
         0          0          0     FIXED TABLE FULL X$KGLCURSOR_CHILD (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=1638400 card=100)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                           18        0.00          0.00
  PX Deq: reap credit                           232        0.00          0.00
  PX Deq: Join ACK                                2        0.00          0.00
  PX Deq: Parse Reply                             2        0.00          0.00
  PX Deq: Execute Reply                         146        0.00          0.00
  Disk file operations I/O                        5        0.00          0.00
  CSS initialization                              2        0.00          0.00
  CSS operation: query                            6        0.00          0.00
  CSS operation: action                           2        0.00          0.00
  asynch descriptor resize                        1        0.00          0.00
  ASM IO for non-blocking poll                 6769        0.00          0.00
  direct path write temp                       2158        0.00          1.59
  db file sequential read                       144        0.00          0.06
  direct path read temp                         144        0.00          0.06
  reliable message                                1        0.00          0.00
  PX Deq: Signal ACK EXT                          2        0.00          0.00
  IPC send completion sync                        1        0.00          0.00
  PX Deq: Slave Session Stats                     2        0.00          0.00
  IPC group service call                          1        0.00          0.00
  enq: PS - contention                            1        0.00          0.00

It is worth noting that the number of rows is 2011 while the number of direct path write temp wait events is 2158. I believe it is a general pattern rather than a coincidence based on my tests. I found that the number of direct path write temp is always greater than the number of rows but not much. That basically means that Oracle does at least one write per CLOB returned.
Let us now compare it with 12.2 (I tested both 12.2 and 12.2 with the latest release update):

SQL> select banner from v$version;

BANNER
--------------------------------------------------------------------------------
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
PL/SQL Release 12.2.0.1.0 - Production
CORE    12.2.0.1.0      Production
TNS for Linux: Version 12.2.0.1.0 - Production
NLSRTL Version 12.2.0.1.0 - Production

Elapsed: 00:00:00.01
SQL> alter session set events 'sql_trace wait=true';

Session altered.

Elapsed: 00:00:00.00
SQL> begin
  2    for r in (
  3      select sql_fulltext
  4        from gv$sql)
  5    loop
  6      null;
  7    end loop;
  8  end;
  9  /

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.05
SQL> alter session set events 'sql_trace off';

Session altered.

Elapsed: 00:00:00.00
SQL>
SQL> select value
  2    from v$diag_info
  3   where name='Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/o122a/o122a1/trace/o122a1_ora_24892.trc

It can be seen that 12.2 is much faster than 19.10.
Here is a tkprof processed output:

SQL ID: 250c8asaww0wz Plan Hash: 1891717107

SELECT SQL_FULLTEXT
FROM
 GV$SQL


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       21      0.02       0.03          0          0          0        2069
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       23      0.03       0.05          0          0          0        2069

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 76     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      2069       2069       2069  PX COORDINATOR  (cr=0 pr=0 pw=0 time=138102 us starts=1)
         0          0          0   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=200200 card=100)
         0          0          0    VIEW  GV$SQL (cr=0 pr=0 pw=0 time=0 us starts=0)
         0          0          0     FIXED TABLE FULL X$KGLCURSOR_CHILD (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=200200 card=100)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  enq: PS - contention                            3        0.00          0.00
  PX Deq: Join ACK                                5        0.00          0.00
  PX Deq: reap credit                           277        0.00          0.00
  IPC send completion sync                        3        0.00          0.00
  PX Deq: Parse Reply                             2        0.00          0.00
  PGA memory operation                           28        0.00          0.00
  PX Deq: Execute Reply                         132        0.00          0.01
  reliable message                                1        0.00          0.00
  PX Deq: Signal ACK EXT                          2        0.00          0.00
  PX Deq: Slave Session Stats                     2        0.00          0.00

Although the number of rows is roughly the same (2069 in 12.2 vs 2011 in 19.10), the runtime performance and wait events are drastically different. Please bear in mind, that I initially asked to investigate why the same query in 11.2 was running in 1 second while the same query in 19.10 was running in 90 seconds with about the same number of rows as in 11.2.
I also reviewed the trace file in 19c to see if I can spot any pattern there:

[oracle@rac1 ~]$ grep 'WAIT #139925193433952' /u01/app/oracle/diag/rdbms/orcl19/orcl191/trace/orcl191_ora_19616.trc | grep -E 'direct path (read|write) temp|db file sequential read'
WAIT #139925193433952: nam='direct path write temp' ela= 758 file number=201 first dba=4355 block cnt=1 obj#=-1 tim=20569064799
WAIT #139925193433952: nam='direct path write temp' ela= 674 file number=201 first dba=4356 block cnt=1 obj#=-1 tim=20569065748
..59 direct path write temp in total
WAIT #139925193433952: nam='direct path write temp' ela= 680 file number=201 first dba=4413 block cnt=1 obj#=-1 tim=20569114649
..then there are groups consisting of one db file sequential read/one direct path read temp (the same block)/multiple direct path write temp:
..group 1
WAIT #139925193433952: nam='db file sequential read' ela= 473 file#=201 block#=4413 blocks=1 obj#=-1 tim=20569115200
WAIT #139925193433952: nam='direct path read temp' ela= 449 file number=201 first dba=4413 block cnt=1 obj#=-1 tim=20569115739
WAIT #139925193433952: nam='direct path write temp' ela= 699 file number=201 first dba=4413 block cnt=1 obj#=-1 tim=20569116529
WAIT #139925193433952: nam='direct path write temp' ela= 643 file number=201 first dba=4414 block cnt=1 obj#=-1 tim=20569117342
WAIT #139925193433952: nam='direct path write temp' ela= 753 file number=201 first dba=4415 block cnt=1 obj#=-1 tim=20569118266
WAIT #139925193433952: nam='direct path write temp' ela= 706 file number=201 first dba=4416 block cnt=1 obj#=-1 tim=20569119134
WAIT #139925193433952: nam='direct path write temp' ela= 593 file number=201 first dba=4417 block cnt=1 obj#=-1 tim=20569119882
WAIT #139925193433952: nam='direct path write temp' ela= 626 file number=201 first dba=4418 block cnt=1 obj#=-1 tim=20569120652
WAIT #139925193433952: nam='direct path write temp' ela= 807 file number=201 first dba=4419 block cnt=1 obj#=-1 tim=20569121585
WAIT #139925193433952: nam='direct path write temp' ela= 625 file number=201 first dba=4420 block cnt=1 obj#=-1 tim=20569122348
WAIT #139925193433952: nam='direct path write temp' ela= 605 file number=201 first dba=4421 block cnt=1 obj#=-1 tim=20569123097
WAIT #139925193433952: nam='direct path write temp' ela= 509 file number=201 first dba=4422 block cnt=1 obj#=-1 tim=20569123753
WAIT #139925193433952: nam='direct path write temp' ela= 577 file number=201 first dba=4423 block cnt=1 obj#=-1 tim=20569124476
WAIT #139925193433952: nam='direct path write temp' ela= 667 file number=201 first dba=4424 block cnt=1 obj#=-1 tim=20569125286
WAIT #139925193433952: nam='direct path write temp' ela= 501 file number=201 first dba=4425 block cnt=1 obj#=-1 tim=20569125930
WAIT #139925193433952: nam='direct path write temp' ela= 617 file number=201 first dba=4426 block cnt=1 obj#=-1 tim=20569126698
WAIT #139925193433952: nam='direct path write temp' ela= 634 file number=201 first dba=4427 block cnt=1 obj#=-1 tim=20569127473
WAIT #139925193433952: nam='direct path write temp' ela= 577 file number=201 first dba=4428 block cnt=1 obj#=-1 tim=20569128188
WAIT #139925193433952: nam='direct path write temp' ela= 868 file number=201 first dba=4429 block cnt=1 obj#=-1 tim=20569129188
WAIT #139925193433952: nam='direct path write temp' ela= 609 file number=201 first dba=4430 block cnt=1 obj#=-1 tim=20569130099
..group 2
WAIT #139925193433952: nam='db file sequential read' ela= 399 file#=201 block#=4430 blocks=1 obj#=-1 tim=20569130544
WAIT #139925193433952: nam='direct path read temp' ela= 454 file number=201 first dba=4430 block cnt=1 obj#=-1 tim=20569131072
WAIT #139925193433952: nam='direct path write temp' ela= 669 file number=201 first dba=4430 block cnt=1 obj#=-1 tim=20569131834
WAIT #139925193433952: nam='direct path write temp' ela= 686 file number=201 first dba=4431 block cnt=1 obj#=-1 tim=20569132665
WAIT #139925193433952: nam='direct path write temp' ela= 588 file number=201 first dba=4432 block cnt=1 obj#=-1 tim=20569133416
WAIT #139925193433952: nam='direct path write temp' ela= 794 file number=201 first dba=4433 block cnt=1 obj#=-1 tim=20569134366
WAIT #139925193433952: nam='direct path write temp' ela= 648 file number=201 first dba=4434 block cnt=1 obj#=-1 tim=20569135192
WAIT #139925193433952: nam='direct path write temp' ela= 792 file number=201 first dba=4435 block cnt=1 obj#=-1 tim=20569136134
WAIT #139925193433952: nam='direct path write temp' ela= 682 file number=201 first dba=4436 block cnt=1 obj#=-1 tim=20569136961
WAIT #139925193433952: nam='direct path write temp' ela= 609 file number=201 first dba=4437 block cnt=1 obj#=-1 tim=20569137753
WAIT #139925193433952: nam='direct path write temp' ela= 563 file number=201 first dba=4438 block cnt=1 obj#=-1 tim=20569138501
WAIT #139925193433952: nam='direct path write temp' ela= 645 file number=201 first dba=4439 block cnt=1 obj#=-1 tim=20569139298
WAIT #139925193433952: nam='direct path write temp' ela= 807 file number=201 first dba=4440 block cnt=1 obj#=-1 tim=20569140265
WAIT #139925193433952: nam='direct path write temp' ela= 679 file number=201 first dba=4441 block cnt=1 obj#=-1 tim=20569141079
WAIT #139925193433952: nam='direct path write temp' ela= 626 file number=201 first dba=4442 block cnt=1 obj#=-1 tim=20569141844
WAIT #139925193433952: nam='direct path write temp' ela= 740 file number=201 first dba=4443 block cnt=1 obj#=-1 tim=20569142718
WAIT #139925193433952: nam='direct path write temp' ela= 753 file number=201 first dba=4444 block cnt=1 obj#=-1 tim=20569143615
WAIT #139925193433952: nam='direct path write temp' ela= 686 file number=201 first dba=4445 block cnt=1 obj#=-1 tim=20569144450
WAIT #139925193433952: nam='direct path write temp' ela= 673 file number=201 first dba=4446 block cnt=1 obj#=-1 tim=20569145257
WAIT #139925193433952: nam='direct path write temp' ela= 728 file number=201 first dba=4447 block cnt=1 obj#=-1 tim=20569146129
WAIT #139925193433952: nam='direct path write temp' ela= 589 file number=201 first dba=4448 block cnt=1 obj#=-1 tim=20569146857
WAIT #139925193433952: nam='direct path write temp' ela= 658 file number=201 first dba=4449 block cnt=1 obj#=-1 tim=20569147672
WAIT #139925193433952: nam='direct path write temp' ela= 666 file number=201 first dba=4450 block cnt=1 obj#=-1 tim=20569148478
WAIT #139925193433952: nam='direct path write temp' ela= 602 file number=201 first dba=4451 block cnt=1 obj#=-1 tim=20569149255
WAIT #139925193433952: nam='direct path write temp' ela= 841 file number=201 first dba=4452 block cnt=1 obj#=-1 tim=20569150247
WAIT #139925193433952: nam='direct path write temp' ela= 763 file number=201 first dba=4453 block cnt=1 obj#=-1 tim=20569151167
WAIT #139925193433952: nam='direct path write temp' ela= 779 file number=201 first dba=4454 block cnt=1 obj#=-1 tim=20569152208
..group 3
WAIT #139925193433952: nam='db file sequential read' ela= 206 file#=201 block#=4454 blocks=1 obj#=-1 tim=20569152457
WAIT #139925193433952: nam='direct path read temp' ela= 711 file number=201 first dba=4454 block cnt=1 obj#=-1 tim=20569153234
WAIT #139925193433952: nam='direct path write temp' ela= 575 file number=201 first dba=4454 block cnt=1 obj#=-1 tim=20569153905
WAIT #139925193433952: nam='direct path write temp' ela= 930 file number=201 first dba=4455 block cnt=1 obj#=-1 tim=20569155093
WAIT #139925193433952: nam='direct path write temp' ela= 809 file number=201 first dba=4355 block cnt=1 obj#=-1 tim=20569156069
WAIT #139925193433952: nam='direct path write temp' ela= 820 file number=201 first dba=4356 block cnt=1 obj#=-1 tim=20569157024
WAIT #139925193433952: nam='direct path write temp' ela= 976 file number=201 first dba=4357 block cnt=1 obj#=-1 tim=20569158174
WAIT #139925193433952: nam='direct path write temp' ela= 683 file number=201 first dba=4358 block cnt=1 obj#=-1 tim=20569159165
WAIT #139925193433952: nam='db file sequential read' ela= 638 file#=201 block#=4358 blocks=1 obj#=-1 tim=20569159850
WAIT #139925193433952: nam='direct path read temp' ela= 183 file number=201 first dba=4358 block cnt=1 obj#=-1 tim=20569160107
..

My next thought was to test how 19c processes CLOB's in traditional tables - I have not found any issues there. There have been no direct path read/write temp on copies of GV$SQL.
I then tried to select the same persistent tables (non-GV$) via database link in 19c - again everything worked as it should.
It seems that only GV$ views are affected. Local selects are not affected at all (the output below is from the first instance):

SQL ID: 87myh1vhjdcf8 Plan Hash: 1891717107

SELECT SQL_FULLTEXT
FROM
 GV$SQL WHERE INST_ID = 1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       13      0.02       0.02          0          0          0        1231
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       15      0.03       0.03          0          0          0        1231

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS   (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
      1231       1231       1231  PX COORDINATOR  (cr=0 pr=0 pw=0 time=13516 us starts=1)
      1231       1231       1231   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=13283 us starts=1 cost=0 size=1639700 card=100)
      1231       1231       1231    VIEW  GV$SQL (cr=0 pr=0 pw=0 time=12908 us starts=1)
      1231       1231       1231     FIXED TABLE FULL X$KGLCURSOR_CHILD (cr=0 pr=0 pw=0 time=12657 us starts=1 cost=0 size=1639700 card=100)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                           99        0.00          0.00

Whereas any select when non-local instance is involved is done utilizing a temporary tablespace:

SQL ID: 4p7vm0hhw6u1v Plan Hash: 1891717107

SELECT SQL_FULLTEXT
FROM
 GV$SQL WHERE INST_ID = 2


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch       10      0.21       1.06        118        118      11953         968
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       12      0.21       1.07        118        118      11953         968

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS   (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
       968        968        968  PX COORDINATOR  (cr=118 pr=118 pw=1075 time=907430 us starts=1)
         0          0          0   PX SEND QC (RANDOM) :TQ10000 (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=1639700 card=100)
         0          0          0    VIEW  GV$SQL (cr=0 pr=0 pw=0 time=0 us starts=0)
         0          0          0     FIXED TABLE FULL X$KGLCURSOR_CHILD (cr=0 pr=0 pw=0 time=0 us starts=0 cost=0 size=1639700 card=100)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PX Deq: reap credit                           158        0.00          0.00
  PX Deq: Join ACK                                1        0.00          0.00
  PX Deq: Parse Reply                             1        0.00          0.00
  PGA memory operation                           11        0.00          0.00
  PX Deq: Execute Reply                          61        0.00          0.01
  Disk file operations I/O                        3        0.00          0.00
  CSS initialization                              2        0.00          0.00
  CSS operation: query                            6        0.00          0.00
  CSS operation: action                           2        0.00          0.00
  asynch descriptor resize                        1        0.00          0.00
  ASM IO for non-blocking poll                 3208        0.00          0.00
  direct path write temp                       1029        0.00          0.81
  db file sequential read                        59        0.00          0.02
  direct path read temp                          59        0.00          0.02
  reliable message                                1        0.00          0.00
  PX Deq: Signal ACK EXT                          1        0.00          0.00
  IPC send completion sync                        1        0.00          0.00
  PX Deq: Slave Session Stats                     1        0.00          0.00
  IPC group service call                          1        0.00          0.00
  enq: PS - contention                            1        0.00          0.00

I then shut one instance down, and rechecked the queries against GV$ - there were no direct path read/write temp wait events.

Conclusion

It is still not clear why Oracle started writing every CLOB from GV$ to a temporary tablespace. I tried several different GV$ views and the same behaviour was observed everywhere. It looks like something was changed inside those GV$ functions.
My initial thought was that it is some kind of a temporary tablespace flush for persistence in case some parallel processes got terminated. However, parallel slaves started on remote instances are sending the blocks to the QC bypassing any temp.
Then I was thinking that it might be done to reduce memory usage. It has little sense to write every CLOB to temp anyway. Why do not keep a small memory area and write to temp everything that exceeded some threshold?
I also do not know how to alter this behavior to make the things the same as they were before 18c. I tested 11.2.0.4, 12.2(vanilla and with the latest RU), 18c, 19c (vanilla and with the latest RU - 19.10). Both 18c and 19c are affected, so that they wait for direct path read/write temp when a CLOB column is selected from GV$ with more than one instance.
I will update the blog post if I get to the bottom of it and identify the root cause.

CHA Alert CHA_DBWR_CKPT_IO_COMPLETE in OEM

A customer was getting the following alerts from Oracle Enterprise Manager (OEM):

Host=rac1.example.com
Target type=Cluster
Target name=myrac
Message=DB Checkpoint Performance on Host rac1 Database/Cluster racdba Instance racdba1.
The Cluster Health Advisor (CHA) detected that Database Writer (DBW) checkpoints were slow because the database writes took longer than expected to complete.
Increase the number of DBWR processes. Add additional disks to the disk group for the database.
Relocate the database files to faster disks or to Solid State Devices.
If the storage subsystem supports a storage write back cache, check that the storage cache is functioning properly.
Severity=Warning
Event reported time=Feb 23, 2021 12:04:53 PM GMT
Operating System=Linux
Platform=x86_64
Event Type=Metric Alert
Event name=cha_alerts:cha_alert_level
Metric Group=CHA Alerts
Metric=Alert Level
Metric value=Warning
Key Value=CHA_INCIDENT_STATE_CHANGE_DATABASE_racdba_racdba1_CHA_DBWR_CKPT_IO_COMPLETE
Key Column 1=Key
Rule Name=SYSMAN Monitor Targets,rule 61
Rule Owner=SYSMAN
Update Details:
DB Checkpoint Performance on Host rac1 Database/Cluster racdba Instance racdba1.
The Cluster Health Advisor (CHA) detected that Database Writer (DBW) checkpoints were slow because the database writes took longer than expected to complete.
Increase the number of DBWR processes. Add additional disks to the disk group for the database.
Relocate the database files to faster disks or to Solid State Devices.
If the storage subsystem supports a storage write back cache, check that the storage cache is functioning properly.

I observed some infamous checkpoint not complete messages in the alert log, so I suspected that they might be the real cause.
Thus, I created quite small log files 20MB in size:

SQL> select group#, thread#, bytes from v$log;

    GROUP#    THREAD#      BYTES
---------- ---------- ----------
         5          1   20971520
         6          1   20971520
         7          1   20971520
         8          2   20971520
         9          2   20971520
        10          2   20971520

6 rows selected.

Then, I wrote a script that generates a lot of redo:

create table t
as
select o.*
  from dba_objects o,
       xmltable('1 to 50');

update t
   set object_name=object_name;

I ran the script and here is an excerpt from the alert log showing checkpoint not complete messages:

2021-02-23T12:04:47.234452+00:00
Thread 1 advanced to log sequence 114 (LGWR switch),  current SCN: 7677512
  Current log# 6 seq# 114 mem# 0: +DATA/RACDBA/ONLINELOG/group_6.290.1065267481
2021-02-23T12:04:47.506174+00:00
PDB(3):Resize operation completed for file# 12, old size 645120K, new size 650240K
2021-02-23T12:04:47.848002+00:00
Thread 1 cannot allocate new log, sequence 115
Checkpoint not complete
  Current log# 6 seq# 114 mem# 0: +DATA/RACDBA/ONLINELOG/group_6.290.1065267481
2021-02-23T12:04:50.392351+00:00
Thread 1 advanced to log sequence 115 (LGWR switch),  current SCN: 7677540
  Current log# 7 seq# 115 mem# 0: +DATA/RACDBA/ONLINELOG/group_7.291.1065267483
2021-02-23T12:04:50.661220+00:00
PDB(3):Resize operation completed for file# 12, old size 650240K, new size 655360K
2021-02-23T12:04:50.993950+00:00
Thread 1 cannot allocate new log, sequence 116
Checkpoint not complete
  Current log# 7 seq# 115 mem# 0: +DATA/RACDBA/ONLINELOG/group_7.291.1065267483
2021-02-23T12:04:53.576282+00:00
Thread 1 advanced to log sequence 116 (LGWR switch),  current SCN: 7677574
  Current log# 5 seq# 116 mem# 0: +DATA/RACDBA/ONLINELOG/group_5.289.1065267477
2021-02-23T12:04:53.845381+00:00
PDB(3):Resize operation completed for file# 12, old size 655360K, new size 660480K
2021-02-23T12:04:54.183174+00:00
Thread 1 cannot allocate new log, sequence 117
Checkpoint not complete
  Current log# 5 seq# 116 mem# 0: +DATA/RACDBA/ONLINELOG/group_5.289.1065267477
2021-02-23T12:04:56.721595+00:00
Thread 1 advanced to log sequence 117 (LGWR switch),  current SCN: 7677600
  Current log# 6 seq# 117 mem# 0: +DATA/RACDBA/ONLINELOG/group_6.290.1065267481
2021-02-23T12:04:56.995439+00:00
PDB(3):Resize operation completed for file# 12, old size 660480K, new size 665600K
2021-02-23T12:04:57.332102+00:00
Thread 1 cannot allocate new log, sequence 118
Checkpoint not complete
  Current log# 6 seq# 117 mem# 0: +DATA/RACDBA/ONLINELOG/group_6.290.1065267481

Shortly afterwards, I got a new CHA alert in the OEM:

To understand what is happening, firstly, I started looking for some clues in the CHA log: /u01/app/grid/crsdata/rac1/trace/chad/ochad.trc.0, in which /u01/app/grid is ORACLE_BASE of the grid user.

[Thread-22] [ 2021-02-23 12:04:53.390 UTC ] [BNet.validate:422]  INFO: Tue Feb 23 12:04:50 UTC 2021 Decided CHA_DBWR_CKPT_IO_COMPLETE NORMAL (Belief= 94.900925  %) --> ABNORMAL (Belief= 81.315659  %)
[Thread-22] [ 2021-02-23 12:04:53.390 UTC ] [BNet.validate:429]  INFO: Tue Feb 23 12:04:50 UTC 2021      Children
[Thread-22] [ 2021-02-23 12:04:53.391 UTC ] [BNet.validate:446]  INFO: Tue Feb 23 12:04:50 UTC 2021           DBWR IO Completion= NORMAL
[Thread-22] [ 2021-02-23 12:04:53.391 UTC ] [BNet.validate:446]  INFO: Tue Feb 23 12:04:50 UTC 2021           log_file_switch_checkpoint_incompleteRANGE3= HIGH
[Thread-22] [ 2021-02-23 12:04:53.391 UTC ] [EventPublisher$EventRequest.dump:193]  INFO: type:DATABASE, target:racdba, host:rac1, instance:racdba1, 
problem:CHA_DBWR_CKPT_IO_COMPLETE, state:ABNORMAL, time:2021-02-23 12:04:50,
evidence:[{"signal":"log_file_switch_checkpoint_incomplete", "fd":"log_file_switch_checkpoint_incompleteRANGE3", "state":"HIGH", "value":1.09745E06, "pred":null, "since":"2021-02-23 12:04:50"}]

Based on the evidence above, I can conclude that CHA is checking the log file switch (checkpoint incomplete) wait event:

SQL> select event, total_waits, total_timeouts, time_waited_micro
  2    from v$system_event
  3   where event='log file switch (checkpoint incomplete)'
  4  /

EVENT                                    TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED_MICRO
---------------------------------------- ----------- -------------- -----------------
log file switch (checkpoint incomplete)          166              0         196362926

The following process accesses this file:

[grid@rac1 grid]$ fuser /u01/app/grid/crsdata/rac1/trace/chad/ochad.trc.0
/u01/app/grid/crsdata/rac1/trace/chad/ochad.trc.0: 13858
[grid@rac1 grid]$ ps fww -p 13858
  PID TTY      STAT   TIME COMMAND
13858 ?        Sl     0:37 /u01/app/19.3.0/grid/jdk/bin/java -server -Xms30M -Xmx512M 
-Djava.awt.headless=true -Ddisable.checkForUpdate=true -DTRACING.ENABLED=false 
-XX:ParallelGCThreads=1 -cp /u01/app/19.3.0/grid/jlib/cha.jar:/u01/app/19.3.0/grid/jlib/chaconfig.jar:/u01/app/19.3.0/grid/jlib/cha-diag-msg.jar:/u01/app/19.3.0/grid/jlib/clsce.jar:/u01/app/19.3.0/grid/jlib/srvm.jar:/u01/app/19.3.0/grid/jlib/srvmhas.jar:/u01/app/19.3.0/grid/jlib/srvmasm.jar:/u01/app/19.3.0/grid/jlib/netcfg.jar:/u01/app/19.3.0/grid/jdbc/lib/ojdbc8.jar:/u01/app/19.3.0/grid/ucp/lib/ucp.jar:/u01/app/19.3.0/grid/jlib/fte.jar:/u01/app/19.3.0/grid/jlib/jai_core.jar:/u01/app/19.3.0/grid/jlib/mlibwrapper_jai.jar:/u01/app/19.3.0/grid/jlib/vecmath.jar:/u01/app/19.3.0/grid/jlib/jai_codec.jar:/u01/app/19.3.0/grid/jlib/jh.jar
oracle.cha.server.CHADDriver

The corresponding CRS resource is ora.chad:

[grid@rac1 trace]$ crsctl stat res ora.chad -t
--------------------------------------------------------------------------------
Name           Target  State        Server                   State details
--------------------------------------------------------------------------------
Local Resources
--------------------------------------------------------------------------------
ora.chad
               ONLINE  ONLINE       rac1                     STABLE
               ONLINE  ONLINE       rac2                     STABLE
--------------------------------------------------------------------------------

It can be managed by srvctl commands: srvctl stop/status/start cha.

CHA is tightly integrated with the Grid Infrastructure Management Repository (GIMR). In fact, most chactl commands cannot work without it. However, I do not use GIMR, and it appears that some CHA functionality is still available, at least part of it that can publish database related events to OEM. It is explained in the following whitepaper: Oracle Database 12c Rel. 2 Cluster Health Advisor - Deep Dive How it Works and How to Use It

Conclusion

I do not think that the message produced by the CHA_DBWR_CKPT_IO_COMPLETE alert has appropriate solutions:

DB Checkpoint Performance on Host rac1 Database/Cluster racdba Instance racdba1. The Cluster Health Advisor (CHA) detected that Database Writer (DBW) checkpoints were slow because the database writes took longer than expected to complete. Increase the number of DBWR processes. Add additional disks to the disk group for the database. Relocate the database files to faster disks or to Solid State Devices. If the storage subsystem supports a storage write back cache, check that the storage cache is functioning properly.

It is usually much easier to increase the total redo size, either by adding additional log groups, changing the size of the existing ones, or both. All of these actions give more chances to DBWR to catch up.

When there are CHA alerts in OEM, it makes sense to check the CHA log: /u01/app/grid/crsdata/rac1/trace/chad/ochad.trc.0. It has some invaluable information that could reveal exactly the cause.

Diagnosing Cluster Verification Utility (CVU) Errors

A cluster verification utility (CVU) command failed with the following error:

[grid@rac1 ~]$ cluvfy comp vdisk -n rac1 -verbose

Verifying Voting Disk ...FAILED (PRVF-5157, PRVF-5431)

Verification of Voting Disk was unsuccessful on all the specified nodes.


Failures were encountered during execution of CVU verification request "Voting Disk".

Verifying Voting Disk ...FAILED
PRVF-5157 : could not verify ASM disk group "GRID" for voting disk location
"/dev/flashgrid/racq.lun1" is available on node "rac1"
PRVF-5157 : could not verify ASM disk group "GRID" for voting disk location
"/dev/flashgrid/rac1.lun1" is available on node "rac1"
PRVF-5157 : could not verify ASM disk group "GRID" for voting disk location
"/dev/flashgrid/rac2.lun1" is available on node "rac1"
PRVF-5431 : Oracle Cluster Voting Disk configuration check failed


CVU operation performed:      Voting Disk
Date:                         Feb 11, 2021 6:18:51 PM
CVU home:                     /u01/app/19.3.0/grid/
User:                         grid

It can be seen that the command already had the verbose option which did not give any hint about the cause of the error.
The documentation says that CVU generates trace data by default unless it has been disabled. The default trace file location is $ORACLE_BASE/crsdata/host_name/cvu. A non-default location can be specified using the CV_TRACELOC environment variable.

That is what I got in the aforementioned directory:

[grid@rac1 ~]$ cd $ORACLE_BASE/crsdata/$(hostname -s)/cvu
[grid@rac1 cvu]$ ll
total 4
drwxrwxrwt 2 grid   oinstall 4096 Feb 11 14:01 cvulog
drwxrwxrwt 2 grid   oinstall  144 Feb 11 14:03 cvutrc
drwxr-xr-x 2 grid   oinstall   78 Feb 11 18:18 grid
drwxr-xr-x 2 grid   oinstall    6 Feb 11 14:03 init
drwxr-xr-x 2 oracle oinstall   28 Feb  2 20:48 oracle
[grid@rac1 cvu]$ cd grid
[grid@rac1 grid]$ ll
total 11272
-rw-r----- 1 grid oinstall   641638 Feb 11 18:18 cvuhelper.log.0
-rw-r--r-- 1 grid oinstall        0 Jan  4 12:12 cvuhelper.log.0.lck
-rw-r--r-- 1 grid oinstall 10899074 Feb 11 18:18 cvutrace.log.0

The cvutrace.log.0 contained actual trace data in which the following lines drew my eye:

[main] [ 2021-02-11 18:18:57.681 UTC ] [ClusterConfig.block:624]  block acquired semnum=0
[main] [ 2021-02-11 18:18:57.681 UTC ] [ClusterConfig.submit:573]  Out of block
[main] [ 2021-02-11 18:18:57.681 UTC ] [ClusterConfig.submit:590]  status=true
[main] [ 2021-02-11 18:18:57.681 UTC ] [ClusterConfig.destroy:468]  destroying resources for client thread Thread[main,5,main]
[main] [ 2021-02-11 18:18:57.681 UTC ] [ResultSet.traceResultTable:1065]

ResultTable Info ===>

        contents of resultTable

Dumping Result data.
  Status     : SUCCESSFUL
  Name       : rac1
  Type       : Node
  Has Results: No
  Exp. value : null
  Act. value : null

  Errors  :
    PRVG-2043 : Command "/u01/app/19.3.0/grid/bin/kfod op=GROUPS nohdr=true " failed on node "rac1" and produced the following output:
KFOD-00101: LRM error [110] while parsing command line arguments
KFOD-00103: LRM message: LRM-00118: syntax error at '=' at the end of input

As the above output demonstrates, CVU called kfod which was failing. Thus, I decided to run it myself and got the same LRM errors:

[grid@rac1 ~]$ /u01/app/19.3.0/grid/bin/kfod op=GROUPS nohdr=true
KFOD-00101: LRM error [110] while parsing command line arguments
KFOD-00103: LRM message: LRM-00118: syntax error at '=' at the end of input
[grid@rac1 ~]$ /u01/app/19.3.0/grid/bin/kfod op=GROUPS
KFOD-00101: LRM error [110] while parsing command line arguments
KFOD-00103: LRM message: LRM-00118: syntax error at '=' at the end of input

LRM seems to be the parameter manager, but it did not ring a bell yet:

[grid@rac1 ~]$ head -9 $ORACLE_HOME/oracore/mesg/lrmus.msg
/
/ $Header: lrmus.msg 19-jun-2003.17:48:08 Exp $
/
/ Copyright (c) 1996, 2003, Oracle.  All rights reserved.
/   NAME
/     lrmus.msg - CORE error message file for the parameter manager (LRM)
/   DESCRIPTION
/     Listing of all CORE error messages for LRM
/

kfod is just a shell script that invokes its binary counterpart kfod.bin similar to what many other Grid Infrastructure (GI) utilities do.
They obviously interact with the operating system, so that we can trace system calls being invoked. That is what I did:

[grid@rac1 ~]$ strace -f -e trace=open,write -s 256 /u01/app/19.3.0/grid/bin/kfod op=GROUPS
..
<skip>
..
open("/u01/app/19.3.0/grid/nls/data/lx40011.nlb", O_RDONLY) = 7
open("/u01/app/19.3.0/grid/dbs/init+ASM1.ora", O_RDONLY) = 7
open("/u01/app/19.3.0/grid/rdbms/mesg/kfodus.msb", O_RDONLY) = 7
write(1, "KFOD-00101: LRM error [110] while parsing command line arguments\n", 65KFOD-00101: LRM error [110] while parsing command line arguments
) = 65
..

In a nutshell, the process opened /u01/app/19.3.0/grid/dbs/init+ASM1.ora. It then went to /u01/app/19.3.0/grid/rdbms/mesg/kfodus.msb, which is a binary message file. After that it put a KFOD error to stdout.
Therefore, it made sense to check that parameter file:

[grid@rac1 ~]$ cat /u01/app/19.3.0/grid/dbs/init+ASM1.ora
SPFILE=

It became obvious that the parameter file is the main culprit of these LRM errors:

KFOD-00101: LRM error [110] while parsing command line arguments
KFOD-00103: LRM message: LRM-00118: syntax error at '=' at the end of input

To confirm that, I renamed the file and reran both kfod and cluvfy commands successfully:

[grid@rac1 ~]$ mv /u01/app/19.3.0/grid/dbs/init+ASM1.ora{,.bak}
[grid@rac1 ~]$ /u01/app/19.3.0/grid/bin/kfod op=GROUPS
--------------------------------------------------------------------------------
Group          Size          Free Redundancy Name
================================================================================
   1:      10240 MB       3712 MB     NORMAL GRID
   3:      65536 MB       3712 MB     NORMAL DATA
[grid@rac1 ~]$ cluvfy comp vdisk -n rac1 -verbose

Verifying Voting Disk ...PASSED

Verification of Voting Disk was successful.

CVU operation performed:      Voting Disk
Date:                         Feb 11, 2021 6:50:38 PM
CVU home:                     /u01/app/19.3.0/grid/
User:                         grid

I still do not know why that parameter file was created, but it is a neat example of how Oracle tools can be debugged.

Pluggable Database not Opened on all RAC Instances Following Switchover

Environment

• GI and DB version: 19.9

Site A

• Hostnames: raca1.example.com, raca2.example.com
• db_unique_name: racdba
• Instance Names: racdba1, racdba2
• Configuration Type: RAC

Site B

• Hostnames: racb1.example.com, racb2.example.com
• db_unique_name: racdbb
• Instance Names: racdbb1, racdbb2
• Configuration Type: RAC

Initial State

Data Guard Configuration

DGMGRL> show configuration;

Configuration - racdb

  Protection Mode: MaxPerformance
  Members:
  racdba - Primary database
    racdbb - Physical standby database

Fast-Start Failover:  Disabled

Configuration Status:
SUCCESS   (status updated 116 seconds ago)

RACDBA: primary

SYS@RACDBA> select database_role from v$database;

DATABASE_ROLE
----------------
PRIMARY

SYS@RACDBA>
SYS@RACDBA> select *
  2    from dba_pdb_saved_states
  3   order by con_id, instance_name;

 CON_ID CON_NAME INSTANCE_NAME    CON_UID GUID                             STATE          RESTRICTED
------- -------- ------------- ---------- -------------------------------- -------------- ----------
      3 PDB      racdba1       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdba2       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdbb1       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdbb2       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO

SYS@RACDBA>
SYS@RACDBA>
SYS@RACDBA> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ WRITE
       1 PDB$SEED   READ ONLY
       2 PDB        READ WRITE
       2 PDB$SEED   READ ONLY

SYS@RACDBA>

RACDBB: standby

SYS@RACDBB> select database_role from v$database;

DATABASE_ROLE
----------------
PHYSICAL STANDBY

SYS@RACDBB>
SYS@RACDBB> select *
  2    from dba_pdb_saved_states
  3   order by con_id, instance_name;

 CON_ID CON_NAME INSTANCE_NAME    CON_UID GUID                             STATE          RESTRICTED
------- -------- ------------- ---------- -------------------------------- -------------- ----------
      3 PDB      racdba1       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdba2       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdbb1       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO
      3 PDB      racdbb2       1682177871 B8C71D7FC2B07CAAE0530101A8C0CF42 OPEN           NO

SYS@RACDBB>
SYS@RACDBB>
SYS@RACDBB> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ ONLY
       1 PDB$SEED   READ ONLY
       2 PDB        READ ONLY
       2 PDB$SEED   READ ONLY

SYS@RACDBB>

Switchover

dgmgrl

DGMGRL> switchover to racdbb;
Performing switchover NOW, please wait...
Operation requires a connection to database "racdbb"
Connecting ...
Connected to "racdbb"
Connected as SYSDBA.
New primary database "racdbb" is opening...
Oracle Clusterware is restarting database "racdba" ...
Connected to "racdba"
Connected to "racdba"
Switchover succeeded, new primary is "racdbb"

RACDBA: new standby, old primary

SYS@RACDBA> select database_role from v$database;

DATABASE_ROLE
----------------
PHYSICAL STANDBY

SYS@RACDBA>
SYS@RACDBA> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ ONLY
       1 PDB$SEED   READ ONLY
       2 PDB        MOUNTED
       2 PDB$SEED   READ ONLY

SYS@RACDBA>

The upshot of that is that PDB is not opened on all instances.

RACDBB: new primary, old standby

SYS@RACDBB> select database_role from v$database;

DATABASE_ROLE
----------------
PRIMARY

SYS@RACDBB>
SYS@RACDBB> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ WRITE
       1 PDB$SEED   READ ONLY
       2 PDB        READ WRITE
       2 PDB$SEED   READ ONLY

SYS@RACDBB>

alert_racdba1.log

2021-01-14T11:06:34.301193+00:00
PDB$SEED(2):This instance was first to open pluggable database PDB$SEED (container=2)
PDB$SEED(2):Endian type of dictionary set to little
PDB$SEED(2):Undo initialization finished serial:0 start:2456242 end:2456242 diff:0 ms (0.0 seconds)
PDB$SEED(2):Database Characterset for PDB$SEED is AL32UTF8
PDB$SEED(2):Opening pdb with no Resource Manager plan active
2021-01-14T11:06:34.854870+00:00
Unable to restore open state for pluggable databases due to               the following errors.
2021-01-14T11:06:34.855107+00:00
Errors in file /u01/app/oracle/diag/rdbms/racdba/racdba1/trace/racdba1_ora_15488.trc:
ORA-65054: Cannot open a pluggable database in the desired mode.
Physical standby database opened for read only access.
2021-01-14T11:06:34.999598+00:00
Completed: ALTER DATABASE OPEN READ ONLY /* db agent *//* {1:39212:957} */

racdba1_ora_15488.trc

*** 2021-01-14T11:06:33.488203+00:00 (CDB$ROOT(1))
kjznppl0: database in migration or not writable
kjac_dpinfo_open: direct path not initialized, reason: in readable standby mode

*** 2021-01-14T11:06:34.082190+00:00 (CDB$ROOT(1))
* Set mstr_rdy 1, lmon_pnpchk 1 
<error barrier> at 0x7fffb4489030 placed kpdb.c@21504
ORA-65054: Cannot open a pluggable database in the desired mode.

drcracdba1.log

2021-01-14T11:05:21.783+00:00
Initiating a healthcheck...
2021-01-14T11:05:23.298+00:00
SWITCHOVER TO racdbb
Switchover to physical standby database cannot be initiated from the primary database
redirecting connection to switchover target database racdbb...
...using connect identifier: //myracb-scan/racdbb
SWITCHOVER TO racdbb
2021-01-14T11:05:26.004+00:00
Notifying Oracle Clusterware to prepare primary database for switchover
Switchover in progress...
2021-01-14T11:05:27.263+00:00
Executing SQL: [ALTER DATABASE SWITCHOVER TO 'racdbb']
2021-01-14T11:05:57.144+00:00
SQL [ALTER DATABASE SWITCHOVER TO 'racdbb'] executed successfully
2021-01-14T11:05:58.295+00:00
Switchover successful
2021-01-14T11:06:03.892+00:00
Notifying Clusterware to restart this instance for Switchover
2021-01-14T11:06:06.080+00:00
Shutting down instance after Switchover
2021-01-14T11:06:26.438+00:00
>> Starting Data Guard Broker bootstrap <<
Broker Configuration File Locations:
      dg_broker_config_file1 = "+DATA/RACDBA/dr1racdba"
      dg_broker_config_file2 = "+DATA/RACDBA/dr2racdba"
2021-01-14T11:06:26.438+00:00                      DMON: Attach state object
2021-01-14T11:06:26.440+00:00                      DMON: Initialization of broker state requires reconciliation
2021-01-14T11:06:26.440+00:00                      DMON: Broker state reconciled, version = 0, state = 00000000
2021-01-14T11:06:26.440+00:00                      DMON: Broker State Initialized
2021-01-14T11:06:26.440+00:00                            Version = 1
2021-01-14T11:06:26.440+00:00                            State = 00000000
2021-01-14T11:06:26.440+00:00                      DMON: Creating INSV process
2021-01-14T11:06:29.458+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr1racdba' with blocksize 4096
2021-01-14T11:06:29.461+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr1racdba'
2021-01-14T11:06:29.474+00:00                      INSV: home block of +DATA/RACDBA/dr1racdba: zzz=0x40, Seq.MIV=12.1, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:06:29.474+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:06:29.476+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:06:29.480+00:00                      INSV: home block of +DATA/RACDBA/dr2racdba: zzz=0x40, Seq.MIV=13.0, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:06:29.480+00:00                      INSV: Set current metadata file ID to 2 (Seq.MIV=13.0)
2021-01-14T11:06:29.480+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:06:29.483+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:06:29.485+00:00                      INSV: Uploading persisted FSFO state:
2021-01-14T11:06:29.485+00:00                             flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:06:29.485+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:06:29.485+00:00                      	pmyshut=1, aft=30, laglim=30, obslim=30
2021-01-14T11:06:29.485+00:00                      INSV: FSFO state RAC reconcile started
2021-01-14T11:06:29.486+00:00                      INSV: FSFO state RAC reconcile finished
2021-01-14T11:06:29.486+00:00                      INSV: INSV is ready
2021-01-14T11:06:30.455+00:00                      DMON: rfm_get_chief_lock() called for CTL_BOOTSTRAP, reason BOOTSTRAP, called from rfm_dmon_wakeup_fn
2021-01-14T11:06:30.455+00:00 7fffffff           0 DMON: start task execution: broker initialization
2021-01-14T11:06:30.455+00:00                      DMON: Boot configuration (0.0.0), loading from "+DATA/RACDBA/dr2racdba"
2021-01-14T11:06:30.465+00:00                      DMON: My instance_name is racdba1 (SID racdba1), broker profile found at (1.2)
2021-01-14T11:06:30.465+00:00                      DMON: Verifying configuration service racdb_CFG
2021-01-14T11:06:30.465+00:00                      DMON: Configuration service not registered
2021-01-14T11:06:30.465+00:00                      DMON: Adding configuration service... racdb_CFG
2021-01-14T11:06:30.465+00:00                      DMON: Registering 1 service/s with listener(s)
2021-01-14T11:06:30.465+00:00                      DMON: Executing SQL [ALTER SYSTEM REGISTER]
2021-01-14T11:06:30.466+00:00                      SQL [ALTER SYSTEM REGISTER] Executed successfully
2021-01-14T11:06:30.466+00:00                      DMON: SCI harvested (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(Host=raca1.example.com)(Port=1522))(CONNECT_DATA=(SERVICE_NAME=racdba_DGMGRL)(INSTANCE_NAME=racdba1)(SERVER=DEDICATED)))
Broker Configuration:             racdb
  Oracle Release:                 19.0.0.0.0
  Oracle Version:                 19.9.0.0.0
  Metadata Version:               4.1 / UID=0x34ca0bad / Seq.MIV=13.0 / blksz.grain=4096.8
  Protection Mode:                Maximum Performance
  Fast-Start Failover (FSFO): DISABLED, flags=0x0, version=0
  Name                            Member Type                Handle      Enabled
  racdbb                          Primary Database           0x02010000  YES
  racdba                          Physical Standby Database  0x01010000  YES
2021-01-14T11:06:30.495+00:00
Physical standby restart after broker operation requires Oracle Clusterware buildup
Notifying Oracle Clusterware to buildup
2021-01-14T11:06:33.484+00:00
Configuration Validation Results:
      Primary database racdbb returned: ORA-0: normal, successful completion
Member racdba successfully completed version check
Broker configuration file is current, completing initialization
2021-01-14T11:06:47.143+00:00
Starting redo apply services...
2021-01-14T11:06:52.764+00:00
instance 2 requested FSFO state reconciliation

alert_racdba2.log

2021-01-14T11:06:55.357652+00:00
PDB$SEED(2):Endian type of dictionary set to little
PDB$SEED(2):Undo initialization finished serial:0 start:2478578 end:2478578 diff:0 ms (0.0 seconds)
PDB$SEED(2):Database Characterset for PDB$SEED is AL32UTF8
2021-01-14T11:06:55.996836+00:00
PDB$SEED(2):Opening pdb with no Resource Manager plan active
Unable to restore open state for pluggable databases due to               the following errors.
2021-01-14T11:06:56.094252+00:00
Errors in file /u01/app/oracle/diag/rdbms/racdba/racdba2/trace/racdba2_ora_20683.trc:
ORA-65054: Cannot open a pluggable database in the desired mode.
Physical standby database opened for read only access.
Completed: ALTER DATABASE OPEN READ ONLY /* db agent *//* {1:39212:1040} */

racdba2_ora_20683.trc

*** 2021-01-14T11:06:54.338847+00:00 (CDB$ROOT(1))
kjznppl0: database in migration or not writable
kjac_dpinfo_open: direct path not initialized, reason: in readable standby mode

*** 2021-01-14T11:06:55.135200+00:00 (CDB$ROOT(1))
* Set mstr_rdy 1, lmon_pnpchk 1 

*** 2021-01-14T11:06:56.094148+00:00 (CDB$ROOT(1))
<error barrier> at 0x7ffe4296eeb0 placed kpdb.c@21504
ORA-65054: Cannot open a pluggable database in the desired mode.

drcracdba2.log

2021-01-14T11:05:25.005+00:00
Updated broker configuration file available, loading from "+DATA/RACDBA/dr1racdba"
2021-01-14T11:06:49.513+00:00
>> Starting Data Guard Broker bootstrap <<
Broker Configuration File Locations:
      dg_broker_config_file1 = "+DATA/RACDBA/dr1racdba"
      dg_broker_config_file2 = "+DATA/RACDBA/dr2racdba"
2021-01-14T11:06:49.513+00:00                      DMON: Attach state object
2021-01-14T11:06:49.521+00:00                      DMON: Broker State Initialized
2021-01-14T11:06:49.521+00:00                            Version = 3
2021-01-14T11:06:49.521+00:00                            State = 00000000
2021-01-14T11:06:49.521+00:00                      DMON: Creating INSV process
2021-01-14T11:06:52.746+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr1racdba' with blocksize 4096
2021-01-14T11:06:52.749+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr1racdba'
2021-01-14T11:06:52.752+00:00                      INSV: home block of +DATA/RACDBA/dr1racdba: zzz=0x40, Seq.MIV=12.1, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:06:52.753+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:06:52.755+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:06:52.757+00:00                      INSV: home block of +DATA/RACDBA/dr2racdba: zzz=0x40, Seq.MIV=13.0, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:06:52.757+00:00                      INSV: Set current metadata file ID to 2 (Seq.MIV=13.0)
2021-01-14T11:06:52.757+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:06:52.758+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:06:52.763+00:00                      INSV: Uploading persisted FSFO state:
2021-01-14T11:06:52.763+00:00                             flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:06:52.763+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:06:52.763+00:00                      	pmyshut=1, aft=30, laglim=30, obslim=30
2021-01-14T11:06:52.763+00:00                      INSV: FSFO state RAC reconcile started
2021-01-14T11:06:52.764+00:00                      INSV: Received reconcile FSFO state from instance #1
2021-01-14T11:06:52.764+00:00                      INSV:        flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:06:52.764+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:06:52.764+00:00                      INSV: FSFO state RAC reconcile finished
2021-01-14T11:06:52.765+00:00                      INSV: INSV is ready
2021-01-14T11:06:53.534+00:00                      DMON: rfm_get_chief_lock() called for CTL_BOOTSTRAP, reason BOOTSTRAP, called from rfm_dmon_wakeup_fn
2021-01-14T11:06:53.539+00:00 7fffffff           0 DMON: start task execution: broker initialization
2021-01-14T11:06:53.539+00:00                      DMON: Boot configuration (0.0.0), loading from "+DATA/RACDBA/dr2racdba"
2021-01-14T11:06:53.553+00:00                      DMON: My instance_name is racdba2 (SID racdba2), broker profile found at (1.1)
2021-01-14T11:06:53.553+00:00                      DMON: Verifying configuration service racdb_CFG
2021-01-14T11:06:53.553+00:00                      DMON: Configuration service not registered
2021-01-14T11:06:53.553+00:00                      DMON: Adding configuration service... racdb_CFG
2021-01-14T11:06:53.554+00:00                      DMON: Registering 1 service/s with listener(s)
2021-01-14T11:06:53.554+00:00                      DMON: Executing SQL [ALTER SYSTEM REGISTER]
2021-01-14T11:06:53.555+00:00                      SQL [ALTER SYSTEM REGISTER] Executed successfully
2021-01-14T11:06:53.555+00:00                      DMON: SCI harvested (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(Host=raca2.example.com)(Port=1522))(CONNECT_DATA=(SERVICE_NAME=racdba_DGMGRL)(INSTANCE_NAME=racdba2)(SERVER=DEDICATED)))
Broker Configuration:             racdb
  Oracle Release:                 19.0.0.0.0
  Oracle Version:                 19.9.0.0.0
  Metadata Version:               4.1 / UID=0x34ca0bad / Seq.MIV=13.0 / blksz.grain=4096.8
  Protection Mode:                Maximum Performance
  Fast-Start Failover (FSFO): DISABLED, flags=0x0, version=0
  Name                            Member Type                Handle      Enabled
  racdbb                          Primary Database           0x02010000  YES
  racdba                          Physical Standby Database  0x01010000  YES
2021-01-14T11:06:56.334+00:00
Configuration Validation Results:
      Primary database racdbb returned: ORA-0: normal, successful completion
Member racdba successfully completed version check
Broker configuration file is current, completing initialization
2021-01-14T11:07:00.357+00:00
Starting redo apply services...

Thoughts and Fix

The problem is that a new standby database does not open a non-seed pluggable database on all instances.
The exact cause is still unclear, but there are certain references in the Oracle documentation that explain how Switchover works when RAC is involved:

SWITCHOVER

If an Oracle RAC primary database is becoming a physical standby database, all but one instance of the primary database will be shut down before performing the switchover. See Switchover for details.

How the Broker Performs a Switchover

Restarts the new standby (former primary) database if the switchover occurs to a physical standby database, and Redo Apply begins applying redo data from the new primary database. If this is an Oracle RAC physical standby database managed by Oracle Clusterware, then the broker directs Oracle Clusterware to restart the new standby database.
The new primary database is opened in read/write mode and redo transport services are started.
If the former physical standby database was running with real-time query enabled, the new physical standby database will run with real-time query enabled.

I tend to think that the current behaviour is not quite consistent. Either all standby instances should open PDB or neither should open it.
There are several workarounds possible to achieve the desired effect.
Oracle itself recommends using user-defined services:
Default and User-Defined Services

Always use user-defined services for applications. The reason is that you can customize user-defined services to fit the requirements of your applications. Oracle recommends that you not use the default PDB service for applications.

I am quite fond of that approach, albeit I do not see it is widely used in the field.
Let us create one PDB service for both primary and standby roles:

# RACDBA
srvctl add service -db racdba -service pdb_svc -pdb pdb -preferred racdba1,racdba2 -role primary,physical_standby
srvctl start service -db racdba -service pdb_svc

# RACDBB
srvctl add service -db racdbb -service pdb_svc -pdb pdb -preferred racdbb1,racdbb2 -role primary,physical_standby
srvctl start service -db racdbb -service pdb_svc

Another Switchover

dgmgrl

DGMGRL> switchover to racdbb;
Performing switchover NOW, please wait...
Operation requires a connection to database "racdbb"
Connecting ...
Connected to "racdbb"
Connected as SYSDBA.
New primary database "racdbb" is opening...
Oracle Clusterware is restarting database "racdba" ...
Connected to "racdba"
Connected to "racdba"
Switchover succeeded, new primary is "racdbb"

RACDBA: new standby, old primary

SYS@RACDBA> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ ONLY
       1 PDB$SEED   READ ONLY
       2 PDB        READ ONLY
       2 PDB$SEED   READ ONLY

SYS@RACDBA>

PDB is opened on all instances this time around.

RACDBB: new primary, old standby

SYS@RACDBB> select inst_id, name, open_mode
  2    from gv$pdbs
  3   order by inst_id, name;

 INST_ID NAME       OPEN_MODE
-------- ---------- ----------
       1 PDB        READ WRITE
       1 PDB$SEED   READ ONLY
       2 PDB        READ WRITE
       2 PDB$SEED   READ ONLY

SYS@RACDBB>

alert_racdba1.log

2021-01-14T11:27:31.788825+00:00
PDB$SEED(2):Endian type of dictionary set to little
PDB$SEED(2):Undo initialization finished serial:0 start:3713780 end:3713780 diff:0 ms (0.0 seconds)
PDB$SEED(2):Database Characterset for PDB$SEED is AL32UTF8
2021-01-14T11:27:31.988785+00:00
Set LMHB to elevated priority
2021-01-14T11:27:32.638396+00:00
Starting background process RSM0
2021-01-14T11:27:32.660794+00:00
RSM0 started with pid=75, OS id=2007 
2021-01-14T11:27:32.986896+00:00
PDB$SEED(2):Opening pdb with no Resource Manager plan active
Unable to restore open state for pluggable databases due to               the following errors.
2021-01-14T11:27:33.111145+00:00
Errors in file /u01/app/oracle/diag/rdbms/racdba/racdba1/trace/racdba1_ora_1534.trc:
ORA-65054: Cannot open a pluggable database in the desired mode.
Physical standby database opened for read only access.
Completed: ALTER DATABASE OPEN READ ONLY /* db agent *//* {2:24204:2659} */
2021-01-14T11:27:33.820334+00:00
ALTER PLUGGABLE DATABASE pdb OPEN   /* svc agent *//* {2:24204:2659} */
2021-01-14T11:27:34.048502+00:00
ALTER SYSTEM SET remote_listener=' myraca-scan.example.com:1521' SCOPE=MEMORY SID='racdba1';
2021-01-14T11:27:34.050341+00:00
ALTER SYSTEM SET listener_networks='' SCOPE=MEMORY SID='racdba1';
PDB(3):Autotune of undo retention is turned on. 
2021-01-14T11:27:34.073923+00:00
PDB(3):Endian type of dictionary set to little
PDB(3):Undo initialization finished serial:0 start:3716088 end:3716088 diff:0 ms (0.0 seconds)
PDB(3):Database Characterset for PDB is AL32UTF8
2021-01-14T11:27:35.152791+00:00
PDB(3):Opening pdb with no Resource Manager plan active
Pluggable database PDB opened read only
Completed: ALTER PLUGGABLE DATABASE pdb OPEN   /* svc agent *//* {2:24204:2659} */
2021-01-14T11:27:35.703268+00:00
PDB(3):Started service pdb_svc/pdb_svc/pdb_svc

Although the ORA-65054 error is still there, the pluggable database is opened shortly afterwards by the Clusterware.

racdba1_ora_1534.trc

*** 2021-01-14T11:27:20.529675+00:00 (CDB$ROOT(1))
*** SESSION ID:(377.9495) 2021-01-14T11:27:20.529708+00:00
*** CLIENT ID:() 2021-01-14T11:27:20.529717+00:00
*** SERVICE NAME:() 2021-01-14T11:27:20.529724+00:00
*** MODULE NAME:(oraagent.bin@raca1.example.com (TNS V1-V3)) 2021-01-14T11:27:20.529731+00:00
*** ACTION NAME:() 2021-01-14T11:27:20.529739+00:00
*** CLIENT DRIVER:() 2021-01-14T11:27:20.529745+00:00
*** CONTAINER ID:(1) 2021-01-14T11:27:20.529753+00:00
 
kcrrmnt: RT: Role transition work is not done

*** 2021-01-14T11:27:20.865334+00:00 (CDB$ROOT(1))
*** 2021-01-14 11:27:20.865323 [krsn.c:548]
krsn_dbrole_change: Database role set to PHYSICAL STANDBY [kcvfdb.c:9212]
krsd_cb_role_change: role 2
*** 2021-01-14 11:27:20.993319 [krsh.c:6348]
Archiving previously deferred ORLs
*** 2021-01-14 11:27:20.993982 [krsq.c:3772]
krsq_arch_all_complete: Finished archiving all complete, unarchived ORLs

*** 2021-01-14T11:27:30.695367+00:00 (CDB$ROOT(1))
kjznppl0: database in migration or not writable

*** 2021-01-14T11:27:30.999497+00:00 (CDB$ROOT(1))
kjac_dpinfo_open: direct path not initialized, reason: in readable standby mode
* Set mstr_rdy 1, lmon_pnpchk 1 

*** 2021-01-14T11:27:32.249955+00:00 (PDB$SEED(2))
IPCLW:[0.0]{-}[WAIT]:PROTO: [1610623652249736]ipclw_data_chunk_process:1165 Discarding msg with seq # 2043340599, expecting 2043340603

*** 2021-01-14T11:27:33.111040+00:00 (CDB$ROOT(1))
<error barrier> at 0x7ffc3992e030 placed kpdb.c@21504
ORA-65054: Cannot open a pluggable database in the desired mode.

drcracdba1.log

2021-01-14T11:27:25.254+00:00
>> Starting Data Guard Broker bootstrap <<
Broker Configuration File Locations:
      dg_broker_config_file1 = "+DATA/RACDBA/dr1racdba"
      dg_broker_config_file2 = "+DATA/RACDBA/dr2racdba"
2021-01-14T11:27:25.254+00:00                      DMON: Attach state object
2021-01-14T11:27:25.261+00:00                      DMON: Broker State Initialized
2021-01-14T11:27:25.261+00:00                            Version = 3
2021-01-14T11:27:25.261+00:00                            State = 00000000
2021-01-14T11:27:25.261+00:00                      DMON: Creating INSV process
2021-01-14T11:27:28.282+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr1racdba' with blocksize 4096
2021-01-14T11:27:28.292+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr1racdba'
2021-01-14T11:27:28.296+00:00                      INSV: home block of +DATA/RACDBA/dr1racdba: zzz=0x40, Seq.MIV=14.1, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:27:28.297+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:27:28.300+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:27:28.301+00:00                      INSV: home block of +DATA/RACDBA/dr2racdba: zzz=0x40, Seq.MIV=15.0, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:27:28.301+00:00                      INSV: Set current metadata file ID to 2 (Seq.MIV=15.0)
2021-01-14T11:27:28.301+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:27:28.303+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:27:28.305+00:00                      INSV: Uploading persisted FSFO state:
2021-01-14T11:27:28.305+00:00                             flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:27:28.305+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:27:28.305+00:00                      	pmyshut=1, aft=30, laglim=30, obslim=30
2021-01-14T11:27:28.305+00:00                      INSV: FSFO state RAC reconcile started
2021-01-14T11:27:28.306+00:00                      INSV: Received reconcile FSFO state from instance #2
2021-01-14T11:27:28.306+00:00                      INSV:        flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:27:28.306+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:27:28.307+00:00                      INSV: FSFO state RAC reconcile finished
2021-01-14T11:27:28.307+00:00                      INSV: INSV is ready
2021-01-14T11:27:29.278+00:00                      DMON: rfm_get_chief_lock() called for CTL_BOOTSTRAP, reason BOOTSTRAP, called from rfm_dmon_wakeup_fn
2021-01-14T11:27:29.284+00:00 7fffffff           0 DMON: start task execution: broker initialization
2021-01-14T11:27:29.284+00:00                      DMON: Boot configuration (0.0.0), loading from "+DATA/RACDBA/dr2racdba"
2021-01-14T11:27:29.301+00:00                      DMON: My instance_name is racdba1 (SID racdba1), broker profile found at (1.2)
2021-01-14T11:27:29.301+00:00                      DMON: Verifying configuration service racdb_CFG
2021-01-14T11:27:29.301+00:00                      DMON: Configuration service not registered
2021-01-14T11:27:29.301+00:00                      DMON: Adding configuration service... racdb_CFG
2021-01-14T11:27:29.303+00:00                      DMON: Registering 1 service/s with listener(s)
2021-01-14T11:27:29.303+00:00                      DMON: Executing SQL [ALTER SYSTEM REGISTER]
2021-01-14T11:27:29.303+00:00                      SQL [ALTER SYSTEM REGISTER] Executed successfully
2021-01-14T11:27:29.303+00:00                      DMON: SCI harvested (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(Host=raca1.example.com)(Port=1522))(CONNECT_DATA=(SERVICE_NAME=racdba_DGMGRL)(INSTANCE_NAME=racdba1)(SERVER=DEDICATED)))
Broker Configuration:             racdb
  Oracle Release:                 19.0.0.0.0
  Oracle Version:                 19.9.0.0.0
  Metadata Version:               4.1 / UID=0x34ca0bad / Seq.MIV=15.0 / blksz.grain=4096.8
  Protection Mode:                Maximum Performance
  Fast-Start Failover (FSFO): DISABLED, flags=0x0, version=0
  Name                            Member Type                Handle      Enabled
  racdbb                          Primary Database           0x02010000  YES
  racdba                          Physical Standby Database  0x01010000  YES
2021-01-14T11:27:32.638+00:00
Configuration Validation Results:
      Primary database racdbb returned: ORA-0: normal, successful completion
Member racdba successfully completed version check
Broker configuration file is current, completing initialization
2021-01-14T11:27:46.120+00:00
Starting redo apply services...

alert_racdba2.log

2021-01-14T11:27:10.590468+00:00
PDB$SEED(2):This instance was first to open pluggable database PDB$SEED (container=2)
PDB$SEED(2):Endian type of dictionary set to little
PDB$SEED(2):Undo initialization finished serial:0 start:3693763 end:3693763 diff:0 ms (0.0 seconds)
PDB$SEED(2):Database Characterset for PDB$SEED is AL32UTF8
2021-01-14T11:27:10.879141+00:00
db_recovery_file_dest_size of 18000 MB is 15.64% used. This is a
user-specified limit on the amount of space that will be used by this
database for recovery-related files, and does not reflect the amount of
space available in the underlying filesystem or ASM diskgroup.
2021-01-14T11:27:11.038141+00:00
PDB$SEED(2):Opening pdb with no Resource Manager plan active
Unable to restore open state for pluggable databases due to               the following errors.
2021-01-14T11:27:11.103829+00:00
Errors in file /u01/app/oracle/diag/rdbms/racdba/racdba2/trace/racdba2_ora_6677.trc:
ORA-65054: Cannot open a pluggable database in the desired mode.
2021-01-14T11:27:11.217024+00:00
Physical standby database opened for read only access.
Completed: ALTER DATABASE OPEN READ ONLY /* db agent *//* {2:24204:2565} */
2021-01-14T11:27:11.849329+00:00
ALTER PLUGGABLE DATABASE pdb OPEN READ ONLY  /* svc agent *//* {2:24204:2565} */

racdb2_ora_6677.trc

*** 2021-01-14T11:27:09.794332+00:00 (CDB$ROOT(1))
kjznppl0: database in migration or not writable
kjac_dpinfo_open: direct path not initialized, reason: in readable standby mode
* Set mstr_rdy 1, lmon_pnpchk 1 

*** 2021-01-14T11:27:11.103734+00:00 (CDB$ROOT(1))
<error barrier> at 0x7ffdf766e730 placed kpdb.c@21504
ORA-65054: Cannot open a pluggable database in the desired mode.

drcracdba2.log

2021-01-14T11:26:06.494+00:00
Initiating a healthcheck...
2021-01-14T11:26:08.044+00:00
SWITCHOVER TO racdbb
Switchover to physical standby database cannot be initiated from the primary database
redirecting connection to switchover target database racdbb...
...using connect identifier: //myracb-scan/racdbb
SWITCHOVER TO racdbb
2021-01-14T11:26:10.771+00:00
Notifying Oracle Clusterware to prepare primary database for switchover
Switchover in progress...
2021-01-14T11:26:12.048+00:00
Executing SQL: [ALTER DATABASE SWITCHOVER TO 'racdbb']
2021-01-14T11:26:33.855+00:00
SQL [ALTER DATABASE SWITCHOVER TO 'racdbb'] executed successfully
2021-01-14T11:26:35.031+00:00
Switchover successful
2021-01-14T11:26:40.618+00:00
Notifying Clusterware to restart this instance for Switchover
2021-01-14T11:26:42.824+00:00
Shutting down instance after Switchover
2021-01-14T11:27:02.925+00:00
>> Starting Data Guard Broker bootstrap <<
Broker Configuration File Locations:
      dg_broker_config_file1 = "+DATA/RACDBA/dr1racdba"
      dg_broker_config_file2 = "+DATA/RACDBA/dr2racdba"
2021-01-14T11:27:02.925+00:00                      DMON: Attach state object
2021-01-14T11:27:02.927+00:00                      DMON: Initialization of broker state requires reconciliation
2021-01-14T11:27:02.927+00:00                      DMON: Broker state reconciled, version = 0, state = 00000000
2021-01-14T11:27:02.927+00:00                      DMON: Broker State Initialized
2021-01-14T11:27:02.927+00:00                            Version = 1
2021-01-14T11:27:02.927+00:00                            State = 00000000
2021-01-14T11:27:02.927+00:00                      DMON: Creating INSV process
2021-01-14T11:27:05.944+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr1racdba' with blocksize 4096
2021-01-14T11:27:05.946+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr1racdba'
2021-01-14T11:27:05.950+00:00                      INSV: home block of +DATA/RACDBA/dr1racdba: zzz=0x40, Seq.MIV=14.1, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:27:05.951+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:27:05.952+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:27:05.954+00:00                      INSV: home block of +DATA/RACDBA/dr2racdba: zzz=0x40, Seq.MIV=15.0, fsfo flags=0x0, version=0, pstseq=0.0
2021-01-14T11:27:05.954+00:00                      INSV: Set current metadata file ID to 2 (Seq.MIV=15.0)
2021-01-14T11:27:05.954+00:00                      INSV: Opening configuration file '+DATA/RACDBA/dr2racdba' with blocksize 4096
2021-01-14T11:27:05.956+00:00                      INSV: Successfully opened configuration file '+DATA/RACDBA/dr2racdba'
2021-01-14T11:27:05.958+00:00                      INSV: Uploading persisted FSFO state:
2021-01-14T11:27:05.958+00:00                             flags=0x00000000, version=0, pstseq=0, target=0, obid=1
2021-01-14T11:27:05.958+00:00                             envsn=0, ackseq=0, new_target=255, new_obid=0
2021-01-14T11:27:05.958+00:00                      	pmyshut=1, aft=30, laglim=30, obslim=30
2021-01-14T11:27:05.958+00:00                      INSV: FSFO state RAC reconcile started
2021-01-14T11:27:05.959+00:00                      INSV: FSFO state RAC reconcile finished
2021-01-14T11:27:05.959+00:00                      INSV: INSV is ready
2021-01-14T11:27:06.940+00:00                      DMON: rfm_get_chief_lock() called for CTL_BOOTSTRAP, reason BOOTSTRAP, called from rfm_dmon_wakeup_fn
2021-01-14T11:27:06.941+00:00 7fffffff           0 DMON: start task execution: broker initialization
2021-01-14T11:27:06.941+00:00                      DMON: Boot configuration (0.0.0), loading from "+DATA/RACDBA/dr2racdba"
2021-01-14T11:27:06.951+00:00                      DMON: My instance_name is racdba2 (SID racdba2), broker profile found at (1.1)
2021-01-14T11:27:06.951+00:00                      DMON: Verifying configuration service racdb_CFG
2021-01-14T11:27:06.951+00:00                      DMON: Configuration service not registered
2021-01-14T11:27:06.951+00:00                      DMON: Adding configuration service... racdb_CFG
2021-01-14T11:27:06.951+00:00                      DMON: Registering 1 service/s with listener(s)
2021-01-14T11:27:06.951+00:00                      DMON: Executing SQL [ALTER SYSTEM REGISTER]
2021-01-14T11:27:06.952+00:00                      SQL [ALTER SYSTEM REGISTER] Executed successfully
2021-01-14T11:27:06.952+00:00                      DMON: SCI harvested (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(Host=raca2.example.com)(Port=1522))(CONNECT_DATA=(SERVICE_NAME=racdba_DGMGRL)(INSTANCE_NAME=racdba2)(SERVER=DEDICATED)))
Broker Configuration:             racdb
  Oracle Release:                 19.0.0.0.0
  Oracle Version:                 19.9.0.0.0
  Metadata Version:               4.1 / UID=0x34ca0bad / Seq.MIV=15.0 / blksz.grain=4096.8
  Protection Mode:                Maximum Performance
  Fast-Start Failover (FSFO): DISABLED, flags=0x0, version=0
  Name                            Member Type                Handle      Enabled
  racdbb                          Primary Database           0x02010000  YES
  racdba                          Physical Standby Database  0x01010000  YES
2021-01-14T11:27:06.981+00:00
Physical standby restart after broker operation requires Oracle Clusterware buildup
Notifying Oracle Clusterware to buildup
2021-01-14T11:27:09.788+00:00
Configuration Validation Results:
      Primary database racdbb returned: ORA-0: normal, successful completion
Member racdba successfully completed version check
Broker configuration file is current, completing initialization
2021-01-14T11:27:21.950+00:00
Starting redo apply services...

Conclusion

User PDB's may not open on all instances following DataGuard Switchover. This behaviour is quite inconsistent since PDB's are opened just on some instances. Thankfully, the workaround is pretty straightforward - we just need to create a dedicated service for these PDB's.

Creating RAC Physical Standby for Single Instance Primary

Oracle made some interesting improvements in Database Configuration Assistant (DBCA) in 18c, namely this:

Creating a copy of an Oracle RAC database
A copy of an Oracle RAC database can be created using the -createDuplicateDB command option -databaseConfigType with the value of RAC or RACONENODE.

It has been possible to create a standby database using the createDuplicateDB DBCA command since 12.2.
18c added a new capability to specify the database configuration type of a new standby, such as: RAC, RAC One Node, or a regular single instance database.

This method by itself requires some prerequisite actions. I do not see that these are documented, so that I am writing this blog post.

Setup

Primary

• Hostname: primary
• db_name: orcl
• db_unique_name: orcl
• Configuration Type: Single Instance

Standby

• Hostnames: rac1.example.com, rac2.example.com
• db_unique_name: racdb
• Configuration Type: RAC
• SCAN port: 1521
• Local listener port: 1522
• Grid Home: /u01/app/19.3.0/grid, owner=grid
• DB Home: /u01/app/oracle/product/19.3.0/dbhome_1, owner=oracle (role separation)
• ASM disk groups: single disk group DATA - it is a sandbox

The naming convention might be a bit odd, but the main purpose of this configuration is to provide some initial steps to setup a new RAC database with a view to making it a new primary.

DBCA Command

This is a DBCA command that I will run to create a standby database in 19.9:

dbca -createDuplicateDB -silent \
     -gdbName orcl \
     -primaryDBConnectionString primary:1521/orcl \
     -sid racdb \
     -initParams "dg_broker_start=true" \
     -sysPassword change_on_install \
     -adminManaged \
     -nodelist rac1,rac2 \
     -recoveryAreaDestination +DATA \
       -recoveryAreaSize 10000 \
     -databaseConfigType RAC \
     -useOMF true \
     -storageType ASM \
       -datafileDestination +DATA \
     -createAsStandby \
       -dbUniqueName racdb \
     -createListener rac1.example.com:1522

Firstly, let me go over the keys that are worth mentioning.

1. -primaryDBConnectionString primary:1521/orcl - it should have a specific port number even if it is default 1521
2. -createListener rac1.example.com:1522 - this is the most interesting part. This is part of the RMAN block that is run to create a physical standby database:

   duplicate target database
   for standby
   from active database
   dorecover
   nofilenamecheck
   ;

   It is the push-based method of active database duplication. Therefore, the primary database should be able to connect to the new standby. I specified the local listener endpoint (1522) in this example. Then, DBCA always tries to create a new listener in this configuration. I do not know how to avoid that here. Even worse, it attempts to create a new listener in DB home. Thankfully, it silently swallows an error if the listener already exists. Here is a sample excerpt from the DBCA log file to substantiate that remark with some facts:

   [progressPage.flowWorker] [ 2020-12-30 19:04:30.642 UTC ] [ClusterInfo.getHostName:462]  Hostname = rac1
   INFO: Dec 30, 2020 7:04:30 PM oracle.install.commons.system.process.ProcessLauncher launchProcess
   INFO: Executing [/u01/app/oracle/product/19.3.0/dbhome_1/bin/lsnrctl, start, rac1.example.com]
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.install.commons.system.process.ProcessLauncher launchProcess
   INFO: Starting Output Reader Threads for process /u01/app/oracle/product/19.3.0/dbhome_1/bin/lsnrctl
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO:
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO: LSNRCTL for Linux: Version 19.0.0.0.0 - Production on 30-DEC-2020 19:04:30
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO:
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO: Copyright (c) 1991, 2020, Oracle.  All rights reserved.
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO:
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper$2 processLine
   INFO: TNS-01106: Listener using listener name LISTENER has already been started
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.install.commons.system.process.ProcessLauncher launchProcess
   INFO: The process /u01/app/oracle/product/19.3.0/dbhome_1/bin/lsnrctl exited with code 1
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.install.commons.system.process.ProcessLauncher launchProcess
   INFO: Waiting for output processor threads to exit.
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.install.commons.system.process.ProcessLauncher launchProcess
   INFO: Output processor threads exited.
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.common.util.NetworkConfigHelper startListener
   INFO: Exit code of lsnrctl is:1
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.dbca.driver.backend.steps.ListenerConfigStep createStaticListener
   INFO: Static listener created.
   
   INFO: Dec 30, 2020 7:04:30 PM oracle.assistants.dbca.driver.StepDBCAJob$1 update
   INFO: Percentage Progress got for job:Listener config step progress:100.0
   

   There is another little drawback with this approach - it creates listener.ora in DB home which uses a static configuration. It is harmless, but I would rather clean it up after the exercise to have a nice and tidy environment.

Prerequisite Steps

It should be possible to establish a connection from the primary host using the local listener endpoint: rac1.example.com:1522.
I do not discuss DNS setup - it is implied.
I need to configure a static registration for the new RAC instance. For that, I edit my GI listener.ora on the host I am going to run the duplicate command from (rac1):

# /u01/app/19.3.0/grid/network/admin/listener.ora
SID_LIST_LISTENER=
  (SID_LIST=
      (SID_DESC=
         (SID_NAME=racdb1)
         (ORACLE_HOME=/u01/app/oracle/product/19.3.0/dbhome_1)
       )
   )

That is basically it. Once I reload the local listener, I am good to continue to the next step.

Creating RAC Physical Standby

[oracle@rac1 ~]$ dbca -createDuplicateDB -silent \
>      -gdbName orcl \
>      -primaryDBConnectionString primary:1521/orcl \
>      -sid racdb \
>      -initParams "dg_broker_start=true" \
>      -sysPassword change_on_install \
>      -adminManaged \
>      -nodelist rac1,rac2 \
>      -recoveryAreaDestination +DATA \
>        -recoveryAreaSize 10000 \
>      -databaseConfigType RAC \
>      -useOMF true \
>      -storageType ASM \
>        -datafileDestination +DATA \
>      -createAsStandby \
>        -dbUniqueName racdb \
>      -createListener rac1.example.com:1522
Prepare for db operation
22% complete
Listener config step
44% complete
Auxiliary instance creation
67% complete
RMAN duplicate
89% complete
Post duplicate database operations
100% complete

Look at the log file "/u01/app/oracle/cfgtoollogs/dbca/racdb/racdb.log" for further details.

That is it:

SQL> select database_role from v$database;

DATABASE_ROLE
----------------
PHYSICAL STANDBY

SQL> select instance_name, host_name from gv$instance;

INSTANCE_NAME    HOST_NAME
---------------- --------------------
racdb1           rac1.example.com
racdb2           rac2.example.com

Further Steps

1. Delete /u01/app/oracle/product/19.3.0/dbhome_1/network/admin/listener.ora. DBCA created this file with the following content:

   SID_LIST_RAC1.EXAMPLE.COM =
     (SID_LIST =
       (SID_DESC =
         (SID_NAME = racdb1)
       )
     )
   
   RAC1.EXAMPLE.COM =
     (ADDRESS_LIST =
       (ADDRESS = (PROTOCOL = TCP)(HOST = rac1.example.com)(PORT = 1522))
     )

2. Adding standby redo logs, creating a new Data Guard Configuration, enabling FORCE_LOGGING, Flashback database, etc. - I do not mention it here. The purpose of this post to show how to instantiate a new RAC standby database in one command after completing some simple preliminary steps.

Notable Downsides

There ain't no such thing as a free lunch.
Both slow connection between the sites, and a "huge" database size limits the applicability of this method.
I do not see how this method can utilize the restartable duplication too.
In all other cases, it is possible to quickly spin up a new RAC standby database using this excellent DBCA createDuplicateDB command.

ORA-600 [kglobpg_is_pkp] During Rolling RU 19.7 Apply

I came across this issue while applying RU 19.7 to my RAC database.
That was the old ORACLE_HOME:

[oracle@rac1 dbhome_1]$ OPatch/opatch lspatches
30128191;OJVM RELEASE UPDATE: 19.5.0.0.191015 (30128191)
30122149;OCW RELEASE UPDATE 19.5.0.0.0 (30122149)
30125133;Database Release Update : 19.5.0.0.191015 (30125133)

OPatch succeeded.

That was the new one:

[oracle@rac1 dbhome_3]$ OPatch/opatch lspatches
30805684;OJVM RELEASE UPDATE: 19.7.0.0.200414 (30805684)
30894985;OCW RELEASE UPDATE 19.7.0.0.0 (30894985)
30869156;Database Release Update : 19.7.0.0.200414 (30869156)

OPatch succeeded.

There were two nodes in the cluster: rac1 and rac2.

I set the new ORACLE_HOME for the database and restarted rac2:

Patch Id: 30805684
Patch Description: OJVM RELEASE UPDATE: 19.7.0.0.200414 (30805684)
Patch Apply Time: 2020-07-09T19:38:43Z
Bugs Fixed: 29254623,29445548,29512125,29540327,29774362,29942275,30134746,
30160625,30534662,30855101
===========================================================
2020-07-11T15:39:33.323415+00:00
Resize operation completed for file# 1, old size 993280K, new size 1003520K
Resize operation completed for file# 1, old size 1003520K, new size 1013760K
2020-07-11T15:39:35.107445+00:00
Resize operation completed for file# 1, old size 1013760K, new size 1024000K
Resize operation completed for file# 1, old size 1024000K, new size 1034240K
2020-07-11T15:39:37.061108+00:00
Resize operation completed for file# 1, old size 1034240K, new size 1044480K
Resize operation completed for file# 1, old size 1044480K, new size 1054720K
2020-07-11T15:39:38.695595+00:00
Resize operation completed for file# 1, old size 1054720K, new size 1064960K
jox_pujs ending in pid 23121 cid 1
2020-07-11T15:39:39.024323+00:00
Java patching prepare phase started.
2020-07-11T15:39:39.068031+00:00
## jox_ujs_status: op_instance_patched: returning TRUE in pid 22749
2020-07-11T15:39:44.069088+00:00
## jox_ujs_status: op_instance_patched: returning TRUE in pid 22749

pid 22749 was GEN0 and it was writing that 'jox_ujs_status' message to the alert log every 5 seconds.

That was what I had on rac1:

2020-07-11T15:38:52.976980+00:00
Increasing priority of 1 RS
Domain Action Reconfiguration started (domid 3, new da inc 6, cluster inc 8)
Instance 2 is attaching to domain 3
 Global Resource Directory partially frozen for domain action
 Non-local Process blocks cleaned out
 Set master node info
 Dwn-cvts replayed, VALBLKs dubious
 All grantable enqueues granted
Domain Action Reconfiguration complete (total time 0.1 secs)
Decreasing priority of 1 RS
2020-07-11T15:39:39.024882+00:00
Java patching prepare phase started.
2020-07-11T15:39:39.049868+00:00
## jox_ujs_status: op_instance_patched: UJS active in root, ujs state present, its version does not match executable version, returning FALSE in pid 31373
2020-07-11T15:39:44.069761+00:00
## jox_ujs_status: op_instance_patched: UJS active in root, ujs state present, its version does not match executable version, returning FALSE in pid 31373
2020-07-11T15:39:49.071807+00:00
## jox_ujs_status: op_instance_patched: UJS active in root, ujs state present, its version does not match executable version, returning FALSE in pid 31373

Although it looked suspicious, I decided to continue the patching.
Once I stopped rac1, I was not able to start it anymore:

2020-07-11T15:42:40.981054+00:00
## jox_ujs_status: op_instance_patched: returning TRUE in pid 4744
Starting background process GTX0
2020-07-11T15:42:41.422960+00:00
GTX0 started with pid=63, OS id=4926
2020-07-11T15:42:41.427547+00:00
joxcsys_required_dirobj_exists: directory object exists with required path /u01/app/oracle/product/19.3.0/dbhome_3/javavm/admin/, pid 4844 cid 1
Starting background process RCBG
2020-07-11T15:42:41.492063+00:00
RCBG started with pid=64, OS id=4928
replication_dependency_tracking turned off (no async multimaster replication found)
2020-07-11T15:42:41.831459+00:00
Errors in file /u01/app/oracle/diag/rdbms/racdb/racdb1/trace/racdb1_ora_4844.trc  (incident=5249) (PDBNAME=CDB$ROOT):
ORA-00600: internal error code, arguments: [kglobpg_is_pkp], [0x077DD9BC8], [], [], [], [], [], [], [], [], [], []
Incident details in: /u01/app/oracle/diag/rdbms/racdb/racdb1/incident/incdir_5249/racdb1_ora_4844_i5249.trc
Use ADRCI or Support Workbench to package the incident.
See Note 411.1 at My Oracle Support for error and packaging details.
..
2020-07-11T15:42:42.782978+00:00
## jox_ujs_status: op_instance_patched: returning TRUE in pid 4744
Errors in file /u01/app/oracle/diag/rdbms/racdb/racdb1/trace/racdb1_ora_4844.trc  (incident=5250) (PDBNAME=CDB$ROOT):
ORA-00603: ORACLE server session terminated by fatal error
ORA-01092: ORACLE instance terminated. Disconnection forced
ORA-00600: internal error code, arguments: [kglobpg_is_pkp], [0x077DD9BC8], [], [], [], [], [], [], [], [], [], []
Incident details in: /u01/app/oracle/diag/rdbms/racdb/racdb1/incident/incdir_5250/racdb1_ora_4844_i5250.trc
2020-07-11T15:42:42.941948+00:00
Dumping diagnostic data in directory=[cdmp_20200711154242], requested by (instance=1, osid=4844), summary=[incident=5249].
2020-07-11T15:42:43.784890+00:00
## jox_ujs_status: op_instance_patched: returning TRUE in pid 4744
2020-07-11T15:42:43.960028+00:00
opiodr aborting process unknown ospid (4844) as a result of ORA-603
2020-07-11T15:42:43.976310+00:00
ORA-603 : opitsk aborting process
License high water mark = 1
USER(prelim) (ospid: 4844): terminating the instance due to ORA error 600

That essentially left me with rac2 whose GEN0 was spamming the following message to the alert log once in 5 seconds:

## jox_ujs_status: op_instance_patched: returning TRUE in pid 22749

Any attempts to run datapatch and finish the patching ended up with the following errors:

ORA-29548: Java system class reported: UJS still running
ORA-06512: at "SYS.DBMS_JAVA_TEST", line 2
ORA-06512: at "SYS.DBMS_JAVA_TEST", line 55
ORA-06512: at line 4

There were some ORA-00600 [kglobpg_is_pkp] errors on My Oracle Support (MOS) but there was nothing specific that I could link to my issue.

When I get no hits, I usually turn PowerView off or extend my search to include bugs, patches, etc.
That worked out well and I found the following patch:
Patch 31359215: INSTANCE STARTUP FAILS ORA-600 [KGLOBPG_IS_PKP] DURING ROLLING RU 19.7 APPLY
I applied that patch to rac1 and was finally able to start that instance successfully. The remaining part of that rolling patch exercise went without a hitch.
The patch itself was released on 7th July. I hope Oracle Support will update the Knowledge Base, or publish some alerts about this issue, or even merge that patch into 19.7 OJVM.