Oracle database is designed to perform well under high concurrent load.<\/p>\n
With flashback data archive (FBDA), though, you might hit some limitations. In particular, the feature can delay the execution of DDL commands.<\/p>\n
I’ll be demonstrating it on two empty tables with the FBDA configuration (tested on 19.10.0.0.210119):<\/p>\n
create flashback archive default fba tablespace users retention 1 year ;\n\ncreate table t1 ( n number ) ;\ncreate table t2 ( n number ) ;\n\nalter table t1 flashback archive ;\nalter table t2 flashback archive ;<\/code><\/pre>\nWARNING: In this demo, I’ll be using debugger for changing memory locations and stopping the program execution to figure out the internal functioning of the feature. Such manipulations are unsafe and unsupported, and can corrupt the database. Therefore, never do them outside your private lab environment.<\/p>\n
Oracle FBDA C functions<\/h1>\n
The script fbda.d traces the execution of the FBDA background process:<\/p>\n
#pragma D option quiet\n\npid$target:oracle:ktfaundoar_main:entry,\npid$target:oracle:ktfaundoar_main:return\n{\n printf(\"%Y %s %s\\n\", walltimestamp, probefunc, probename );\n}\n\npid$target:oracle:ktfaundoar_main:return\n{\n printf(\"\\n\");\n}\n\npid$target:oracle:ktfa_partition_fba_tables:entry\n{\n printf(\"%Y \\n\", walltimestamp );\n ustack() ;\n}<\/code><\/pre>\nIn particular, it focuses on the following two functions: ktfaundoar_main and ktfa_partition_fba_tables. ktfaundoar_main calls other functions when there’s work to do. Among others, it periodically calls ktfa_partition_fba_tables, which creates new partitions on FBDA tables as they grow.<\/p>\n
ps -ef | grep fbda | grep DB\n1000 7584 13824 0 16:10:15 ? 0:00 ora_fbda_DB<\/code><\/pre>\ndtrace -s fbda.d -p 7584<\/code><\/pre>\n2021 Jul 8 18:34:27 ktfaundoar_main entry\n2021 Jul 8 18:34:27 ktfaundoar_main return\n\n2021 Jul 8 18:39:27 ktfaundoar_main entry\n2021 Jul 8 18:39:27 ktfaundoar_main return\n\n2021 Jul 8 18:44:27 ktfaundoar_main entry\n2021 Jul 8 18:44:27 ktfaundoar_main return<\/code><\/pre>\nAs we can see, the FBDA process calls ktfaundoar_main every 5 minutes.<\/p>\n
Interprocess communication<\/h1>\n
Between two consecutive calls, the FBDA process is waiting on a message:<\/p>\n
pstack 7584\n7584: ora_fbda_DB\n00007ff75427741a portfs (5, 4, 7fffbfff8200, 3, 0, 7fffbfff8220)\n00000000062a650d sskgpwwait () + dd\n00000000062a60f3 skgpwwait () + c3\n00000000064a984d ksliwat () + 9ad\n00000000064a8a3f kslwaitctx () + af\n000000000a7f618d ktfaundoar () + 86d\n00000000073e2473 ksbrdp () + 543\n0000000006fe0399 opirip () + 2b9\n00000000061f0cd0 opidrv () + 160\n00000000061f0ae7 sou2o () + 97\n00000000061f08b4 opimai_real () + a4\n00000000061f040b ssthrdmain () + 26b\n00000000061f0179 main () + a9\n0000000007868c34 ???????? ()<\/code><\/pre>\nThis waiting is instrumented by the “fbar timer” wait event:<\/p>\n
column program format a25\ncolumn event format a10\nSQL> select program,event,seconds_in_wait from v$session where program like '%FBDA%' ;\n\nPROGRAM EVENT SECONDS_IN_WAIT\n------------------------- ---------- ---------------\noracle@svdbp01i (FBDA) fbar timer 112<\/code><\/pre>\nThe “fbar timer” wait event is an idle wait, i.e. not contributing to the total database time. Simply put, the FBDA process isn’t doing any work during this time – it’s just waiting on a message without blocking anyone.<\/p>\n
A process performing DDL on a table with configured FBDA will ask the FBDA process to do some work on its behalf, for example:<\/p>\n
truncate t1<\/code><\/pre>\nThe FBDA process immediately exits the waiting state to perform the work – we can see several consecutive calls to ktfaundoar_main:<\/p>\n
2021 Jul 8 17:27:45 ktfaundoar_main entry\n2021 Jul 8 17:27:46 ktfaundoar_main return\n\n2021 Jul 8 17:27:47 ktfaundoar_main entry\n2021 Jul 8 17:27:47 ktfaundoar_main return\n\n2021 Jul 8 17:27:48 ktfaundoar_main entry\n2021 Jul 8 17:27:48 ktfaundoar_main return\n\n2021 Jul 8 17:27:49 ktfaundoar_main entry\n2021 Jul 8 17:27:49 ktfaundoar_main return\n\n2021 Jul 8 17:27:50 ktfaundoar_main entry\n2021 Jul 8 17:27:50 ktfaundoar_main return\n\n2021 Jul 8 17:27:51 ktfaundoar_main entry\n2021 Jul 8 17:27:51 ktfaundoar_main return<\/code><\/pre>\nIn addition, I configured SQL trace on FBDA:<\/p>\n
select sid,serial# from v$session where program like '%FBDA%' ;\n\n SID SERIAL#\n---------- ----------\n 289 53053\n\nexec dbms_system.set_ev(si=>289, se=>53053, ev=>10046, le=>8, nm=>'');<\/code><\/pre>\nThe FBDA process executed some SQL statements, like the following one:<\/p>\n
update SYS_FBA_BARRIERSCN set BARRIERSCN=:1, ACTIVESCN=:2, STATUS=:3 where INST_ID=:4<\/code><\/pre>\nI used the update.d script to find out Oracle C functions underpinning the update.<\/p>\n
#pragma D option quiet\n\npid$target:oracle:*upd*:entry\n{\n ustack(200) ;\n}<\/code><\/pre>\ndtrace -s update.d -p 7584\n\n\noracle`kokbntupd\noracle`kauupd+0x348\noracle`updrow+0x7e7\noracle`qerupUpdRow+0x369\noracle`qerupRopRowsets+0x111\noracle`qerstRowP+0x587\noracle`kdstf110110100001000km+0xe91\noracle`kdsttgr+0x757\noracle`qertbFetch+0x542\noracle`qerstFetch+0x542\noracle`qerupFetch+0x3e6\noracle`qerstFetch+0x5c0\noracle`updaul+0x676\noracle`updThreePhaseExe+0x14a\noracle`updexe+0x1ec\noracle`opiexe+0x3182\noracle`kpoal8+0xb5a\noracle`opiodr+0x439\noracle`kpoodrc+0x26\noracle`rpiswu2+0x2d6\noracle`kpoodr+0x2bb\noracle`upirtrc+0xf7b\noracle`kpurcsc+0x6e\noracle`kpuexec+0x1e8e\noracle`OCIStmtExecute+0x29\noracle`ktfaubscn+0x506\noracle`ktfaarchiver1+0x10b0\noracle`ktfaarchiver+0x529\noracle`ktfaundoar_main+0x2c8\noracle`ktfaundoar+0x8c5\noracle`ksbrdp+0x543\noracle`opirip+0x2b9\noracle`opidrv+0x160\noracle`sou2o+0x97\noracle`opimai_real+0xa4\noracle`ssthrdmain+0x26b\noracle`main+0xa9<\/code><\/pre>\nWhy’s that interesting?<\/p>\n
Because if we set the breakpoint in any of those functions, we can simulate a performance problem with the FBDA process and observe how the sessions are behaving during that time.<\/p>\n
Serialization<\/h1>\n
After attaching the debugger to the FBDA process and setting a breakpoint on the updrow function, I’ll truncate the T1:<\/p>\n
attach 7584\nb updrow<\/code><\/pre>\ntruncate table t1 ;<\/code><\/pre>\nThe FBDA process hit the breakpoint, and truncate table is hanging as long as the FBDA process execution is paused.<\/p>\n
In this state, I’ll start the truncate on another table, which will also hang:<\/p>\n
truncate table t2 ;<\/code><\/pre>\nInstrumentation gap<\/h1>\n
Now we can observe the sessions in V$SESSION:<\/p>\n
column program format a25\ncolumn event format a10\nselect program, state, event, seconds_in_wait\n from v$session se\n where sid != userenv('SID') and\n ( program like 'sqlplus%' or program like '%FBDA%' ) ;\n\nPROGRAM STATE EVENT SECONDS_IN_WAIT\n------------------------- ------------------- ---------- ---------------\nACTION\n----------------------------------------------------------------\nsqlplus@svdbp01i (TNS V1- WAITING fbar timer 57\nV3)\n\n\nsqlplus@svdbp01i (TNS V1- WAITING fbar timer 451\nV3)\n\n\noracle@svdbp01i (FBDA) WAITED KNOWN TIME fbar timer 483<\/code><\/pre>\nBoth sessions executing truncate are waiting on the “fbar timer” wait event, i.e. they are waiting on a message from the FBDA process. The FBDA process will send this message after it completes its part.<\/p>\n
But notice the ambiguity of the “fbar timer” wait event. On the one hand, the FBDA process is waiting on “fbar timer” when it doesn’t have anything else to do, so it’s an idle event. On the other hand, the user session is in the same wait while waiting on the FBDA process to complete. Since the DDL statement doesn’t complete before the user process receives the message from the FBDA process, it shouldn’t be classified as “idle” in this partucular case.<\/p>\n
Consequently, ASH doesn’t capture the user session waiting on a message from FBDA to complete:<\/p>\n
@ashtop session_id,program2,event2 1=1 &5min\n Total Distinct\n Seconds AAS %This SESSION_ID PROGRAM2 EVENT2 FIRST_SEEN LAST_SEEN Execs Seen\n--------- ------- ------- ---------- ---------------------------------------- ------------------------------------------ ------------------- ------------------- ----------\n 300 1.0 97% | 289 (FBDA) ON CPU 2021-07-08 18:23:44 2021-07-08 18:28:43 1\n 5 .0 2% | 53 (DBRM) ON CPU 2021-07-08 18:24:16 2021-07-08 18:28:41 1<\/code><\/pre>\nIn other words, the DBA won’t be able to analyze slow truncates retrospectively.<\/p>\n
I covered this instrumentation gap in a previous blog post<\/a> and also provided workarounds.<\/p>\nSo far, I demonstrated how a performance problem in the FBDA process can slow down DDL operations. I also showed the blind spot in the Oracle database instrumentation.<\/p>\n
FBDA maintenance<\/h1>\n
With debugger, I simulated a performance problem on the update statement, which is less likely to happen in the real world. But during the maintenance window, the FBDA process executes much heavier statements, like split partition on large FBDA tables:<\/p>\n
select floor(sum(BYTES\/1024\/1024)) from DBA_SEGMENTS where SEGMENT_NAME='SYS_FBA_HIST_4925624' and OWNER='OWNER' and PARTITION_NAME='HIGH_PART'\n\nselect sum(extents) from DBA_SEGMENTS where SEGMENT_NAME='SYS_FBA_HIST_4925624' and OWNER='OWNER' and PARTITION_NAME='HIGH_PART'\n\nalter table \"OWNER\".SYS_FBA_HIST_4925624 split partition high_part at (74291633007) into (partition part_74291633007, partition high_part)<\/code><\/pre>\nThis is likely to cause a concurrency problem with DDL statements coming from user processes.<\/p>\n
This maintenance code runs once per day at 2 AM. That schedule is inconvenient for experimenting except for night owls.<\/p>\n
Unfortunately, there isn’t a known way to shorten the interval or adjust the starting time. But I figured out a hack (for lab environments only).<\/p>\n
The interval is stored in the memory chunk marked as “ktfa dynamic SG”:<\/p>\n
select KSMCHPTR, KSMCHSIZ from\n x$ksmsp\nwhere ksmchcom = 'ktfa dynamic SG' ;\n\nKSMCHPTR KSMCHSIZ\n---------------- ----------\n000000009091FDB8 648<\/code><\/pre>\nWith debugger, we can search for the value 86400 (86400 seconds = 1 day) in this chunk:<\/p>\n
(gdb) x\/648d 0x000000009091FDB8\n...\n0x90920018: 86400 0 0 0<\/code><\/pre>\nIn our case, the interval value is stored in the location 0x90920018;<\/p>\n
(gdb) x\/d 0x90920018\n0x90920018: 86400<\/code><\/pre>\nAfter storing a low (unsigned integer) value in this address location, ktfaundoar_main will start executing the maintenance on each run, i.e. every 5 minutes, instead of once per day:<\/p>\n
(gdb) set *0x90920018=1\n(gdb) x\/d 0x90920018\n0x90920018: 1<\/code><\/pre>\n2021 Jul 8 18:54:27 ktfaundoar_main entry\n2021 Jul 8 18:54:27\n\noracle`ktfa_partition_fba_tables\noracle`ktfa_traverse_tracked_tables+0x361\noracle`ktfa_do_scheduled_tasks_pdb+0xbd\noracle`ktfa_do_scheduled_tasks+0x24\noracle`ktfaundoar_main+0xa6d\noracle`ktfaundoar+0x8c5\noracle`ksbrdp+0x543\noracle`opirip+0x2b9\noracle`opidrv+0x160\noracle`sou2o+0x97\noracle`opimai_real+0xa4\noracle`ssthrdmain+0x26b\noracle`main+0xa9\na.out`0x7868c34<\/code><\/pre>\nNow we can set a breakpoint somewhere in the maintenance procedures to emulate a performance problem:<\/p>\n
(gdb) b ktfa_partition_fba_tables\n\nThread 2 hit Breakpoint 1, 0x000000000a87f520 in ktfa_partition_fba_tables ()<\/code><\/pre>\nAfter hitting the first breakpoint, we’ll set another breakpoint at fetching:<\/p>\n
(gdb) b *qertbFetch\nNote: breakpoint 2 (disabled) also set at pc 0x67e9980.\nBreakpoint 3 at 0x67e9980\n(gdb) c\nContinuing.\n\nThread 2 hit Breakpoint 3, 0x00000000067e9980 in qertbFetch ()<\/code><\/pre>\nNow we can see what the FBDA process is currently executing:<\/p>\n
column program format a25\ncolumn event format a10\nselect program, state, event, seconds_in_wait, sql_text\n from v$session se, v$sqlarea sq\n where sid != userenv('SID') and\n program like '%FBDA%' and sq.address = se.sql_address ;\n\nPROGRAM STATE EVENT SECONDS_IN_WAIT\n------------------------- ------------------- ---------- ---------------\nSQL_TEXT\n--------------------------------------------------------------------------------\noracle@svdbp01i (FBDA) WAITED SHORT TIME fbar timer 232\nselect OWNERNAME, OBJNAME from SYS_FBA_TRACKEDTABLES where OBJ#=52340<\/code><\/pre>\nIt’s currently processing the T1 table:<\/p>\n
select object_name from dba_objects where object_id=52340 ;\n\nOBJECT_NAME\n--------------------------------------------------------------------------------\nT1<\/code><\/pre>\nNext, I’ll truncate a completely different table, currently not being processed by the FBDA process. The truncate of T2 will wait in fbar timer, even though the FBDA is currently processing the T1 table:<\/p>\n
truncate table t2 ;<\/code><\/pre>\nset pagesize 100\ncolumn program format a25\ncolumn event format a10\nselect program, state, event, seconds_in_wait, se.action\n from v$session se\n where sid != userenv('SID') and\n ( program like 'sqlplus%' or program like '%FBDA%' ) ;\n\nPROGRAM STATE EVENT SECONDS_IN_WAIT\n------------------------- ------------------- ---------- ---------------\nACTION\n----------------------------------------------------------------\noracle@svdbp01i (FBDA) WAITED SHORT TIME fbar timer 379\n\n\nsqlplus@svdbp01i (TNS V1- WAITING fbar timer 65\nV3)<\/code><\/pre>\nTruncate completed immediately after the FBDA process had continued the execution:<\/p>\n
(gdb) detach\nDetaching from program: \/u00\/oracle\/orabase\/product\/19.10.0.0.210119_b\/bin\/oracle, process 7584\n[Inferior 1 (process 7584) detached]<\/code><\/pre>\nTable truncated.<\/code><\/pre>\nConclusion<\/h1>\n
The FBDA background process is in the critical path of every DDL statement executed on a table with configured FBDA. Simply put, FBDA has to execute something on behalf of the user session before the DDL statement completes. The user process sends a message to the FBDA process when the action is required and then waits on the message from the FBDA process, which will arrive only after FBDA completes its part.<\/p>\n
While being busy with serving the current request, the FBDA process is not able to accept requests from any other process. In other words, it’s a serialization point for DDLs.<\/p>\n
It doesn’t even need two user sessions to suffer this serialization. It can also happen while the FBDA process is being busy with the maintenance work on FBDA tables, like splitting partitions.<\/p>\n
The serialization problem is not visible in retrospect, because it isn’t properly instrumented. So if you weren’t aware of these undocumented mechanisms, you would be clueless when users start complaining about slow truncates, because you wouldn’t find any ASH samples for it.<\/p>\n
What’s exactly the problem with the instrumentation?<\/p>\n
Both the FBDA background process and the user process use wait event “fbar timer” when waiting on each other. While in the case of the FBDA process, this is an idle event, i.e. not contributing to the total database time, in the case of the user process, it should definitely count as the database time, because the statement doesn’t complete until the process receives the message from the FBDA process.<\/p>\n
Since in both cases “fbar timer” is treated as an idle event, the sessions waiting on it will neither be captured in ASH nor contribute to the total database time.<\/p>\n
You need to build your own instrumentation for overcoming this problem.<\/p>\n","protected":false},"excerpt":{"rendered":"
Undocumented flashback data archive internals Continue Reading