Oracle SQL | Monthly Archives: May 2021

Another interesting troubleshooting case

Posted on May 29, 2021 by Sayan Malakshinov Posted in oracle, PL/SQL, PL/SQL optimization, trace, troubleshooting Leave a comment

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

Posted on May 28, 2021 by Sayan Malakshinov Posted in diagnostic event 10046, oracle, SQL*Plus, SQL*PLus tips, trace, troubleshooting Leave a comment

@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

Posted on May 20, 2021 by Sayan Malakshinov Posted in diagnostic event 10046, oracle, statistics, trace, troubleshooting, undocumented Leave a comment

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:

сначала выполняем запрос с настройками по умолчанию, а затем с _rowsource_statistics_sampfreq=1 — executing a query twice: with default parameters and with _rowsource_statistics_sampfreq=1

Разница в трейсе заметна — The difference is noticeable: 12 vs 26 traced events

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.