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  |
trantuananh24hg
Messages: 744
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 #662330 is a reply to message #662329] |
Tue, 25 April 2017 06:53  |
Roachcoach
Messages: 1576
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 #662334 is a reply to message #662330] |
Tue, 25 April 2017 08:40 |
trantuananh24hg
Messages: 744
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 
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 #662337 is a reply to message #662335] |
Tue, 25 April 2017 09:07 |
trantuananh24hg
Messages: 744
Registered: January 2007
Location: Ha Noi, Viet Nam
|
Senior Member |
|
|
Michel Cadot wrote on Tue, 25 April 2017 13:42Roachcoach 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 |
 |
Michel Cadot
Messages: 68716
Registered: March 2007
Location: Saint-Maur, France, https...
|
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 |
trantuananh24hg
Messages: 744
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 |
|
|
|
|
|
|
|
Goto Forum:
Current Time: Thu Nov 28 13:40:12 CST 2024
|
] 
Blog
Search
Help
Members
Register
Login
Home
i have not got any idea to do still now