{"id":4127,"date":"2022-02-04T23:04:37","date_gmt":"2022-02-04T23:04:37","guid":{"rendered":"https:\/\/nenadnoveljic.com\/blog\/?p=4127"},"modified":"2022-08-06T07:49:22","modified_gmt":"2022-08-06T07:49:22","slug":"ora-00600-on-materialized-view-refresh","status":"publish","type":"post","link":"https:\/\/nenadnoveljic.com\/blog\/ora-00600-on-materialized-view-refresh\/","title":{"rendered":"ORA-00600 on Materialized View Refresh"},"content":{"rendered":"

We hit ORA-12008 and ORA-00600 errors on materialized view refresh. The ORA-00600 error message were not directly related to the problem. A service request didn’t bear fruit – after getting some random action plans and inquiries for a couple of weeks, we decided to let it go. It was one of those cases where I had to use debugger to understand the root cause and find a workaround.<\/p>\n

It turned out, there are two serious problems in how Oracle handles MV refresh. One is that the population of meta data isn’t atomic – if the process breaks, it will leave inconsistent information. As a consequence, the subsequent refreshes will fail. The other is, that the error isn’t raised immediately upon the retrieval of the corrupt metadata. The program continues, instead, and will fail at some random point with a random error message, completely unrelated to the issue. In 21c it was ORA-00600, and in 19c we saw “ORA-01031: insufficient privileges”, even when the privileges were correctly set.<\/p>\n

Metadata<\/h1>\n

A simple table and a materialized view (MV) are sufficient to reproduce the problem:<\/p>\n

drop materialized view mv ;\ndrop table t;\n\ncreate table t (n number);\ncreate materialized view mv as select * from t ;<\/code><\/pre>\n
The information in the table sys.snap_refop$ is critical. That table is empty after creating the MV:<\/p>\n
select sql_txt FROM sys.snap_refop$  \n  where operation# IN (21, 22)  \n    and sowner = user and vname = 'MV' ;\n\nno rows selected<\/code><\/pre>\n
The first refresh populates the table:<\/p>\n
exec DBMS_MVIEW.REFRESH( LIST=>'MV', atomic_refresh => false, out_of_place => TRUE);\n\nPL\/SQL procedure successfully completed.\n\nselect sql_txt FROM sys.snap_refop$  \n  where operation# IN (21, 22)  \n    and sowner = user and vname = 'MV' ;\n\nSQL_TXT\n--------------------------------------------------------------------------------\n\/* MV_REFRESH (CTB) *\/ CREATE TABLE \"U\".\"%s\"\n   (    \"N\" NUMBER\n   ) SEGMENT CREAT\n\nINSERT \/*+ APPEND *\/ INTO \"U\".\"%s\"  select * from t<\/code><\/pre>\n
The table contains two SQL statements. One is to create the table that underpins the MV. The other is an insert to populate it. The excerpts from the SQL trace below show that the subsequent refresh indeed reads the table and executes the retrieved commands:<\/p>\n
@ev<\/a> 10046 1\n\nexec DBMS_MVIEW.REFRESH( LIST=>'MV', atomic_refresh => false, out_of_place => TRUE);\n\n...\nSELECT operation#, cols, sql_txt FROM sys.snap_refop$  WHERE operation# IN (21, 22)        AND sowner = :1 AND vname = :2 AND instsite = :3  ORDER BY operation#\n...\n\/* MV_REFRESH (CTB) *\/\/* MV_REFRESH (CTB) *\/ CREATE TABLE \"U\".\"RV$705F\"\n   (    \"N\" NUMBER\n   ) SEGMENT CREATION DEFERRED\n  PCTFREE 10 PCTUSED 40 INITRANS 1 MAXTRANS 255\n NOCOMPRESS LOGGING\n  TABLESPACE \"USERS_DAYT2CP\"\n...\n\/* MV_REFRESH (ITB) *\/INSERT \/*+ APPEND *\/ INTO \"U\".\"RV$705F\"  select * from t<\/code><\/pre>\n
In this case everyhing went well because sys.snap_refop$ contained both entries. But, as we shall see, if the second row is missing, the refresh will fail.<\/p>\n
When things go wrong<\/h1>\n
I’m going to demonstrate this by crashing the process just before inserting the INSERT entry. For that purpose, I’m going to set a breakpoint on the Oracle C function rpisplu_internal (“recursive program interface switch user and parse”, according to Frits Hoogland’s orafun<\/a>). Simply put, this function executes recursive SQLs under SYS user on user’s behalf. It receives the pointer to SQL text in the 5th argument (at least in Oracle 21.4, where I conducted this analysis). Since according to x86 calling conventions<\/a>, the 5th argument is passed through the CPU registry R8, the following breakpoint will stop at the function entry and print the SQL text:<\/p>\n
b rpisplu_internal if $_regex( (char *)$r8, \"(?i)insert.*snap_refop\")\ncommands 1\nx\/s $r8\nend<\/code><\/pre>\n
The stack trace on the breakpoint, when the second SQL text is just about to be inserted, looks as follows:<\/p>\n
Breakpoint 1, 0x000000000432b680 in rpisplu_internal ()\n0x15f77a80 :  \"INSERT INTO sys.snap_refop$ (sowner, vname, tabnum, operation#, cols, sql_txt, instsite, fcmaskvec, ejmaskvec, setnum)  VALUES (:1, :2, :3, :4, :5, :6, :7, :8, :9, :10)\"\n(gdb) bt 3\n#0  0x000000000432b680 in rpisplu_internal ()\n#1  0x0000000009ebb1ed in kkzfrc_ofp ()\n#2  0x0000000009eb9fb4 in kkzfrc ()<\/kkzfrco2><\/code><\/pre>\n
rpisplu_internal is called by kkzfrc_ofp. Oracle C function kkzfrc_ofp orchestrates the whole MV refresh and is called only once.<\/p>\n
We’ll continue the execution until hitting the breakpoint for the 2nd time.<\/p>\n
0x15f77a80 :  \"INSERT INTO sys.snap_refop$ (sowner, vname, tabnum,    operation#, cols, sql_txt, instsite, fcmaskvec, ejmaskvec, setnum)  VALUES (:1, :2, :3, :4, :5, :6, :7, :8, :9, :10)\"<\/kkzfrco2><\/code><\/pre>\n
The CREATE entry is already commited at that point:<\/p>\n
select sql_txt FROM sys.snap_refop$\n  where operation# IN (21, 22)\n    and sowner = user and vname = 'MV' ;\n  2    3\nSQL_TXT\n--------------------------------------------------------------------------------\n\/* MV_REFRESH (CTB) *\/ CREATE TABLE \"U\".\"%s\"\n   (    \"N\" NUMBER\n   ) SEGMENT CREAT<\/code><\/pre>\n
I’m crashing the process on the breakpoint, so that the second SQL text (for INSERT) won’t be inserted:<\/p>\n
(gdb) kill\nKill the program being debugged? (y or n) y\n[Inferior 1 (process 1849638) killed]<\/code><\/pre>\n
Since the inserts weren’t atomic, we ended up with an incomplete information in sys.snap_refop$.<\/p>\n
The subsequent refresh fails:<\/p>\n
exec DBMS_MVIEW.REFRESH( LIST=>'MV', atomic_refresh => false, out_of_place => TRUE);\nBEGIN DBMS_MVIEW.REFRESH( LIST=>'MV', atomic_refresh => false, out_of_place => TRUE); END;\n\n*\nERROR at line 1:\nORA-12008: error in materialized view or zonemap refresh path\nORA-00600: internal error code, arguments: [kghstack_alloc], [kkzfrc_ofpBegin],\n[18446603592378862232<\/span>], [], [], [], [], [], [], [], [], []\nORA-06512: at \"SYS.DBMS_SNAPSHOT_KKXRCA\", line 91\nORA-06512: at \"SYS.DBMS_SNAPSHOT_KKXRCA\", line 288\nORA-06512: at \"SYS.DBMS_SNAPSHOT_KKXRCA\", line 2601\nORA-06512: at \"SYS.DBMS_SNAPSHOT_KKXRCA\", line 3194\nORA-06512: at \"SYS.DBMS_SNAPSHOT_KKXRCA\", line 3481\nORA-06512: at \"SYS.DBMS_SNAPSHOT_KKXRCA\", line 3513\nORA-06512: at \"SYS.DBMS_SNAPSHOT\", line 16\nORA-06512: at line 1<\/code><\/pre>\n
ORA-00600 was generated in the Oracle C function kghstack_alloc, which allocates the memory on the stack. kkzfrc_ofpBegin ist the allocation reason. The allocation reason is the comment passed to the allocation function, and stored in the allocated memory chunk. The memory dump displays the allocation reason, which is useful for analyzing memory allocations long after the chunk was allocated.
\nThe number 18446603592378862232<\/span> looks suspicious because it looks neither as a plausible size in bytes nor as a pointer. First, we need to grasp what that number is. Let’s convert it in the hexadecimal notation:<\/p>\n
printf '%X\\n' 18446603592378862232<\/span>\nFFFF803BA42FCA98<\/span><\/code><\/pre>\n
We can see that the value was passed to kghstack_alloc as the second argument:<\/p>\n
kghstack_alloc()+31  call     kgeasnmierr()        7FC4616FA060 ? 7FC4615A0050 ?\n6                                                  017A5F84C ? 000000258 ?\n                                                   000000001 00000000F\nkkzfrc_ofp()+11747   call     kghstack_alloc()     7FC4616FA060 ?\n                                                   FFFF803BA42FCA98<\/span> 015F6F32C<\/span> ?\n                                                   000000258 ? 000000001 ?\n                                                   00000000F ?\nkkzfrc()+19876       call     kkzfrc_ofp()         7FC45BD01FD0 000007078\n                                                   7FC461596800 000000258 ?\n                                                   000000001 ? 00000000F ?<\/code><\/pre>\n
This number is huge, but only if represented as an unsigned long integer. The other representation, as a signed long integer, looks more meaningfull:<\/p>\n
 p\/d 18446603592378862232<\/span>\n$2 = -140481330689384<\/code><\/pre>\n
It finally becomes obvious when we see the absolute value in the hexadecimal notation – it’s an address on the heap or on the stack:<\/p>\n
 p\/x 140481330689384\n$3 = 0x7fc45bd03568<\/code><\/pre>\n
Simply put, a negative heap (or stack) address was passed as the second argument to kghstack_alloc. It doesn’t make any sense to use negative addresses – this was just an error. Further, kghstack_alloc expects an unsigned long integer as the second argument. To understand the cause for that error, we have to look at the usual argument values for kghstack_alloc. In particular, we’re interested in the second argument. Out of curiosity, we might take a look at the third argument as well because 015F6F32C<\/span> looks like a string.<\/p>\n
We can obtain all that information with the following breakpoint:<\/p>\n
# breakpoint on entry\nb kghstack_alloc \n\ncommands 2\n# print 2nd argument as unsigned long \np\/d $rsi<\/span>\n# dereferenced string pointer in the 3th argument \nx\/s $rdx<\/span>\nend<\/code><\/pre>\n
The output is below:<\/p>\n
Breakpoint 2, 0x0000000015347780 in kghstack_alloc ()\n$16 = 384<\/span>\n0x1707878c:     \"psdnam:parts\"<\/span>\n(gdb) c\nContinuing.\n\nBreakpoint 2, 0x0000000015347780 in kghstack_alloc ()\n$18 = 4000<\/span>\n0x165b3e34:     \"kzctxEUsrEnv: tmp ctx\"<\/span>\n(gdb) c\nContinuing.\n\nBreakpoint 2, 0x0000000015347780 in kghstack_alloc ()\n$19 = 84<\/span>\n0x16f2296c:     \"rpi role space\"<\/span><\/code><\/pre>\n
The string passed by the fourth argument looks like the allocation reason. The second argument is always a small positive integer (384, 4000, 84<\/span>) that might be the requested allocation size. But when the error was thrown, kghstack_alloc received a negative pointer instead of the size in bytes.<\/p>\n
Now we can reconstruct what happened. The size passed to kghstack_alloc for the allocation reason kkzfrc_ofpBegin is calculated as a difference between two pointers. In case of error, the minuend was a null pointer that was left unchecked, so the difference was a negative value of the subtrahend.<\/p>\n
Unhandled errors<\/h1>\n
The problem first appeared in the Oracle C function kkzdrro. kkzdrro is called by kkzfrc_ofp to select the information from the table sys.snap_refop$ and populates the structure which holds the text of both SQL statements. But since there was no insert statement, the pointer remained uninitialized. Unfortunately, the program didn’t stop and raise the error. It continued, instead, and threw a random error at some random point. In 21.4, the problem manifests itself as ORA-00600 in kghstack_alloc, but it can just as well be any other error message where the program can’t deal with the null pointer anymore.<\/p>\n
The analysis would have been much easier if only the developer had decided to throw an error immediately after retrieving the incomplete information. rpifch is another function in the recursive programming interface which we can use for tracking down the root cause. This function fetches the rows from sys queries executed on user’s behalf and is directly called by kkzdrro:<\/p>\n
b rpifch\n\n(gdb) bt 3\n#0  0x000000000432c200 in rpifch ()\n#1  0x0000000009e53647 in kkzdrro ()\n#2  0x0000000009eba159 in kkzfrc_ofp ()<\/code><\/pre>\n
It returns an ORA- error code or 0 on good execution. It returned 1403 (“no data found”) when it tried to fetch the second row (INSERT command):<\/p>\n
(gdb) p $rax\n$31 = 1403<\/code><\/pre>\n
oerr ora 1403\n01403, 00000, \"no data found\"\n\/\/ *Cause: No data was found from the objects.\n\/\/ *Action: There was no data from the objects which may be due to end of fetch.<\/code><\/pre>\n
As I already mentioned, this error is ignored until the problem with the memory allocation on the stack. I ran pin debugtrace just to calculate the number of function calls between the ignored “no data error” and failed memory allocation on the stack:<\/p>\n
sudo \/export\/home\/oracle\/workspace_vbnov\/pin-3.21-98484-ge7cd811fd-gcc-linux\/pin  -pid 1895209 -t source\/tools\/DebugTrace\/obj-intel64\/debugtrace.so<\/code><\/pre>\n
3460965<\/span>: 121462970 Return 0x000000000432c235 21.4.0.0.211019_a\/bin\/oracle:rpifch+0x000000000035 returns: 0x57b\n...\n3620569<\/span>: 127665538 Call 0x0000000009ebce1e 21.4.0.0.211019_a\/bin\/oracle:kkzfrc_ofp+0x000000002dde -> 0x0000000015347780 21.4.0.0.211019_a\/bin\/oracle:kghstack_alloc(0x7fda927ce060, 0xffff80256d988aab, ...)<\/code><\/pre>\n
This number is immense – there have been ( 3620569<\/span> – 3460965<\/span> ) \/ 2 = 79802 function calls between the retrieval of the inconsistent information and raising the error. Some random error could have been raised anywhere. Whenever a null pointer remains unchecked and propagates it’s going to be difficult to identify the root cause.<\/p>\n
Monitoring<\/h1>\n
This (now) known problem can be monitored with the following query:<\/p>\n
SELECT sowner, vname FROM sys.snap_refop$  \n  WHERE operation# IN (21, 22)  \n  group by sowner,vname\n  having count(*) = 1 ;<\/code><\/pre>\n
Workaround<\/h1>\n
As a workaround you can recreate the affected MVs, which will also delete the corrupted information in the snapshot table.<\/p>\n
Summary<\/h1>\n
In the course of the first MV refresh, the Oracle process populates the table sys.snap_refop$ with two SQL commands that will be used in future refreshes. The first is CREATE TABLE, the other is INSERT. Unfortunately, these two inserts don’t happen in the same transaction. Consequently, if the process dies in-between, we might end up only with the first entry. The subsequent MV refresh isn’t able to handle this inconsistency. Moreover, the program doesn’t stop after not finding the expected information; it continues, instead, and breaks at some later random point with a random error message.<\/p>\n
I’ve provided the query to monitor these inconsistencies in the metadata. Should you encounter such a problem, recreate the MV as a workaround.<\/p>\n
Updates<\/h1>\n
February 18, 2022<\/h2>\n
The test case produces the same error message on the following Oracle versions:<\/p>\n