Home » RDBMS Server » Server Administration » SQL Statement can not be traced (Oracle 11gr2, Linux x86_64)
SQL Statement can not be traced [message #662327] Tue, 25 April 2017 05:42 Go to next message
trantuananh24hg
Messages: 705
Registered: January 2007
Location: Ha Noi, Viet Nam
Senior Member
Good afternoon,

I have a strange case today, till now, I have not had any idea to track the SQL Statement, so, post here with your help. Brief as following:

1- Instance activity
-----------------------------------------------------------------------
Active% | SQL_ID          | EVENT                     | WAIT_CLASS
-----------------------------------------------------------------------
   889% |                 | ON CPU                    | ON CPU
   444% | bts6n0q6c0tfc   | ON CPU                    | ON CPU

2- SQL trace with SQL_ID

SQL> @sqltext
-- Tracking SQL details
-- trantuananh24hg@gmail.com
Enter value for sql_id: bts6n0q6c0tfc

no rows selected


no rows selected


no rows selected


no rows selected

-- Get the plan associated with the sql
Enter value for sql_id: bts6n0q6c0tfc

no rows selected

-- Press any key to define which object associated

Enter value for objid: 0

no rows selected

3- Review with ADDM
Quote:

Finding 2: Top SQL Statements
Impact is 6.31 active sessions, 34.7% of total activity.
--------------------------------------------------------
SQL statements consuming significant database time were found. These
statements offer a good opportunity for performance improvement.

Recommendation 1: SQL Tuning
Estimated benefit is 5.41 active sessions, 29.72% of total activity.
--------------------------------------------------------------------
Action
Investigate the INSERT statement with SQL_ID "bts6n0q6c0tfc" for
possible performance improvements. You can supplement the information
given here with an ASH report for this SQL_ID.
Related Object
SQL statement with SQL_ID bts6n0q6c0tfc.

Rationale
The SQL spent only 0% of its database time on CPU, I/O and Cluster
waits. Therefore, the SQL Tuning Advisor is not applicable in this case.
Look at performance data for the SQL to find potential improvements.
Rationale
Database time for this SQL was divided as follows: 0% for SQL execution,
100% for parsing, 0% for PL/SQL execution and 0% for Java execution.
Rationale
Waiting for event "cursor: mutex S" in wait class "Concurrency"
accounted for 10% of the database time spent in processing the SQL
statement with SQL_ID "bts6n0q6c0tfc".
Same to ASH without any text associated to this SQL_ID

4- Seeking the session
SQL> col username format a8
SQL> col sid format 99999
SQL> col program format a19
SQL> col terminal format a25
SQL> set linesize 250
SQL> select sid, serial#, username, status, program, terminal
  2  from v$session
  3  where sql_id='bts6n0q6c0tfc';
 
   SID    SERIAL# USERNAME STATUS   PROGRAM             TERMINAL
------ ---------- -------- -------- ------------------- -------------------------
    38      29134 vkc     ACTIVE   JDBC Thin Client    unknown
    93      27915 vkc     ACTIVE   JDBC Thin Client    unknown
   212      52624 vkc     ACTIVE   JDBC Thin Client    unknown
   226      63821 vkc     ACTIVE   JDBC Thin Client    unknown
   237      25147 vkc     ACTIVE   JDBC Thin Client    unknown

5- Invoke session trace using dbms_monitor package
SQL> execute dbms_monitor.session_trace_enable(session_id=>226,serial_num=>63821,waits=>true,binds=>true);

PL/SQL procedure successfully completed.

SQL> select pid from spid_and_pid where sid=226;

PID
------------------------------------
53178

[oracle@SQ1 trace]$ pwd
/u01/app/oracle/diag/rdbms/vkc/vkc/trace
[oracle@SQ1 trace]$ ls -llrt *53178*
-rw-r----- 1 oracle oinstall   66772 Apr 25 17:30 vkc_ora_53178.trm
-rw-r----- 1 oracle oinstall 1986632 Apr 25 17:30 vkc_ora_53178.trc
[oracle@SQ1 trace]$ ls -llrt *53178*
-rw-r----- 1 oracle oinstall   97003 Apr 25 17:31 vkc_ora_53178.trm
-rw-r----- 1 oracle oinstall 2719842 Apr 25 17:31 vkc_ora_53178.trc
[oracle@SQ1 trace]$ ls -llrt *53178*
-rw-r----- 1 oracle oinstall  100636 Apr 25 17:31 vkc_ora_53178.trm
-rw-r----- 1 oracle oinstall 2805277 Apr 25 17:31 vkc_ora_53178.trc
[oracle@SQ1 trace]$ ls -llrt *53178*
-rw-r----- 1 oracle oinstall  102338 Apr 25 17:31 vkc_ora_53178.trm
-rw-r----- 1 oracle oinstall 2870639 Apr 25 17:31 vkc_ora_53178.trc
[oracle@SQ1 trace]$ ls -llrt *53178*
-rw-r----- 1 oracle oinstall  103143 Apr 25 17:31 vkc_ora_53178.trm
-rw-r----- 1 oracle oinstall 2913634 Apr 25 17:31 vkc_ora_53178.trc
[oracle@SQ1 trace]$ ls -llrt *53178*
-rw-r----- 1 oracle oinstall  103700 Apr 25 17:31 vkc_ora_53178.trm
-rw-r----- 1 oracle oinstall 2942862 Apr 25 17:31 vkc_ora_53178.trc

6- Using tkprof
SQL> execute dbms_monitor.session_trace_disable(session_id=>226,serial_num=>63821);

PL/SQL procedure successfully completed.

SQL> exit

[oracle@SQ1 trace]$ tkprof vkc_ora_53178.trc
output = vkc2.lst

TKPROF: Release 11.2.0.1.0 - Development on Tue Apr 25 17:32:47 2017

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


[oracle@SQ1 trace]$ cat vkc2.lst

TKPROF: Release 11.2.0.1.0 - Development on Tue Apr 25 17:32:47 2017

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

Trace file: vkc_ora_53178.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
********************************************************************************
Trace file: vkc_ora_53178.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       2  sessions in tracefile.
       0  user  SQL statements in trace file.
       0  internal SQL statements in trace file.
       0  SQL statements in trace file.
       0  unique SQL statements in trace file.
   32318  lines in trace file.
       0  elapsed seconds in trace file.


[oracle@SQ1 trace]$ 

Nothing occured here, with only special words "32318 lines in trace file"

7- Now, see at the trace file
[oracle@SQ1 trace]$ more vck_ora_124895.trc
Trace file /u01/app/oracle/diag/rdbms/vck/vck/trace/vck_ora_124895.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/11.2.0/dbhome_1
System name:    Linux
Node name:      SQ1
Release:        2.6.32-573.22.1.el6.x86_64
Version:        #1 SMP Wed Mar 23 03:35:39 UTC 2016
Machine:        x86_64
Instance name: vck
Redo thread mounted by this instance: 1
Oracle process number: 26
Unix process pid: 124895, image: oracle@SQ1


*** 2017-04-25 17:34:20.817
*** SESSION ID:(212.52624) 2017-04-25 17:34:20.817
*** CLIENT ID:() 2017-04-25 17:34:20.817
*** SERVICE NAME:(SYS$USERS) 2017-04-25 17:34:20.817
*** MODULE NAME:(JDBC Thin Client) 2017-04-25 17:34:20.817
*** ACTION NAME:() 2017-04-25 17:34:20.817
 

*** TRACE FILE RECREATED AFTER BEING REMOVED ***

WAIT #4: nam='cursor: mutex S' ela= 160 idn=0 value=884763262981 where=4902870773 obj#=-1 tim=1493116460817105
WAIT #4: nam='cursor: mutex S' ela= 70 idn=0 value=399431958534 where=4902870821 obj#=-1 tim=1493116460818136
WAIT #4: nam='cursor: mutex S' ela= 93 idn=0 value=635655159814 where=4902870847 obj#=-1 tim=1493116460818779
WAIT #4: nam='cursor: mutex S' ela= 11 idn=0 value=1017907249157 where=4902870870 obj#=-1 tim=1493116460819146

Thank you for your guide.

[Updated on: Tue, 25 April 2017 05:50]

Report message to a moderator

Re: SQL Statement can not be traced [message #662329 is a reply to message #662327] Tue, 25 April 2017 06:33 Go to previous messageGo to next message
Michel Cadot
Messages: 65258
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator

And the statement is?

Re: SQL Statement can not be traced [message #662330 is a reply to message #662329] Tue, 25 April 2017 06:53 Go to previous messageGo to next message
Roachcoach
Messages: 1502
Registered: May 2010
Location: UK
Senior Member
>100% for parsing

This means it didn't get as far as executing, so it would follow that the sql trace is "empty". Check for crazy version counts in the shared pool/shared pool contention or similar things.
Re: SQL Statement can not be traced [message #662333 is a reply to message #662329] Tue, 25 April 2017 08:36 Go to previous messageGo to next message
trantuananh24hg
Messages: 705
Registered: January 2007
Location: Ha Noi, Viet Nam
Senior Member
Michel Cadot wrote on Tue, 25 April 2017 11:33

And the statement is?

The statement is ... your help Smile i have not got any idea to do still now

Thank you Smile
Re: SQL Statement can not be traced [message #662334 is a reply to message #662330] Tue, 25 April 2017 08:40 Go to previous messageGo to next message
trantuananh24hg
Messages: 705
Registered: January 2007
Location: Ha Noi, Viet Nam
Senior Member
Roachcoach wrote on Tue, 25 April 2017 11:53
>100% for parsing

This means it didn't get as far as executing, so it would follow that the sql trace is "empty". Check for crazy version counts in the shared pool/shared pool contention or similar things.
Thank you, the first action, of course, i saw at the version counts and parsing column in workload, nothing captured here Sad

In the rows of the trace file. I think I can find some information of value column.

Cursor mute S caused by some problem, such as
- call from application and got the no row fetched cursor
- call to non exist table
- the cursor has many child but the parent did not cached because of cursor-sharing
- a bug in 11.2.0.1
- delivery a wrong schematic from app/client but using literal without bind variable
...
Or another cases ..

In fact, I have got all cases below in only one database, then, now I device and analysis each case
Will feed back as soon as possible. However, regardless to any help

[Updated on: Tue, 25 April 2017 08:52]

Report message to a moderator

Re: SQL Statement can not be traced [message #662335 is a reply to message #662334] Tue, 25 April 2017 08:42 Go to previous messageGo to next message
Michel Cadot
Messages: 65258
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Roachcoach wrote on Tue, 25 April 2017 11:53
>100% for parsing
...
This may indicate a bug in the memory structures, did you try to restart the instance to see if it happens again?

Re: SQL Statement can not be traced [message #662337 is a reply to message #662335] Tue, 25 April 2017 09:07 Go to previous messageGo to next message
trantuananh24hg
Messages: 705
Registered: January 2007
Location: Ha Noi, Viet Nam
Senior Member
Michel Cadot wrote on Tue, 25 April 2017 13:42
Roachcoach wrote on Tue, 25 April 2017 11:53
>100% for parsing
...
This may indicate a bug in the memory structures, did you try to restart the instance to see if it happens again?

Exactly I thought same to you. Cursor mute often cause latch buffer chained, and it is memory lock
It's 9pm in Ha Nội, and I am going on home, will come back tomorrow and test to verify the latch. But, it is the production database, I can not restart without any plan.
Assuming restart the instance release the internal lock of memory, but I have got find out the root cause.

Michel, please correct me if I am wrong. The latch can occurs anytime, but it always returns a address? If yes, oradump can get the address and I will map them in select statement to find out what did cause?

Thank you.

[Updated on: Tue, 25 April 2017 09:21]

Report message to a moderator

Re: SQL Statement can not be traced [message #662339 is a reply to message #662337] Tue, 25 April 2017 10:27 Go to previous messageGo to next message
Michel Cadot
Messages: 65258
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator

What is the content of "@sqltext"?
What is the result of the query on the underlying X£ tables?

select kglnaobj, kglfnobj, kglhdpar, kglnahsh from x$kglcursor where kglobt03 = 'bts6n0q6c0tfc';
select kglnaobj, kglfnobj, kglhdpar, kglnahsh from x$kglcursor_child where kglobt03 = 'bts6n0q6c0tfc';
select kglnaobj, kglfnobj, kglhdpar, kglnahsh from x$kglcursor_child_sqlid where kglobt03 = 'bts6n0q6c0tfc';
select SQL_TEXT, SQL_FULLTEXT FROM x$kkssqlstat where SQL_ID = 'bts6n0q6c0tfc';

Can you purge the sql from the sqlarea and see what happens (address and hash_value found from the previous queries (kglhdpar, kglnahsh) or one on v$session):
exec dbms_shared_pool.purge('address,hash_value','C',1);

Re: SQL Statement can not be traced [message #662348 is a reply to message #662339] Tue, 25 April 2017 21:56 Go to previous messageGo to next message
trantuananh24hg
Messages: 705
Registered: January 2007
Location: Ha Noi, Viet Nam
Senior Member
Dear, Michel

The results of your suggestion query are here:
sys@vkc> col kglnaobj format a35
sys@vkc> col kglfnobj format a35
sys@vkc> set linesize 250
sys@vkc> select kglnaobj, kglfnobj, kglhdpar, kglnahsh from x$kglcursor where kglobt03 = 'bts6n0q6c0tfc';

KGLNAOBJ                            KGLFNOBJ                            KGLHDPAR           KGLNAHSH
----------------------------------- ----------------------------------- ---------------- ----------
INSERT INTO STATS_RAW(site_id,root_ INSERT INTO STATS_RAW(site_id,root_ 00000007CD4BC598 2361419212
id , cate_id, page_id, page_title,  id , cate_id, page_id, page_title,
referer, url, ip, ip_number, user_a referer, url, ip, ip_number, user_a
gent, access_time , mean)  values ( gent, access_time , mean)  values (
:1 ,:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:"S :1 ,:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:"S
YS_B_0",:"SYS_B_1",:9 ,:"SYS_B_2")  YS_B_0",:"SYS_B_1",:9 ,:"SYS_B_2")

INSERT INTO STATS_RAW(site_id,root_ INSERT INTO STATS_RAW(site_id,root_ 00000007CD4BC598 2361419212
id , cate_id, page_id, page_title,  id , cate_id, page_id, page_title,
referer, url, ip, ip_number, user_a referer, url, ip, ip_number, user_a
gent, access_time , mean)  values ( gent, access_time , mean)  values (
:1 ,:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:"S :1 ,:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:"S
YS_B_0",:"SYS_B_1",:9 ,:"SYS_B_2")  YS_B_0",:"SYS_B_1",:9 ,:"SYS_B_2")

INSERT INTO STATS_RAW(site_id,root_ INSERT INTO STATS_RAW(site_id,root_ 00000007CD4BC598 2361419212
id , cate_id, page_id, page_title,  id , cate_id, page_id, page_title,
referer, url, ip, ip_number, user_a referer, url, ip, ip_number, user_a
gent, access_time , mean)  values ( gent, access_time , mean)  values (
:1 ,:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:"S :1 ,:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:"S
YS_B_0",:"SYS_B_1",:9 ,:"SYS_B_2")  YS_B_0",:"SYS_B_1",:9 ,:"SYS_B_2")

INSERT INTO STATS_RAW(site_id,root_ INSERT INTO STATS_RAW(site_id,root_ 00000007CD4BC598 2361419212
id , cate_id, page_id, page_title,  id , cate_id, page_id, page_title,
referer, url, ip, ip_number, user_a referer, url, ip, ip_number, user_a
gent, access_time , mean)  values ( gent, access_time , mean)  values (
:1 ,:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:"S :1 ,:2 ,:3 ,:4 ,:5 ,:6 ,:7 ,:8 ,:"S
YS_B_0",:"SYS_B_1",:9 ,:"SYS_B_2")  YS_B_0",:"SYS_B_1",:9 ,:"SYS_B_2")

sys@VKC> select owner, table_name from dba_tables where table_name='STATS_RAW';

OWNER                          TABLE_NAME
------------------------------ ------------------------------
STATS                          STATS_RAW

sys@VKC> desc stats.stats_raw
 Name                                                  Null?    Type
 ----------------------------------------------------- -------- ------------------------------------
 ID                                                    NOT NULL NUMBER(10)
 ROOT_ID                                                        VARCHAR2(255)
 SITE_ID                                                        VARCHAR2(255)
 CATE_ID                                                        VARCHAR2(255)
 PAGE_ID                                                        VARCHAR2(255)
 PAGE_TITLE                                                     VARCHAR2(1500 CHAR)
 REFERER                                                        VARCHAR2(1500 CHAR)
 URL                                                            VARCHAR2(1500 CHAR)
 IP                                                             VARCHAR2(255)
 IP_NUMBER                                                      NUMBER(19)
 USER_AGENT                                                     VARCHAR2(1500 CHAR)
 ACCESS_TIME                                                    DATE
 MEAN                                                           NUMBER

sys@VKC> select kglnaobj, kglfnobj, kglhdpar, kglnahsh from x$kglcursor_child where kglobt03 = 'bts6n0q6c0tfc';

no rows selected

sys@VKC> select kglnaobj, kglfnobj, kglhdpar, kglnahsh from x$kglcursor_child_sqlid where kglobt03 = 'bts6n0q6c0tfc';

no rows selected

sys@VKC> select SQL_TEXT, SQL_FULLTEXT FROM x$kkssqlstat where SQL_ID = 'bts6n0q6c0tfc';

no rows selected

sys@VKC> exec dbms_shared_pool.purge('00000007CD4BC598,2361419212','C',1);
PL/SQL procedure successfully completed.

[Updated on: Tue, 25 April 2017 21:57]

Report message to a moderator

Re: SQL Statement can not be traced [message #662349 is a reply to message #662348] Wed, 26 April 2017 00:52 Go to previous messageGo to next message
Michel Cadot
Messages: 65258
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator

So now you know the statement (and you have to modify your script which was unable to get it).
Now wait and see if the problem appears again.

Re: SQL Statement can not be traced [message #662350 is a reply to message #662349] Wed, 26 April 2017 01:00 Go to previous message
trantuananh24hg
Messages: 705
Registered: January 2007
Location: Ha Noi, Viet Nam
Senior Member
Thank you very much, Michel.

Nice day.
Previous Topic: last_analyzed column is not getting updated after gather stats
Next Topic: ORA-02165
Goto Forum:
  


Current Time: Mon Dec 18 13:41:17 CST 2017

Total time taken to generate the page: 0.08875 seconds