One of the easiest ways is to use diagnostic events:
alter session set events 'sql_trace {callstack: fname xctend} errorstack(1)';
Where does the commit or rollback happen in PL/SQL code?
Yearly Archives: 2021
:1 and SP2-0553: Illegal variable name “1”.
You may know that some applications generate queries with bind variables’ names like :1 or :”1″, and neither SQL*Plus nor SQLCl support such variables:
SQLPlus:
SQL> var 1 number;
SP2-0553: Illegal variable name "1".
SQLCL:
SQL> var 1 number;
ILLEGAL Variable Name "1"
So we can’t run such queries as-is, but, obviously, we can wrap them into anonymous PL/SQL blocks and even create a special script for that:
SQL> exec execute immediate 'select count(*) cnt from dual where :1=dummy' using 'x';
PL/SQL procedure successfully completed.
SQL> select sql_id from v$sqlarea a where sql_text like 'select count(*) cnt from dual%';
SQL_ID
-------------
8y7sav2n21055
1 row selected.
SQL> ed tests/run_sql.sql
SQL> !cat tests/run_sql.sql
declare
vsql clob;
begin
select sql_fulltext into vsql from v$sqlarea a where a.sql_id='&1';
execute immediate vsql using &2;
end;
/
SQL> @tests/run_sql.sql 8y7sav2n21055 123
PL/SQL procedure successfully completed.
But it’s even easier in SQLCl with alias command:
SQL> alias sel1=select :1 from dual;
SQL> sel1 123
:1
--------------------------------------
123
1 row selected.
ORA exceptions that can’t be caught by exception handler
I know 2 “special” exceptions that can’t be processed in exception handler:
- “ORA-01013: user requested cancel of current operation”
- “ORA-03113: end-of-file on communication channel”
- and + “ORA-00028: your session has been killed” from Matthias Rogel
Tanel Poder described the first one (ORA-01013) in details here: https://tanelpoder.com/2010/02/17/how-to-cancel-a-query-running-in-another-session/ where Tanel shows that this error is based on SIGURG signal (kill -URG):
-- 1013 will not be caught:
declare
e exception;
pragma exception_init(e,-1013);
begin
raise e;
exception when others then dbms_output.put_line('caught');
end;
/
declare
*
ERROR at line 1:
ORA-01013: user requested cancel of current operation
ORA-06512: at line 5
ORA-3113 and ORA-28 works in a similar way, but even worse: they also kill a session(process)!
declare
e exception;
pragma exception_init(e,-3113);
begin
raise e;
exception when others then dbms_output.put_line('caught');
end;
/
declare
*
ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 30787
Session ID: 1 Serial number: 8517
-- 28 will not be caught:
declare
e exception;
pragma exception_init(e,-28);
begin
raise e;
exception when others then dbms_output.put_line('caught');
end;
/
declare
*
ERROR at line 1:
ORA-00028: your session has been killed
ORA-06512: at line 5
SQL> select sysdate from dual;
select sysdate from dual
*
ERROR at line 1:
ORA-01012: not logged on
Process ID: 23223
Session ID: 9 Serial number: 2198
And just for fun: did you know that NO_DATA_FOUND exception has error code +100? (The only error with a positive number 🙂 While it returns “ORA-01403: no data found”.
SQL> select sys.standard.sqlerrm(100) s100,
2 sys.standard.sqlerrm(-1403) s1403
3 from dual;
S100 S1403
---------------------------------------- ----------------------------------------
ORA-01403: no data found ORA-01403: no data found
SQL> exec raise no_data_found;
BEGIN raise no_data_found; END;
*
ERROR at line 1:
ORA-01403: no data found
ORA-06512: at line 1
You can see that both -1403 and +100 return the same ORA-1403.
NO_DATA_FOUND exception is declared in sys.standard and has errorcode = 100 because of ANSI standard:
NO_DATA_FOUND exception;
pragma EXCEPTION_INIT(NO_DATA_FOUND, 100);
And we even can’t define an exception with 1403 🙂
SQL> declare
2 e exception;
3 pragma exception_init(e,100);
4 begin
5 raise e;
6 exception when others then
7 dbms_output.put_line('sqlerrm:'||sqlerrm);
8 dbms_output.put_line('sqlcode:'||sqlcode);
9 end;
10 /
sqlerrm:ORA-01403: no data found
sqlcode:100
PL/SQL procedure successfully completed.
SQL> declare
2 e exception;
3 pragma exception_init(e,-1403);
4 begin
5 raise e;
6 end;
7 /
e exception;
*
ERROR at line 2:
ORA-06550: line 2, column 2:
PLS-00701: illegal ORACLE error number -1403 for PRAGMA EXCEPTION_INIT
PS. Original twitter thread:
Another interesting troubleshooting case
Got an interesting question today in RuOUG:
Some very simple PL/SQL procedures usually are completed within ~50ms, but sometimes sporadically longer than a second. For example, the easiest one from these procedures:
create or replace PROCEDURE XXXX (
P_ORG_NUM IN number,
p_result OUT varchar2,
p_seq OUT number
) AS
BEGIN
p_seq := P_ORG_NUM; p_result:='';
END;
sql_trace shows that it was executed for 1.001sec and all the time was “ON CPU”:
Trace file /opt/oracle/diag/rdbms/rdb4/rdb/trace/rdb_ora_7100.trc
Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.10.0.0.0
Build label: RDBMS_19.10.0.0.0DBRU_SOLARIS.SPARC64_210107
ORACLE_HOME: /opt/oracle/product/19
System name: SunOS
Node name: node2.zzzzz.ru
Release: 5.11
Version: 11.3
Machine: sun4v
Oracle process number: 137
Unix process pid: 7100, image: oracle@node2.zzzzz.ru
*** 2021-05-26T15:38:31.321550+03:00
*** SESSION ID:(68.47940) 2021-05-26T15:38:31.321609+03:00
*** CLIENT ID:() 2021-05-26T15:38:31.321633+03:00
*** SERVICE NAME:(SYS$USERS) 2021-05-26T15:38:31.321656+03:00
*** MODULE NAME:(JDBC Thin Client) 2021-05-26T15:38:31.321679+03:00
*** ACTION NAME:() 2021-05-26T15:38:31.321703+03:00
*** CLIENT DRIVER:(jdbcthin : 19.3.0.0.0) 2021-05-26T15:38:31.321728+03:00
=====================
PARSING IN CURSOR #18446744071368904384 len=53 dep=0 uid=51 oct=47 lid=51 tim=190436799743741 hv=804128640 ad='12345678' sqlid='aabbaabbaa123'
BEGIN AAAA.XXXX(:1 ,:2 ,:3 ); END;
END OF STMT
PARSE #18446744071368904384:c=28,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=190436799743741
BINDS #18446744071368904384:
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1000000 frm=01 csi=873 siz=24 off=0
kxsbbbfp=ffffffff747c6c98 bln=22 avl=02 flg=05
value=6
Bind#1
oacdty=01 mxl=32767(32767) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1400010 frm=01 csi=873 siz=32767 off=0
kxsbbbfp=ffffffff747b8020 bln=32767 avl=00 flg=05
Bind#2
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=03 fl2=1400000 frm=01 csi=873 siz=24 off=0
kxsbbbfp=ffffffff747c6c68 bln=22 avl=00 flg=05
*** 2021-05-26T15:38:33.172899+03:00
WAIT #18446744071368904384: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=190436800744970
EXEC #18446744071368904384:c=1104,e=1001110,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=190436800745125
XCTEND rlbk=0, rd_only=1, tim=190436800745192
Originally I asked for dtrace/flamegraph and got just this:
unix`_resume_from_idle+0x280
genunix`cv_timedwait_sig_hires+0x1c4
genunix`cv_waituntil_sig+0x90
genunix`nanosleep+0xd4
unix`syscall_trap+0x228
0xffffffff7c04dbcc
0xffffffff7c0393ec
0xffffffff7c02e084
0xffffffff7c02f860
0x1176ef724
0x118376518
0x118366b84
0x118365d14
0x118366078
0x118314b60
0x1183973cc
0x1182c707c
0x1102edef8
0x10aa60064
0x10c224038
0x10aa50ca8
0x115bbc370
0x10aa196dc
0x10aa2c59c
0x10aa50ca8
ns
value ------------- Distribution ------------- count
268435456 | 0
536870912 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
1073741824 | 0
But truss showed much more interesting details:
0.000037 write(11, " B i n d # 2\n", 8) = 8
0.000045 write(12, " 2 0 m 7 } M X 8\n", 9) = 9
0.000022 lseek(11, 0, SEEK_CUR) = 4673
0.000038 write(11, " o a c d t y = 0 2 ".., 104) = 104
0.000040 write(12, " 2 0 m N } 5 Y e 1\n", 10) = 10
0.000020 lseek(11, 0, SEEK_CUR) = 4777
0.000037 write(11, " k x s b b b f p = f".., 52) = 52
0.000038 write(12, " 2 0 m 7 } j Y q\n", 9) = 9
0.000028 pathconf("/tmp/", _PC_NAME_MAX) = 255
0.000029 open("/tmp/.SHMLPESLD_rdb4_26_000000047334dc80", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW|O_CLOEXEC, 0666) Err#17 EEXIST
1.000029 nanosleep(0xFFFFFFFF7FFF5FF0, 0xFFFFFFFF7FFF5FE0) = 0
0.000038 open("/tmp/.SHMLPESLD_rdb4_26_000000047334dc80", O_RDWR|O_CREAT|O_EXCL|O_NOFOLLOW|O_CLOEXEC, 0666) = 13
0.000023 close(13) = 0
0.000026 open("/tmp/.SHMDPESLD_rdb4_26_000000047334dc80", O_RDONLY|O_NOFOLLOW|O_CLOEXEC) = 13
0.000028 unlink("/tmp/.SHMLPESLD_rdb4_26_000000047334dc80") = 0
0.000052 mmap(0x00000000, 528, PROT_READ|PROT_EXEC, MAP_PRIVATE, 13, 0) = 0xFFFFFFFF74700000
0.000020 close(13) = 0
0.000023 lseek(11, 0, SEEK_CUR) = 4829
0.000044 write(11, "\n * * * 2 0 2 1 - 0 5".., 38) = 38
0.000040 write(12, " - T + 7 } d b k t . c *".., 16) = 16
0.000020 lseek(11, 0, SEEK_CUR) = 4867
0.000037 write(11, " W A I T # 1 8 4 4 6 7".., 130) = 130
0.000037 write(12, " 8 4 j U 1 y 5 $ o 7 2 2".., 18) = 18
0.000020 lseek(11, 0, SEEK_CUR) = 4997
0.000037 write(11, " E X E C # 1 8 4 4 6 7".., 105) = 105
0.000037 write(12, " 8 0 j d 0 y 5 $ k x s t".., 20) = 20
0.000022 lseek(11, 0, SEEK_CUR) = 5102
As you can see it calls nanosleep in the line #11 and sleeps 1 sec, but more interesting a line before and a few after nanosleep: oracle tries to open (and fails “err17”) a file "/tmp/.SHMLPESLD_rdb4_XXX” , which means that it tries to open a pl/sql procedure compiled in native mode (pesld – Plsql code Execution Shared object manager native code Loader). I’ve asked to check compilation parameters of the procedure, and it was really compiled in native mode:
PLSQL_OPTIMIZE_LEVEL 2
PLSQL_CODE_TYPE NATIVE
PLSQL_DEBUG FALSE
So obvious workaround to recompile those procedures in the INTERPRETED mode fixed the issue.
UPDATE: Forgot to show what exactly is going on here: Finally I got normal stack:
unix`_resume_from_idle+0x280
genunix`cv_timedwait_sig_hires+0x1c4
genunix`cv_waituntil_sig+0x90
genunix`nanosleep+0xd4
unix`syscall_trap+0x228
libc.so.1`__nanosleep+0x4
libc.so.1`sleep+0x14
libc.so.1`__pos4obj_lock+0x68
libc.so.1`shm_open+0x50
oracle`pesld02_Map_Object+0xbc4
oracle`penglur+0x1d18
oracle`pfrins+0x8e4
oracle`pfri7_inst_body_common+0x214
oracle`pfri3_inst_body+0x18
oracle`pfrrun+0x9e0
oracle`plsql_run+0x22c
oracle`peicnt+0xfc
oracle`kkxexe+0x2f8
oracle`opiexe+0x5784
oracle`kpoal8+0x918
oracle`opiodr+0x448
oracle`ttcpip+0x430
oracle`opitsk+0x83c
oracle`opiino+0x39c
oracle`opiodr+0x448
ns
value ------------- Distribution ------------- count
268435456 | 0
536870912 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
1073741824 | 0
As you can see pesld02_Map_Object is trying to load (map) a user-defined function (native compilation) and calls shm_open which calls __pos4obj_lock and if we look at it, we can find why and when it calls sleep(which calls nanosleep internally):
int
__pos4obj_lock(const char *name, const char *ltype)
{
char *dfile;
int fd;
int limit = 64;
if ((dfile = __pos4obj_name(name, ltype)) == NULL) {
return (-1);
}
while (limit-- > 0) {
if ((fd = __open_nc(dfile, O_RDWR | O_CREAT | O_EXCL, 0666))
< 0) {
if (errno != EEXIST)
break;
(void) sleep(1);
continue;
}
(void) __close_nc(fd);
free(dfile);
return (1);
}
free(dfile);
return (-1);
}
SQL*Plus tips #9: Reading traces and incident files
@tracefile_read_last_by_mask filemask [regexp] [ignore_regexp]
– finds last trace by filemask and filters rows by regexp and filters out rows by ignore_regexp:
@ tracefile_by_mask.sql [mask] – finds and shows last 10 trace files by mask
@tracefile_current – shows a file name of the your session’s trace file
@tracefile_read_current – reads a trace file of the current session
@tracefile_last [n] – shows last N trace files (by default 10)
@tracefile_read filename – reads a specified trace file
@tracefile_read_full.sql <filename> – reads a specified trace file and shows it with additional columns: component_name, operation_name, file_name, function_name
@tracefile_spool <tracefilename> <dest_file> – saves tracefilename to dest_file on local machine:
Incidents, problems and incident files
@diag/problems_last.sql [N] – shows last N problems, N is optional, by default shows last 10 problems
@diag/incidents_last.sql [N] – shows last N incidents (by default 10)
@diag/incidents_by_problem.sql <problem_id> [N] – shows last N incidents by problem_id
@diag/adr_home_create.sql – creates a directory object for reading incident files:
@diag/incident_files_by_mask.sql filemask – shows incident file names by file mask
SQL> @diag/incident_files_by_mask.sql %incident%387.%
INCIDENT_ID OWNER_ID FLAGS CON_ID BFILE
----------- ---------- ---------- ------ ------------------------------------------------------------
26387 1 1 3 <ADR_HOME>/incident/incdir_26387/ORA19_ora_2942_i26387.trc#0
1 row selected.
@diag/incident_files_by_id.sql incident_id – shows incident files by incident_id
@diag/incident_files_spool_by_id.sql incident_id – saves an incident file on local machine:
Oracle diagnostic events — Cheat sheet
Oracle diagnostic events is a great feature, but unfortunately poorly documented and nonintuitive, so it’s difficult to remember all events/actions/parameters and even read its internal documentation using oradebug. So I decided to compile its internal doc as a more convenient html-version (http://orasql.org/files/events/) and make a cheat sheet of some unknown or little-known use cases.
alter system set events
'kg_event[1476]
{occurence: start_after 1, end_after 3}
trace("stack is: %\n", shortstack())
errorstack(2)
';
- kg_event[errno] – Kernel Generic event in library Generic for error number events, which instructs to trace ORA-errno errors;
- {occurence: start_after X, end_after Y} – is a filter, which instructs to skip X event checks and trace just Y times;
- trace(format, str1, str2, …, str15) – is a function from ACTIONS for printing into a trace file;
- shortstack() – is a function from ACTIONS , which returns a short call stack as a string;
- errorstack(level) – is a function from ACTIONS, which prints extended info (level: 0 – errorstack only, 1 – errorstack + call stack, 2 – as level 1 + processtate, 3 – as level 2 + context area). You can get more details with PROCESSSTATE or SYSTEMSTATE. If you need just a call stack, you can use CALLSTACK(level) , with function arguments in case of level>1.
alter system set events
'trace[SQL_Compiler.* | SQL_Execution.*]
[SQL: ...]
{process: ospid = ...}
{occurence:end_after 3}
controlc_signal()';
- trace[component] – is the main diagnostic event, which allows to specify Components to trace. This command shows how to specify all child components of SQL_Compiler and SQL_Execution.
- SQL[SQL: sqlid ] – is the only SCOPE in library RDBMS, which allows to trace specific SQL_ID and all its recursive calls (or for example, if you specify sql_id of a PL/SQL call, then all its internal queries will be traced too);
- {process: …} – is a filter, which allows to filter processes;
- controlc_signal – is an ACTION, that raises “ORA-01013: user requested cancel of current operation”, ie it’s like this session interrupted own call.
I’ve used this command recently when I had to help developers to find where some suboptimal and unnecessary queries, discovered during performance load testing, come from their code (huge webapp with hibernate).
alter system set events
'sql_trace {process: ospid = ...}
trace("sqlid(%): %\n", sqlid(), evfunc())
';
sql_trace – is just a good old trace event #10046, and this function forces oracle to print a function name and sql_id for each sql_trace event. Simple example:
As you can see we get 26 “occurrences” in case of “_rowsource_statistics_sampfreq”=1 instead just 12 by default. More details about this here: https://alexanderanokhin.com/2012/12/24/timing-rowsource-statistics-part-2-overhead-and-inconsistent-time/
alter system set events
'wait_event["enq: TM - contention"]
{wait: minwait=1000}
errorstack(1)
trace("event=[%] sqlid=%, ela=% p1=% p2=% p3=%\n",
evargs(5), sqlid(), evargn(1), evargn(2), evargn(3), evargn(4))
';
- wait_event[name] – event to control wait event post-wakeup actions, first argument is a wait event name, all wait event names and their parameters (P1,P2,P3) you can find in v$event_name:
select
wait_class,name
,parameter1,parameter2,parameter3
,display_name
from v$event_name;
- {wait: … } – is a filter that allows to specify both the minimum wait time(ms) and parameters P1, P2, P3. For example, for this “TM-contention” wait event, P2 is “object #”, and we can specify {wait: minwait=1000; p2=12345}, ie only table TM-lock wait events on the table with object_id=12345 and longer than 1 sec;
- evargX() – functions from ACTIONs, which return event check arguments values, where 1st argument is an elapsed time(ms), 2nd-4th – parameters p1-p3, and 5th – wait event name. kg_event has own related functions – errargX().
or another example, when you need to find out which session variables have been changed: Let’s imagine someone forgot to specify nls parameters in to_number() and didn’t specify “on conversion error” clause, and some session sporadically get “ORA-01722: invalid number”:
-- original parameters:
SQL> alter session set nls_numeric_characters='.,';
Session altered.
-- all works fine...
SQL> select to_number('1,200.3','999g999d999') + 10 from dual;
TO_NUMBER('1,200.3','999G999D999')+10
-------------------------------------
1210.3
-- until they've been changed at some point:
SQL> alter session set nls_numeric_characters=".'";
Session altered.
-- obviously we get errors:
SQL> select to_number('1,200.3','999g999d999') + 10 from dual;
select to_number('1,200.3','999g999d999') + 10 from dual
*
ERROR at line 1:
ORA-01722: invalid number
There is no special view for session parameters which are not a part of v$ses_optimizer_env, but we can easily get them using MODIFIED_PARAMETERS():
alter system set events
'kg_event[1722]
{process: ospid=27556}
{occurence:end_after 1}
MODIFIED_PARAMETERS()';
And since we have v$diag_alert_ext for alert.log and v$diag_trace_file_contents for trace files, we can get them using this simple query:
select c.payload
from v$diag_trace_file_contents c
where 1=1
and c.session_id = &sid -- session sid
and c.serial# = &serial -- session serial#
and c.section_name = 'Error Stack' -- they will be in "Error Stack"
-- and c.payload like '%nls_numeric%' -- we can filter only specific nls parameters
and c.timestamp>systimestamp-interval'15'minute -- last 15 minutes
;
-- Results:
DYNAMICALLY MODIFIED PARAMETERS:
nls_language = "AMERICAN"
nls_territory = "AMERICA"
nls_sort = "BINARY"
nls_date_language = "AMERICAN"
nls_date_format = "yyyy-mm-dd hh24:mi:ss"
nls_currency = "$"
nls_numeric_characters = ".'"
nls_iso_currency = "AMERICA"
nls_calendar = "GREGORIAN"
nls_time_format = "hh24:mi:ssxff"
nls_timestamp_format = "yyyy-mm-dd hh24:mi:ssxff"
nls_time_tz_format = "hh24:mi:ssxff TZR"
nls_timestamp_tz_format = "yyyy-mm-dd hh24:mi:ssxff TZR"
nls_dual_currency = "$"
nls_comp = "BINARY"
local_listener = ""
Update: I’ve just got a question in RuOUG:
We use “Extensible Optimizer Interface“, i.e. Oracle CBO calls such code internally, which fails periodically with “ORA-06550 PL/SQL compile error”. Can we specify both “kg_event” and “sql_id” so we could get those errors with details in alert.log
Of course, simple example:
alter system set events
'kg_event[6550]
[sql: 5cmnpq8t0g7pd]
{occurence: start_after 1, end_after 3}
errorstack(3)
incident(plserrors)
';
As you can see we use incident(label) here to generate an incident file (which you can easily pack and send to Oracle support or consulters) and kg_event[6550] to trace “ORA-06550: line %, column %” errors.
PS, More details in Tanel Poder’s articles:
1. The full power of Oracle’s diagnostic events, part 1: Syntax for KSD debug event handling
2. The full power of Oracle’s diagnostic events, part 2: ORADEBUG DOC and 11g improvements
3. What Caused This Wait Event: Using Oracle’s wait_event[] tracing
4. http://tech.e2sn.com/oracle/troubleshooting/oradebug-doc
Ora C functions on Frits Hoogland’s site: http://orafun.info/
HTML version of the internal oradebug/diagnostic events doc: http://orasql.org/files/events
v$blog #funny #friday
select title, short_url
from v$blog
where pubDate>=systimestamp - interval '5' month;
with v$blog as (
select
title
,to_timestamp_tz(pubDate,'DY, dd mon yyyy hh24:mi:ss TZR') pubDate
,short_url
,description
from xmltable(
'/rss/channel/item'
passing
xmltype(httpuritype('http://orasql.org/feed/').getclob())
columns
title varchar2(70) path 'title'
,pubDate varchar2(40) path 'pubDate'
,url varchar2(128) path 'link'
,short_url varchar2(50) path 'guid'
,description varchar2(500) path 'fn:substring(./description,1,500)'
)
)
select title, short_url from v$blog where pubDate>=systimestamp - interval '5' month;
pySyncOracleStandby – Simple sync service for Oracle manual standby
I created this simple service a couple of years ago. It’s pretty simple, small and intuitive Python app, so you can easily modify it to suit your own needs and run on any platform: https://github.com/xtender/pySync