12 Replies Latest reply: Mar 4, 2010 5:22 AM by ScoobySi RSS

    Process Flow - delay within flow during execution


      I have two process flows e.g. PF1 and PF1_1. PF1_1 is executed as a subprocess within PF1.

      On execution of PF1 the scheduled job runs the mappings up to the end of PF1_1 and then pauses for approx. 1 to 2 minutes for (what appears to be) no apparent reason. The mappings do not have analyze set and looking on the DB there is no activity related to the job.

      Can anyone help on the reason for the delay and how to avoid it?

      I've done a bit of digging on Scheduled Jobs and I'm wondering if it's something to do with the PRIOIRTY the job is given? At the moment the job has a priority of 3 or Medium in OEM i.e. the defaults.

      Any help much appreciated.

        • 1. Re: Process Flow - delay within flow during execution
          bump...anyone able to help?

          • 2. Re: Process Flow - delay within flow during execution
            did you check execution of your processflow via OWB public view (ALL_RT_AUDIT_EXECUTIONS) or workflow view (WF_ITEM_ACTIVITY_STATUSES)?
            If OWB/Workflow repositories reports finish time by 1-2 minutes earlier it means that delay produce scheduling tool.
            How did you chedule your processflow?

            • 3. Re: Process Flow - delay within flow during execution
              Hi Oleg

              I've been using all_rt_audit_map_runs.

              Basically the final mapping finishes in the sub process flow and the next mapping in the top process flow doesn't start for a couple of minutes, sometimes longer.

              The process flow was deployed and started through Control Center.

              • 4. Re: Process Flow - delay within flow during execution
                Can you identify last mapping in PF1_1 subprocess and first mapping after PF1_1 (I ask about this because you can design processflows with several flows and in this case it is harder identify sequence of mapping executions)?

                Then try to select from ALL_RT_AUDIT_EXECUTIONS info about three objects - last mapping in PF1_1, subprocess PF1_1 and first mapping after PF1_1

                select task_name,object_name,to_char(created_on,'yyyy/mm/dd hh24:mi:ss') start_time, elapse_time, to_char(created_on+elapse_time/3600/24,'yyyy/mm/dd hh24:mi:ss') end_time,top_execution_audit_id
                from ALL_RT_AUDIT_EXECUTIONS where object_name in ('MAP_LAST_PF1_1','PF1_1','MAP_FIRST_AFTER_PF1_1')
                order by created_on

                Compare start and finish time for last execution

                • 5. Re: Process Flow - delay within flow during execution
                  Thanks Oleg, within the sub process 3 mappings converge into an AND operator. Between the 3 mappings finishing (last one) and the AND operator starting there is a delay of 2 minutes. After the AND there is another delay of 1 minute until STD_SWITCH_TASK (presumabley a standard Workflow task) starts.


                  • 6. Re: Process Flow - delay within flow during execution
                    this delay may produce different components - OWB runtime, Workflow and Oracle database instace.
                    You should identify the source of this delay.
                    Try to execute SQL on workflow repository ( change <OWB processflow pkg name> to processflow package name from your OWB project,
                    and maybe correct processflow names PF1 and PF1_1)

                    select s.begin_date,s.end_date,s.item_key,s.item_type,pa.process_name,pa.activity_name,pa.activity_item_type
                    from owf_mgr.wf_item_activity_statuses s,owf_mgr.wf_process_activities pa
                    where pa.process_item_type=s.item_type and s.process_activity=pa.instance_id and s.item_type='<OWB processflow pkg name>'
                    and s.item_key in (
                    select s.item_key from owf_mgr.wf_item_activity_statuses s,owf_mgr.wf_process_activities pa
                    where pa.process_item_type=s.item_type and s.process_activity=pa.instance_id and s.item_type='<OWB processflow pkg name>'
                    and pa.activity_name in ('PF1','PF1_1') and pa.process_name='ROOT'
                    order by begin_date,end_date;

                    Please post SQL output for last run of your processflow here

                    • 7. Re: Process Flow - delay within flow during execution
                      Hi Oleg

                      PF1 and PF1_1 were just for my example, the actuals are PF_SS_CLEANSE_1 and PF_SS_AGENT.

                      Added Instance_Label and ordered by End Date Desc
                      23/12/2009 14:14:34     23/12/2009 14:14:34     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     END     END_SUCCESS     OWB_10G
                      23/12/2009 14:13:41     23/12/2009 14:14:34     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     A7A5D54FC0CECD7F5E04013AC2D287     PF_SS_EMAIL_SUCESS     LOAD_AD
                      23/12/2009 14:10:01     23/12/2009 14:14:34     WB_IK_20091223_141001_6227307     LOAD_AD     ROOT     PF_SS_AGENT     PF_SS_AGENT     LOAD_AD
                      23/12/2009 14:13:40     23/12/2009 14:13:41     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     A63D3B8BE1271F097E04013AC2D284     APPEND_DB_NAME_TO_TEXT_SUCCESS     LOAD_AD
                      23/12/2009 14:13:39     23/12/2009 14:13:40     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     A5A74F8CAE5156A24E04013AC2D287     GATHER_TABLE_GROUP_STATS     LOAD_AD
                      23/12/2009 14:13:15     23/12/2009 14:13:39     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     AND     AND_SUCCESS     OWB_10G
                      23/12/2009 14:13:14     23/12/2009 14:13:15     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     A74628F90794268C4E04013AC2D283     UPD_D_AGENT_CURR_ROW     LOAD_AD
                      23/12/2009 14:13:12     23/12/2009 14:13:14     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     A74628F8FC6BD68C4E04013AC2D283     UPD_D_AGENT     LOAD_AD
                      23/12/2009 14:12:49     23/12/2009 14:13:12     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     OR     OR1_2     OWB_10G
                      23/12/2009 14:12:44     23/12/2009 14:12:49     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     A7530A4866A5CFBFCE04013AC2D285     LOAD_D_AGENT     LOAD_AD
                      23/12/2009 14:12:20     23/12/2009 14:12:44     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     SWITCH     ROUTE1     OWB_10G
                      23/12/2009 14:12:20     23/12/2009 14:12:20     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     ROUTE     ROUTE     OWB_10G
                      23/12/2009 14:11:00     23/12/2009 14:12:20     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     P02_PF_SS_CLEANSE_1     PF_SS_CLEANSE_1     LOAD_AD
                      23/12/2009 14:12:19     23/12/2009 14:12:19     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     END     END_SUCCESS     OWB_10G
                      23/12/2009 14:11:07     23/12/2009 14:12:19     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     AND     AND_SUCCESS     OWB_10G
                      23/12/2009 14:11:01     23/12/2009 14:12:19     WB_IK_20091223_141101_6227379     LOAD_AD     ROOT     PF_SS_CLEANSE_1     PF_SS_CLEANSE_1     LOAD_AD
                      23/12/2009 14:11:06     23/12/2009 14:11:07     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     A5B90750E3C6A81B2E04013AC2D287     CLEAN_TEAM     LOAD_AD
                      23/12/2009 14:11:05     23/12/2009 14:11:07     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     A5B9139CD54AF3314E04013AC2D280     CLEAN_TEAM_GROUP     LOAD_AD
                      23/12/2009 14:11:05     23/12/2009 14:11:05     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     FORK     FORK     OWB_10G
                      23/12/2009 14:11:04     23/12/2009 14:11:05     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     A5B9139CD5C4C3314E04013AC2D280     CLEAN_AGENT     LOAD_AD
                      23/12/2009 14:11:04     23/12/2009 14:11:05     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     A74B4104CC78F95CBE04013AC2D281     CLEAN_TEAM_GROUP_HISTORY     LOAD_AD
                      23/12/2009 14:11:04     23/12/2009 14:11:04     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     FORK     FORK_1     OWB_10G
                      23/12/2009 14:11:03     23/12/2009 14:11:04     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     A7465C6DA7FE4CB89E04013AC2D285     CLEAN_AGENT_TEAM_HISTORY     LOAD_AD
                      23/12/2009 14:11:01     23/12/2009 14:11:03     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     A74A0BC144826AECCE04013AC2D280     CLEAN_AGENT_TEAM_HISTORY_DATES     LOAD_AD
                      23/12/2009 14:11:01     23/12/2009 14:11:01     WB_IK_20091223_141101_6227379     LOAD_AD     PF_SS_CLEANSE_1     START     START1     OWB_10G
                      23/12/2009 14:10:59     23/12/2009 14:11:00     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     A5673591317F622DCE04013AC2D287     GET_EXECUTION_ID     LOAD_AD
                      23/12/2009 14:10:03     23/12/2009 14:10:59     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     A7A5D54FC0CECD7F5E04013AC2D287     PF_SS_EMAIL_START     LOAD_AD
                      23/12/2009 14:10:02     23/12/2009 14:10:03     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     A63D3B8BE1271F097E04013AC2D284     APPEND_DB_NAME_TO_TEXT     LOAD_AD
                      23/12/2009 14:10:01     23/12/2009 14:10:02     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     A63D3B8BE125BF097E04013AC2D284     GET_DATABASE_NAME     LOAD_AD
                      23/12/2009 14:10:01     23/12/2009 14:10:01     WB_IK_20091223_141001_6227307     LOAD_AD     PF_SS_AGENT     START     START1     OWB_10G
                      This is a mini schedule that I use to maintain a single dimension. The main schedule to load multiple dimensions and facts has even larger delays.


                      Edited by: ScoobySi on Dec 24, 2009 9:39 AM
                      • 8. Re: Process Flow - delay within flow during execution
                        As I can see the problem is with AND activity (there are two execution of AND activity - with duration of 72 and 24 seconds)...
                        It is very starnge, maybe it is an effect of processflow design. Why do you use two FORK activity in PF_SS_CLEANSE_1 processflow,
                        and what is the reason to use AND activity in PF_SS_AGENT process?

                        What is the version of Oracle database?

                        • 9. Re: Process Flow - delay within flow during execution
                          The first Fork in PF_SS_CLEANSE_1 allows two mappings to run in parallel, the second FORK occurs when one of the mappings finish and another two start in parallel. The AND then in effect waits until all three mappings (1 from first fork, 2 from second) finish before moving on.

                          I think I can remove the AND from PF_SS_AGENT.

                          Oracle 64bit RAC.

                          • 10. Re: Process Flow - delay within flow during execution
                            it is very strange workflow/OWB behavior. There are several "standard" OWB activities in yoyr processflow which produce "mysterious" delay - AND, OR and SWITCH processflow activities (another strange thing - duration of delay on this sctivities is multiple of 24 seconds).

                            Try to look at Oracle database waitevent (EVENT column from SQL) during execution of these activities (the best example is AND activity from PF_SS_CLEANSE_1 processflow because it is longest)
                            with query
                            select sid,to_char(logon_time,'yyyy/mm/dd hh24:mi:ss') logon_time,status,EVENT,seq#,seconds_in_wait,state from v$session where username in ('<OWB repository owner>','OWF_MGR') order by logon_time;

                            For identifing session which execute "delaying" activity look at database sessions to OWB/workflow repository owner with logon time close to start time of processflow PF_SS_CLEANSE_1
                            (or PF_SS_AGENT if you will decide to analyze activities from this processflow)
                            Output from sql (sorry not sure how to apply formatting):
                            use PRE tag
                            col1      col2
                               1         2
                            • 11. Re: Process Flow - delay within flow during execution
                              Thanks for all your help Oleg.

                              Just found a Process Flow in our Live schedule that takes 11 minutes, 2 minutes of activity + 9 minutes of Process Flow stuff. One OR takes 7 minutes.

                              I'll get back to this after Xmas.

                              Merry Christmas and all the best for 2010.

                              • 12. Re: Process Flow - delay within flow during execution
                                An update in case anyone has the same issue in the future.

                                Turns out the delays in our Process Flows were due to the amount of data in the OWB Audit/Executions tables.

                                Metalink (oops My Oracle Support) note 430755.1 provides a script e.g. truncate_audit_execution_tables_10_2.sql that once run removed the delays from our schedule. Process flows that were taking 10+ minutes are now run in less than 1 minute. This trunc is something that we'll need to schedule on a regular basis.

                                The support note mentions that the tables can also be purged via the Runtime Audit Browser, the Purge API script $Oracle_Home/owb/rtp/sql/purge_audit_template.sql or the package wb_rt_api_purge.purge_execution. There may be performance issues with these methods if the tables haven't been cleared recently.

                                Thanks Oleg, it was the WAIT events that pointed us down this route.