ASE Query Processing Errors and Query Plan Diagnostics

Content

1. Three types of ASE error messages
2. ASE errorlog
3. Query processing errors or messages
4. Query plan diagnostics and tools
5. References and useful URLs

1.Three types of ASE error messages:

1.1 Numbered errors

• • • Sample error numbers: 208, 701 and 1105.
    • Error_number = module_number x 100 + minor_number.

• • • Minor number range is 0-99. Each module number has limit of 100 errors.
    • One module name may have a few module numbers, e.g., PARSER has 5 module numbers: (1, 66, 73,117, 163).
    • New releases may have more module names, module numbers and error numbers than older releases.
    • Errors are defined with Severity Levels.
    • An error may be raised with state number (and argument(s)) to identify source code location.
    • They are generic, raised from server layer (above kernel layer), independent of ASE host platform.
    • May be sent to client, or write to ASE errorlog, or to both client and errorlog.
    • System table dbo.sysmessages stores:
      • Numbered errors.
      • Other informational messages, e.g., showplan messages have severity=10 (INFO).

          For a given error number (in errorlog), may query this table:

 select error, severity, description from master.dbo.sysmessages where error=error_number

• • • May enable | disable logging for a specific error to errorlog via sp_altermessage.
    • Login with sa_role may dynamically enable |disable internal server wide trace flag 3601 to print error stack to errorlog:
      • To turn on 3601 trace flag: ‘dbcc traceon(3601)’ or ‘set switch on 3601 with override’.
      • To turn off 3601 trace flag after capture error stack(s) to errorlog: ‘dbcc traceoff(3601)’ or ‘set switch off 3601’.
    • Attentions and error fields in a server process' Process Status Structure (PSS):

pattention, pexattn, plasterror, ppreverror, ppss_errs[10] (a ring buffer which tracks most recent errors and messages).

          Login having sa_role may use command DBCC PSS to print target process’ pss:  set switch on 3604; dbcc pss(0, spid).

1.2 Un-numbered messages

• • • For errorlog only.
    • Un-numbered messages may have internal message id and symbol.
    • Example:
      • Message text: Stack guardword corrupted.
      • Internal message id = 30010.
      • Internal message symbol: CLKPROF_STKGUARDWDCORRUPTED.
      • Please see URL Stack guardword corrupted for more details on this message and stack overflow message.
    • Some un-number messages may be platform specific.

1.3 Hard-coded messages

• • • For errorlog only.
    • No message id, no message symbol.
    • Example:

 Message text: “FATAL UNHANDLED EXCEPTION: signal %d hit while handling a previously hit signal. The server cannot continue and will shut down."

When ASE hits 2^nd signal while handling 1^st signal, if configurable parameter secondary signal handling = default (1), then it may print the message to errorlog.

2. ASE errorlog

• • • Error message format:  <instance_ID_2digits>:<thread_ID_4digits>:<family_ID_5digits>:<spid_5digits>:<datetime> {<server> | <kernel>} <message>
      • First field on the left is instance_ID_2digits, 00 by default. Only old ASE cluster edition releases have instance id > 0.
      • Example: The following four lines from an old errorlog:

00:0007:00000:00000:2018/04/19 12:10:38.63 kernel  Thread 7 (LWP 31662) of Threadpool syb_default_pool online as engine 5

00:0012:00000:00000:2018/04/19 12:10:38.63 kernel  Thread 12 (LWP 32098) of Threadpool syb_default_pool online as engine 10

00:0007:00913:00566:2018/05/07 09:20:45.42 kernel  Current process (0x11f0090) infected with signal 11 (SIGSEGV)

00:0012:00913:00565:2018/05/07 09:20:45.42 kernel  Current process (0x1210091) infected with signal 11 (SIGSEGV)

The top two lines show two engines (5 and 10) started and their thread IDs (7 and 12)

Last two lines show worker processes (spid 566 and spid 565) got signal 11 (SIGSEGV) on engine 5 and engine 10. Their family id (parent spid) =913.

• • • A complete errorlog covers ASE boot time and related error message(s). For urgent issues, please attach ASE configuration file and complete errorlog to SAP incident.

• • • For big ASE errorlog, we may use grep to pull out information, e.g.,
      • Grep 5-digit spid 00072:   grep –n 00072 errorlog > msg_spid_72.     

If a phantom lock has spid=72, then may check last message from spid 72. 

• • • • Grep fatal errors with severity level >=20:   grep –n “Severity: 2” errorlog > error_fatal.     Please see URL Severity Levels 19-26.

• • • • Grep all numbered errors:     grep -n ‘Error’ errorlog >Errors
      • Check siginfo or signal address:   ‘grep –n “Address” errorlog’ or ‘grep –n “siginfo” errorlog’.

• • • • Check spid which output stack trace:    grep  -n ‘stack trace’ errorlog > stack_trace_spid.   Please see KBA 3095878 - Understanding stack traces.

• • • • Grep EBF(or FBO) from errorlog to check EBF number and ASE started time:   'grep -n EBF errorlog' or 'grep -n FBO errorlog'.

• • • SPID might have been recycled if timestamps of messages have different days. A server process’ start time is in field ptimestamp in PSS (Process Status Structure).
    • Enable configurable parameter ‘log audit logon success’ may write login name, client name and version with connection timestamp to errorlog.
    • If existing errorlog file size is big (e.g., >1Gbs), then may
      • Consider setting parameter ‘errorlog size’ so that ASE may dynamically close the current errorlog and opens a new one when the size exceeds the threshold.
      • When reboot ASE next time, may move errorlog to new file (e.g., errorlog_date), then start ASE with new errorlog.
      • May compress previous errorlog and keep the file in case we want to check history later.

3. Query processing errors or messages

            Query processor modules are discussed in session Understanding Query Processing in document Performance and Tuning Series: Query Processing and Abstract Plans 16.0.

3.1 Table: Errors raised by query processor modules on 16.0 SP04 PL03

Note:              

• • • Sometimes may have error number(s) in lasterror (and preverror) in stack trace in errorlog, may query master.dbo.sysmessages to get error text and severity level.
    • For fatal error 551, the message is “An unknown EVAL was sent to the execution module.”. This is a symptom of execution plan has been corruption in procedure cache.

Query processing may get into errors raised by database access module or resource managers.

3.2 Table: Errors raised by database access module and resource managers:

4. Query plan diagnostics

• • • For query execution time errors (detected errors or undetected errors), sometimes may happen under conditions, e.g.
      • The process used a previous cached plan in procedure cache.
      • Specific operator(s) | algorithm(s) exists in a query plan.

An example in KBA-3114932 which has a reproduction of CR 825779. It listed three conditions in symptom session. It has been fixed on 16.0 SP03 PL12 and 16.0 SP04 PL02.

                               Conditions of CR 825779:

• • • • Parallelism is enabled server wide.
      • The process uses previous cached parallel plan which has merge join operator.
      • The query |statement has search clause with variable | parameter.

This may affect ad-hoc query when statement cache is on and ‘literal autoparam’=1, and some statement inside a procedure or trigger.

Google search via keywords: “merge join parallel KBA SAP ASE”, search result includes KBA 3114932 (on the top).

• • • Query plan analysis may help the following:
      • Find out if a problem query plan is the same as a newly created plan.

To generate new query plan:

• • • • • • For ad-hoc query, disable statement cache for the session, then run the query again: set statement cache off; set showplan on; go; sql_text; go.
          • For stored procedure, execute procedure with recompile option: set showplan on; go; exec procedure_name param_list with recompile; go.

• • • • Check operator names, join order, index, parallel or serial in a query plan.
      • Compare query plans and configurations between two servers if they generate different result sets for the same query and data.
      • Look for alternative operator |algorithm to test and compare.

BTW, if a problem query gets a very big showplan and no solution | workaround, then may consider simplifying the logic and break big query into a few smaller ones.

There are three query plan diagnostics: abstract plan, showplan and execution plan.

4.1 Abstract plans

• • • A language for ASE optimizer with grammar.
    • Short description of final plan generated by optimizer before compilation.
    • Abstract plan has operator | algorithm names, join order, access methods (index scans, tables scans), scan parallel degree and buffer pool information.
    • Partial or full abstract plan (AP) sometimes may be used as hints or force option by adding plan clause to the end of query text.
    • Command ‘set option show_abstract_plan on | off’ may be used to enable |disable abstract plan diagnostics during query optimization.
    • Examples in URLs:  Introduction to Abstract Plan and Using the Plan Clause.
    • Optimization criterion alternative_greedy_search may use internal abstract plans for queries joining more than six tables.
    • For critical queries on critical production systems, it may be helpful to backup good abstract plans associate with the queries for future reference if needed.
    • For query performance regression issue after major upgrade, if query plans change between two releases, then may try a test using previous abstract plan on new release.
    • Example:

Query text:  select o.name, o.id, i.name from sysobjects o, sysindexes i where o.id = i.id and o.name like 'sys%'

Output:        The Abstract Plan (AP) of the final query execution plan:

( nl_join ( i_scan ncsysobjects ( table ( o sysobjects ) ) )

             ( i_scan csysindexes ( table ( i sysindexes ) ) ) )

 ( prop ( table ( o sysobjects ) ) (parallel 1 ) ( prefetch 16 ) ( lru ) )

 ( prop ( table ( i sysindexes ) ) (parallel 1 ) ( prefetch 16 ) (lru ) )

To experiment with the optimizer behavior, this AP can be modified and then passed to the optimizer using the PLAN clause: SELECT/INSERT/DELETE/UPDATE ...PLAN '( ... )'.

4.2 Showplan

• • • Text description of a compiled query plan.
    • A showplan example using query with PLAN clause is in URL Statement Level Showplan Output.
    • It has more detail plan information than abstract plan. Please see slides 4-5 in previous presentation Abstract Plan, Diagnostics and Reproduction.
    • Most common use as query tuning diagnostics.
    • Use ‘set showplan on’ to capture showplan for current session.
    • A login having sa_role may use stored procedure ‘sp_showplan’ or ‘sp_sp spid’ (on 16) to check another long running process’s plan on live server.

If the target process is running a fast query on a different ASE engine and query plan context is changing while current process is displaying the plan, then it’s possible to cause current session stack trace.

• • • For cached statement having statement id sql_id, set switch on 3604; dbcc prsqlcache(sql_id,1); go; may print SSQL_DESC structure for the cached statement and showplan for the query plan.
    • To trace another session, may try application tracing KBA-2209721.
    • To trace a specific procedure| trigger running by multiple sessions on a test environment, may put ‘set show_sqltext on’, ‘set showplan on’, ‘set statistics time, io, plancost on’ inside procedure |trigger, then turn on server wide trace flag 3602 via dbcc traceon(3602) to print information to errorlog. When it’s done, disable traceflag(s) including 3602.
    • Showplan messages:
      • When statement cache is on, it may tell statement id and if this is new statement or previously cached statement, e.g.
        • Executing a newly cached statement (SSQL_ID = 1826154570). --- first execution
        • Executing a previously cached statement (SSQL_ID = 1826154570).     --- second execution

BTW, if previously cached statement causing problem, then may delete the statement via tool dbcc purgesqlcache(sql_id).

When test different optimizer setting, may ‘set statement_cache off’ to generate new plan.

• • • • Parallel optimizer or serial optimizer messages:
        • “Optimized using Serial Mode” OR “Optimized using Parallel Mode”

          If a suboptimal plan or invalid plan is generated by parallel optimizer, then please test serial optimizer. Session level: ‘set parallel_query off’ or ‘set parallel_degree 1’.

• • • • Forces options or abstract plan messages
        • Optimized using the forced options (internally generated Abstract Plan).
        • Optimized using the Abstract Plan in the PLAN clause.

                                          If the force option is not good, then run the query without forcing option to see if optimizer can generate a better plan.

• • • Differences between native query processor (QP) showplan and compatibility mode QP showplan:
      • Native QP showplan has Operators
      • Compatibility mode QP showplan has no ‘Operator’

BTW, when report query processing issue, please confirm it is native query processor issue, rather than compatibility mode issue.

Compatibility mode query processor may be too slow for some queries since only a few algorithms are available.

For recent 16 releases, configurable parameter ‘enable compatibility mode’ should be default (0).

Compatibility mode may be used as reference, or temporary workaround on query level or session level when no other native QP workaround available.

• • • Disabling |enabling an operator to try an alternative plan.

For a specific query, it’s possible to test alternative query plans by enabling | disabling an operator |criterion.

May query master.dbo.sysoptions to see 'Query Tuning' options, e.g., the following query may output Optimizer Criteria having name like '%_join,'

select distinct name from sysoptions where category='Query Tuning' and name like '%_join'

If disable a basic operator to workaround a query issue, then please remember to enable it again after the query.

Disabling a basic operator |optimizer criterion session wide may cause error 325 e.g., 'set store_index off' to disable reformatting session wide may cause error 325. 

Message of error 325:"Adaptive Server finds no legal query plan for this statement. If an Abstract Plan is forcing the query plan, check its correspondence to the query. If not, please contact SAP Technical Support. "

4.3 Execution plan

• • • Compiled plan with low level information.
    • For invalid query plan or unexpected result issue, may consider it when: 
      • Problem is not reproducible at will on non-production system.
      • Root cause is unknown.
      • Cannot provide enough information to SAP to test the query in house.
    • Tool DBCC Procbuf may be used to print out execution plan in procedure cache, or compiled object’s query tree in procedure cache or read from sysprocedures.
      • Example 1: Syntax to print procedure buffer for cached statement id (sql_id=157292639) in tempdb to see compiled time and memory usage:

Set switch on 3604; dbcc procbuf(tempdb, 157292639, 0,0,1)

• • • • Example 2: Syntax to print procedure buffer and execution plan in procedure cache for this cached statement:

 dbcc procbuf(tempdb, 157292639, 0,1,1)

                   To check operator name in execution plan in output file dbcc.out: grep -n this dbcc.out|grep VA             

312:====== Emit (VA = 5) (State = LSTATE_INITIAL) (this = 0x15dd22720) ======

446:====== MergeJoin (VA = 4) (State = LSTATE_INITIAL) (this = 0x15dd222b8) ======

521:====== Sort (VA = 2) (State = LSTATE_INITIAL) (this = 0x15dcf0c58) ======

639:====== Restrict (VA = 1) (State = LSTATE_INITIAL) (this = 0x15dcf0538) ======

659:====== IndexScan (VA = 0) (State = LSTATE_INITIAL) (this = 0x15dcf0430) ======

715:====== IndexScan (VA = 3) (State = LSTATE_INITIAL) (this = 0x15dcf1998) ======

This plan uses merge join, index scan to access two tables, one internal sort.

• • • • Example 3: Syntax to print query tree in sysprocedures for a specific procedure which causes issue:

                                                                                    dbcc procbuf(dbname, proc_name, 0,1,2)

If query tree of a compiled object in sysprocedures is invalid, then may need to rebuild the query tree, or drop and recreate the compiled object.

• • • Tool DBCC deleteplan may be used to clean up specific invalid or suboptimal query plans in procedure cache.
    • Tool dbcc upgrade_object may be used to rebuild query tree(s) of compiled object(s) in sysprocedures from text in syscomments.
    • If a procedure, trigger, user defined function, or view doesn’t work after recent major upgrade, dbcc upgrade_object has been run on the database, then please output DDL via ddlgen; drop the object; recreate the object to see if it can fix the problem.

5. References and useful URLs:

5.1 User documentations

• Troubleshooting: Error Messages
• Diagnosing System Problems in System Administration Guide
• Query Processing and Abstract Plans

5.2 Useful URLs:

• ASE Error, Fault, and Message Writeups
• SET options, Switchs and Traceflags
• SAP DM Customer Coffee Corner
• ASE Procedure and Statement Cache Memory Pools
• Sample Dianostics for ASE Error or Exception Handling
• Abstract Plan, Diagnostics and Reproduction
• Compiled Objects on Disks
• Optimizer Change between ASE 15.7 and ASE 16.0