Skip to Content

This is part 1 of a blog in 3 parts (at the moment) on how IdM manages queue processing and the audits and logs created during processing

Part 1: Tables, views and processing logic: http://scn.sap.com/community/netweaver-idm/blog/2014/02/05/on-queue-processing-or-the-lack-thereof

Part 2: Viewing the current queues: http://scn.sap.com/community/netweaver-idm/blog/2014/02/10/on-queue-processing-or-the-lack-thereof-part-2

Part 3: Post execution audits and logs: http://scn.sap.com/community/netweaver-idm/blog/2014/02/21/on-queue-processing-what-just-happened-part-3

Though this post will be focused on the solution as it is from 72SP7 I’ll try to point out the differences to earlier versions.

Feedback is most welcome, and additions as well as corrections can be expected. So for now while publish is clicked, some errors expected 🙂

Overview

A common issue we see in support are messages about processing of tasks and workflows stopping. Frequently the message to us is “the dispatcher has stopped”. In many cases it’s not stopped, but rather has found something else to do than what you expected. So I’ve decided to try to document a few things about queue processing, the dispatcher, troubleshooting processing halts and provide some useful queries.

The dispatcher is the key component for processing workflows in IdM. It processes task expansions, conditional and switch task evaluations, approvals/attestation, executes link evaluation of assignments and it’s also responsible for starting the runtimes that executes actions and jobs. This is quite a lot to do for a single component, so let’s look at how it does this.

To process all of this the dispatcher runs multiple threads, each with their own database connection. This also allows us to give you control over what task(s) each dispatcher can process. Meaning you can let a dispatcher running on or very near the database host do database intensive tasks such as task/approval/link processing; while a dispatcher closer to a data source can process jobs and actions dealing with the target system(s). The reason that I include some of the procedure names in here is that using some of the queries I’ve documented previously you might recognize what is stuck.

Tables and Views

mxp_provision/mxpv_provision

The mxp_provision table is the main table for all workflow processing. Any workflow that is initiated by assignment events, users through a UI, uProvision calls in scripts, etc. all end up making an initial entry in this table. The main columns are mskey, actionid and auditid which are unique. There are more columns as well that we’ll get to later. It’s important to know that when processing a workflow (or process) the unique identifier in the system is mskey, auditid, actionid. If the same task is executed several times on a user it will always have a different auditid. This is also why it’s not possible to have the same task linked twice within an ordered task in a workflow. If you do you get constraint violations in the database and messages like “Error expanding task” in the audit. The provision table is dynamic and there is no history.

mxpv_grouptasks_<approval/attestation/conditional/ordered/switch>

The dispatcher(s) uses these views to get the next bulk of entries to process. By default these will list the 1000 first entries in the queue of each task type as indicated by their name. Older versions of IdM would list everything in one view, mxpv_grouptasks, and the dispatcher would process all the different taskt ypes in a single thread. This could be controlled by setting a global constant, MX_DISPATCHER_POLICY, which would switch between using the joint view or the separate views in a couple of service packs. I can’t say for sure in which release this approach was abandoned, but I believe it’s to blame for the excessive amount of dispatchers we see in use in productive systems. Now the dispatcher creates an independent thread per view and running many dispatchers on a single host has less of a positive effect.

mxp_audit/mxpv_audit

Any workflow that is initiated also gets a corresponding entry in mxp_audit where the overall state of processing of this entry/task/audit combo is kept. The audit information is kept forever.

mxp_ext_audit/mxpv_ext_audit

If you enable the somewhat mislabeled Trace the system will create an entry per task/action in the mxp_ext_audit table. This will contain the result of conditional/switch tasks and other useful information. This is also kept forever.

extAuditEnable.png

mc_execution_log/mcv_executionlog_list

Update 2014-03-06: This is a new table/view that is included in SP9. It was ready from SP8 but was not included due to missing UIs. It contains messages that you usually would find in the runtime log files as well as messages from the dispatcher when processing entries. This is really fantastic and will get its own blog post.

A small test scenario

Let’s look at it in action using a setup I’ve used for performance and function testing

queueWorkflow#1.png

My example workflow called Dispatcher test #1.0.0 has an ordered task with multiple task types below it.

It starts with a simple ordered task with an action containing a To Generic pass that sets CTX variable

Next is a conditional task that always goes into True

Then a conditional task that always goes into False

Followed by a new ordered task that expands into

A switch task with cases for the last digit of the mskey (0..9), each contains an action

Then an ordered task with “Wait for Events” containing a single action executing another ordered task

And finishing off with an ordered task containing an action that logs that its complete

0 – “Dispatcher test #1.0.0” task initiated

Let’s see what happens when this is executed. In this example I’ve just executed it using the “test provision” function on my “administrator” user

mxpv_provision

queueLevel0.png

This is the Initial state. uProvision/event/assignment/test_provision/something else has initiated the task. At this point the top level task is in the queue, ready to run.

mxpv_grouptasks_ordered

queueLevel0_grptskordered.png

This task is also visible to the dispatcher in the mxpv_grouptasks_ordered view, which contains the first 1000 ordered tasks ready for processing from the provisioning queue. One ordered task entry is available for processing. Ordered tasks have one operation and that is expanding the tasks/actions they contain which we see in the next step.

mxp_audit

queueLevel0_audit.png

The audit shows that the task has been initiated.

1 – “Dispatcher test #1.0.0” task expansion

A dispatcher tasks thread will now pick up 1/Dispatcher test #1.0.0 from the view mxpv_grouptasks_ordered and expands the task.


mxp_provision

queueLevel1.png

mxpv_grouptasks_ordered:

queueLevel1_grptskordered.png

Now the ordered task 2892/Update ctx emu is ready for processing indicated by state=2.

mxpv_audit:

queueLevel1_audit.png

State of the audit is now officially Running

2 – “Update CTX emu” task expansion

mxpv_provision

queueLevel2.png

Now the ordered task 2892/Update ctx emu is expanded and this adds our first action task to the queue.


mxpv_grouptasks_ordered

<empty>

Actions can only be processed by a runtime, so at this point the mxpv_groupstasks_ordered view is empty as there are no more ordered tasks to process at the moment.

mxpv_audit

queueLevel2_audit.png

The audit shows that the last completed action is now 2892/Update ctx emu.

3 – Processing the action task


At this point another thread in the dispatcher looking for actions takes over. This runs a procedure called mc_dispatcher_check whose only task is to let the dispatcher know if there are, andif so, how many, jobs or provisioning actions available for it to run. This check (*) requires a lot of joins on lots of tables and as a result this procedure is sometimes seen to take a few seconds when the queue reaches around 1 million rows in pre-SP7 releases.

In this case it will return 0 windows jobs, 0 java jobs, 0 windows provisioning actions, 1 java provisioning action.

From SP7 this procedure will generate a cache table to avoid rerunning the check too frequently as it would start slowing down systems when the queue got to about 1 million rows. This table, mc_taskjob_queue, will contain a list of actions available that no runtimes has yet picked up. It refreshes as it nears empty.

queueLevel3_tskjbq.png

So with this result the dispatcher will now know there is 1 action ready to run, and a runtime started by dispatcher with id=1 will have an action/job to run.

If there were more than 1 returned, it would look at its “Max rt engines to start” value to see if it should start more than one runtime at this moment.

It also checks how many it already has started that have not ended and compares this to the “Max concurrent rt engines” setting.

And then checks against the global “Max concurrent rt engines” to see that it’s not exceeding this.

So, if all is OK, the dispatcher will now start a java runtime process to run a job.

4 – The runtime executes the action task


At this point the dispatcher has started the runtime by initiating a java.exe with lots of parameters such as the database connection string and classpath extensions. It’s important to note that the dispatcher does not tell the java runtime process which job it wants it to start. It just starts the runtime process and lets it pick something from the queue by itself. The runtimedoes this using the procedure mc_getx_provision, which in pre SP7 releases would run a somewhat complex query looking for an action to run which was basically just the same as the dispatcher had already done(*). If this started to take more than 5 seconds (or whatever you configured your dispatcher check interval to) the dispatcher would see that the jobs were not picked up and start more runtimes which got stuck in the same procedure. From SP7 we do a quick look up in the cache table mc_taskjob_queue to avoid this problem


As the runtime engine initializes it will log to a file called /usr/sap/IdM/Identity Center/prelog.log. This file can be useful to check it should contain messages that occur before it can connect to the database, especially if it’s not able to connect to the database at all. Once the runtime has run mc_getx_provision it will download the job/action configuration into /usr/sap/IdM/Identity Center/Jobs/<folder with GUID of job/action> where it will keep its temporary files from now on. This folder contains the last versions of the text-formatted .log and .xml log-files. The full path of this folder is listed in each log in the management console as well. The text log is very useful in cases where there are so many messages that they can’t all be uploaded to the IdM database.


jobLogLocation.png jobTempFolders.png


Anyway, in most cases the runtime is able to get the configuration and start processing entries. Each entry is processed by itself and after each entry the runtime will update the provisioning queue mskey/actionid/auditid combination using either the mxp_set_ok or mxp_set_fail procedure depending on success/failure of the operation.

5 – Test something true

According to the workflow the next step to process should be “Test something true” which is a conditional task and will as such be listed in the mxpv_grouptasks_conditional view.

mxp_provision

queueTestSomethingTrue.png

And “Test something true” is now in the queue, ready to run.

mxpv_grouptasks_conditional

queueTestSomethingTrueTGC.png

Also notice that the SQL statement for the conditional operation is part of this view.

mxpv_audit

queueTestSomethingTrueAudit.png

Our task is still a work in progress.


The dispatcher does a parameter replacement on %% values in the MXP_SQL and runs the statement, then evaluates the result. Depending on the result being 0 (false) or higher (true) it will run the mxp_set_FALSE or mxp_set_TRUE procedure for the mskey, actionid, auditid combination and the procedures will expand to the next step.

6 – Test something true action, and so on…

As a result of the previous evaluation ending in a True result the action in the True node has been expanded into the queue. Also notice how the mxpv_provision view includes the result of the conditional statement. This also occurs with switches. This information is stored in the extended audits if enabled which is really useful for tracing problems.

mxpv_provision

queueLevel6Prov.png

At this point the processing should start to be clear and this document is already too long before I’ve even started on the troubleshooting part 🙂 Now the action will trigger a runtime to start, then the Test something false process will be expanded and so on through my test scenario.

The dispatcher picks up the entry from the queue, evaluates and runs procedure to continue workflow. Nothing interesting happens until the Exec external and wait for task is started, which has the Wait for event tasks results option checked.

queueLevel6WaitForEvent.png

This is used in various places in the provisioning framework such as in the Provision workflow where a user needs to get an account created in the target repository before any assignments are added.

7 – Exec external and wait for


In this case I’ve halted my event task so that I can see what the queue looks like.


mxpv_provision

queueLevel7waitForExternal.png

The MSG column shows that audit 1273983is waiting for audit 1273984 before it continues. In this case I’ve stopped the dispatcher capable of running the action of task 45, so it’s temporarily stuck here. So, starting the dispatcher it will continue the external and eventually continue and finish the workflow.


8 – Suddenly all done, but wait, what happened?


To close this off and get on to the troubleshooting I just wanted to mention the extended audit table. With it I can get a complete picture of the events for my two audits:
extAudit.png

As a mew feature from SP8 and on, I can even get all the messages from the runtimes as well by looking at the mcv_executionlog_list view.



Additional notes and curiosities

How does the runtime process entries?

As mentioned previously the runtime uses mc_getx_provision to reserve an action to run. With the actionid it also gets a repository ID, and then it retrieves the jobdefinition linked to the action and prepares to process all entries in the queue for the task it’s been handed for given repository. So it will process the queue for the task one repository at a time (by default). This is nice when connection/disconnecting to repositories take a long time. Not so nice during bulk loads when you have 20.000 entries processing to your least important ABAP system that somehow got priority over the important one. Anyway, the queue it will process is found using:

SELECT * FROM MXPROV_ENTRIES WHERE MXP_ACTIONID=@P0 AND MXP_REPOSITORY=@P1

(it’s using a prepared statement so @P0 and @P1 are input parameters)

I’ve once more created a small scenario to test and demonstrate this:

RTprocessingUnremarkableTask.png

For this task I’ve queued 9 entries targeted to 3 different repositories, and as a result mxp_provision contains 9 entries for repositories GENREP1, GENREP2 and GENREP3. (The query that lists this is in part #2):

RTprocessingUnremarkableTaskQUEUE.png

This is also what ends up in the cache (mc_taskjob_queue) table, and what the query in the procedure of older versions resolve:

RTprocessingUnremarkableTaskQUEUECache.png

With a somewhat recent release you should also see that the logs for the job are uploaded per repository, and that they appear to be processed in order:

RTprocessingUnremarkableLOG.png

So how do do I optimize the runtime processing then?

Glad I asked. Some time ago an option called Allow parallel provisioning was added to tasks. This option allows IdM to create clones of the original job that can run in parallel. The clones are empty in the sense that they don’t have a configuration of their own, just a reference to the shared master. With this enabled the timing in the log changes completely (enabled in green, not enabled in red):

RTprocessingRemarkableOptionLOG.png

If I’m quick I can even catch it in the status screen, and the action will also reflect it:

RTprocessingRemarkableOptionStatus.png

RTprocessingRemarkableOptionNewData.png

Basically what happens is that the dispatcher has started 3 runtimes at the same time to process each repository in parallel. This also requires that the Max rt engines to start setting is bigger than 1 in my demo since my queue is too small for it to have any effect otherwise. This is done behind the scenes by the procedures that the runtime calls so no action is required by you when adding new repositories.

“This is so awesome! Why didn’t you make this the default?!?!” You might ask. This works best when used selectively. Imagine you have hundreds of ABAP repositories (some actually do). If your system could handle 50-70 runtimes in parallel you run the risk of them all being busy updating your ABAP repositories while nothing else happened.

[edit, some spelling fixes]

This editor is getting a bit slow and perhaps unstable, so I’ll continue this in part #2.

To report this post you need to login first.

11 Comments

You must be Logged on to comment or reply to a post.

    1. Brandon Bollin

      OK, so now I have had a chance to really get into some of this blog entry a little further and a question has come up in my current environment that you may have the answer to. If I have a switch task with a SQL query as my condition, or for that matter a conditional task with an audit flag or SQL query set, how often are those conditions evaluated?

      (0) 
      1. Per Krabsetsve Post author

        Good question. They are evaluated exactly once when the dispatcher processes the mskey/action/audit combination. The condtitional & switch tasks don’t have a max retry count setting (exposed to the user atleast) so if the query fails due to a broken syntax, using non-existing table/view or similar, the task will be failed. The workflow for this auditid will then fail and trigger On Fail/On Chain Fail if configured. You will see the mxp_audit.MSG column contain something similar to:

        TaskId:2921 – Could not carry out execCheckSQL:(select what from thisdo) –

        exception:com.microsoft.sqlserver.jdbc.SQLServerException: Invalid object name ‘thisdo’.

        Yet… We’ve seen that an entry is blocking the processing of switch/cond’t completetly because the DB connection has died or timed out (due to bad sql on the cond’t or switc) and the dispatcher is unable to set the failed state. In these few cases the SQL statement fails in such spectacular ways that it somehow ends the jdbc session or breaks something I’m unable to reproduce in local environments, This means the dispatcher will pick up the same mskey/action/audit when restarted which typically fails the same way again.

        Br,

        Chris

        (0) 
        1. Brandon Bollin

          Hmmm… Here’s the issue I’m having. I have a scheduled job that updates some attributes in the Identity Store on entry type MX_PERSON. This job runs once week. Immediately after that job finishes, a number of switch and conditional tasks kick off. Those tasks are not tied into any of those attributes / entry type as add or modify tasks. Additionally, none of the scripts being used in this job update anything that would fire off these tasks as a result of the job’s action. I put a trace on one of the user records being updated and I can see these tasks being executed after the scheduled job runs but I cannot figure out what’s making those tasks execute. It’s pretty frustrating so if you have any suggestions on what might be firing these tasks, I would be appreciative.

          (0) 
          1. Per Krabsetsve Post author

            You have the reverse issue from what this blog is attempting to cover; something is being processing and I don’t know why 🙂

            Look at the users audits, they usually tell you why something is started.

            Link audits(privileges):

            select LA.userMSKEYVALUE, LA.auditDate, LA.AssignmentMSKEYVALUE, LA.operationtext, LA.auditid, A.taskid, T.taskname

            from idmv_linkaudit_ext LA

              left outer join mxp_audit A on A.AuditID = LA.auditid

              left outer join mxp_tasks T on T.taskid = A.TaskId

            where LA.userMSKEYVALUE = ‘USER.TEST.3

            General audits:

            select A.auditid, A.AuditRoot, A.RefAudit auditParent, A.userid, A.StartedBy, A.taskid, T.taskname, A.mskey, A.PostedDate, A.StatusDate, A.provstatus, A.LastAction, A.msg

            from MXP_AUDIT A, MXP_Tasks T where A.TaskId = T.TaskID

            and A.msKey = (select mcmskey from idmv_entry_simple where mcMskeyValue = ‘ADMINISTRATOR‘)

            order by auditroot,RefAudit

            Replace underlined texts with the userId you’re looking for. The Admin UI should also have some screens that show the audits and their sources.

            Br,

            Per Christian

            (0) 
  1. Ian Daniel

    This is the sort of content SAP must produce if this product is to go main stream, so the community of experts can truly understand how it works, not just how to develop on it – well done Chris!

    (0) 
  2. Matthias Bartel

    Hi,

    I think this is a really awesome tutorial. I was just wondering about mcv_executionlog_list. We’ve got a IdM System 7.20.8.2-SQL-2013-09-18. I think this means 7.2 SP8 Patch 2, so the view/table should exist?

    best regards

    Matthias

    (0) 
    1. Per Krabsetsve Post author

      Hi Matthias,

      So it seems that it was not included in SP8 at all. The runtime has support for it but its supressed and the tables are missing. Sorry. Seems SP9p0 is the first version where this will be functional.

      Br,

      Chris

      (0) 

Leave a Reply