Re: Weird "ORA-03113: end-of-file on communication channel" during parse

From: Mohamed Houri <mohamed.houri_at_gmail.com>
Date: Thu, 25 Mar 2021 15:56:25 +0100
Message-ID: <CAJu8R6jVyoajLhdi5NVMX-kNaUj7xcVarZwNhLRSrp-i1ScPWw_at_mail.gmail.com>



>
>
>> As Andy has already pointed it out you need to get the alert log trace
>> file
>>
>>
>>
>> I was thinking that the column delpackoutloc has been added using the
>> DDL optimization technique
>>
>>
>>
>> SQL> alter table add delpackoutloc number default -1 null;
>>
>>
>>
>> But this DDL optimization technique is only possible for a 12cR2 database
>> (where it has been extended to nullable columns) and you are using 12cR1.
>> And even in the execution plan that works and which you have shown, I don't
>> see any added NVL function in the predicate part
>>
>>
>>
>> I got the same error a couple of years ago when I was moving from 11gR2
>> to 12cR2 which turned to be due to a DDL optimized column. The solution was
>> drop/recreate the table. This was possible because the underlying table was
>> not very big and not very critical
>>
>>
>>
>> Best regards
>> Mohamed Houri
>>
>

> oing to need access to the alert log to see what’s going on. There will be
>> an ORA-7445 being hit which is ending your connection.
>>
>> Thanks,
>> Andrew
>>
>> On Thu, 25 Mar 2021 at 14:24, Kim Berg Hansen <kibeha_at_gmail.com> wrote:
>>
>>> Hmmm... If I query for two values, I get again that it works for one
>>> less row than it would return:
>>>
>>> SQL> explain plan for
>>> 2 select sd.iddelivery
>>> 3 from arrow.splitdelivery sd
>>> 4 where sd.delpackoutloc in (-1, 2)
>>> 5 and rownum <= 343251 + 525 - 1;
>>>
>>> Explained.
>>>
>>>
>>> And it fails at the exact number of rows for the two values together:
>>>
>>> SQL> explain plan for
>>> 2 select sd.iddelivery
>>> 3 from arrow.splitdelivery sd
>>> 4 where sd.delpackoutloc in (-1, 2)
>>> 5 and rownum <= 343251 + 525;
>>> where sd.delpackoutloc in (-1, 2)
>>> *
>>> ERROR at line 4:
>>> ORA-03113: end-of-file on communication channel
>>> Process ID: 9016
>>> Session ID: 69 Serial number: 1934
>>>
>>>
>>>
>>> Hmm... ???
>>>
>>>
>>>
>>> Regards
>>>
>>>
>>> Kim Berg Hansen
>>> Senior Consultant at Trivadis
>>> Oracle ACE Director
>>>
>>> Author of Practical Oracle SQL
>>> <https://www.apress.com/gp/book/9781484256169>
>>> http://www.kibeha.dk
>>> kibeha_at_kibeha.dk
>>> _at_kibeha <http://twitter.com/kibeha>
>>>
>>>
>>>
>>> On Thu, Mar 25, 2021 at 3:12 PM Kim Berg Hansen <kibeha_at_gmail.com>
>>> wrote:
>>>
>>>> Hi, List
>>>>
>>>> I have an ORA-03113 error on a Windows 12.1.0.2 that seems to happen
>>>> during parse?
>>>> I don't have a good idea about what happens, so any ideas would be nice.
>>>>
>>>> Database version:
>>>>
>>>> SQL> select banner
>>>> 2 from v$version;
>>>> BANNER
>>>>
>>>> --------------------------------------------------------------------------------
>>>> Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit
>>>> Production
>>>> PL/SQL Release 12.1.0.2.0 - Production
>>>> CORE 12.1.0.2.0 Production
>>>> TNS for 64-bit Windows: Version 12.1.0.2.0 - Production
>>>> NLSRTL Version 12.1.0.2.0 - Production
>>>>
>>>>
>>>>
>>>> I do a simple query and my connection breaks with an ORA-03113:
>>>>
>>>> SQL> select sd.iddelivery
>>>> 2 from splitdelivery sd
>>>> 3 where sd.delpackoutloc = -1;
>>>> select sd.iddelivery
>>>> *
>>>> ERROR at line 1:
>>>> ORA-03113: end-of-file on communication channel
>>>> Process ID: 3964
>>>> Session ID: 38 Serial number: 45993
>>>>
>>>>
>>>>
>>>> Adding a superfluous NVL makes it work - the data can be retrieved
>>>> (doesn't look like corrupted data):
>>>>
>>>> SQL> set autotrace traceonly
>>>> SQL> select sd.iddelivery
>>>> 2 from arrow.splitdelivery sd
>>>> 3 where nvl(sd.delpackoutloc, 0) = -1;
>>>> 343251 rows selected.
>>>>
>>>> Execution Plan
>>>> ----------------------------------------------------------
>>>> Plan hash value: 87431401
>>>>
>>>> -----------------------------------------------------------------------------------
>>>> | Id | Operation | Name | Rows | Bytes | Cost
>>>> (%CPU)| Time |
>>>>
>>>> -----------------------------------------------------------------------------------
>>>> | 0 | SELECT STATEMENT | | 343K| 3352K| 3075
>>>> (1)| 00:00:01 |
>>>> |* 1 | TABLE ACCESS FULL| SPLITDELIVERY | 343K| 3352K| 3075
>>>> (1)| 00:00:01 |
>>>>
>>>> -----------------------------------------------------------------------------------
>>>> Predicate Information (identified by operation id):
>>>> ---------------------------------------------------
>>>> 1 - filter(NVL("SD"."DELPACKOUTLOC",0)=(-1))
>>>>
>>>> Statistics
>>>> ----------------------------------------------------------
>>>> 67 recursive calls
>>>> 0 db block gets
>>>> 33210 consistent gets
>>>> 0 physical reads
>>>> 0 redo size
>>>> 4592111 bytes sent via SQL*Net to client
>>>> 251949 bytes received via SQL*Net from client
>>>> 22885 SQL*Net roundtrips to/from client
>>>> 1 sorts (memory)
>>>> 0 sorts (disk)
>>>> 343251 rows processed
>>>>
>>>>
>>>>
>>>> But the erroneous statement gives ORA-03113 even when trying just to
>>>> explain it:
>>>>
>>>> SQL> explain plan for
>>>> 2 select sd.iddelivery
>>>> 3 from splitdelivery sd
>>>> 4 where sd.delpackoutloc = -1;
>>>> explain plan for
>>>> *
>>>> ERROR at line 1:
>>>> ORA-03113: end-of-file on communication channel
>>>> Process ID: 11760
>>>> Session ID: 72 Serial number: 52015
>>>>
>>>>
>>>>
>>>> The column in the predicate is very skewed - 343 thousand out of 350
>>>> thousand have the value -1:
>>>>
>>>> SQL> select delpackoutloc, count(*)
>>>> 2 from splitdelivery
>>>> 3 group by rollup(delpackoutloc)
>>>> 4 order by delpackoutloc;
>>>> DELPACKOUTLOC COUNT(*)
>>>> ------------- ----------
>>>> -1 343251
>>>> 1 417
>>>> 2 525
>>>> 3 5865
>>>> 350058
>>>>
>>>>
>>>> The column has no NULL values, but it is *not *defined as NOT NULL.
>>>>
>>>> The query above that fails searches for the value -1. If I search for
>>>> values 1, 2 or 3, there is no issue at all, works fine.
>>>>
>>>> The table/index statistics are recently gathered - gathered number of
>>>> rows fit exactly:
>>>>
>>>> SQL> select num_rows
>>>> 2 from user_tables
>>>> 3 where table_name = 'SPLITDELIVERY';
>>>> NUM_ROWS
>>>> ----------
>>>> 350058
>>>>
>>>>
>>>> And column histogram also fit exactly the current values:
>>>>
>>>> SQL> select endpoint_value, endpoint_number, endpoint_number -
>>>> lag(endpoint_number) over (order by endpoint_number) as num
>>>> 2 from user_histograms
>>>> 3 where table_name = 'SPLITDELIVERY'
>>>> 4 and column_name = 'DELPACKOUTLOC'
>>>> 5 order by endpoint_number;
>>>> ENDPOINT_VALUE ENDPOINT_NUMBER NUM
>>>> -------------- --------------- ----------
>>>> -1 343251
>>>> 1 343668 417
>>>> 2 344193 525
>>>> 3 350058 5865
>>>>
>>>>
>>>> There's an index on the column and stats are current here as well:
>>>>
>>>> SQL> select blevel, leaf_blocks, distinct_keys,
>>>> avg_leaf_blocks_per_key, avg_data_blocks_per_key, clustering_factor,
>>>> num_rows, sample_size
>>>> 2 from user_indexes
>>>> 3 where table_name = 'SPLITDELIVERY'
>>>> 4 and index_name = 'SPLITDELIVERY_IND01';
>>>> BLEVEL LEAF_BLOCKS DISTINCT_KEYS AVG_LEAF_BLOCKS_PER_KEY
>>>> AVG_DATA_BLOCKS_PER_KEY CLUSTERING_FACTOR NUM_ROWS SAMPLE_SIZE
>>>> ---------- ----------- ------------- -----------------------
>>>> ----------------------- ----------------- ---------- -----------
>>>> 2 864 4 216
>>>> 3393 13573 350058 350058
>>>>
>>>>
>>>>
>>>> I noticed it worked by adding AND ROWNUM <= xxx, so I tried different
>>>> values and found that 343250 (one less than the actual row count) worked
>>>> fine:
>>>>
>>>> SQL> set autotrace traceonly
>>>> SQL> select sd.iddelivery
>>>> 2 from splitdelivery sd
>>>> 3 where sd.delpackoutloc = -1
>>>> 4 and rownum <= 343250;
>>>> 343250 rows selected.
>>>>
>>>> Execution Plan
>>>> ----------------------------------------------------------
>>>> Plan hash value: 1924021054
>>>>
>>>> ------------------------------------------------------------------------------------------------------------
>>>> | Id | Operation | Name |
>>>> Rows | Bytes | Cost (%CPU)| Time |
>>>>
>>>> ------------------------------------------------------------------------------------------------------------
>>>> | 0 | SELECT STATEMENT | |
>>>> 343K| 3352K| 14182 (1)| 00:00:01 |
>>>> |* 1 | COUNT STOPKEY | |
>>>> | | | |
>>>> | 2 | TABLE ACCESS BY INDEX ROWID BATCHED| SPLITDELIVERY |
>>>> 343K| 3352K| 14182 (1)| 00:00:01 |
>>>> |* 3 | INDEX RANGE SCAN | SPLITDELIVERY_IND01 |
>>>> | | 852 (1)| 00:00:01 |
>>>>
>>>> ------------------------------------------------------------------------------------------------------------
>>>> Predicate Information (identified by operation id):
>>>> ---------------------------------------------------
>>>> 1 - filter(ROWNUM<=343250)
>>>> 3 - access("SD"."DELPACKOUTLOC"=(-1))
>>>>
>>>> Statistics
>>>> ----------------------------------------------------------
>>>> 0 recursive calls
>>>> 0 db block gets
>>>> 56495 consistent gets
>>>> 0 physical reads
>>>> 0 redo size
>>>> 4592104 bytes sent via SQL*Net to client
>>>> 251962 bytes received via SQL*Net from client
>>>> 22885 SQL*Net roundtrips to/from client
>>>> 0 sorts (memory)
>>>> 0 sorts (disk)
>>>> 343250 rows processed
>>>>
>>>>
>>>>
>>>> That worked fine, though I find it weird that it chooses an INDEX RANGE
>>>> SCAN + TABLE ACCESS BY INDEX when it knows that it is going to retrieve 98%
>>>> of the rows? A full table scan would use fewer gets as seen in the
>>>> autotrace above?
>>>>
>>>> Anyway, ORA-03113 appears when I add 1 to 343250 making it 34325*1*
>>>> (which is the exact number of rows having the value -1, which the optimizer
>>>> knows from the histogram):
>>>>
>>>> SQL> select sd.iddelivery
>>>> 2 from splitdelivery sd
>>>> 3 where sd.delpackoutloc = -1
>>>> 4 and rownum <= 343251;
>>>> select sd.iddelivery
>>>> *
>>>> ERROR at line 1:
>>>> ORA-03113: end-of-file on communication channel
>>>> Process ID: 11164
>>>> Session ID: 72 Serial number: 37013
>>>>
>>>>
>>>>
>>>> Same for just calling EXPLAIN PLAN - it works for 343250:
>>>>
>>>> SQL> explain plan for
>>>> 2 select sd.iddelivery
>>>> 3 from splitdelivery sd
>>>> 4 where sd.delpackoutloc = -1
>>>> 5 and rownum <= 343250;
>>>> Explained.
>>>>
>>>> SQL> select * from table(dbms_xplan.display);
>>>> PLAN_TABLE_OUTPUT
>>>>
>>>> ----------------------------------------------------------------------------------------------------------------------------------------------------------------
>>>> Plan hash value: 1924021054
>>>>
>>>> ------------------------------------------------------------------------------------------------------------
>>>> | Id | Operation | Name |
>>>> Rows | Bytes | Cost (%CPU)| Time |
>>>>
>>>> ------------------------------------------------------------------------------------------------------------
>>>> | 0 | SELECT STATEMENT | |
>>>> 343K| 3352K| 14182 (1)| 00:00:01 |
>>>> |* 1 | COUNT STOPKEY | |
>>>> | | | |
>>>> | 2 | TABLE ACCESS BY INDEX ROWID BATCHED| SPLITDELIVERY |
>>>> 343K| 3352K| 14182 (1)| 00:00:01 |
>>>> |* 3 | INDEX RANGE SCAN | SPLITDELIVERY_IND01 |
>>>> | | 852 (1)| 00:00:01 |
>>>>
>>>> ------------------------------------------------------------------------------------------------------------
>>>> Predicate Information (identified by operation id):
>>>> ---------------------------------------------------
>>>> 1 - filter(ROWNUM<=343250)
>>>> 3 - access("SD"."DELPACKOUTLOC"=(-1))
>>>> 16 rows selected.
>>>>
>>>>
>>>>
>>>> But it fails for 343251:
>>>>
>>>> SQL> explain plan for
>>>> 2 select sd.iddelivery
>>>> 3 from splitdelivery sd
>>>> 4 where sd.delpackoutloc = -1
>>>> 5 and rownum <= 343251;
>>>> explain plan for
>>>> *
>>>> ERROR at line 1:
>>>> ORA-03113: end-of-file on communication channel
>>>> Process ID: 10888
>>>> Session ID: 457 Serial number: 32869
>>>>
>>>>
>>>>
>>>> At the moment I have no access to trace files or alert log on this
>>>> server. Might get it after the weekend.
>>>> Also it is a development server, nothing urgent to solve. I'm only
>>>> diving a bit deeper for curiosity as well as check if this potentially
>>>> could happen in production database as well.
>>>>
>>>> It'll be easier if/when I get trace access, but do anyone have an idea
>>>> about what might be happening here?
>>>>
>>>>
>>>> Thanks in advance.
>>>>
>>>> Cheerio
>>>> /Kim
>>>>
>>>>
>>>> Regards
>>>>
>>>>
>>>> Kim Berg Hansen
>>>> Senior Consultant at Trivadis
>>>> Oracle ACE Director
>>>>
>>>> Author of Practical Oracle SQL
>>>> <https://www.apress.com/gp/book/9781484256169>
>>>> http://www.kibeha.dk
>>>> kibeha_at_kibeha.dk
>>>> _at_kibeha <http://twitter.com/kibeha>
>>>>
>>>>

-- 

Houri Mohamed

Oracle DBA-Developer-Performance & Tuning

Visit My         - Blog <http://www.hourim.wordpress.com/>

Let's Connect -
<http://fr.linkedin.com/pub/mohamed-houri/11/329/857/>*Linkedin
Profile <http://fr.linkedin.com/pub/mohamed-houri/11/329/857/>*

My Twitter <https://twitter.com/MohamedHouri>      - MohamedHouri
<https://twitter.com/MohamedHouri>


--
http://www.freelists.org/webpage/oracle-l
Received on Thu Mar 25 2021 - 15:56:25 CET

Original text of this message