What Does A Blank, Empty Or Null SQL_ID Mean?
If you have ever encountered a blank, empty or null SQL_ID before and wondered what the heck is going on, then this post is for you.
Recently, I was doing some performance tuning work with the top Oracle wait event being log file sync. As I drilled into the situation, what I discovered confirmed some beliefs and also disproved some "google based learning."
In a nutshell, a blank SQL_ID can mean the foreground process is in the middle of a commit. But this story has more twists and turns than you may think.
In this article I will focus on the empty SQL_ID based on doing a performance analysis from the AWR ASH table, dba_hist_active_sess_history.
The journey I traveled to unravel the "blank SQL_ID" was fascinating. If you want to dive into part one of this series, read on!
Random, Quick And Massive Wait Time Wall
I was doing some consulting work trying to better understand a random, quick and massive log file sync wait time build-up. It reminded me of the time during a nice warm summer evening when I walked straight into (and through) a screen door. Surprise! The OEM graphic below is what the situation looks like.
Confronted With Lots Of Empty SQL_IDs
The picture above is what I had to start with... and a little more. I also knew the time and of course the instance and database ID. But that's it. Thankfully, I had ASH data stored in the AWR table, dba_hist_active_sess_history.
For this analysis I used my BloodHound ASH performance analysis toolkit. I set the BloodHound analysis window between 10:00am and 10:30am using my local dba_hist_active_sess_history table as the data source. BloodHound can also reference v$active_session_history data or pull remote v$active_session_history or dba_hist_active_sess_history data into my local database.
One of the first things I do when analyzing performance is to find the top CPU consuming SQL and the top wait time related SQL. If you are familiar with my 3-Circle Analysis Method, this would be related to the Application circle.
The output below shows the SQL_ID and their related percentage for all "ON CPU" sessions for any ASH sample_id within the analysis window.
SQL> @bhtopcolcpu SQL_ID sample_id % Database: prod40 01-May 06:13am Report: bhtopcolcpu.sql BloodHound by OraPub, Inc. Page 1 When On CPU Show Top SQL_ID - ASH Sample Based Analysis Report (from 01-Aug-2014 10:00 to 01-Aug-2014 10:30, where: sample_id filter:%) % Samples SQL_ID ON CPU -------------------- --------- 10.68 97zrpt9jy9tgq 10.07 4tdpuxb82b7ju 4.86 1r0xtxsud9g2m 3.31 82x8r96g6ng5u 2.20 7bbr0v5mnh81c 1.89 ... There were 2323 ON CPU samples available and used for this analysis. Only sessions with % ON CPU >= 0.5% of sample ON CPU are displayed. This report shows the top dba_hist_active_sess_history ON CPU BH SQL_ID(s) samples when the sample_id was like %%
Wow! 11% of the "ON CPU" SQL_IDs are blank... empty! The text at the bottom of the report shows there are 2323 ASH rows "ON CPU" during the analysis window within my filters (sample_id like '%'). The empty SQL_ID accounts for 10.68% of those rows, which means there are 248 rows with an empty SQL_ID.
Moving on, the output below shows the SQL_ID and their related percentage for all "WAITING" sessions for any sample_id within the analysis window.
SQL> @bhtopcolwait SQL_ID sample_id % Database: prod40 01-May 06:14am Report: bhtopcolwait.sql BloodHound by OraPub, Inc. Page 1 When Waiting Show Top SQL_ID - ASH Sample Based Analysis Report (from 01-Aug-2014 10:00 to 01-Aug-2014 10:30, where: sample_id filter:%) % Samples SQL_ID Waited -------------------- --------- 6.73 5vzuhg5ua64gc 5.08 8sksw60nkukuf 4.61 50x2a24c5kwah 2.66 g067jhzv664cu 2.07 5y3pw51p0qbpy 2.01 9wawuprw988tc 1.95 ... There were 1693 WAITING samples available and used for this analysis. Only sessions with % wait >= 0.5% of sample waits are displayed. This report shows the top dba_hist_active_sess_history sql_id(s) by wait samples when the sample_id was like %%
Similarly, 7% of the "WAITING" SQL_IDs are blank... empty! The text at the bottom of the report says there are 1693 ASH rows "WAITING" during the analysis window within my filter (sample_id like '%'). The empty SQL_ID accounts for 6.73% of those rows, which means there are 114 rows with an empty SQL_ID. Push that on your brain stack.
How does this relate to the top wait event, log file sync? Read on...
Log File Sync And An Empty SQL_ID
I was told yet never actually checked that the SQL_ID during a log file sync wait is empty. Now was a perfect opportunity to investigate this using production system data.
If you think about it, it's not possible get the top CPU consuming SQL_ID related to a log file sync wait event. Why? Because when a session is consuming CPU, it is not waiting and therefore there is no associated wait event.
This is a great example of when we know Oracle is consuming CPU yet we don't know exactly what it is doing with the CPU cycles. But there are ways to get this information. If you're interested in drilling into this fascinating topic, I have some blog postings on this topic and also an online video seminar entitled, Detailing Oracle CPU Consumption: The Missing Link. You can watch the seminar Introduction below.
Practically speaking, since I can not find the top SQL consuming CPU with a wait event of log file sync, this means I need to find the top SQL when a session is "WAITING" and the wait event is log file sync. Using my BloodHound toolkit again, this is what I did.
SQL> @bhtopcolwait SQL_ID event log%file%sync Database: prod40 01-May 06:11am Report: bhtopcolwait.sql BloodHound by OraPub, Inc. Page 1 When Waiting Show Top SQL_ID - ASH Sample Based Analysis Report (from 01-Aug-2014 10:00 to 01-Aug-2014 10:30, where: event filter:log%file%sync) % Samples SQL_ID Waited -------------------- --------- 100.00 There were 32 WAITING samples available and used for this analysis. Only sessions with % wait >= 0.5% of sample waits are displayed. This report shows the top dba_hist_active_sess_history sql_id(s) by wait samples when the event was like log%file%sync%
The above report shows 32 ASH rows have a blank SQL_ID when waiting on a log file sync event. From another perspective, this report shows whenever there was a log file sync session waiting, 100% of the time the SQL_ID is blank!
The above output demonstrates that:
when a session is in the commit process, not consuming CPU and posting a log file sync wait, there may not be an associated SQL_ID.
So, that is one possible reason why the SQL_ID can be blank. But there could be others... Read on.
There Is More To This Story
A couple of sections above, the wait event focused report showed 114 waiting sessions had an empty SQL_ID. That is, 6.73% of all the 1693 "WAITING" rows. Just above we discovered that 32 of these empty SQL_SID rows are related to the wait event log file sync. 114-32=82 So, what about the other 82 rows when a session was waiting with an empty SQL_ID? I didn't go down that path... Perhaps another time.
Summary And What's Coming Your Way
In this article I demonstrated using AWR ASH data from a large production Oracle Database system, the SQL_ID related to a log file sync can be empty. While all the data I referenced shows all log file sync waiting sessions had a blank/empty SQL_ID, this does NOT PROVE this will ALWAYS be the case.
Next, I'd like to turn this around by Oracle tracing a commit in SQL*Plus and seeing what the SQL_ID is. Is it always the same result? And if not, what's going on? And why would a commit have a blank/empty SQL_ID anyways? The results are really interesting but to keep this post short, I'll save these details for next week.
Thanks for reading,
If you have any questions or comments, feel free to email me directly at craig at orapub.com.
|Gotta Love Oracle Database Latch Classes||When Is Oracle Database View V$SQLSTATS Refreshed?||Upgrade? What's New In Stori 2j|