Posts mit dem Label V$DIAG_TRACE_FILE_CONTENTS werden angezeigt. Alle Posts anzeigen
Posts mit dem Label V$DIAG_TRACE_FILE_CONTENTS werden angezeigt. Alle Posts anzeigen

2020-06-06

wrong LINE_NUMBER in v$diag_trace_file_contents

V$DIAG_TRACE_FILE_CONTENTS is a very nice way to access Oracle trace files without direct access to the instances host.
But for very long lines there is a problem, as PAYLOAD is limited to VARCHAR2(4000)

PAYLOAD
VARCHAR2(4000)
Displays the trace record payload (contents)

Oracle tries to do it's best and presents the one-line in multiple rows. In my 19.7 sandbox it looks like: 


This excerpt was created by a SQL which shows exactly the problem:
SELECT parsing_line,
       line_number,
       payload
FROM
    v$diag_trace_file_contents MATCH_RECOGNIZE (
        PARTITION BY trace_filename
        ORDER BY line_number, timestamp
        MEASURES
            parse.line_number AS parsing_line
        ALL ROWS PER MATCH
    PATTERN ( parse lines_ + endline nextline ) DEFINE
        parse    AS ( payload LIKE 'PARSING IN CURSOR%' ),
        lines_   AS ( line_number = prev(line_number) ),
        endline  AS ( line_number = prev(line_number) + 1 ),
        nextline AS ( line_number = prev(line_number) + 1 )
    )
WHERE trace_filename = '&trace_file'
/
Here you see the beauty of MATCH_RECOGNIZE: it describes quite clear, what I want to show. 
The pattern shown 
  • Starts with a row payload LIKE 'PARSING IN CURSOR%'
  • show all row where it's line_number is equal to previous rows line_number
  • the 2 lines afterwards which increases their line_number (in comparison to previous row) again

The wring line number can be seen easily: All the rows with the SQLs PAYLOAD have LINE_NUMBER 57. But in fact 57 is only 
PARSING IN CURSOR #140574625525808 len=20604 dep=1 uid=0 oct=3 lid=0 tim=529427750 hv=1387884324 ad='63388040' sqlid='9ygdp6j9bkvt4'
Only the last SQLs fragment is shown as LINE_NUMBER 58.

An additional problem is the missing capability of order these multiple rows properly. 
The ORDER BY line_number, timestamp is not sufficient, as all the lines 57 and 58 share the same timestamp. The fixed view x$DBGTFVIEW has a column INDX which is a good candidate for such purpose, but it's not available right now. 

For those who read my previous post: if the .trm file is missing, v$diag_trace_file_contents provides one row per line and the payload is truncated to 4000 characters. 


Update 2020-06-23: Oracle created Bug 31528203 - V$DIAG_TRACE_FILE_CONTENTS SHOWS WRONG LINE_NUMBER WHEN PAYLOAD > 4000 CHAR for this issue.

2020-06-05

one purpose of trm files

Since Oracle version 11g, beside trace files (.trc) there are also trace metadata files (.trm). They are often quite small. Still often they are seen as useless and cleaned up. 

Oracle Support Document TRM Trace Files Getting Generated (Doc ID 750982.1) claims:

The metadata in .trm files describes the trace records stored inside of .trc trace files.
The Trace metadata allows tools, such as Adrci, to post-process the trace information.

By deleting the .trm file, you make the .trc file unusable for post processing from ADR using ADRCI tool.
One additional purpose is to assist in proper results in V$DIAG_TRACE_FILE_CONTENTS.

Here a small example of a SQL_TRACE file: 
In a text editor, you can see the line numbers and it's content:



But V$DIAG_TRACE_FILE_CONTENTS shows it slightly different:


You can see a gap between LINE_NUMBER 28 and 40. 
The full payload of line 40 is 
declare
    stm varchar2(32767) := 'select payload from v$diag_trace_file_contents where trace_filename = ''cdb1_ora_3435.trc'' and rownum = 1';
    app varchar2(1000) := ' and trace_filename = ''cdb1_ora_3435.trc''';
    val varchar2(4000);
    n number;
begin
    for i in 1 .. 500 loop
        stm := stm || app;
    end loop;
    execute immediate stm into val;
end;

The full content of original lines 29..40 is proposed in only 1 line here - with the real line number of it's last line as LINE_NUMBER

This can be useful, e.g. to identify the SQL at one entity, instead of parsing the result set line by line. 
It is one of several ways how trace metadata files help interpreting the trace files content. 



If the .trm file is removed, the result looks slightly different: 


every line on the tracefile is a real line in V$DIAG_TRACE_FILE_CONTENTS
There is also no COMPONENT_NAME visible. 
The simple content if the tracefile without any additional metadata or interpretation.