Skip to Content
Author's profile photo Former Member

On queue processing, what (just) happened? Part #3

So it seems that finding out what happened to an entry/assignment and why is also an issue. Here are some hints on how.

Please note that these are not official table definitions. Views that start with idmv and mxpv are public and stable, but the tables themselves can and have occasionally changed.

2014-05-27: Listing task execution in time intervals added

Audits

All provisioning tasks are audited, the combination mskey, actionid, auditid is unique in the system. Any task that is started using the IdM UI, Rest interface, attribute events, privilege events etc. will get a unique AuditId. If the workflow processes triggers addd

mxp_audit

The main audit table is mxp_audit. This contains a single row entry for each task/event that has been triggered for your entries. Some notable columns:

Column Value
auditid unique identifier
taskid Taskid of root task of this audit (such as change identity, provision, deprovision, modify in provision framework)

mskey

Entry for which this audit was started
auditroot root audit or itself. Root audit points back beyond the parent audit (refaudit) to the very first audit in case of deep nested events
posteddate Datetime when the task was initiated and put into the provisioning queue
statusdate Datetime when the task or any subtask of this audit was last updated or evaluated
provstatus See mxp_provstatus, Key values: 0=Initiated OK, 1000=Task OK, 1001=Task Failed, 1100= OK, 1101=FAILED
LastAction Id of last subtask that has been executed or attempted executed. Will be the task that failed in case of provstatus 1001 or 1101
refaudit null or the parent audit
MSG Error message or just informational message depending on provStatus
userid

Somewhat fuzzy logic datablob, but there is a structure to it

If its simply a number then it should be the mskey of an entry, and the task was started by a user in the IdM UI.

When value starts with # this column indicates an privilege attribute event that caused the task to start. The Format is  #<attrid>:<operation>:<checksum>:<oldvalueid>

Example: #395:INSERT;3285570;0

395 is the attribute ID (MXREF_MX_PRIVILEGE), 3285570 is the checksum of the value that triggered the task (mxi_values.bCheckSum=<checksum>), oldvalueid = 0 means this is a new value, not a replacement/modify otherwise the old value can be found in mxi_old_values.old_id=<oldvalueid>

When starting with + this value indicates that this is an On event such as On (chain) OK or On (chain) Fail. Format is +<taskid>:<eventname>

Example: +1002083:On Chain OK task

When starting with * this value indicate that it was started by an entry event (defined on the entry type). Format *<entryid>:<operation> where operation should be Insert, Modify or Delete.

startedBy Only valid when task is started from Workflow UI/REST, contains the mskey of the logged in user that ran the task

Views: mxpv_audit

A fun/useful thing to do with the audit includes checking the average execution time of a task from start to end over time. Change taskid=X to taskid in (x,y,z) to get more tasks or extend this sequel with a link to mxp_tasks to use tasknames and be creative. I suggest keeping it limited to a few tasks or the results might become difficult to interpret.

SQL Server:


select taskid,convert(varchar(10),posteddate,20) Date,count(auditid) as numExecs,avg(datediff(ss,A.posteddate,A.statusdate)) AvgTimeToComplete
from mxp_audit A with(nolock)
where taskid = 1 and posteddate > '2014-02-01' and ProvStatus >999
group by taskid,convert(varchar(10),posteddate,20)
order by taskid,convert(varchar(10),posteddate,20)













Oracle:


select taskid,to_char(posteddate,'YYYY-MM-DD') "date",count(auditid) "numExecs",round(avg(statusdate-posteddate)*24*60*60,2) "avgTimeToComplete"
from mxp_audit
where taskid = 20 and postedDate > to_date('2014-02-01','YYYY-MM-DD') and provstatus > 999
group by taskid,to_char(posteddate,'YYYY-MM-DD')
order by taskid,to_char(posteddate,'YYYY-MM-DD')













This calculates the average time between start-time and end-time of the task with id=1 (SQL) and 20 (Oracle), and I suggest using the taskid for Provision or Modify to test this. ProvStatus >= 1000 are completed, those still running will have no statusdate worth using in this case.

On SQL Server changing the length of the convert statement to 7 characters you can group it by month, 4 to get per year. On Oracle you can change to to_char conversions to YYYY-MM, or just YYYY.

You can also query for posteddate between two dates and much more. This is also useful to spot negative trends over time, but you must consider the overall load of the system. This is also useful during testing and tuning to verify if improvements you do have any impact on a full workflow execution.

part3_auditLogExecOverTime.png

List all tasks that have been executed on a user (SQL Server and Oracle):


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












mxp_audit.taskid can be linked to mxp_tasks.taskid to get the taskname when accessing the mxp_table instead of the view (which has an unfortunate top 1000 limit).

mxp_ext_audit

The extended audit is stored in mxp_ext_audit. This contains a single row entry for each task/action executed within an audit and is enabled by checking the “Enable trace” checkbox.

Column Value
Aud_ref Audit Id
Aud_Task Task Id
Aud_OnEntry Mskey
Aud_datetime Datetime when the ext_audit record was created
Aud_Approver Mskey of approver. You should use mxp_link_audit for this when getting link approval records
Aud_Info

Generic information. If the audited task is a switch or conditional this column will contain the result of the evaluation. In case of conditionals it will be TRUE or FALSE, for switches it will contain the value returned by the SQL Statement.

Aud_Startedby

Reason for the task starting. Another fuzzy logic data blob. Some of the common value formats:

USER:<mskey>

ATTR:<attributeid>:<operation>

ENTRY:<entryid>:<operation>

TASK:<taskid>:<task operation. 0=inittask, 1=OnError, 2=OnOk, 3=OnChainError, 4=OnChainOk>

PRIV:<priv mskey>:<entryoperation>

ROLE:<role mskey>:<entryoperation>

OTHER:<other info>    : This is typical for tasks started using uProvision.

Operation values: 1=Modify, 2=Delete, 3=Insert

Entryoperation values: 0=Provision, 1=Deprovision, 2=Modify

Views: mxpv_ext_audit

The extended audit is useful for when you need to see what happened in subtasks, what conditional or switch statements returned or find out where a workflow stopped for a user. This query lists all tasks started by and including auditid 1307812, but can easily be modified to filter on aud_onEntry (mskey), and dates.


SQL Server and Oracle:


select t.taskname,A.aud_ref,aud_Datetime,aud_info,Aud_StartedBy
from mxp_ext_audit A, mxp_tasks T
where T.taskid = A.aud_task and aud_ref
in (select auditid from mxp_audit where AuditRoot=1307812)
order by aud_datetime















The red arrows shows a child audit being started, in this case by a uProvision call in a script, and the green arrows show where the child-audit is completed and allowing the parent audit to continue from its wait for events state.

part3_extAudit.png

Listing task execution in time intervals

(SQL Server only for the moment)

It is also possible to use the audit and extended audit to list task executions per X minutes between date A and date B:


-- Create helper table for intervals and declare vars
declare @intervaltbl table(st datetime,et datetime)
declare @it datetime
declare @interval int
set @interval = 5 -- interval length in minutes
set @it = '2014-05-27 10:00:00' -- Interval Start time
while @it <= '2014-05-27 12:30:00' -- Interval End time
begin
    insert into @intervaltbl values (@it,dateadd(mi, @interval, @it))
    set @it = dateadd(mi, @interval, @it)   -- Increase to the next @interval minute interval
end
-- Do a count per interval in mxp_audit
select it.st startinterval, it.et endinterval, count(*) troottaskstarted
  from @intervaltbl it, MXP_AUDIT A with(nolock)
  where A.PostedDate between it.st and it.et
group by it.st,it.et

It’s also possible to list the number of task/actions the same way. This query can be modified to group on t.actiontype to list the number of ordered/conditional/switch/actions were performed per interval:


-- Create helper table for intervals and declare vars
declare @intervaltbl table(st datetime,et datetime)
declare @it datetime
declare @interval int
set @interval = 15 -- Interval length minutes
set @it = '2014-02-04 10:00:00' -- Interval Start time
while @it <= '2014-02-04 16:00:00' -- Interval End time
begin
    insert into @intervaltbl values (@it,dateadd(mi, @interval, @it))
    set @it = dateadd(mi, @interval, @it)  -- Increase to the next @interval minute interval
end
--Do a count of tasks and actions started per interval in mxp_ext_audit
select it.st startinterval, it.et endinterval, T.taskname, count(*) TimesStarted
  from @intervaltbl it, MXP_EXT_AUDIT A with(nolock), MXP_Tasks T with(nolock)
  where A.Aud_datetime between it.st and it.et and A.Aud_task = T.taskid
group by it.st,it.et, T.taskname
order by it.st, T.taskname

Link audits, mxi_link_audit

Audits related to evaluation and processing of reference values (role/privilege assignments, manager and other references) have information stored in mxi_link_audit (also see mxi_link_audit_operations). This has a lot of columns and I suggest you look at the views and see what is there. Some of the key columns are:

Column Value
mcLinkid/linkId Reference to mxi_link.mcUniqueId
mcauditid/auditid Reference to mxp_audit.auditid
mcDate/date Date of entry
mcOperation/operation Reference to mxi_link_audit_operations
mcReason/reason Request/approve/decline reasons
mcMSKEYUser Mskey of user
mcMSKEYAssignment Mskey of the assigned entry (privilege, role, manager etc.)

Views: idmv_linkaudit_<basic/ext/ext2/simple>

Example data from idmv_linkaudit_ext2 view for an audit in which a role was added to a person, which caused to two inherited privileges to be assigned. Later the role was removed.

SQL Server and Oracle:


select linkid,auditid,auditDate,userMSKEYVALUE,AssignmentMSKEYVALUE,OperationText,AdditionalInfo
from idmv_linkaudit_ext2
where userMskey = 23
order by auditdate















part3_linkAudit.png

Note that a new audit be created only when there’s an event task execution. The privilege in my example only had a del-member event and this event got a new audit (944072), the rest shared the add-audit of the role they were inherited from.

Useful variation with tasknames (SQL Server and Oracle):


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'
order by LA.auditDate















Logs

There are additional logs in jobs and actions that are stored in base64 blobs in the database. From SP8 we’ve added a new log, the execution log, which now stores messages from the runtime logged with uInfo/uWarning/uError.

Job and action logs, mc_logs

This contains the logs of all jobs and actions as well as other useful values. Some columns I find useful are:

Column Value
JobId Id of the job. An action is linked to a jobconfiguration on mxp_tasks.jobguid = mc_jobs.guid
TimeUsed The number of seconds the action/job used to complete for this logentry
TotalEntries The total number of entries processed in this logentry
Num_Adds Number of add operations performed
Num_Mods Number of modify operations performed
Num_Del Number of delete operations performed
Num_Warnings Number of warnings reported
Num_Errors Number of errors reported

Views: mcv_logall,  mcv_logwarn, mcv_logerr

One of the things this can be used for is to calculate how many entries per second an action/job processes.

SQL Server:


select jobname,JobId,sum(TotalEntries) totalEntries,sum(TimeUsed) totalTime,
round(cast(sum(TotalEntries) as float)/cast(sum(TimeUsed) as float),2) entriesPerSecond
from mcv_logall group by jobname,jobid
order by round(cast(sum(TotalEntries) as float)/cast(sum(TimeUsed) as float),2)  asc











Oracle:


select jobname,JobId,sum(TotalEntries) totalEntries,sum(TimeUsed) totalTime ,Round(sum(TotalEntries) /sum(TimeUsed),2) entriesPerSecond
from mcv_logall
group by jobname,jobid
order by entriesPerSecond










part3_jobLogCalc.png

This can give valuable hints about actions or jobs that are slow and will cause problems at some point in time. In this case my “Test something true: False” task is slow and needs a look. You can also reverse this by calculating totalTime/totalEntries to get time used per entry. This can be used in combination with the threshold log when running mass-update/performance tests in dev/qa cycles to detect potential issues before they cause downtime in production.

execution log

View: mcv_executionlog_list

This is a new log that has been in hiding for a while as it needed a UI. It still doesn’t have one outside the MMC, but it is very useful. This log contains all the messages from the runtimes that would usually be locked inside the big blob of mc_logs or the dse.log file on the file system. So in short, this means that messages like this one:

part3_execLogXML.png

Are now also logged individually and linkable to the user and auditids. My root audit was 1316231 so this query will find all related audits and list runtime messages reported during the processing of these audits:


select mcAuditId,mcTaskId,mcTaskName,mcMskey,mcMsg,mcLogLevel,mcLogTime From mcv_executionlog_list where mcAuditId in
(select auditid from mxp_audit where AuditRoot = 1316231) order by mcUniqueId








This output would usually would be “hidden” inside the logfiles associated with each individual job:

part3_execLog.png

There is a lot more to the execution-log though, so have a look at it when you get your hands on a version supporting it.

Pulling it all together

To summarize there is

  • One audit per task executed on an entry (mxp_Audit)
    • One extended audit entry per sub-task (mxp_ext_audit)
      • 0 to many execution log entries per action (mcv_executionlog_list)


And combining all this information can be done using joins and unions:



select
  AT.NAme,T.taskname taskname, EA.aud_ref auditid, ea.aud_datetime logtime,
  '' loglevel, ea.Aud_Info info, ea.Aud_StartedBy startedby
from
  mxp_tasks T, mxp_actiontype AT, MXP_Ext_Audit EA
where
  T.taskid=EA.Aud_task and T.actiontype = AT.actType and
  EA.Aud_ref in (select auditid from mxp_audit where AuditRoot = 1316231)
union
select 'Action' as type, mcTaskName taskname,mcAuditId auditid,mcLogTime logtime,
case
  When mcLogLevel = 0 then 'Info'
  when mcLogLevel = 1 then 'Warning'
  when mcLogLevel = 2 then 'Error'
  else cast (mcLogLevel as varchar)
end loglevel,mcMsg info ,'' startedby
From
  mcv_executionlog_list where mcAuditId in (select auditid from mxp_audit where AuditRoot = 1316231)
order by logtime



Providing a complete view like this:

part3_AllLogsTogether.png

And that I believe is all the detail one could look for on the processing of a specific task, “dispatcher test #1.0.0” through two child tasks and back, for a user all in a single view. I’m sure there’ll be an admin UI for this later, but for now I expect this to be most useful in the development and QA cycle.

Assigned Tags

      11 Comments
      You must be Logged on to comment or reply to a post.
      Author's profile photo Matt Pollicove
      Matt Pollicove

      Chris, another great insight into the back end of IDM! Thanks!!!

      Author's profile photo Former Member
      Former Member

      This really is a wealth of information Chris. I'm glad I finally had the time to sit down and read it much less be able to use it prior to this blog release. Thanks again for your knowledge sharing.

      Author's profile photo Matt Pollicove
      Matt Pollicove

      Chris,

      In the mxi_link_audit table, can you please tell us what the possible values for AuditID are and what they mean?

      Thanks,

      Matt

      Author's profile photo Andreas Trinks
      Andreas Trinks

      Hi Matt,

      according to the table in Chris' description it is a reference to mxp_audit.auditid.

      Therefore it should be a number and I expect to should only see values of mxp_audit.auditid.

      Column Value
      mcauditid/auditid Reference to mxp_audit.auditid

      Andreas

      Author's profile photo Matt Pollicove
      Matt Pollicove

      Andreas, the values are usually something like 0, -1, 1.  What I'm looking for is what these numbers represent.

      Matt

      Author's profile photo Former Member
      Former Member

      The definition of the table is that this a link to an auditid in mxp_audit, or -1 which is the default when no value or NULL value is provided as auditid (and should be fairly rare).

      But...(this is my inpterpretation of the situation):

      Entries made before an audit exists will have 0 in linkaudit I believe. AuditIds are only available after a provision task (process) is initiated/put in the queue, so any operation that happens without an actual provision task running (before or after) will not have an audit to use in mxi_link_audit. For example when setting a link from a job. When the link is evaluated and a process is started for validate or addmember it will get an audit, but not until then. And roles/privileges without validate or member tasks won't have validate or member tasks audits to use...

      You can also do assignments using {DIRECT_REFERENCE=1} to bypass validate & addmember tasks (or delmember for that matter) and this will also be reflected with val/add/del-audit=-1 in mxi_link and link_audit (if I remember correctly).

      Author's profile photo Andreas Trinks
      Andreas Trinks

      Hi Chris, for your first SQL (average execution time) I get 0 as execution time.

      After trying a little bit I were successful moving the putting the round()-function far most out...

      select

           taskid,

           to_char(posteddate,'YYYY-MM-DD') "date",

           count(auditid) "numExecs",

           round(AVG((statusdate-posteddate)*24*60*60),2) "avgTimeToComplete"

      from mxp_audit

      where taskid = 1002119

           and postedDate > to_date('2014-02-01','YYYY-MM-DD')

           and provstatus > 999

      group by taskid,to_char(posteddate,'YYYY-MM-DD')

      order by taskid,to_char(posteddate,'YYYY-MM-DD')

      Andreas

      PS Is it possible to get syntax highlighting in a reply/comment?

      The {code}, {code:sql} and <script> markups do no work for me.

      Author's profile photo Laurent Vandenbemden
      Laurent Vandenbemden

      Very helpful to learn understand the provisioning structure in the different tables. A lot of things cleared up to me about the provisioning process. Thanks a lot for sharing this.

      Author's profile photo Former Member
      Former Member

      Hi

      I tried to execute the statement under "Pulling it all together", but the view MCV_EXECUTIONLOG_LIST doesn't exist. Is our installation missing something? We are running 7.20.8 2013-09-18.

      Best regards

      Matthias

      Author's profile photo Siarhei Pisarenka
      Siarhei Pisarenka

      I would say that this feature appeared starting from 7.2 SP9.

      Author's profile photo Former Member
      Former Member

      You are right. This view was added in sp9p0. The definition of it is simple and does not depend on other updates, and is dropped and added again on every update so I've added its definition  to the blogtext. It should only be run by those running pre-SP9 releases.

      Nevermind, dependencies make it difficult.

      Br,

      Chris (my account still works!)