Oracle Database - Identifying Session Tracefiles - without actually tracing them :-)

{ Abhilash Kumar Bhattaram : Follow on LinkedIn }

There are several times where I need to monitor my active sessions and what are running long running sessions and what it is actually doing. I do not need to trace it extensively but I would like to know what it is actually going on.

Tracing is mostly done for working with Oracle Support WHEN something goes wrong and DBA's would need to upload logs.

In my case I use the tracefiles to actually understand what the SQL's are doing , it's the intuition of digging into tracefiles to better understand the applications.

Firstly , there is a column called tracefile in v$process , it is one of the most underlooked aspects by DBA's. Each process has some amount of default tracing which gives us sufficient information on what is happeing for the process.

To put in simply , I have a SQL which gives the tracefile associated with a particular SID. Testing this in for some very long running sessions that are currently running as below.

uatsedb11>

col tracefile for a100
SELECT s.inst_id,  s.sid||','||s.serial# SIDSERIAL#, s.sql_id, 
       to_char(s.logon_time, 'MM.DD.YYYY HH24:MI') "LOGIN TIME", s.machine, s.status,
       floor(s.last_call_et/3600)||':'||
       floor(mod(s.last_call_et,3600)/60)||':'||
       mod(mod(s.last_call_et,3600),60) "ACTIVE", p.tracefile
  FROM gv$session s, gv$process p
 WHERE s.paddr = p.addr (+)
  AND s.status = 'ACTIVE'
   AND s.type <> 'BACKGROUND'
ORDER BY last_call_et;


 INST|SIDSERIAL#|SQL_ID        |LOGIN TIME      |MACHINE           |S|ACTIVE    |TRACEFILE
-----|----------|--------------|----------------|------------------|-|----------|----------------------------------------------------------------------------------------------------
    3|1032,45502|3tn4kz46gq0zt |04.17.2024 22:56|RX1UAT1-pxprm1    |A|0:0:0     |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb13/trace/uatsedb13_ppa7_107664.trc
    1|907,21608 |3tn4kz46gq0zt |04.17.2024 22:56|RX1UAT1-pxprm1    |A|0:0:0     |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb11/trace/uatsedb11_ppa7_107559.trc
    2|2415,60724|das6cbf1mjc2d |04.17.2024 22:35|uatapps017ser1x4y8|A|0:0:0     |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb12/trace/uatsedb12_ora_358285.trc
    2|2085,34405|4zk85jpm2v6ds |04.17.2024 22:50|uatapps015ser1x4y8|A|0:0:0     |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb12/trace/uatsedb12_ora_64476.trc
    2|899,44975 |3tn4kz46gq0zt |04.17.2024 22:56|RX1UAT1-pxprm1    |A|0:0:0     |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb12/trace/uatsedb12_ppa7_113674.trc
    1|2079,24365|3tn4kz46gq0zt |04.17.2024 22:56|RX1UAT1-pxprm1    |A|0:0:0     |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb11/trace/uatsedb11_ora_240165.trc
    3|13,89     |5tz8mwg8vd7vz |04.17.2024 18:31|CUSTOMAPP1\B1-INFA|A|0:0:1     |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb13/trace/uatsedb13_ora_182669.trc
    1|1468,31583|              |04.17.2024 22:51|uatapps017ser1x4y8|A|0:0:1     |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb11/trace/uatsedb11_ora_206388.trc
    1|229,64929 |61ph9d47adv1x |04.17.2024 22:16|RX1UAT1-pxprm1    |A|0:40:26   |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb11/trace/uatsedb11_j002_328915.trc
    2|1025,49605|2k8h6m1xt272z |04.17.2024 22:16|RX1UAT1-pxprm2    |A|0:40:28   |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb12/trace/uatsedb12_j000_230867.trc
    3|577,38431 |8y55rdrnd8rby |04.17.2024 22:00|uatapps012ser1x4y8|A|0:56:30   |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb13/trace/uatsedb13_ora_311006.trc
    1|8,63773   |fg8w04bfrkhbw |04.17.2024 19:59|RX1UAT1-pxprm3    |A|2:57:46   |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb11/trace/uatsedb11_p000_101257.trc
    1|1628,34363|fg8w04bfrkhbw |04.17.2024 19:59|RX1UAT1-pxprm3    |A|2:57:46   |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb11/trace/uatsedb11_p003_117481.trc
    1|10,32337  |fg8w04bfrkhbw |04.17.2024 19:59|RX1UAT1-pxprm3    |A|2:57:46   |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb11/trace/uatsedb11_p002_117479.trc
    1|1858,30503|fg8w04bfrkhbw |04.17.2024 19:59|RX1UAT1-pxprm3    |A|2:57:46   |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb11/trace/uatsedb11_p001_101298.trc
    3|1970,3657 |fg8w04bfrkhbw |04.17.2024 19:30|RX1UAT1-pxprm3    |A|3:26:40   |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb13/trace/uatsedb13_j001_154706.trc
    3|1465,1098 |5rrccwqxzpg2h |04.17.2024 19:14|uatapps017ser1x4y8|A|3:35:47   |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb13/trace/uatsedb13_ora_50591.trc
    3|1239,27806|4qmvazc2h4rhm |04.17.2024 19:00|CUSTOMAPP1\Jump2-T|A|3:56:24   |/u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb13/trace/uatsedb13_ora_362624.trc

18 rows selected.

Elapsed: 00:00:00.02

As you can see in the last column the tracefile is the exact location where the trace is generated in each of the RAC nodes.

Now lets say from from one the traces , I see the below

$ cat /u02/app/oracle/diag/rdbms/uatsedb1_z18_chn/uatsedb13/trace/uatsedb13_ora_362624.trc

WARNING: kcbz_log_block_read - failed to record BRR for 44/1124385662 (0x4304c37e) SCN 0x68c73c3707 SEQ 1

*** 2024-04-17T19:02:24.341102+05:30 (PDB1(3))
WARNING: kcbz_log_block_read - failed to record BRR for 44/1062352592 (0x3f5236d0) SCN 0x686bdaba96 SEQ 1

*** 2024-04-17T19:02:24.341591+05:30 (PDB1(3))
WARNING: kcbz_log_block_read - failed to record BRR for 44/1124388370 (0x4304ce12) SCN 0x6a5d99161b SEQ 1

*** 2024-04-17T19:02:24.342072+05:30 (PDB1(3))
WARNING: kcbz_log_block_read - failed to record BRR for 44/1017525244 (0x3ca633fc) SCN 0x6a5d99196c SEQ 1

*** 2024-04-17T19:02:24.343304+05:30 (PDB1(3))
WARNING: kcbz_log_block_read - failed to record BRR for 44/1072655715 (0x3fef6d63) SCN 0x6a5dc0fd37 SEQ 1

*** 2024-04-17T19:02:24.343726+05:30 (PDB1(3))

Now what do they really mean , there is a known pattern in MOS DOcumentation that these are known pattern of tracing when switches logfiles , per the below MOS note this can be ignored.

Searching about kcbz_log_block_read in MOS I found this seems to be a known pattern of log switching

Trace Files Generated Having WARNING: kcbz_log_block_read - Failed To Record BRR (Doc ID 2005854.1)

I am quite aware that the SID 1239 is a highly trasactional session run by the application. From the Oracle traces I can also confirm with the events that the logs are switching busily as expected.

This way I can understand from the tracefiles what is actually happening for the sessions without actually enabling heavier tracing for the sessions.

For situations where more tracing are needed , you can always work with Oracle Support to enable 10046 traces or relevant traces. The scope of the blog is to understand how to find the live tracefiles for an active session and understand what they are doing.