Gregor

Logging capabilities in PI Advanced Computing Engine (PI ACE)

Blog Post created by Gregor on Sep 24, 2012

 

 

1.       Introduction

 

PI Advanced Computing Engine (PI ACE) is designed for users with basic programming knowledge. Most calculations can be done within the ACECalculations() routine. Even code that has been debugged and found to be generally working may fail or not always deliver the expected results. Troubleshooting timing issues or dependencies from previous events using debugging can be painful and may not help at all understanding runtime failures. Hence one requires convenient methods to allow capturing and logging information during runtime. This is where the LogPIACEMessage() method from OSIsoft.PI.ACE.PIACEBIFunctions class comes into play.

 


 

2.       A word of caution and recommendation on logging

 

On large systems there may be a lot of log messages. Please only turn on logging when required i.e. for testing and debugging purposes and turn it off at other times. Logging slows down performance. This is because there are additional tasks to perform but without logging we are lost in understanding what's going on. This becomes more and more important an increasing number and increasing complexity of calculations.

 


 

3.       Log levels

 

LogPIACEMessage() supports 7 different log levels. 6 of them can be switched on and off per PI ACE Manager for a specific Context during runtime. There is no need for recompilation or for re-starting the related PI ACE Module. Not all of the existing log levels are considered relevant for the usage within your PI ACE code, meaning that levels considered not relevant are used by PI ACE to provide additional information when enabled.

Description

Message type string

Can be switched on and off through PI ACE Manager

Relevant

Errors

mlErrors

No (always on)

Yes

Warnings

mlWarnings

Yes

Yes

Updates

mlUpdates

Yes

Yes

User Messages

mlUserMessage

Yes

Yes

Counter Information

mlCounterInfo

Yes

No

Notification

mlInterProcessCommunication

Yes

No

Calculation Events

mlCalculationExecuted

Yes

No

 

 

4.       Importing  MessageLevel namespace and PIACEBIFunctions class

 

Since I expect that most users will be using Visual Studio .NET, I am concentrating on this development environment but note that PI ACE logging functionality is also available when using Microsoft Visual Basic 6.

 

When creating a new PI ACE Module, the PI ACE Wizard creates a new VB .NET library project, adds a reference to OSIsoft.PIACENet library, and imports the OSI.PIACE namespace.

 

The first thing that I recommend to do within a new PI ACE project is importing the MessageLevel namespace and the PIACEBIFunctions class.

 

 

 
Imports OSIsoft.PI.ACE.PIACEBIFunctions
Imports OSIsoft.PI.ACE.MessageLevel

 

 

This is not a mandatory step but helps keeping code lines short and having a clear view to your project. The following code snippet is without the import:

 

 

 

 

 
PIACEBIFunctions.LogPIACEMessage(OSIsoft.PI.ACE.MessageLevel.mlErrors, ex.Message, Me.Name)

 

 

With the recommended imports it looks like this:

 

 

 

 

 
LogPIACEMessage(mlErrors, ex.Message, Me.Name)

 

 

5.       Exception handling

 

Exception handling is very easy with Visual Studio .NET. I strongly recommend using it. After all I like to know why my code is failing and control output behavior on error:

 

 

 

 

 
    Public Overrides Sub ACECalculations()
        Try
            '****************************
            '* Place your ACE code here *
            '****************************
        Catch ex As Exception
            LogPIACEMessage(mlErrors, ex.Message, Me.Name)
        End Try
    End Sub

 

 

Without using the above code snippet exceptions will be handled but the PI Message Log will only contain "Error" messages about the failing module and may not tell me enough information to troubleshoot the failure.

 

Another good practice is disabling ACE outputs when we don't want "Calc failed" written to the output tags. If ACE outputs are not disabled, "Calc failed" will be written to outputs by ACE when no values are written to them by the ACE calculation logic, possibly due to the code failing. So let's enhance above example accordingly.

 

 

 

 

 
    Public Overrides Sub ACECalculations()
        Try
            '****************************
            '* Place your ACE code here *
            '****************************
        Catch ex As Exception
            SendDataToPI = False
            LogPIACEMessage(mlErrors, ex.Message, Me.Name)
        End Try
    End Sub

 

 

6.       Creating custom messages -  some examples

 

Besides mlErrors to capture exceptions, one may use mlWarnings and mlUserMessage.

 


 

6.1   Example Warning: Input out of range

 

Let's assume an input is supposed to be between 0 and 200. By switching on Warnings, I like to see when the limits exceed.

 

 

 
If Input.Value < 0 Or Input.Value > 200 Then
       LogPIACEMessage(mlWarnings, "Input out of range (0..200): " & Input.Value.ToString(), Me.Name)
End If

 

 

6.2   Example Warning: Input hasn't received any update in the past 10 minutes

 

If the Input of my ACE calculation hasn't updated for a while, I like to see a corresponding Warning in the PI Message Log (with Warnings switched on for the Context). This example requires either a clock scheduled calculation or another input being the trigger in case natural scheduling is configured. Because we are dealing with PI Times I have added a reference to OSIsoft.PITimeServer library and the corresponding import: 

 

 

 
Imports PITimeServer


Dim prevTime As PITime
Dim timeDiff As Double
prevTime = Input.PrevEvent
timeDiff = ExeTime - prevTime.UTCSeconds
If (timeDiff > 600) Then
       Dim sLog As String
       sLog = "Input has not updated for more than 10 minutes" & vbCrLf
       sLog = sLog & "Last update at: " & prevTime.LocalDate.ToString()
       LogPIACEMessage(mlWarnings, sLog, Me.Name)
End If

 

 

6.3   Example User Message: Logging of values and Timestamps

 

 

This time I like to calculate the average of the 10 most recent events for the Input and write the result to the Output. This allows me seeing values and timestamps in the log, comparing them against archived values and validating results. Whenever I believe logging is necessary, I can enable User Messages for the corresponding Context in PI ACE Manager.

 

 

 
Dim sLog As String = vbCrLf
Dim inpTime As New PITime
Dim inpValue As Double
Dim outValue As Double = 0
Dim iLoop As Integer
inpTime.SetToCurrent()
For iLoop = 1 To 10
       inpValue = Input.PrevVal(inpTime)
       outValue += inpValue
       inpTime = Input.PrevEvent(inpTime)
       sLog = sLog & iLoop.ToString() & " - value: " & inpValue.ToString()
       sLog = sLog & " at " & inpTime.LocalDate.ToString() & vbCrLf
Next
Output.Value = outValue / 10
sLog = sLog & vbCrLf & "Result: " & Output.Value.ToString() & vbCrLf
LogPIACEMessage(mlUserMessage, sLog, Me.Name)

 

 

7.       Maintaining PI ACE logging in PI ACE Manager

  • Launch PI ACE Manager

  • Browse to the ACE Context level (expand Server -> Scheduler -> Library -> Module -> Context)

  • Right click the context and select "Message Log Level ..."

 4617.ACE_5F00_EnableLogging.jpg

  • Setting Message Log Level

 3146.LogLevels.jpg

  • Confirm by clicking [OK]

A change in log level will be reported in the PI Message Log as follows:

 

I 31-Aug-12 11:32:47 PIACEClassLibraryHost                                                                          (0)
 >> ACEDebug: Set message log level for ACE Context NEMESIS\ACEDebug\ACEClassDebug\\\NEMESIS\ACE\Debugging to 65

 

 

 

 

 

8.       Looking into the PI Message Log

 

We recommend using pigetmsg.exe on the PI ACE Server to monitor the PI Message Log continuously (pigetmsg -f) when working with PI ACE (developing Modules, maintaining ACE using PI ACE Manager).

 

Especially on larger systems with multiple ACE modules running the amount of messages may be confusing because there are many messages being logged at the same time causing the command prompt scrolling fast what makes it difficult seeing messages that are related to what one is currently working at.

 

I will write some guidance on effectively analyzing the PI Message Logs in a later blog post - stay tuned.

 

There are multiple options to filter messages with the pigetmsg.exe command line utility. One of the most useful ones is filtering by the Process ID:

 

 2630.ACEManagerProcessID.jpg

 

Please note that each time an ACE Module is started a new process ID is assigned to the PIACEClassLibraryHost.exe process. Be sure using the current process ID

 

8321.CMD_5F00_ACE_5F00_LOG1.jpg.

 

 

 

9.       Logging to a PI Tag

 

You may like the idea logging debug information to a PI tag. When doing so, please use a tag of type Digital and a correspondent Digital State Set whenever possible. It is possible using tags of string data types as well but please keep in mind that string tags consume a lot of space in archives because each single character will require one byte. If you decide to use string tags for debugging purpose, please consider setting the archiving tag attribute to 0 (off). Whenever necessary you can set it back to 1 (on) temporarily. Setting archiving to off means that no historical data events will be recorded in the PI Data Archive and only the latest value will be available

 

The following example is meant to be complementary to the one provided with 6.1 "Example Warning: Input out of range" and 6.2 "Example Warning: Input hasn't received any update in the past 10 minutes". The output tag referred to with Alias "Debug" is of type Digital and has the "SYSTEM" Digital State Set assigned. In case the input drops below zero, "Under Range" will be reported. In case the output goes above 200, we will recognize "Over Range". When the current snapshot is neither under range nor over range we check if it might be older than 10 minutes (600 seconds) and if it is status "Unit Down" will be reported by the debug tag. "Debug" will report "Good" status in case of good "Input".

 

 

 

 

 
    Public Overrides Sub ACECalculations()
        Try
            If Input.Value < 0 Then
                Debug.Value = Debug.StateNo("Under Range")
            ElseIf Input.Value > 200 Then
                Debug.Value = Debug.StateNo("Over Range")
            Else
                Dim prevTime As PITime
                Dim timeDiff As Double
                prevTime = Input.PrevEvent
                timeDiff = ExeTime - prevTime.UTCSeconds
                If (timeDiff > 600) Then
                    Debug.Value = Debug.StateNo("Unit Down")
                Else
                    Debug.Value = Debug.StateNo("Good")
                    output.Value = Math.Sqrt(2) * Input.Value
                End If
            End If
        Catch ex As Exception
            SendDataToPI = False
            LogPIACEMessage(mlErrors, ex.Message, Me.Name)
        End Try
    End Sub

 

 

10.   A complete example

 

Finally please find the complete code of example 9. "Logging to a PI Tag" for your reference:

 

 

 

 

 
Imports OSIsoft.PI.ACE
Imports OSIsoft.PI.ACE.PIACEBIFunctions
Imports OSIsoft.PI.ACE.MessageLevel
Imports PITimeServer

Public Class ACEClassDebug
    Inherits PIACENetClassModule
    Private output As PIACEPoint
    Private Input As PIACEPoint
    Private Debug As PIACEPoint
    '
    '      Tag Name/VB Variable Name Correspondence Table
    ' Tag Name                                VB Variable Name
    ' ------------------------------------------------------------
       ' Debug                                   Debug
       ' Input                                   Input
       ' output                                  output
    '

    Public Overrides Sub ACECalculations()
        Try
            If Input.Value < 0 Then
                Debug.Value = Debug.StateNo("Under Range")
            ElseIf Input.Value > 200 Then
                Debug.Value = Debug.StateNo("Over Range")
            Else
                Dim prevTime As PITime
                Dim timeDiff As Double
                prevTime = Input.PrevEvent
                timeDiff = ExeTime - prevTime.UTCSeconds
                If (timeDiff > 600) Then
                    Debug.Value = Debug.StateNo("Unit Down")
                Else
                    Debug.Value = Debug.StateNo("Good")
                    output.Value = Math.Sqrt(2) * Input.Value
                End If
            End If
        Catch ex As Exception
            SendDataToPI = False
            LogPIACEMessage(mlErrors, ex.Message, Me.Name)
        End Try
    End Sub
 
    Protected Overrides Sub InitializePIACEPoints()
              Debug = GetPIACEPoint("Debug")
              Input = GetPIACEPoint("Input")
              output = GetPIACEPoint("output")
    End Sub
 
    '
    ' User-written module dependent initialization code
    '
    Protected Overrides Sub ModuleDependentInitialization()
    End Sub
 
    '
    ' User-written module dependent termination code
    '
    Protected Overrides Sub ModuleDependentTermination()
    End Sub
End Class

Outcomes