Saturday 29 September 2012

Difference between EXEC & EXECUTE()


EXECUTE


 The EXECUTE, or EXEC statement executes a stored procedure by following the command with the name of the stored procedure and any proper parameter arguments:

 EXEC sp_Empfind @City='DE'

EXECUTE()

 The EXECUTE(character_string) function executes a character string containing a Transact-SQL command.
 It can be written like EXEC(character_string) also. The EXECUTE(character_string) function is not compiled until run time and the generated plan is not cached and reused. The following example executes a dynamic string that concatenates literal strings with variable values:

 DECLARE @mycol varchar(30)
 DECLARE @mytable varchar(30)
 SELECT @mycol = 'EMPID'
 SELECT @mytable = 'Employee'
 EXEC('SELECT ' + @mycol + ' FROM ' + @mytable)


sp_execute of pl sql



[sp_executesql in comparison to Execute]


 If you want to have the flexibility of dynamic SQL, but the persistence of a stored query plan, consider using sp_executesql in your stored procedures instead of EXEC. The syntax for sp_executesql is as follows:

 sp_executesql @SQL_commands, @parameter_definitions, param1,...paramN

sp_executesql operates just as the EXEC statement with regard to the scope of names, permissions, and database context. However, sp_executesql is more efficient when executing the same SQL commands repeatedly, and the only change is the values of the parameters. Because the SQL statement remains constant and only the parameters change, SQL Server is more likely to reuse the execution plan generated for the first execution and simply substitute the new parameter values. This saves the overhead from having to compile a new execution plan each time.

[Via:Microsoft SQL Server 2000 Unleashed By Ray Rankins, Paul Jensen, Paul Bertucci]

 The sp_executesql SP provides a second method of executing dynamic sql. When used correctly, it is safer than the simple EXECUTE method for concatenating strings and executing them. Like EXECUTE, sp_executesql takes a string constant or variable as a sql statement to execute. Unlike EXECUTE, the sql statement parameter must be an nchar or nvarchar.

 The sp_executesql procedure offers a distinct advantage over the EXECUTE method; you can specify your parameters seperately from the SQL statement. When you specify the parameters separately instead of concatenating them into one large string, SQL server passes the parameters to sp_executesql seperately. SQL server then substitutes the value of the parameters in the parameterized SQL statement. Because the parameter values are not concatenated into the SQL statement, sp_executesql protects against SQL injection attacks. sp_executesql parameterization also improves query execution plan cache reuse, which helps with performance.

 A limitation to this approach is that you cannot use the parameters in your SQL statement in place of table, column or other object names.

Example of sp_executesql

 DECLARE @product_name NVARCHAR(50) = N' Mountain%';
 DECLARE @sql_stmt NVARCHAR(128) = N'SELECT ProductID, Name ' +
 N'FROM Production.Product ' +
 N'WHERE Name LIKE @name';
 EXECUTE sp_executesql @sql_stmt,
 N'@name NVARCHAR(50)',
 @name = @product_name;

 [Via:Pro T-SQL 2008 Programmer's Guide By Michael Coles]

 The key difference in the syntax between the EXEC() and sp_executeSQL is that EXEC() will allow you to concatenate literals and variables to build up a string expression, while sp_executesql needs a string constant or a single string variable.

 sp_executesql must be passed a Unicode string.


Performance tuning - 02



In a pre-production test, I find out that application did not use bind variables and there was no time to change code before the production rollout. So we suggested changing CURSOR_SHARING parameter from EXACT to FORCE in order to turn hard parse to soft parse. When testing this change for the two webservice functions , which mainly consists of two inserts, one update and bunch of select statements, the results are promising:
  1. Summary of testing results from 15 min interval AWR reports from a 4-node 11.2.0.2 RAC database  
  2.   
  3. 2-node test (CURSOR_SHARING=EXACT)  
  4.   
  5. dd1    DB Time:   23.04 (mins)  143 tx/s   Parses: 440.7 per sec  Hard parses: 315.2 per sec         
  6. dd4    DB Time:   23.35 (mins)  140 tx/s   Parses: 414.4 per sec  Hard parses: 303.5 per sec                 
  7.   
  8.   
  9. 2-node test (CURSOR_SHARING=FORCE)  
  10.   
  11. dd1   DB Time:    16.68 (mins)  146 tx/s   Parses: 383.9 per sec  Hard parses: 2.6 per sec  
  12. dd4   DB Time:    16.01 (mins)  147 tx/s   Parses: 384.2 per sec  Hard parses: 2.6 per sec  
  13.   
  14.   
  15. -- dd1  Time Model Statistics (CURSOR_SHARING=FORCE)   
  16.    
  17. Statistic Name                                       Time (s) %  of DB Time  
  18. ------------------------------------------ ------------------ ------------  
  19. sql execute elapsed time                                666.6         66.6  
  20. DB CPU                                                      350.0         35.0  
  21. parse time elapsed                                        80.0          8.0  
  22. hard parse elapsed time                                 15.1          1.5  
  23. hard parse (sharing criteria) elapsed time        1.7           .2  
  24. PL/SQL execution elapsed time                     1.1           .1  
  25. hard parse (bind mismatch) elapsed time        1.0           .1  
  26. PL/SQL compilation elapsed time                  0.8           .1  
  27. connection management call elapsed time       0.4           .0  
  28. sequence load elapsed time                            0.4           .0  
  29. repeated bind elapsed time                             0.0           .0  
  30. DB time                                                         1,000.9  
  31. background elapsed time                                200.0  
  32. background cpu time                                      143.9  
  33.           -------------------------------------------------------------  
  34.    
  35. -- dd1  Time Model Statistics (CURSOR_SHARING=EXACT)   
  36.   
  37. Statistic Name                                       Time (s)  % of DB Time  
  38. ------------------------------------------ ------------------ ------------  
  39. DB CPU                                                  728.2         52.7  
  40. sql execute elapsed time                            632.9         45.8  
  41. parse time elapsed                                     481.2         34.8  
  42. hard parse elapsed time                             390.0         28.2  
  43. hard parse (sharing criteria) elapsed time    3.2           .2  
  44. hard parse (bind mismatch) elapsed time    2.9           .2  
  45. PL/SQL execution elapsed time                 1.4           .1  
  46. PL/SQL compilation elapsed time              1.2           .1  
  47. connection management call elapsed time    0.5           .0  
  48. sequence load elapsed time                         0.5           .0  
  49. repeated bind elapsed time                          0.0           .0  
  50. failed parse elapsed time                              0.0           .0  
  51. DB time                                                1,382.4  
  52. background elapsed time                          261.8  
  53. background cpu time                                115.5  
  54.           -------------------------------------------------------------  
  55.    

Bascially, I saw hard parse was greatly reduced. For the same level transaction rate, DB time was reduced from 46 min to 32 min after changing to FORCE. However, when another module was enabled and added to the two webserverice workload, things went wrong. I saw large amount of "cursor:mutex S" and "liberary cache lock" waits (>80% DB time). We identified an insert statement that has large amount of child cursors ( ~ 8000) caused the problem.

Below is a test case demonstrating large number of child cursors are created with CURSOR_SHARING=FORCE:

Test case 1

This test was carried out to repeat what we encountered in our pre-production test. Inserts into a table called MY_STB_LOG2 were performed with CUROSR_SHARING=FORCE, with 324 total number of inserts similar to the following:

  1. insert into MY_STB_LOG2 values('0000043862420080','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-04 07:51:40.000',timestamp'2011-05-04 02:20:45.000',timestamp'2011-05-04 02:35:07.000','N','N','','','','P',SYSDATE);  
  2. insert into MY_STB_LOG2 values('0000048201268050','VHO6_W07_MTR_30243_20110504094656__.101.Zip',CURRENT_TIMESTAMP,timestamp'2011-05-05 01:02:07.000',timestamp'2011-05-04 21:10:22.000','','N','N','','','','P',SYSDATE);  

After run, checking v$sqlarea and v$sql, we got:


  1. SQL> select sql_text,sql_id, executions from v$sqlarea where sql_text like 'insert into MY_STB_LOG2%';  
  2.    
  3. SQL_TEXT  
  4. ------------------------------------------------------------------------------------------------------------------------  
  5. SQL_ID        EXECUTIONS  
  6. ------------- ----------  
  7. insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",timestamp:"SYS_B_03",:"SYS  
  8. _B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)  
  9. 16yq35g1c433b         71  
  10.    
  11. insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",:"SYS_B_03",:"SYS_B_04",:"  
  12. SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)  
  13. 4yzz9r14n53fg         28  
  14.    
  15. insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",timestamp:"SYS_B_03",times  
  16. tamp:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)  
  17. gpb19na8zd67s        210  
  18.    
  19. insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS_B_02",:"SYS_B_03",timestamp:"SYS  
  20. _B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)  
  21. 6ua1jndb5ud4x         15  
  22.   
  23.   
  24. SQL> select sql_id, count(*) from v$sql  where sql_text like 'insert into MY_STB_LOG2%' group by sql_id;  
  25.   
  26. SQL> select sql_id, count(*) from v$sql  where sql_text like 'insert into MY_STB_LOG2%' group by sql_id;  
  27.    
  28. SQL_ID          COUNT(*)  
  29. ------------- ----------  
  30. gpb19na8zd67s        210  
  31. 16yq35g1c433b         71  
  32. 4yzz9r14n53fg         28  
  33. 6ua1jndb5ud4x         15  

It can be seen that we have 4 versions of insert statements after literals are replaced by system-generated bind varialbes. For each version, the execution times equal to the number of its child cursors. It indicates for every insert, Oracle actually does hard parse with extra cost to search child cursors.


When using Dion's script to query v$sql_shared_cursor, I can see the reason for unshared cursor is "HASH_MATCH_FAILED"




--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 0000000093C96F80
CHILD_NUMBER = 68
HASH_MATCH_FAILED = Y
--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 00000000AB5E4300
CHILD_NUMBER = 69
HASH_MATCH_FAILED = Y
--------------------------------------------------
SQL_TEXT = insert into MY_STB_LOG2 values(:"SYS_B_00",:"SYS_B_01",CURRENT_TIMESTAMP,timestamp:"SYS
_B_02",timestamp:"SYS_B_03",:"SYS_B_04",:"SYS_B_05",:"SYS_B_06",:"SYS_B_07",:"SYS_B_08",:"SYS_B_09",:"SYS_B_10",SYSDATE)
SQL_ID = 16yq35g1c433b
ADDRESS = 0000000113DCCE88
CHILD_ADDRESS = 000000013C695090
CHILD_NUMBER = 70
HASH_MATCH_FAILED = Y
--------------------------------------------------



It should be noted that even application using the bind varialbe, this problem could occur. One possible solution is to use PL/SQL procedure to do the insert:


Test case 2

I create a procedure STB_INS (see appendix) to insert into a table called MY_STB_LOG3 ( same structure as LOG2), then I run 324 exec procedure such as:
exec STB_INS('0001097562293114',
'VHO6_W07_MTR_30243_20110504094656__.101.Zip',
CURRENT_TIMESTAMP,timestamp'2011-05-05 01:30:01.000',
timestamp'2011-05-05 00:20:03.000',
timestamp'2011-05-04 23:42:57.000','N','N','','','','P',SYSDATE);
 
exec STB_INS('0000027988805135',
'VHO6_W07_MTR_30243_20110504094656__.101.Zip',
CURRENT_TIMESTAMP,timestamp'2011-05-05 01:46:21.000',
timestamp'2011-05-05 01:02:54.000',
timestamp'2011-05-04 22:55:10.000','N','N','','','','P',SYSDATE);
 

After run, check v$sqlarea and v$sql

  1. SQL>  select sql_id, sql_text, executions from v$sqlarea where sql_text like '%MY_STB_LOG3%';  
  2.   
  3. SQL_ID  
  4. -------------  
  5. SQL_TEXT  
  6. ------------------------------------------------------------------------------------------------------------------------  
  7. EXECUTIONS  
  8. ----------  
  9. 4fdv39rhjag5n  
  10. INSERT INTO MY_STB_LOG3 VALUES( :B13 ,:B12 ,:B11 ,:B10 ,:B9 ,:B8 ,:B7 ,:B6 ,:B5 ,:B4 ,:B3 ,:B2 ,:B1 )  
  11.        324  
  12.   
  13.   
  14.   
  15. SQL> select count(*) from v$sql where sql_id='4fdv39rhjag5n';  
  16.   
  17.   COUNT(*)  
  18. ----------  
  19.          1  


We see 324 executions shared same cursor.

Appendix

  1. create or replace procedure stb_ins(  
  2. p_UNIT_ADDRESS             VARCHAR2  
  3. ,p_BATCH_NUMBER            VARCHAR2  
  4. ,p_RECEIVED_TIME           TIMESTAMP  
  5. ,p_LAST_LOG_TIME           TIMESTAMP  
  6. ,p_POWERON_TIME            TIMESTAMP  
  7. ,p_POWEROFF_TIME           TIMESTAMP  
  8. ,p_UNAVAILABLE_FLAG        VARCHAR2  
  9. ,p_UNSUBSCRIBE_FLAG        VARCHAR2  
  10. ,p_WORK_ID                 VARCHAR2  
  11. ,p_STATUS_CODE             VARCHAR2  
  12. ,p_STATUS_DESC             VARCHAR2  
  13. ,p_PROC_STATUS             VARCHAR2  
  14. ,p_CREATE_DATE             DATE  
  15. )   
  16. is  
  17. begin  
  18.   insert into my_stb_log3 values(  
  19.                p_UNIT_ADDRESS             
  20.                 ,p_BATCH_NUMBER            
  21.                 ,p_RECEIVED_TIME           
  22.                 ,p_LAST_LOG_TIME           
  23.                 ,p_POWERON_TIME            
  24.                 ,p_POWEROFF_TIME           
  25.                 ,p_UNAVAILABLE_FLAG        
  26.                 ,p_UNSUBSCRIBE_FLAG        
  27.                 ,p_WORK_ID                 
  28.                 ,p_STATUS_CODE             
  29.                 ,p_STATUS_DESC             
  30.                 ,p_PROC_STATUS              
  31.                 ,p_CREATE_DATE              
  32.   );  
  33.   commit;  
  34. end;  
  35. /