Skip to Main Content
  • Questions
  • Stored Procedure behaves randomly - sometimes takes 15 minutes where it should take 15 milli-seconds.

Breadcrumb

May 4th

Question and Answer

Connor McDonald

Thanks for the question, Khalid.

Asked: April 19, 2019 - 7:04 am UTC

Last updated: June 23, 2019 - 6:43 pm UTC

Version: 12c

Viewed 1000+ times

You Asked

We developed a procedure to be used in database-A and in database-A. In this procedure we send an input parameter on the basis of which a select statement searches the data from a table located in remote database-B. The selected columns are set in Output parameters of the stored procedure and that's all. There is some logging as well in the procedure where we log progress of parameter to a table from which no one is ready data. Every row is kind of unique in log table.

The remote database-B is synched using Golden gate from another database-C (oltp). So there are no chances of locking we believe.


Below is the stored procedure;



create or replace PROCEDURE prc_live_bvs_check_g2p_data_op (
                                                        /*
                                                         Procedure Purpose : To handle BVS issue due to patch. Returns MSISDN and CNIC of a G2P transaction.
                                                         Created by : Khalid Mehmood
                                                         Created date : 2019-Feb-12
                                                         Modified at : 2019-Apr-10 20:00 by Khalid
                                                         Created for : Saad Saif.
                                                        */
    in_trx_order_id               IN VARCHAR2,
    out_trx_order_id              OUT VARCHAR2,
    out_trx_receiver_cnic         OUT VARCHAR2,
    out_trx_receiver_msisdn       OUT VARCHAR2,
    out_trx_amount                OUT VARCHAR2,
    out_trx_payment_time          OUT VARCHAR2,
    out_trx_org_short_code        OUT VARCHAR2,
    out_trx_collecting_trans_id   OUT VARCHAR2,
    out_trx_collect_time          OUT VARCHAR2,
    out_trx_return_code           OUT VARCHAR2,
    out_prc_execution             OUT VARCHAR2
) IS

    v_temp           VARCHAR(32);
    v_success_flag   BOOLEAN := true;
    v_success        VARCHAR2(20);
    exp_tid_invalid EXCEPTION;
    exp_tid_length EXCEPTION;
    exp_tid_null EXCEPTION;
    v_tempstring     VARCHAR2(2000);
    v_sequence_id    NUMBER;
    v_in_trx_order_id varchar2 (50);
BEGIN
    
    v_in_trx_order_id := in_trx_order_id;

    SELECT
        mobilink.seq_mfs_cps_prc_logging.nextval
    INTO
        v_sequence_id
    FROM
        dual;

    prc_mfs_prc_log_output_v2('{Start}','MFS-BVS-G2P-PROC',v_in_trx_order_id,v_sequence_id,'Start');
    BEGIN
        IF
            v_in_trx_order_id IS NULL OR v_in_trx_order_id = ''
        THEN
            RAISE exp_tid_null;
        ELSIF length(v_in_trx_order_id) <> 12 THEN
            RAISE exp_tid_length;
        ELSIF v_in_trx_order_id IS NOT NULL THEN
      -- This to check if the input is numeric or not.
            SELECT
                to_number(v_in_trx_order_id)
            INTO
                v_temp
            FROM
                dual;

        END IF;

        SELECT
            order_id,
            receiver_cnic,
            nvl(receiver_msisdn,'') receiver_msisdn,
            amount / 100 amount,
            payment_time,
            g2porg_shortcode,
            collecting_trans_id,
            collect_time
        INTO
            out_trx_order_id,out_trx_receiver_cnic,out_trx_receiver_msisdn,out_trx_amount,out_trx_payment_time,out_trx_org_short_code,out_trx_collecting_trans_id
,out_trx_collect_time
        FROM
            lbi_ogg_mk.t_o_g2ppayment_record@cps_live_rpt_db
        WHERE
            order_id = v_in_trx_order_id;

        out_prc_execution := 'RESULT:0000: Completed Successfully.';
        out_trx_return_code := '0000';
  
    --        prc_mfs_prc_log_output_v2(out_prc_execution
    --        || ' :: '
    --        || out_trx_order_id
    --        || ' : '
    --        || out_trx_receiver_cnic
    --        || ' : '
    --        || out_trx_receiver_msisdn
    --        || ' : '
    --        || out_trx_amount
    --        || ' : '
    --        || out_trx_payment_time
    --        || ' : '
    --        || out_trx_org_short_code
    --        || ' : '
    --        || out_trx_collecting_trans_id
    --        || ' : '
    --        || out_trx_collect_time,'MFS-BVS-G2P-PROC',v_in_trx_order_id,v_sequence_id);
    EXCEPTION
        WHEN value_error THEN
            out_prc_execution := 'RESULT:1001: Invalid input parameter. should be numeric only.';
            v_success_flag := false;
            out_trx_return_code := '1001';
        WHEN no_data_found THEN
            out_prc_execution := 'RESULT:1002: No record found against this TID.';
            v_success_flag := false;
            out_trx_return_code := '1002';
        WHEN exp_tid_invalid THEN
            out_prc_execution := 'RESULT:1003: TID is invalid.';
            v_success_flag := false;
            out_trx_return_code := '1003';
        WHEN exp_tid_length THEN
            out_prc_execution := 'RESULT:1004: TID length is invalid. should be 12.';
            v_success_flag := false;
            out_trx_return_code := '1004';
        WHEN exp_tid_null THEN
            out_prc_execution := 'RESULT:1005: TID is null.';
            v_success_flag := false;
            out_trx_return_code := '1005';
        WHEN OTHERS THEN
            out_prc_execution := 'RESULT:2000: Unknown error occurred';
            v_success_flag := false;
            out_trx_return_code := '2000';
    END;

    IF
        v_success_flag = false
    THEN
        v_success := 'Failed';
        out_trx_receiver_cnic := NULL;
        out_trx_receiver_msisdn := NULL;
        out_trx_amount := NULL;
        out_trx_payment_time := NULL;
        out_trx_org_short_code := NULL;
        out_trx_collecting_trans_id := NULL;
        out_trx_collect_time := NULL;
    ELSE
        v_success := 'Success';
    END IF;

    v_tempstring := '{End..} TID: '
    || v_in_trx_order_id
    || ' : Out : Exception:  '
    || out_prc_execution
    || ' : CNIC: '
    || out_trx_receiver_cnic
    || ' : MSISDN: '
    || out_trx_receiver_msisdn
    || ' : ShortCode : '
    || out_trx_org_short_code
    || ' : Collect-TID : '
    || out_trx_collecting_trans_id
    || ' : Collect-Time : '
    || out_trx_collect_time
    || ' : Result Code : '
    || out_trx_return_code
    || ' : Success Flag: '
    || CASE v_success_flag
        WHEN true THEN 'true'
        WHEN false THEN 'false'
    END;

    prc_mfs_prc_log_output_v2(v_tempstring,'MFS-BVS-G2P-PROC',v_in_trx_order_id,v_sequence_id,v_success);
END;

and Connor said...

I would try this. Edit the procedure to enable a trace, ie

BEGIN
    dbms_monitor.session_trace_enable(waits=>true);
    
    v_in_trx_order_id := in_trx_order_id;
..
..
..

    prc_mfs_prc_log_output_v2(v_tempstring,'MFS-BVS-G2P-PROC',v_in_trx_order_id,v_sequence_id,v_success);
    dbms_monitor.session_trace_disable;
END;


and then wait for the next occurrence that takes longer than expected. Run tkprof on that trace file and see where the time was lost. This will let you hone in on precisely where the issue is.

Rating

  (6 ratings)

Is this answer out of date? If it is, please let us know via a Comment

Comments

Further Query

Khalid Mehmood, April 30, 2019 - 10:45 am UTC

and then wait for the next occurrence that takes longer than expected. Run tkprof on that trace file and see where the time was lost. This will let you hone in on precisely where the issue is. 


You mentioned some trace file here. Please note that this procedure is currently in production and issues appear only in Production environment.
1. Where will the trace file be made ?
2. Will the trace file be for every procedure call
3. How would i look for a trace file for particular procedure call / instance ?
Connor McDonald
May 02, 2019 - 6:45 am UTC

This should help


GH, May 02, 2019 - 6:43 pm UTC

First of all v_in_trx_order_id must be declared as a Number not varchar2. I assumed that the key of the target table is a number. Second how is defined this table? Is it large? Partitionned? Indexed?
I again suspect an index exists on the order Id.
Is this table intensive oltp dmled? Look also if so at the cost maintenance of such index cause index contention is possibly occurring..
Well with no more details on structures an objects I will get my crystal ball (or borrow Asktom ones)
You can at least provide the exec plan of the select made standalone in a separate qry...

v$diag_trace_file and v$diag_trace_file_contents

Rajeshwaran, Jeyabal, May 06, 2019 - 11:05 am UTC

with 12.2 database, the access to the tracefile got ev even simple with the two new v$ tables introduced.

we dont even need access to the servers.
if we get SELECT_CATALOG_ROLE granted, then we can get access to these v$tables.

no sure if the above question came from 12.2 database, if so they can make use of these views.

demo@PDB1> desc v$diag_trace_file
 Name                                                                    Null?    Type
 ----------------------------------------------------------------------- -------- ------------------------------
 ADR_HOME                                                                         VARCHAR2(444)
 TRACE_FILENAME                                                                   VARCHAR2(68)
 CHANGE_TIME                                                                      TIMESTAMP(3) WITH TIME ZONE
 MODIFY_TIME                                                                      TIMESTAMP(3) WITH TIME ZONE
 CON_ID                                                                           NUMBER

demo@PDB1> desc v$diag_trace_file_contents
 Name                                                                    Null?    Type
 ----------------------------------------------------------------------- -------- ------------------------------
 ADR_HOME                                                                         VARCHAR2(444)
 TRACE_FILENAME                                                                   VARCHAR2(68)
 RECORD_LEVEL                                                                     NUMBER
 PARENT_LEVEL                                                                     NUMBER
 RECORD_TYPE                                                                      NUMBER
 TIMESTAMP                                                                        TIMESTAMP(3) WITH TIME ZONE
 PAYLOAD                                                                          VARCHAR2(4000)
 SECTION_ID                                                                       NUMBER
 SECTION_NAME                                                                     VARCHAR2(64)
 COMPONENT_NAME                                                                   VARCHAR2(64)
 OPERATION_NAME                                                                   VARCHAR2(64)
 FILE_NAME                                                                        VARCHAR2(64)
 FUNCTION_NAME                                                                    VARCHAR2(64)
 LINE_NUMBER                                                                      NUMBER
 THREAD_ID                                                                        VARCHAR2(64)
 SESSION_ID                                                                       NUMBER
 SERIAL#                                                                          NUMBER
 CON_UID                                                                          NUMBER
 CONTAINER_NAME                                                                   VARCHAR2(30)
 CON_ID                                                                           NUMBER

Connor McDonald
May 06, 2019 - 4:34 pm UTC

Especially relevant for cloud.

relevant for cloud

Rajeshwaran, Jeyabal, May 07, 2019 - 3:33 am UTC

when you say "relevant for cloud" does that mean it don't work/need for On-premise.

we got that used for a couple of scenarios in our real project for on-premise databases too. Kindly advice.
Connor McDonald
May 13, 2019 - 3:24 am UTC

when you say "relevant for cloud" does that mean it don't work/need for On-premise.


No, just that on most cloud offerings you do not get OS level access, so getting access to the trace data relies on being able to query it from the database

How to View tkprof output in some tool so see user friend output

Khalid Mehmood, June 19, 2019 - 2:21 pm UTC

I managed to get an output of tkprof tool, however, is there any tool where i can see the output of the tool in some user friendly way ?
Connor McDonald
June 23, 2019 - 6:40 pm UTC

Depends on your definition of friendly :-)

You might want to check out this site

https://method-r.com/



Unable to View my Questions (e.g. This Questions) Under Office Hours >> My Questions Menu

Khalid Mehmood, June 19, 2019 - 2:27 pm UTC

Unable to View my Questions (e.g. This Questions) Under Office Hours >> My Questions Menu.

Nothing appears there. However, I can access this question only using a link that AskTom support sent me in my email. i.e.

https://asktom.oracle.com/pls/apex/asktom.search?tag=9540740000346091111
Connor McDonald
June 23, 2019 - 6:43 pm UTC

I should make that more intuitive - I'll look at that for a future AskTOM release.

You go here:

Questions => Advanced Search => Your Questions


More to Explore

Administration

Need more information on Administration? Check out the Administrators guide for the Oracle Database