Masking Logs: What is IORWUE? (KBA1132)

Log Format

The format in the log files are as follows: 

[Step X] - Finished processing (I=n1, O=n2, R=n3, W=n4, U=n5, E=n6)

The Counters

There are 6 counters: 

• Input/Output
  • I -Input Counter. This is in from an external database or file.
  • O -Output Counter. This is out to an external database or file.
     
• Read/Write
  • R -Read Counter. This is the number of rows Read into the step in the masking process.
  • W -Write Counter. This is the number of rows Written (out) from the step in the masking process.
     
• Update 
  • U -Update Counter. This is updated rows out to an external database. Used only in In-Place database job.
     
• Error Counter (Flag)
  • E -Error Counter. This is a flag. The default value is 0 (no error). If the step had an error, then the value is E=1.

In-Place DB Masking Job

Final counters in an In-Place database masking job. The example below uses Secure Lookup v1 (this to show Input from both database and file in the same job). 

[JOB_ID_x_y] 0000/00/00 00:00:00 - DelphixTableInput.0 - Finished processing (I=150000, O=0, R=0, W=150000, U=0, E=0)
[JOB_ID_x_y] 0000/00/00 00:00:00 - Select values.0 - Finished processing (I=0, O=0, R=150000, W=150000, U=0, E=0)
...
[JOB_ID_x_y] 0000/00/00 00:00:00 - Col0_dataFromXML.0 - Finished processing (I=124, O=0, R=0, W=124, U=0, E=0)
[JOB_ID_x_y] 0000/00/00 00:00:00 - Col0_lookUp.0 - Finished processing (I=0, O=0, R=150124, W=150000, U=0, E=0)
...
[JOB_ID_x_y] 0000/00/00 00:00:00 - String Cut - Finished processing (I=0, O=0, R=150000, W=150000, U=0, E=0)
[JOB_ID_x_y] 0000/00/00 00:00:00 - DelphixTableUpdate.0 - Finished processing (I=150000, O=0, R=150000, W=150000, U=150000, E=0)

We can here see that we have:

1. DelphixTableInput:
   • I=150000 - Input 150,000 rows from the database
   • W=150000 - Wrote 150,000 rows to the next step.
2. Select values:
   • R=150000 - Read 150,000 rows from the previous step.
   • W=150000 - Wrote 150,000 rows to the next step.
     ...
3. Col0_dataFromXML: 
   • I=124 - Input 124 (Secure Lookup) values from XML file.
   • W=124 - Wrote rows to the next step.
4. Col0_lookUp: (Since two streams merge in this step the counts are aggregated).
   • R=150124 - Read 150,000 and 124 rows from previous steps (Select values and Col0_dataFromXML).
   • W=150000 - Wrote 150,000 rows to the next step.
     ...
5. Update:  some interesting observations: 
   • I=150000 - Input 150,000 rows from the databases (this data is not transferred to the engine but read to update the value).
   • O=0 - Output 0 rows - this is correct, we did not output any rows as we Updated the rows in the database.
   • R=150000 - Read 150,000 rows from the last step.
   • W=150000 - Wrote 150,000 rows - all rows written out.
   • U=150000 - Updated 150,000 rows in the database.

Note: The number of rows masked (processed) is the same from Input, through the masking process (exception for lookups where Input is aggregated), to the Update.

Masking Job with Error 

The example below is an Error in the Update step - in this example it is caused by a database deadlock.

[JOB_ID_x_y] 0000/00/00 00:00:00 - DelphixTableUpdate.0 - ORA-00001: unique constraint (xzy) violated
[JOB_ID_x_y] 0000/00/00 00:00:00 - DelphixTableUpdate.0 - Finished processing (I=39, O=0, R=39, W=39, U=39, E=1)

A description of the steps and counters:

• Input 39 rows (I=39).
• Read 39 rows (R=39).
• Wrote 39 rows (W=39).
• Updated 39 rows (U=39).
• 1 Error (E=1).

Pre/Post SQL Scripts

[JOB_ID_x_y] 0000/00/00 00:00:00 - Execute_Disable_Triggers_Script.0 - Finished processing (I=0, O=0, R=0, W=1, U=0, E=0)

• All steps: Writes 1 row to the next process (this is always 1 independent on how many statements are executed).