28 October, 2015

Trace Files -- 5.2 : Interpreting the SQL Trace Summary level

Picking up the same SQL Trace file from my previous post, I run (the well known) utility tkprof on it.

[oracle@ora11204 Desktop]$ tkprof /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc My_Query.PRF sys=no

TKPROF: Release 11.2.0.4.0 - Development on Wed Oct 28 22:53:46 2015

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.


[oracle@ora11204 Desktop]$ 
[oracle@ora11204 Desktop]$ cat My_Query.PRF

TKPROF: Release 11.2.0.4.0 - Development on Wed Oct 28 22:53:46 2015

Copyright (c) 1982, 2011, Oracle and/or its affiliates.  All rights reserved.

Trace file: /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing 
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

SQL ID: dc03x7r071fvn Plan Hash: 0

BEGIN DBMS_SESSION.SESSION_TRACE_ENABLE(waits=>TRUE,binds=>FALSE); END;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.03          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        1      0.00       0.03          0          0          0           1

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1       11.45         11.45
********************************************************************************

SQL ID: 7c1rnh08dp922 Plan Hash: 3580537945

select count(*) 
from
 employees


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.01          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.01          1          1          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        4      0.01       0.03          1          1          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  SORT AGGREGATE (cr=1 pr=1 pw=0 time=14407 us)
       107        107        107   INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=1 pw=0 time=14577 us cost=1 size=0 card=107)(object id 16404)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       2        0.00          0.00
  Disk file operations I/O                        1        0.00          0.00
  db file sequential read                         1        0.00          0.00
  SQL*Net message from client                     2       13.27         13.27
********************************************************************************

SQL ID: 9wuhwhad81d36 Plan Hash: 0

BEGIN DBMS_SESSION.SESSION_TRACE_DISABLE; END;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.00          0          0          0           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 43  



********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        2      0.00       0.02          0          0          0           0
Execute      3      0.00       0.03          0          0          0           2
Fetch        2      0.00       0.01          1          1          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        7      0.01       0.06          1          1          0           3

Misses in library cache during parse: 2
Misses in library cache during execute: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       3        0.00          0.00
  SQL*Net message from client                     3       13.27         24.73
  db file sequential read                         1        0.00          0.00
  Disk file operations I/O                        1        0.00          0.00


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute     43      0.00       0.00          0          0          0           0
Fetch       90      0.00       0.01          3        165          0          68
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      133      0.00       0.01          3        165          0          68

Misses in library cache during parse: 0

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         3        0.01          0.01

    3  user  SQL statements in session.
   12  internal SQL statements in session.
   15  SQL statements in session.
********************************************************************************
Trace file: /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
       3  user  SQL statements in trace file.
      12  internal SQL statements in trace file.
      15  SQL statements in trace file.
      15  unique SQL statements in trace file.
     284  lines in trace file.
      24  elapsed seconds in trace file.


[oracle@ora11204 Desktop]$ 


With the "sys=no" command-line flag, I have excluded reporting the recursive (SQL) calls although the summary statistics on them do appear.  There were a total of 43 executions of recursive calls.  The SQL*Net message from client is a wait of 13.27seconds (which is normally considered as an "idle wait").  We see this also in the previous post on the raw trace as the wait event before Tracing is disabled.
The only significant wait event was "db file sequential read" which is less than 1centisecond so is reported as 0.00second.  However, from the previous post, we can see that the raw trace file shows a wait time of 6,784 microseconds
.
.
.


Trace Files -- 5.1 : Reading an SQL Trace

Here's a short introduction to reading an SQL Trace.

First I execute these in my sqlplus session :

SQL> connect hr/oracle
Connected.
SQL> exec DBMS_SESSION.SESSION_TRACE_ENABLE(waits=>TRUE,binds=>FALSE);

PL/SQL procedure successfully completed.

SQL> select count(*) from employees;

  COUNT(*)
----------
       107

SQL> exec DBMS_SESSION.SESSION_TRACE_DISABLE;

PL/SQL procedure successfully completed.

SQL> select value from v$diag_info where name = 'Default Trace File';

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc

SQL> 



Now, I extract selective portions of the trace file.

The header of the trace file gives me inormation about the platform and session/module :

Trace file /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3039.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/orcl
System name:    Linux
Node name:      ora11204
Release:        2.6.39-400.17.1.el6uek.x86_64
Version:        #1 SMP Fri Feb 22 18:16:18 PST 2013
Machine:        x86_64
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 27
Unix process pid: 3039, image: oracle@ora11204 (TNS V1-V3)


*** 2015-10-28 22:19:42.291
*** SESSION ID:(141.7) 2015-10-28 22:19:42.291
*** CLIENT ID:() 2015-10-28 22:19:42.291
*** SERVICE NAME:(SYS$USERS) 2015-10-28 22:19:42.291
*** MODULE NAME:(SQL*Plus) 2015-10-28 22:19:42.291
*** ACTION NAME:() 2015-10-28 22:19:42.291


The trace file tells me that I am running 64bit Oracle 11.2.0.4 on a speciic Linux (UEK) kernel on a host called "ora11204".  This is useful information if I have to provide the trace file to Oracle Support.  (True, it doesn't list all the Oracle patches that may have been applied).
It then identifies my Service Name and Module (and Action if I had set it with DBMS_APPLICATION_INFO).

Next, the trace file tells me when and how I have enabled tracing.

PARSING IN CURSOR #140174891232936 len=73 dep=0 uid=43 oct=47 lid=43 tim=1446041982290677 hv=3228613492 ad='99446cc8' sqlid='dc03x7r071fvn'
BEGIN DBMS_SESSION.SESSION_TRACE_ENABLE(waits=>TRUE,binds=>FALSE); END;
END OF STMT
EXEC #140174891232936:c=1000,e=31608,p=0,cr=0,cu=0,mis=1,r=1,dep=0,og=1,plh=0,tim=1446041982290670
WAIT #140174891232936: nam='SQL*Net message to client' ela= 4 driver id=1650815232 #bytes=1 p3=0 obj#=13246 tim=1446041982291265


It tells me that I have used DBMS_SESSION to enable tracing.

That cursor is then closed.

*** 2015-10-28 22:19:53.745
WAIT #140174891232936: nam='SQL*Net message from client' ela= 11453710 driver id=1650815232 #bytes=1 p3=0 obj#=13246 tim=1446041993745004
CLOSE #140174891232936:c=0,e=38,dep=0,type=0,tim=1446041993745175


We can identify the CURSOR Number (140174891232936-- this numbering format was introduced in 11g, if I am correct) that was closed.  This number is NOT the SQL_ID (which is dc03x7r071fvn -- yes even PLSQL blocks and procedures have SQL_IDs).  This number is NOT the SQL Hash Value either (the SQL Hash Value is present as hv=3228613492).

After that we start seeing the recursive (SYS) calls executed during the parsing of the actual user query (the query on EMPLOYEES).

PARSING IN CURSOR #140174891988920 len=202 dep=1 uid=0 oct=3 lid=0 tim=1446041993745737 hv=3819099649 ad='997c03e0' sqlid='3nkd3g3ju5ph1'
select obj#,type#,ctime,mtime,stime, status, dataobj#, flags, oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkname is null and subname is null
END OF STMT
EXEC #140174891988920:c=0,e=50,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2853959010,tim=1446041993745733
FETCH #140174891988920:c=999,e=88,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=2853959010,tim=1446041993745957
CLOSE #140174891988920:c=0,e=11,dep=1,type=3,tim=1446041993746025
=====================
PARSING IN CURSOR #140174891955728 len=493 dep=1 uid=0 oct=3 lid=0 tim=1446041993746138 hv=2584065658 ad='997a6590' sqlid='1gu8t96d0bdmu'
select t.ts#,t.file#,t.block#,nvl(t.bobj#,0),nvl(t.tab#,0),t.intcols,nvl(t.clucols,0),t.audit$,t.flags,t.pctfree$,t.pctused$,t.initrans,t.maxtrans,t.rowcnt,t.blkcnt,t.empcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl(t.degree,1),nvl(t.instances,1),t.avgspc_flb,t.flbcnt,t.kernelcols,nvl(t.trigflag, 0),nvl(t.spare1,0),nvl(t.spare2,0),t.spare4,t.spare6,ts.cachedblk,ts.cachehit,ts.logicalread from tab$ t, tab_stats$ ts where t.obj#= :1 and t.obj# = ts.obj# (+)
END OF STMT
EXEC #140174891955728:c=0,e=30,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3526770254,tim=1446041993746134
FETCH #140174891955728:c=0,e=53,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,plh=3526770254,tim=1446041993746225
CLOSE #140174891955728:c=0,e=8,dep=1,type=3,tim=1446041993746254


I have shown only the first two recursive calls.  These are identified by "dep=1"  (the parent call by the user we shall see is at depth level 0) and also by uid=0, lid=0  (schema id and privilege userid being 0 for SYS).  len=493 is the length of the SQL statement.

The elapsed time in microseconds is the "e=" value while the CPU time is "c=" in microseconds.  The "p=" value is Physical Reads, the "cr=" value is Consistent Gets, "cu=" is Current Gets, "r=" is Number of Rows.  "og=" shows the Optimizer Goal (og=4 is "Choose").  "tim=" is an ever-increasing timestamp (i.e. to calculate elapsed time between two SQL calls you can deduct the first "tim" value from the second.

Following these two are a number of other recursive SQL calls that I shall skip over until I come to my user SQL.

PARSING IN CURSOR #140174891232936 len=30 dep=0 uid=43 oct=3 lid=43 tim=1446041993782992 hv=282764354 ad='99446f28' sqlid='7c1rnh08dp922'
select count(*) from employees
END OF STMT
PARSE #140174891232936:c=8998,e=37717,p=3,cr=165,cu=0,mis=1,r=0,dep=0,og=1,plh=3580537945,tim=1446041993782979
EXEC #140174891232936:c=0,e=69,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3580537945,tim=1446041993783188
WAIT #140174891232936: nam='SQL*Net message to client' ela= 5 driver id=1650815232 #bytes=1 p3=0 obj#=13246 tim=1446041993783286
WAIT #140174891232936: nam='Disk file operations I/O' ela= 76 FileOperation=2 fileno=4 filetype=2 obj#=16404 tim=1446041993790690
WAIT #140174891232936: nam='db file sequential read' ela= 6784 file#=4 block#=211 blocks=1 obj#=16404 tim=1446041993797581
FETCH #140174891232936:c=7000,e=14409,p=1,cr=1,cu=0,mis=0,r=1,dep=0,og=1,plh=3580537945,tim=1446041993797727
STAT #140174891232936 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=1 pr=1 pw=0 time=14407 us)'
STAT #140174891232936 id=2 cnt=107 pid=1 pos=1 obj=16404 op='INDEX FULL SCAN EMP_EMAIL_UK (cr=1 pr=1 pw=0 time=14577 us cost=1 size=0 card=107)'
WAIT #140174891232936: nam='SQL*Net message from client' ela= 486 driver id=1650815232 #bytes=1 p3=0 obj#=16404 tim=1446041993819989
FETCH #140174891232936:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=3580537945,tim=1446041993820032
WAIT #140174891232936: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=16404 tim=1446041993820057


The "dep=0" and "uid" and "lid" not being 0 indicate that this is a User SQL.  "oct" is the Oracle Command Type.
Here in addition to information on the PARSE call, the EXEC call, the individual WAITs and the FETCH call, we can also see Row Source Statistics indicated by the STAT lines.
The Parse was 37,717 microseconds and the FETCH time was 14,409 microseconds.  (This is a very quick running SQL but since it had never been parsed in ths instance, the Parse time exceeded the FETCH time),  The "mis=1" for the Parse indicates a Miss in the Library Cache -- so Oracle had to do a Hard Parse.
I would look at EXEC for INSERT/UPDATE/DELETE statements but here for a simple SELECT, I look at the FETCH time.
For the 'db file sequential read' wait of 6,784microseconds, we can also see the File Number ("file#"), the Block ID ("block#"), number of Blocks (1 for this wait event) and Object ID ("obj#")


The STAT lines have additional information about the position ("pos")  and parent id ("pid") in the Execution Plan.  The Object ID is indicated by "obj" and the operation by "op". STAT lines show the Consistent Gets ("cr"), Physical Reads ("pr") , the Time ("time") in microseconds, the cost ("cost") and expected cardinality ("card") for each step of the Execution Plan. Note that the expected cardinality is "card" but the actual count of rows is "cnt".

Next, the cursor is closed, and tracing disabled.

*** 2015-10-28 22:20:07.096
WAIT #140174891232936: nam='SQL*Net message from client' ela= 13276436 driver id=1650815232 #bytes=1 p3=0 obj#=16404 tim=1446042007096511
CLOSE #140174891232936:c=0,e=19,dep=0,type=0,tim=1446042007096668
=====================
PARSING IN CURSOR #140174891232936 len=48 dep=0 uid=43 oct=47 lid=43 tim=1446042007097875 hv=2592126054 ad='96fff810' sqlid='9wuhwhad81d36'
BEGIN DBMS_SESSION.SESSION_TRACE_DISABLE; END;
END OF STMT
PARSE #140174891232936:c=999,e=1129,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1446042007097870
EXEC #140174891232936:c=0,e=313,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=1446042007098285


Note how the CURSOR ID get's reused by the next SQL if the previous SQL cursor was closed.  Thus "140174891232936" was used by the PLSQL call  that enabled Tracing, then closed, then by the user SQL query on EMPLOYEES, then Closed, then by the  PLSQL call that disabled Tracing.
(The recursive SQLs in between had different CURSOR IDs).

(As an observation : Notice how the "obj#" doesn't get cleared even when the next wait is an "SQL*Net message to client" or "SQL*Net message from client")
.
.
.

18 October, 2015

Trace Files -- 4 : Identifying a Trace File

This post updated on 21-Oct-15 to show retrieval of the tracefile name from v$process
The server processid 2992 was on 18-Oct.  The 21-Oct server processid was 3079.

11g has a V$SQL_DIAG that one can use to identify a session's own trace file.

SQL> select name, value                             
  2  from v$diag_info
  3  where name = 'Default Trace File'
  4  /

NAME
----------------------------------------------------------------
VALUE
--------------------------------------------------------------------------------
Default Trace File
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2992.trc

SQL>

Thus, my current session's trace file name is displayed. If I (or the DBA) enable tracing for my session, this would be where the trace would be captured.

The DBA can identify the tracefile for a session.   In earlier versions, the instance parameters user_dump_dest and  background_dump_dest would be set to define the location of trace files. 11g relies on diagnostic_dest and automatically derives the user / background dump dests.

SQL> show parameter diag

NAME         TYPE  VALUE
------------------------------------ ----------- ------------------------------
diagnostic_dest        string  /u01/app/oracle
SQL> show parameter user

NAME         TYPE  VALUE
------------------------------------ ----------- ------------------------------
license_max_users       integer  0
parallel_adaptive_multi_user      boolean  TRUE
redo_transport_user       string
user_dump_dest        string  /u01/app/oracle/diag/rdbms/orc
       l/orcl/trace
SQL>

The actual trace file name can then be identified for a given session where we know the USERNAME / SID / SERIAL# values in v$session as :

SQL> l
  1  select p.value || '/' || instance_name || '_ora_' || p.spid || '.trc'
  2  from v$parameter p, v$process p, v$session s , v$instance
  3  where
  4  p.name = 'user_dump_dest'
  5  and
  6  s.username = 'HEMANT'
  7  and s.sid = 145
  8  and s.serial#=11
  9* and p.addr=s.paddr
SQL> /

P.VALUE||'/'||INSTANCE_NAME||'_ORA_'||P.SPID||'.TRC'
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2992.trc

SQL> 

UPDATE 21-Oct-15 :  Actually, 11g does present the tracefile name in V$PROCESS.  So, the query can be simplified as :

SQL> select s.sid, s.serial#, p.spid, p.tracefile
  2  from v$session s, v$process p
  3  where s.paddr=p.addr
  4  and s.username = 'HEMANT'
  5  order by 1;

       SID    SERIAL# SPID
---------- ---------- ------------------------
TRACEFILE
--------------------------------------------------------------------------------
       146     5 3079
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3079.trc


SQL> 


However, a user session can change the name of it's trace file to append a desired string with :

SQL> alter session set tracefile_identifier='Hemant';

Session altered.

SQL> select value                 
  2  from v$diag_info
  3  where name = 'Default Trace File'
  4  /

VALUE
--------------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_2992_Hemant.trc

SQL> 

The tracefile_identifer can be changed as many times as desired as in a session while it is connected.
This actually allows the session to create new (distinct) trace files as and when desired.  One set of SQL operations in the session may be done with tracefile_identifier='Hemant' resulting in the file orcl_ora_2992_Hemant.trc.  Thereafter, without disconnecting the session, it may define a different tracefile_identifier='Chitale' and execute another set of SQL operations.  This second set of SQL operations would go to a trace file orcl_ora_2992_Chitale.trc   Notice that the SPID (2992) doesn't change but the actual trace file name does change.

 However, if  a session sets or changes it's own tracefile_identifier the DBA query shown earlier cannot detect this.

UPDATE 21-Oct-15: The DBA can query v$process to get the new tracefilename :

SQL> l
  1  select s.sid, s.serial#, p.spid, p.tracefile
  2  from v$session s, v$process p
  3  where s.paddr=p.addr
  4  and s.username = 'HEMANT'
  5* order by 1
SQL> /

       SID    SERIAL# SPID
---------- ---------- ------------------------
TRACEFILE
--------------------------------------------------------------------------------
       146     5 3079
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3079_Hemant.trc


SQL> 

.
.
.


11 October, 2015

Trace Files -- 3 : Tracing for specific SQLs

11g allows definition of tracing by SQL_ID as well.

Here is an example.

Given a particular SQL that has been executed in the past, which we've identified as :

SQL> select sql_id, sql_text, executions from v$sql where sql_id='06d4jjswswagq';

SQL_ID       SQL_TEXT              EXECUTIONS
------------- ------------------------------------------------------------------------------------- ----------
06d4jjswswagq select department_id, sum(salary) from hr.employees group by department_id order by 1      1

SQL> 

We could use either ALTER SESSION (from the same session) or ALTER SYSTEM (from another session, to trace all sessions) to enable tracing specifically for this SQL alone.

SQL> connect system/oracle
Connected.
SQL> alter system set events 'sql_trace [sql:06d4jjswswagq] wait=true, plan_stat=all_executions';

System altered.

SQL> 

(note : The options for "plan_stat" are "never", "first_execution", "all_executions").  This allows us to capture execution plan statistics.
Once I have enabled SQL-specific tracing, it is not limited to a session but can run across all sessions that execute the SQL.  Even if I execute other SQLs from the same session that executed this SQL, the other SQLs are *not* traced.

Thus, I started another session that executed :

SQL> select department_id, sum(salary) from hr.employees group by department_id order by 1;

DEPARTMENT_ID SUM(SALARY)
------------- -----------
    10      4400
    20     19000
    30     24900
    40      6500
    50    156400
    60     28800
    70     10000
    80    304500
    90     58000
   100     51608
   110     20308

DEPARTMENT_ID SUM(SALARY)
------------- -----------
       7000

12 rows selected.

SQL> select count(*) from hr.employees;

  COUNT(*)
----------
       107

SQL> select count(*) from hr.departments;

  COUNT(*)
----------
 27

SQL>
The trace file only captured the target SQL. The other two SQLs were *not* in the trace file.  Tracing is not bound to a session, so if you have multiple sessions executing the target SQL, each session creates a trace file.

Tracing is disabled with :

SQL> alter system set events 'sql_trace [sql:06d4jjswswagq] off';

System altered.

SQL> 

Thus, just as in the previous post where I demonstrated tracing by module and action, we can enable tracing for a specific SQL.
.
.
.