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.

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.

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

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

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:

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:

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:

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.