There is also a way to show real plan used to run last query in this session via DBMS_XPLAN.DISPLAY_CURSOR. The query of interest doesn t need to be prepended with EXPLAIN PLAN FOR.
try (Statement st = connection.createStatement()) {
try (ResultSet rs = st.executeQuery(
"select plan_table_output from table(dbms_xplan.display_cursor())")) {
while (rs.next()) {
System.out.println(rs.getString(1));
}
}
}
Note that the user needs to be granted the following permissions in order to use DBMS_XPLAN.DISPLAY_CURSOR:
GRANT SELECT ON v_$session TO USER;
GRANT SELECT ON v_$sql_plan TO USER;
GRANT SELECT ON v_$sql_plan_statistics_all TO USER;
GRANT SELECT ON v_$sql TO USER;
Credits go to https://myoracledbablog.wordpress.com/2016/07/26/dbms_xplan-and-the-user-has-no-select-privilege-on-v-error/.
See also https://blogs.oracle.com/optimizer/how-do-i-display-and-read-the-execution-plans-for-a-sql-statement.
But I ve experienced that calling dbms_xplan.display_cursor() right after the executed query may still return unrelated results a in case a multi-thread app uses a shared connection pool.
This can be worked around by searching the most recent sql_id in v$sql system view and providing it as parameter to dbms_xplan.display_cursor.
So here is a ready to use java code to log actual execution plan of recently executed query by its sql (maybe partial).
public void explainActualPlan(String sql, boolean sqlIsPartial, Logger log) {
if (!log.isTraceEnabled()) return;
try (Connection connection = dataSource.getConnection()) {
String sqlId;
String sqlFilter = sqlIsPartial
? "sql_text like % || ? || % "
//+ " and parsing_schema_id = sys_context( USERENV , CURRENT_SCHEMAID )"
: (sql.length() <= 1000 ? "sql_text = ?" : "dbms_lob.compare(sql_fulltext, ?) = 0");
try (PreparedStatement st = connection.prepareStatement(
"select sql_id from v$sql where " + sqlFilter +
" order by last_active_time desc fetch next 1 row only")) {
st.setString(1, sql);
try (ResultSet rs = st.executeQuery()) {
if (rs.next()) {
sqlId = rs.getString(1);
} else {
log.warn("Can t find sql_id for sql {} . Has it really been just executed?", sql);
return;
}
}
}
String planFormat = "TYPICAL";
if (sql.contains("GATHER_PLAN_STATISTICS")) {
planFormat += " ALLSTATS LAST +cost +bytes OUTLINE";
}
try (PreparedStatement st = connection.prepareStatement(
"select plan_table_output from table(dbms_xplan.display_cursor(" +
"sql_id => ?, format => " + planFormat + " ))")) {
st.setString(1, sqlId);
try (ResultSet rs = st.executeQuery()) {
StringBuilder sb = new StringBuilder("Last query plan:
");
while (rs.next()) {
sb.append(rs.getString(1)).append(
);
}
log.trace(sb.toString());
}
}
} catch (Exception e) {
log.warn("Failed to explain query plan for {} ", sql, e);
log.warn("Check that permissions are granted to the current db user:
"
+ "GRANT SELECT ON v_$session TO <USER>;
"
+ "GRANT SELECT ON v_$sql_plan TO <USER>;
"
+ "GRANT SELECT ON v_$sql_plan_statistics_all TO <USER>;
"
+ "GRANT SELECT ON v_$sql TO <USER>;
"
);
}
}
Some notes:
- Oracle always converts prepared statement params from
? to :n syntax before storing the query text in v$sql, so searching by sql with ? s won t find any matches
- both
v$sql.sql_text (truncated to first 1000 chars) and v$sql.sql_fulltext (full CLOB) store sql text without line breaks, so it may be needed perform a join with V$SQLTEXT_WITH_NEWLINES in case you use them in the query text
LIKE matching is used in partial mode, so it may be needed to escape % and _ special chars- I ve checked that Oracle allows to include any unknown strings in the hints comment like
/*+ labuda FIRST_ROWS(200) */. It would still apply known hints in case the appendix is valid identifier (is alphanumeric and starts with letter). This may be useful for tracking queries of interest by appending some hashcode to hints clause.
v@sql could be additionally filtered by and parsing_schema_id = sys_context( USERENV , CURRENT_SCHEMAID ) but this would exclude some plans in case DB instance is used by several similar apps in different schemas with exactly matching sql requests- the code above supplies additional details in plan output in case sql was executed with
GATHER_PLAN_STATISTICS hint
Here is an example of above code output for a query from my another answer:
22:54:53.558 TRACE o.f.adminkit.AdminKitSelectorQuery - Last query plan:
SQL_ID c67mmq4wg49sx, child number 0
-------------------------------------
select * from (select * from (select /*+ FIRST_ROWS(200)
INDEX_RS_DESC("FR_MESSAGE_PART" ("TS")) GATHER_PLAN_STATISTICS */ "ID",
"MESSAGE_TYPE_ID", "TS", "REMOTE_ADDRESS", "TRX_ID",
"PROTOCOL_MESSAGE_ID", "MESSAGE_DATA_ID", "TEXT_OFFSET", "TEXT_SIZE",
"BODY_OFFSET", "BODY_SIZE", "INCOMING" from "FR_MESSAGE_PART" where
"TS" + 0 >= :1 and "TS" < :2 and "ID" >= 376894993815568384 and "ID" <
411234940974268416 order by "TS" DESC) where ROWNUM <= 200) offset 180
rows
Plan hash value: 2499404919
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes|E-Temp | Cost (%CPU)| E-Time | Pstart| Pstop | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | | 640K(100)| | | | 20 |00:00:00.01 | 322 | | | |
|* 1 | VIEW | | 1 | 200 | 130K| | 640K (1)| 00:00:26 | | | 20 |00:00:00.01 | 322 | | | |
| 2 | WINDOW NOSORT | | 1 | 200 | 127K| | 640K (1)| 00:00:26 | | | 200 |00:00:00.01 | 322 | 142K| 142K| |
| 3 | VIEW | | 1 | 200 | 127K| | 640K (1)| 00:00:26 | | | 200 |00:00:00.01 | 322 | | | |
|* 4 | COUNT STOPKEY | | 1 | | | | | | | | 200 |00:00:00.01 | 322 | | | |
| 5 | VIEW | | 1 | 780K| 487M| | 640K (1)| 00:00:26 | | | 200 |00:00:00.01 | 322 | | | |
|* 6 | SORT ORDER BY STOPKEY | | 1 | 780K| 68M| 89M| 640K (1)| 00:00:26 | | | 200 |00:00:00.01 | 322 | 29696 | 29696 |26624 (0)|
| 7 | PARTITION RANGE ITERATOR | | 1 | 780K| 68M| | 624K (1)| 00:00:25 | 3 | 2 | 400 |00:00:00.01 | 322 | | | |
|* 8 | COUNT STOPKEY | | 2 | | | | | | | | 400 |00:00:00.01 | 322 | | | |
|* 9 | TABLE ACCESS BY LOCAL INDEX ROWID| FR_MESSAGE_PART | 2 | 780K| 68M| | 624K (1)| 00:00:25 | 3 | 2 | 400 |00:00:00.01 | 322 | | | |
|* 10 | INDEX RANGE SCAN DESCENDING | IX_FR_MESSAGE_PART_TS | 2 | 559K| | | 44368 (1)| 00:00:02 | 3 | 2 | 400 |00:00:00.01 | 8 | | | |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Outline Data
-------------
/*+
BEGIN_OUTLINE_DATA
IGNORE_OPTIM_EMBEDDED_HINTS
OPTIMIZER_FEATURES_ENABLE( 12.1.0.2 )
DB_VERSION( 12.1.0.2 )
OPT_PARAM( optimizer_dynamic_sampling 0)
OPT_PARAM( _optimizer_dsdir_usage_control 0)
FIRST_ROWS(200)
OUTLINE_LEAF(@"SEL$3")
OUTLINE_LEAF(@"SEL$2")
OUTLINE_LEAF(@"SEL$1")
OUTLINE_LEAF(@"SEL$4")
NO_ACCESS(@"SEL$4" "from$_subquery$_004"@"SEL$4")
NO_ACCESS(@"SEL$1" "from$_subquery$_001"@"SEL$1")
NO_ACCESS(@"SEL$2" "from$_subquery$_002"@"SEL$2")
INDEX_RS_DESC(@"SEL$3" "FR_MESSAGE_PART"@"SEL$3" ("FR_MESSAGE_PART"."TS"))
END_OUTLINE_DATA
*/
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter("from$_subquery$_004"."rowlimit_$$_rownumber">180)
4 - filter(ROWNUM<=200)
6 - filter(ROWNUM<=200)
8 - filter(ROWNUM<=200)
9 - filter("ID">=376894993815568384)
10 - access("TS"<:2)
filter((INTERNAL_FUNCTION("TS")+0>=:1 AND "TS"<:2))
