8 Replies Latest reply: Nov 9, 2012 8:05 AM by Chrisjenkins-Oracle RSS

    Timesten Table Locking - ttxactadmin

    856103
      Hi,

      Point number 1.
      Trace file output
      15:42:41.961   10667 SQL      2L   13C   7866P Preparing: {CALL ttOptSetFlag('RowLock', 0)}
      15:42:41.961   10668 SQL      3L   13C   7866P Executing: {CALL ttOptSetFlag('RowLock', 0)}
      15:42:41.961   10669 SQL      2L   13C   7866P Preparing: {CALL ttOptSetFlag('TblLock', 1)}
      15:42:41.961   10670 SQL      3L   13C   7866P Executing: {CALL ttOptSetFlag('TblLock', 1)}
      15:44:11.013  246101 SQL      3L    1C  23864P Opening: SELECT SMST_SHORT_SELL_FLG, NVL(SM.SMST_INTRADAY_ALLWED_FLG, 'N'), NVL(SM.SMST_MAR_ALLOWD_FLG, 'N'), NVL(SM.SMST_T2_ALLOW_FLG, 'N'), NVL(SM.SMST_COVER_ALLOW_FLG, 'N'), DECODE(:B3 , :B2 , NVL(SM.SMST_RCBM_BASKET_ID, 'NO_BKT'), NVL(SMST_EBM_BASKET_ID, 'NO_BKT')), SM.SMST_ISIN_CODE, SM.SMST_OPEN_POSITION, SM.SMST_EXPOSURE_LIMIT FROM SECURITY_MASTER SM WHERE SMST_SECURITY_ID = :B1 
      15:44:11.013  246102 SQL      3L   10C   8041P Executing: update ttrep.reppeers set sendlsnhigh = :h, sendlsnlow = :l, reptableslsnhigh = :rh, reptableslsnlow = :rl, commit_timestamp = :ct, commit_seqnum = :cs, timesend = :t where replication_name = :rname and replication_owner = :rowner and tt_store_id   = :mid and subscriber_id = :sid 
      15:44:11.013  246103 SQL      3L    1C  23864P execEnvGet: Allocated new env 8412790936 due to size reqd, nr=52, sdsz=34343
      15:44:11.013  246104 SQL      3L    1C  23864P Opening: SELECT NVL(SUM(TONE_CURR_TRADE_QTY),0), NVL(SUM(TONE_BUY_ORD_QTY),0), NVL(SUM(TONE_SELL_ORD_QTY),0) FROM TRADE_ORD_NET_EXPOSURE WHERE TONE_ENTITY_ID = :B6 AND TONE_SECURITY_ID = :B5 AND TONE_EXCH_ID = :B4 AND TONE_ACC_TYPE = :B3 AND TONE_PRODUCT_ID = :B2 AND TONE_DATE = :B1 
      15:44:11.014  246105 SQL      3L   62C  23943P execEnvGet: Allocated new env 8413003648 due to size reqd, nr=47, sdsz=18633
      15:44:11.014  246106 SQL      3L   62C  23943P Opening: select nvl(RQ.RQ_ORDER_NO,0) ,nvl(RQ.RQ_ORD_SERIAL_NO,0) ,trim(RQ.RQ_BUY_SELL_IND) ,trim(RQ.RQ_CLIENT_ID) ,to_number(trim(RQ.RQ_USER_ID)) ,trim(RQ.RQ_ENTITY_ID) ,trim(RQ.RQ_SECURITY_ID) ,trim(RQ.RQ_EXCH_ID) ,RQ.RQ_SEQ_NO ,nvl(RQ.RQ_D2C1_FLAG,'Y') ,nvl(RQ.RQ_FI_RETAIL_FLG,'L') ,nvl(RQ.RQ_OIB_INT_REF_ID,0) ,RQ.RQ_SOURCE_FLAG ,RQ_SESSION_TYPE ,RQ_PRODUCT_ID ,RQ_GROUP_ID ,RQ_HANDL_INST ,RQ_SETTLEMENT_TYPE ,RQ_CLIENT_SUB_TYPE ,RQ_ALGO_OI_NUM into :b1,:b2,:b3,:b4,:b5,:b6,:b7,:b8,:b9,:b10,:b11,:b12,:b13,:b14,:b15,:b16,:b17,:b18,:b19,:b20  from REQUEST_QUEUE RQ where (((RQ.RQ_EXCH_ORDER_NO=:b21 and RQ
      15:44:11.014  246107 SQL      3L    1C  23864P Opening: SELECT RELD_LMT_FLG FROM RMS_ENTITY_LIMIT_DTLS WHERE RELD_EM_ENTITY_ID = :B2 AND RELD_SEGMENT_TYPE = 'C' AND RELD_EXM_EXCH_ID = 'ALL' AND RELD_ACC_TYPE = :B1 
      15:44:11.014  246108 SQL      3L    1C  23864P Opening: SELECT SEM_VAR_PERCENTAGE, SEM_EXCH_SPCL_MAR_PCT FROM SECURITY_EXCH_MAP S WHERE SEM_SMST_SECURITY_ID = :B2 AND SEM_EXM_EXCH_ID = :B1 AND SEM_STATUS = 'A' AND SEM_DERIVATIVE_FLG = 'N'
      15:44:11.014  246109 SQL      3L   62C  23943P Opening: select OS_SEQ_NO into :b1  from ORDER_SEQ where OS_ORDER_NO=:b2
      15:44:11.014  246110 SQL      3L    1C  23864P execEnvGet: Allocated new env 8412793368 due to size reqd, nr=108, sdsz=2400
      15:44:11.014  246111 SQL      3L    1C  23864P Opening: SELECT SUM(NVL(TONE_TOT_NET_EXP, 0)), SUM(NVL(TONE_CURR_NET_EXP, 0)), SUM(NVL(TONE_BUY_ORD_QTY, 0)), SUM(NVL(TONE_SELL_ORD_QTY, 0)), SUM(NVL(TONE_CURR_TRADE_QTY, 0)), MAX(TONE_MARGIN_PCT), SUM(TONE_BUY_ORD_VAL), SUM(TONE_SELL_ORD_VAL), SUM(T.TONE_AVG_TRANS_PRICE), SUM(TONE_AVG_CUM_BUY_AMT), SUM(TONE_AVG_CUM_SELL_AMT), SUM(TONE_BUY_EXPOSURE), SUM(TONE_SELL_EXPOSURE), SUM(TONE_CURR_TRADE_VAL), SUM(TONE_BOOKED_PROFIT) FROM TRADE_ORD_NET_EXPOSURE T WHERE TONE_ENTITY_ID = :B7 AND TONE_EXCH_ID = :B6 AND TONE_SECURITY_ID = :B5 AND TONE_TCURR = :B4 AND TONE_ACC_TYPE = :B3 AND TONE_PRODUCT_ID = :B2 AND
      15:44:11.014  246112 SQL      3L   62C  23943P execEnvGet: Allocated new env 8411217112 due to size reqd, nr=121, sdsz=5916
      15:44:11.014  246113 SQL      3L   62C  23943P Opening: select ORD_ORDER_NO ,ORD_SERIAL_NO ,LTRIM(RTRIM(ORD_SEM_SMST_SECURITY_ID)) ,ORD_BTM_EMM_MKT_TYPE ,ORD_EXCH_ID ,LTRIM(RTRIM(ORD_EPM_EM_ENTITY_ID)) ,nvl(ORD_EXCH_ORDER_NO,0) ,nvl(ORD_CLIENT_ID,'0') ,ORD_BUY_SELL_IND ,to_char(ORD_ENTRY_DATE,'DD-MM-YYYY HH24:MI:SS') ,to_char(ORD_ORDER_TIME,'DD-MM-YYYY HH24:MI:SS') ,to_char(ORD_ORIGINAL_TIME,'DD-MM-YYYY HH24:MI:SS') ,ORD_QTY_ORIGINAL ,ORD_ORDER_PRICE ,nvl(ORD_TRIGGER_PRICE,0) ,ORD_DISC_QTY_FLG ,to_char(ORD_GTC_FLG) ,to_char(ORD_DAY_FLG) ,to_char(ORD_IOC_FLG) ,to_char(ORD_MIN_FILL_FLG) ,to_char(nvl(ORD_MKT_FLG,0)) ,to_char(ORD_STOP_LOSS_FLG) ,to_cha
      15:44:11.014  246114 SQL      3L    1C  23864P Executing: UPDATE TRADE_ORD_NET_EXPOSURE SET TONE_BUY_ORD_QTY = TONE_BUY_ORD_QTY + :B17 , TONE_BUY_ORD_VAL = TONE_BUY_ORD_VAL + :B16 , TONE_SELL_ORD_QTY = TONE_SELL_ORD_QTY + :B15 , TONE_SELL_ORD_VAL = TONE_SELL_ORD_VAL + :B14 , TONE_CURR_NET_EXP = TONE_CURR_NET_EXP + :B13 , TONE_TOT_NET_EXP = TONE_TOT_NET_EXP + :B12 , TONE_TOT_BROKERAGE = TONE_TOT_BROKERAGE + :B11 , TONE_BUY_EXPOSURE = TONE_BUY_EXPOSURE + :B10 , TONE_SELL_EXPOSURE = TONE_SELL_EXPOSURE + :B9 WHERE TONE_ENTITY_ID = :B8 AND TONE_EXCH_ID = :B7 AND TONE_SECURITY_ID = :B6 AND TONE_TCURR = :B5 AND TONE_PRODUCT_ID = :B4 AND TONE_ACC_TYPE = :B3 
      15:44:11.014  246115 SQL      3L    1C  23864P execEnvGet: Allocated new env 8412792952 due to size reqd, nr=62, sdsz=1994
      15:44:11.014  246116 SQL      3L   10C   8041P Executing: update ttrep.reppeers set sendlsnhigh = :h, sendlsnlow = :l, reptableslsnhigh = :rh, reptableslsnlow = :rl, commit_timestamp = :ct, commit_seqnum = :cs, timesend = :t where replication_name = :rname and replication_owner = :rowner and tt_store_id   = :mid and subscriber_id = :sid 
      15:44:11.014  246117 SQL      3L    1C  23864P Executing: UPDATE RMS_ENTITY_LIMIT_DTLS R SET RELD_RTO_EXP = NVL(RELD_RTO_EXP, 0) + :B12 , RELD_NE_EXP = NVL(RELD_NE_EXP, 0) + :B11 , RELD_MAR_UTILIZATION = NVL(RELD_MAR_UTILIZATION, 0) + :B5 , RELD_BROKERAGE_AMT = NVL(RELD_BROKERAGE_AMT, 0) + :B10 , RELD_BUY_EXP = R.RELD_BUY_EXP + :B9 , RELD_SELL_EXP = R.RELD_SELL_EXP + :B8 , RELD_EMARGIN_UTILIZATION = RELD_EMARGIN_UTILIZATION + DECODE(:B7 , :B6 , :B5 , 0) WHERE RELD_EM_ENTITY_ID = :B4 AND R.RELD_EXM_EXCH_ID = :B3 AND R.RELD_SEGMENT_TYPE = 'E' AND R.RELD_ACC_TYPE = :B2 AND R.RELD_PROCESS_ID = :B1 
      15:44:11.014  246118 SQL      3L    1C  23864P execEnvGet: Allocated new env 8412793496 due to size reqd, nr=54, sdsz=2524
      This content is displayed in my trace file

      and o/p of ttxactadmin is
      Program File Name: EquNseParent1
      
      30486   0x139202b0           54.7002   Active      Database  0x01312d0001312d00   IX    0
                                                         Command   8416780720           S     8416780720
                                                         Row       BMUFVUAAAC2BwAALDe   Xn    8416776768           DAIWAPRODV7.RMS_ENTITY_LIMIT_DTLS
                                                         Row       BMUFVUAAABGEAAABgz   Xn    8416766544           DAIWAPRODV7.RMS_ENTITY_LIMIT_DTLS
                                                         Table     12144968             IXn   8416766544           DAIWAPRODV7.RMS_ENTITY_LIMIT_DTLS
                                                         Row       BMUFVUAAABPEAAAFhL   Xn    8416493904           DAIWAPRODV7.TRADE_ORD_NET_EXPOSURE
                                                         Table     719136               IXn   8416493904           DAIWAPRODV7.TRADE_ORD_NET_EXPOSURE
                                                         Row       BMUFVUAAACoFAAAIBt   Xn    8413989000           DAIWAPRODV7.RMS_SOD_EOD_LOG
                                                         Table     721136               IXn   8413989000           DAIWAPRODV7.RMS_SOD_EOD_LOG
                                                         Command   8419805088           S     8419805088
                                                         Command   8419800256           S     8419800256
                                                         Command   8419759480           S     8419759480
                                                         Command   8412801112           S     8412801112
                                 13 locks found for transaction 54.7002
      As per my understanding of this " Table 12144968 IXn 8416766544" lock is that there is a table lock.

      So we tried setting as per http://docs.oracle.com/cd/E11882_01/timesten.112/e21643/proced.htm#TTREF271

      CALL ttOptSetFlag('RowLock', 1)
      CALL ttOptSetFlag('TblLock', 0)

      but result is still the same.
      22878 0x9555770 151.643 Active Database 0x01312d0001312d00 IX 0
      Row BMUFVUAAAAOJQAAJD2 Xn 6306707440 VSEVEN.RMS_ENTITY_LIMIT_DTLS
      Table 12827064 IXn 6306707440 VSEVEN.RMS_ENTITY_LIMIT_DTLS
      Row BMUFVUAAABbKwAAIDO Xn 6306693872 VSEVEN.TRADE_ORD_NET_EXPOSURE
      Table 719232 IXn 6306693872 VSEVEN.TRADE_ORD_NET_EXPOSURE
      Row BMUFVUAAABqBgAAGj1 Xn 6306573400 VSEVEN.RMS_SOD_EOD_LOG
      Table 12826952 IXn 6306573400 VSEVEN.RMS_SOD_EOD_LOG
      We are facing locking issues degrading our performance. What does ttoptesetflag('TblLock', 1) and ttoptesetflag('TblLock', 0) implies and why is it showing table level locks

      Point number 2.
      Also we run the procedure from backend it takes 1 ms for complete process, where as same when called from proc is taking more than 160 ms

      Point number 3.
      Also as seen in trace file there is frequent statement
      "23864P execEnvGet: Allocated new env 8412790936 due to size reqd, nr=52, sdsz=34343"
      what does it imply..?

      Regards,
      Yogita
        • 1. Re: Timesten Table Locking - ttxactadmin
          Chrisjenkins-Oracle
          An IX (or IXn) lock is a weak lock that simply means that something is currently accessing that object. It does not block anyone else from accessing it; it is simply used to e.g. prevent an object being dropped while it is being accessed by something. These locks have no impact on performance or concurrency. What evidence makes you believe that you have a locking issue? Does ttXactAdmin ever show transactions waiting for locks? Are SYS.MONITOR.LOCK_TIMEOUTS or SYS.MONITOR.DEADLOCKS large and increasing rapidly? Is SYS.MONITOR.LOCK_GRANTS_WAIT a large fraction of SYS.MONITOR.LOCK_GRANTS_IMMED? Unless one or more of these is true you do not have a locking problem.

          The execEnvGet trace item is normal and is not a cause for concern. It is just tracking some internal memory allocation.

          The table and row lock hints suggest to the optimsier that it should use table or row level locking for statement execution. Note that (a) in general you do not need to use these hints (they will have no effect on the IX/IXn locks, bit those locks are not a problem anyway). Hints take effect at PREPARE time not execute time and have to be set in the same transaction as the PREPARE call (so if you have autocommit enabled, which is the default, hints will never have any effect).

          You said:

          +Also we run the procedure from backend it takes 1 ms for complete process, where as same when called from proc is taking more than 160 ms+

          What exactly constitutes the 'procedure' here? And how exactly are you 'running it on the backend'?

          Chris
          • 2. Re: Timesten Table Locking - ttxactadmin
            856103
            Dear Chris,

            The description of 'backend' and 'proc' sought by you is as follows.

            The main PLSQL package which is called on timesten by our Order Routing system(ORS) to perform Business level checks and update the various tables is PK_RMS_INTEGRATED_MAIN. We did a benchmark wherein order placement was simulated from a dealer terminal (ie pro C code was used to call the package). After the benchmark, it was found that The processing in PK_RMS_INTEGRATED_MAIN alone required 160-170 milliseconds (ms) per order.

            We then tested the procedure from the backend .ie (We executed the procedure in a loop 1000 times from the sql developer window) It was found that the initial call took about 40 ms and later towards the end the time required to execute the procedure reduced to about 1 ms per order.

            After doing some reading , what we understood is that when a query is executed multiple times , Timesten caches/prepares in advance the query so that the subsequent executions take less time (this is evident from the second case).

            Oracle documentation : http://docs.oracle.com/cd/E11882_01/timesten.112/e21633/perform.htm#CACBAGDC search *'Avoid unnecessary prepare operations'* clearly indicates that prepare operation is an expensive operation.

            We execute a fixed set of queries for both order and trade paths of the INTEGRATED MAIN package. Can we infer that if we somehow manage to pre-prepare/ cache the queries in advance the problem can be solved , also the procedure takes less time to execute (case 1) when called from a single parent session (around 25 ms) but when the number of sessions are increased the time rises upto 160-170 ms.

            I read in another document http://www-css.fnal.gov/dsg/external/oracle_dcm/v11.2.0.2/timesten.112/e13065/ttisql.htm search *'Working with prepared and parameterized SQL statements'* that ttiSql utility can be used to pre prepare several sql statements in the start of continuous sessions (Parents are continuous )

            Can we in some way pre prepare the sql statements present INSIDE my package. (the where clauses - parameters will differ every time )

            Also the log sql trace log (level 4 ttTraceMon) shows a lot of durable commits . we believe this too affects the performance.

            This was called by looping
            16:57:10.697 109129 SQL 3L 3C 5061P execEnvGet: Allocated new env 6304496528 due to size reqd, nr=291, sdsz=6768
            16:57:10.697 109130 SQL 3L 3C 5061P Opening: SELECT HIR_NO, ENTITY_ID, EXCH_ID, REASON_EXCH, REASON_SEGMENT, RTO_VIOLATION_AMT, RELD_RTO_LMT_FLG, NE_VIOLATION_AMT, RELD_MAR_NE_LMT_FLG, MAR_VIOLATION_AMT, RELD_LMT_VAL, MAR_MARGIN_EXP, M2M_EXP, CNC_UTILIZATION, RELD_COLL_LIMIT, RELD_MAR_DRV_CASH_RECVBL, EQ_CASH_SALES_PROCEED, DRV_EXP, EQU_EXP, RELD_MAR_VM_ADDN_MARGIN, NBP_OPTBUY, EMARGIN_UTILIZATION, MF_UTILIZATION, RELD_LMT_FLG, BUY_VIOLATION, SELL_VIOLATION FROM (SELECT DECODE(RELD_EM_ENTITY_ID, :B5 , 1, :B4 , 2, 3) HIR_NO, RELD_EM_ENTITY_ID ENTITY_ID, RELD_EXM_EXCH_ID EXCH_ID, 'SE' REASON_EXCH, 'S' REASON_SEGMENT, (RELD_RTO_LMT_VAL - RE
            16:57:10.698 109131 SQL 4L 3C 5061P Fetching: SELECT HIR_NO, ENTITY_ID, EXCH_ID, REASON_EXCH, REASON_SEGMENT, RTO_VIOLATION_AMT, RELD_RTO_LMT_FLG, NE_VIOLATION_AMT, RELD_MAR_NE_LMT_FLG, MAR_VIOLATION_AMT, RELD_LMT_VAL, MAR_MARGIN_EXP, M2M_EXP, CNC_UTILIZATION, RELD_COLL_LIMIT, RELD_MAR_DRV_CASH_RECVBL, EQ_CASH_SALES_PROCEED, DRV_EXP, EQU_EXP, RELD_MAR_VM_ADDN_MARGIN, NBP_OPTBUY, EMARGIN_UTILIZATION, MF_UTILIZATION, RELD_LMT_FLG, BUY_VIOLATION, SELL_VIOLATION FROM (SELECT DECODE(RELD_EM_ENTITY_ID, :B5 , 1, :B4 , 2, 3) HIR_NO, RELD_EM_ENTITY_ID ENTITY_ID, RELD_EXM_EXCH_ID EXCH_ID, 'SE' REASON_EXCH, 'S' REASON_SEGMENT, (RELD_RTO_LMT_VAL - RE
            16:57:10.698 109132 SQL 4L 3C 5061P Fetching: SELECT HIR_NO, ENTITY_ID, EXCH_ID, REASON_EXCH, REASON_SEGMENT, RTO_VIOLATION_AMT, RELD_RTO_LMT_FLG, NE_VIOLATION_AMT, RELD_MAR_NE_LMT_FLG, MAR_VIOLATION_AMT, RELD_LMT_VAL, MAR_MARGIN_EXP, M2M_EXP, CNC_UTILIZATION, RELD_COLL_LIMIT, RELD_MAR_DRV_CASH_RECVBL, EQ_CASH_SALES_PROCEED, DRV_EXP, EQU_EXP, RELD_MAR_VM_ADDN_MARGIN, NBP_OPTBUY, EMARGIN_UTILIZATION, MF_UTILIZATION, RELD_LMT_FLG, BUY_VIOLATION, SELL_VIOLATION FROM (SELECT DECODE(RELD_EM_ENTITY_ID, :B5 , 1, :B4 , 2, 3) HIR_NO, RELD_EM_ENTITY_ID ENTITY_ID, RELD_EXM_EXCH_ID EXCH_ID, 'SE' REASON_EXCH, 'S' REASON_SEGMENT, (RELD_RTO_LMT_VAL - RE
            16:57:10.698 109133 SQL 4L 3C 5061P Closing: SELECT HIR_NO, ENTITY_ID,


            This was called through the proc code

            17:23:56.412 1635386 SQL 3L 75C 19655P execEnvGet: Allocated new env 8415295976 due to size reqd, nr=336, sdsz=6816
            17:23:56.412 1635387 SQL 3L 75C 19655P Opening: SELECT HIR_NO, ENTITY_ID, EXCH_ID, REASON_EXCH, REASON_SEGMENT, RTO_VIOLATION_AMT, RELD_RTO_LMT_FLG, NE_VIOLATION_AMT, RELD_MAR_NE_LMT_FLG, MAR_VIOLATION_AMT, RELD_LMT_VAL, MAR_MARGIN_EXP, M2M_EXP, CNC_UTILIZATION, RELD_COLL_LIMIT, RELD_MAR_DRV_CASH_RECVBL, EQ_CASH_SALES_PROCEED, DRV_EXP, EQU_EXP, RELD_MAR_VM_ADDN_MARGIN, NBP_OPTBUY, EMARGIN_UTILIZATION, MF_UTILIZATION, RELD_LMT_FLG, BUY_VIOLATION, SELL_VIOLATION FROM (SELECT DECODE(RELD_EM_ENTITY_ID, :B6 , 1, :B5 , 2, 3) HIR_NO, RELD_EM_ENTITY_ID ENTITY_ID, RELD_EXM_EXCH_ID EXCH_ID, 'SE' REASON_EXCH, 'S' REASON_SEGMENT, (RELD_RTO_LMT_VAL - RE
            17:23:56.423 1635388 SQL 3L 75C 19655P Opening: select (ord_seq.nextval +:b1) into :b2 from DUAL




            as you can see the select hir.... qry took 11 ms in proc 1 ms when called from loop

            I will share the trace files if required

            Kindly assist us regarding the behavior demonstrated above.


            regards
            Abhishek Roy Bardhan.
            • 3. Re: Timesten Table Locking - ttxactadmin
              Chrisjenkins-Oracle
              Hi,

              SQL within a PL/SQL procedure/function which is not being executed using EXECUTE IMMEDIATE is prepared the first time the procedure/function is executed. If the SQL statement is already in the TimesTen SQL command cache then this will be a 'soft parse' otherwise it will be a 'hard parse'. While a PL/SQL procedure is running (i.e. after it has called and before it has returned) it will keep handles to any statements it has prepared and subsequent executions within the same call will not require any kind of re-prepare. Once the procedure or function has returned hese handles are closed and a subsequent call to the procedure will re-prepare the statements that get executed. If these statemetns are still in the TimesTen SQL command cache then these will be soft parses otherwise they will be hard parses. By default, the SQL command cache is shared across all connections (except any which have specified PrivateCommands=1).

              This behaviour is the same as it is in Oracle DB PL/SQL. There is no facility for explicit statement preparation in PL/SQL. You can of course 'prime' the SQL command cache by explicitly preparing identical statements (and they have to be exactly identical) from application code or a script. Or by executing a PL/SQL procedure that executes (exactly) the same statements.

              Are you able to share the following information?

              1. Exact version of TimesTen being used (output of the ttVersion command).

              2. The full set of DSN attributes used for the datastore.

              3. Whether the Pro*C program is connecting in direct mode or client/server (the TNS entry that you use would show this) and if it is running on the same machine as TimesTen or a different machine

              4. An example of how you call the procedure from the Pro*C program

              Thanks,

              Chris
              • 4. Re: Timesten Table Locking - ttxactadmin
                Chrisjenkins-Oracle
                Correction. After more investigation I find that handles for prepared statements are cached in the top level PL/SQL execution context (i.e. the connection) so in fact once a SQL statement within a PL/SQL procedure has been executed once on a connection it will not need to be reprepared on that connection regardless of when/how it gets executed. And once it has been executed once on any connection it will be in the command cache and the first execution on a different connection will be a soft parse.

                I think we need to see the big picture to better I understand the reason for the difference in performance. The segments of trace provided don't really reveal anything that helpful.

                As for durable commits; they are opf coirse hugely more expensive than non-durable commits and they will certainly affect performance if they are occurring in the context of the application's connection. But there are many things in TimesTen that do durable commits and many of them are nothing to do with the application (e.g. replication agent, cache agent, log flusher) and thsoe won't have any significant effect on application performance. So without knowing what is doing them it is hard to say.

                If you can provide the info I asked for in my previous post then we may be able to get some idea of what is goign on.

                Chris
                • 5. Re: Timesten Table Locking - ttxactadmin
                  856103
                  Hi,


                  Kindly find the parameters


                  1. Exact version of TimesTen being used (output of the ttVersion command).

                  TimesTen Release 11.2.1.8.0 (64 bit Linux/x86_64) (matrix:53385) 2011-02-02T02:20:46Z
                  Instance admin: matrix
                  Instance home directory: /application/matrix/TimesTen/matrix
                  Group owner: dba
                  Daemon home directory: /application/matrix/TimesTen/matrix/info
                  PL/SQL enabled.


                  2. The full set of DSN attributes used for the datastore.
                  [DAIWAPRODV7_DSN]
                  Driver=/application/matrix/TimesTen/matrix/lib/libtten.so
                  DataStore=/application/matrix/TimesTen/DAIWAPRODV7_DSN_datastore/DAIWAPRODV7_DSN_DS_DIR
                  LogDir=/logs_timeten/DAIWAPRODV7_DSN_logdir
                  PermSize=8000
                  TempSize=250
                  PLSQL=1
                  DatabaseCharacterSet=WE8MSWIN1252
                  OracleNetServiceName=fodbprod
                  Connections=500
                  PassThrough=0
                  SQLQueryTimeout=250
                  LogBufMB=512
                  LogFileSize=512
                  LogPurge=1

                  3. Whether the Pro*C program is connecting in direct mode or client/server (the TNS entry that you use would show this) and if it is running on the same machine as TimesTen or a different machine
                  Direct Mode
                  FODBPROD_TT =
                  (DESCRIPTION =
                  (CONNECT_DATA =
                  (SERVICE_NAME = DAIWAPRODV7_DSN)
                  (SERVER = timesten_direct)
                  )
                  )


                  4. An example of how you call the procedure from the Pro*C program
                  EXEC SQL AT :db_conn EXECUTE
                  BEGIN
                  PK_RMS_INTEGRATED_MAIN.PR_RMS_ORDER_MAIN (
                  rtrim(ltrim(:TempEntityId)),
                  rtrim(ltrim(:TempClientFamilyId)),
                  rtrim(ltrim(:TempEntityType)),
                  :TempClientAccType,
                  :TempSettType,
                  rtrim(ltrim(:TempAccCode)),
                  rtrim(ltrim(:TempClientProdPriv)),
                  rtrim(ltrim(:TempClientId)),
                  rtrim(ltrim(:TempClientProfileId)),
                  :TempClientStatus,
                  rtrim(ltrim(:D2C1ControllerId)),
                  rtrim(ltrim(:TempDealerProfileId)),
                  :TempDealerStatus,
                  rtrim(ltrim(:TempBranchId)),
                  rtrim(ltrim(:TempBranchProfileId)),
                  :TempBranchStatus,
                  rtrim(ltrim(:TempBrokerId)),
                  rtrim(ltrim(:TempBrokerProfileId)),
                  :TempBrokerStatus,
                  :RMS_Deact_Entity,
                  :RMS_Status,
                  :RMS_Reason_Id,
                  :TempOrderNo,
                  :TempSerialNo,
                  rtrim(ltrim(:TempExchId)),
                  :TempQtyRemaining,
                  :TempPrice,
                  :TempPrice_Mrg,
                  :old_ord_qty_remaining,
                  :old_price,
                  :Transcode,
                  rtrim(ltrim(:TempBuyOrSell)),
                  rtrim(ltrim(:TempSecurityId)),
                  :SeriesInd,
                  rtrim(ltrim(:TempMktType)),
                  :off_on_order,
                  'F001',
                  rtrim(ltrim(:TempUserId)),
                  :TempProductId,
                  :TempSourceFlag,
                  :BasketOrderNumber,
                  :TempSeqNo,
                  :TempSeqNo_Mrg,
                  :msg_count,
                  :TempUserIdString,
                  :TempUsrMesgString,
                  :RetCode,
                  :RetString
                  );
                  END;
                  END-EXEC;




                  regards,
                  Abhishek Roy bardhan
                  • 6. Re: Timesten Table Locking - ttxactadmin
                    Chrisjenkins-Oracle
                    There is nothing untoward in the DSN settings other than the absence of MemoryLock=4. For a database of this size you really should use either MemoryLock=4 or (better still) LargePages. Running with unlocked memory can result in unpredictable performance due to system level paging.

                    I was hoping to see more of the Pro*C code - such as how you are timing the execution and where the timing points are. Please do not use TimesTen tracing for timing operations; it is not intended for that purpose and the very act of tracing also affects performance and timing. If you wish to accurately time operations you need to (a) instrument your code to do so and (b) be sure to average the timing over a reasonable number of iterations (such that the total time measures is many seconds) in order to eliminate the many sources of error that can otherwise affect the timing. Also, be sure to eliminate any 'initial prepare' cost from timing runs as this will also distort the results. Note that as well as the internal PL/SQL prepare cost there is also the Pro*C prepare cost when the procedure call is first executed from Pro*C.

                    I note that there are significant differences in the two trace segments you provided; the one that you say comes from the Pro*C execution does not show any fetches or closing of the SELECT statement so obviously something quite different is occurring for that case versus the first trace. On that basis it seems unreasonable to try and compare the timings.

                    Chris

                    Edited by: ChrisJenkins on Nov 6, 2012 1:58 PM
                    • 7. Re: Timesten Table Locking - ttxactadmin
                      856103
                      Hi Chris,

                      Sorry for the delay.. The Pro*C code snippet is :
                      logTimestamp("BEFORE PK_RMS_INTEGRATED_MAIN.PR_RMS_ORDER_MAIN");
                              logDebug3("TESTIN db_conn value: %s", db_conn.arr);
                      
                              EXEC SQL AT :db_conn EXECUTE
                                      BEGIN
                                              PK_RMS_INTEGRATED_MAIN.PR_RMS_ORDER_MAIN (
                      
                                              rtrim(ltrim(:TempEntityId)),
                                              rtrim(ltrim(:TempClientFamilyId)),
                                              rtrim(ltrim(:TempEntityType)),
                                              :TempClientAccType,
                                              :TempSettType,
                                              rtrim(ltrim(:TempAccCode)),
                                              rtrim(ltrim(:TempClientProdPriv)),
                                              rtrim(ltrim(:TempClientId)),
                                              rtrim(ltrim(:TempClientProfileId)),
                                              :TempClientStatus,
                                              rtrim(ltrim(:D2C1ControllerId)),
                                              rtrim(ltrim(:TempDealerProfileId)),
                                              :TempDealerStatus,
                                              rtrim(ltrim(:TempBranchId)),
                                              rtrim(ltrim(:TempBranchProfileId)),
                                              :TempBranchStatus,
                                 rtrim(ltrim(:TempBranchId)),
                                              rtrim(ltrim(:TempBranchProfileId)),
                                              :TempBranchStatus,
                                              rtrim(ltrim(:TempBrokerId)),
                                              rtrim(ltrim(:TempBrokerProfileId)),
                                              :TempBrokerStatus,
                                              :RMS_Deact_Entity,
                                              :RMS_Status,
                                              :RMS_Reason_Id,
                                              :TempOrderNo,
                                              :TempSerialNo,
                                              rtrim(ltrim(:TempExchId)),
                                              :TempQtyRemaining,
                                              :TempPrice,
                                              :TempPrice_Mrg,
                                              :old_ord_qty_remaining,
                                              :old_price,
                                              :Transcode,
                                              rtrim(ltrim(:TempBuyOrSell)),
                                              rtrim(ltrim(:TempSecurityId)),
                                              :SeriesInd,
                                              rtrim(ltrim(:TempMktType)),
                                              :off_on_order,
                                              'F001',
                                              rtrim(ltrim(:TempUserId)),
                                              :TempProductId,
                                              :TempSourceFlag,
                                              :BasketOrderNumber,
                                              :TempSeqNo,
                                              :TempSeqNo_Mrg,
                                              :msg_count,
                                              :TempUserIdString,
                                              :TempUsrMesgString,
                                              :RetCode,
                                              :RetString
                                              );
                                      END;
                              END-EXEC;
                      logTimestamp("AFTER PK_RMS_INTEGRATED_MAIN.PR_RMS_ORDER_MAIN");
                      
                            if(sqlca.sqlcode !=0)
                              {
                                      printf("\n 1. Error in execution RMS_MAIN   : %d",sqlca.sqlcode );
                                      printf("\n ERROR :%s\n",sqlca.sqlerrm.sqlerrmc) ;
                                      /**Added for user friendly_RMS Message for version 3.3***/
                                      printf("\n Error is %s : %d",errstr,sqlca.sqlcode);
                                      /**Added for user friendly_RMS Message for version 3.3***/
                                      sprintf(p_req_out->ind_str[0],RMS_ERROR);
                                      EXEC SQL ROLLBACK;               /* ganesh */
                                      p_req_out->user_id[0]=p_req->IntReqHeader.UserIdOrLogPktId ;
                                      p_req_out->tot_num_user=1;
                                      logDebug3("User Id:%d,Tot Num Of User:%d",p_req_out->user_id[0],p_req_out->tot_num_user) ;
                                      return (FALSE);
                              }
                      logTimestamp function is defined as
                      void
                      logTimestamp (const char *fmt, ...)
                      {
                              va_list ap;
                      
                              va_start(ap, fmt);
                          CHAR buffer[LOG_TIMESTAMP_LENGTH];
                              CHAR chktime[DATE_LEN];
                          static CHAR message[LOG_BUFFER_LENGTH];
                              struct timeval tv;
                              time_t curtime;
                              gettimeofday(&tv, NULL);
                              curtime=tv.tv_sec;
                      
                             strftime(chktime, DATE_LEN, "%d:%m:%Y", localtime(&curtime));
                              if ( strcmp(chktime,logTime))
                              {
                                      logLevelSet = 0;
                              }
                              strftime(buffer, LOG_TIMESTAMP_LENGTH, "%d:%m:%Y %T", localtime(&curtime));
                              vsprintf(message, fmt, ap);
                          fprintf(stdout, "%s.%06ld: %s\n", buffer, tv.tv_usec, message);
                              va_end(ap);
                          return;
                      }
                      Can you point us towards some documentation towards the impact of using memorylock=4 for linux ?

                      Regards,
                      Karan
                      • 8. Re: Timesten Table Locking - ttxactadmin
                        Chrisjenkins-Oracle
                        Thanks. Not sure what you mean by 'the impact' of using MemoryLock=4...

                        Without memoryLock, the shared memory segment that is the TimesTen database is treated as regular memory by the kernel and the VMM and pages can be stolen as and when it sees fit (contents written to disk, memory assigned to a different process/usage) . The next time that page is them referenced it must be paged back in (free page found and allocated, possibly requiring a forced page-out, old page contents read in from disk). Even in a system that is not under memory pressure it is quite likely that less often referenced pages will be paged out. This is highly undersirable if one is looking for the highest and most consistent performance.

                        Using memoryLock=4 tells the kernel to lock the shared memory segment into RAM. None of the pages in the segment is then eligible for paging. You are effectively dedicating that RAM to the datastore while it is up and running. If you configure the Linux kernel to use huge pages and tell TimesTen to use them further performance benefits can be realised due to much lower TLB overhead. Large p[age memory is implicitly locked and so MemoryLock is not needed (but is harmless) in that case.

                        Chris