Tag Archives: IDE

Profile logging updates in OpenInsight 10.2

Previous releases of OpenInsight have included a simple logging system that records all stored procedure calls and the time taken to execute them. This logging system is enabled by creating a blank file called “RevProfile.log” in the OpenInsight directory before the application is started. If this file is present when the system boots it creates a new log file (with a name based on the application’s Windows Process ID) and writes all stored procedure activity to it until the application is stopped.

Whilst this can be a useful tool it does suffer from a few issues:

  • The log file records all activity. This usually results in very large files that are difficult to navigate and process, making them very tedious to use.
  • There is no facility to annotate parts of the log, so it can be difficult to narrow down the actual section of code that needs to be profiled.
  • The profile timing uses the classic Windows “tick count” which has a granularity of 16ms. Many stored procedures take much less time to execute than this, so entries in the log can be wildly inaccurate, usually appearing as “0ms” or “16ms”.
  • There are no tools to actually parse the log so that it can be analyzed more easily.

With this release of OpenInsight we have provided some new functionality to address these issues, namely:

  • The “RevProfileLog” function, and
  • The “RevProfile Log Analyzer” form.

In this post we’ll take a look at these additions and examine how they can help in your application development.

The RevProfileLog function

This is a new stored procedure for version 10.2 that allows much greater control of the profile logging process and offers the following benefits:

  • It can be started and stopped as needed, allowing the scope of recording to be narrowed to a critical area (we call this “Dynamic Logging“, as opposed to the old way of profile logging mentioned above, which we call “Static Logging“).
  • The log file can be created using a custom name and location.
  • The file can be appended to each time it is started, or cleared.
  • The log can exclude specific stored procedures.
  • The log can record notes against a specific stored procedure to help identify a particular call in the log.
  • The log can record arbitrary text in the file to help with subsequent analysis.

All of this is controlled via the new RevProfileLog stored procedure (this is compiled as a subroutine so has no return value):

Call RevProfileLog( Method, Param1, Param2 )

The Method parameter is a numeric value that specifies the logging operation to perform; the Param1 and Param2 parameters depend on Method as described below:

1Start Log: Starts the profile logging activity.The name of the log file to use or create.A boolean flag – if TRUE$ then the log file is cleared before use. Defaults to FALSE$.
2Stop Log: Stops the profile logging activity.N/a.N/a.
3Set Note: Appends text to the next stored procedure call written to the log. It is reset to null afterwards.The note text.N/a.
4Output Text: Outputs text to the log.The text to output.The indent to output to. Specify “-1” (the default) to output at the current indent, otherwise specify a value between 1 and 256 if desired.
5Exclude Proc: Prevents a stored procedure from being included in the log file.The name of the stored procedure (upper- case).N/a.
6Include Proc: Removes a stored procedure from the list of excluded stored procedures so that it may be written to the log again.The name of the stored procedure (upper-case).N/a.
7Clear Excluded: Clears the excluded stored procedure list.N/a.N/a.

Equates for these methods can be found in the RTI_REVPROFILE_EQUATES insert record.

Example: Profiling a call to Get_Property

Compile Subroutine Test_RevProfileLog( void )

   Declare Function Get_Property
   $Insert RTI_RevProfileLog_Equates
   $Insert Logical
   LogFile = "c:\temp\test_revprofile.log"
   // Create the log file and clear it before it is written to:
   Call RevProfileLog( RPL_STARTLOG$, logFile, TRUE$ )
   // Let's not see any RTP57/A calls (if any)
   Call RevProfileLog( RPL_EXCLUDEPROC$, "RTP57" )
   Call RevProfileLog( RPL_EXCLUDEPROC$, "RTP57A" )
   // Add a note so we can see why we are calling Get_Property
   Call RevProfileLog( RPL_SETNOTE$, "Getting SYSTEM VERSION" )
   Version = Get_Property( "SYSTEM", "VERSION" )
   // Add some text to the log, but don't indent it.
   Call RevProfileLog( RPL_OUTPUTTEXT$, "Done with this log now ***", 0 )
   // Stop the log
   Call RevProfileLog( RPL_STOPLOG$ )


Produces the following log file:

				OEREQINFO 0.15
				OEREQINFO 2.29 2.14
			PS_GET_PROPERTY 2.31 2.19
				OEREQINFO 2.32
				OEREQINFO 2.42 0.10
			PS_GET_PROPERTY 2.43 0.12
				OEREQINFO 2.44
				OEREQINFO 2.53 0.09
			PS_GET_PROPERTY 2.55 0.11
				OEREQINFO 2.56
				OEREQINFO 2.65 0.09
			PS_GET_PROPERTY 2.66 0.11
			RTP65 2.67
			RTP65 2.67 0.01
				OEREQINFO 2.69
				OEREQINFO 2.78 0.09
			PS_GET_PROPERTY 2.79 0.11
		GET_PROPERTY 2.80 2.80
>> Done with this log now ***

Things to note:

  • Text lines added with the “Output Text” method are prefixed with a “>>” string to denote that they are text.
  • The timings now use the Windows high resolution “QueryPerfomanceCounter” functions to record timings, so the results are far more accurate and we’re now reporting at a 100th of a millsecond.
  • The indenting does not begin at “level 1” because the system call stack was already several levels in before logging was started.
  • Calls to RevProfileLog itself are always excluded.
  • As we mentioned above we call the original method of profile logging “static logging” (i.e. create a file called “RevProfile.log” and record everything). This feature still works in the same way, but with the added bonus of using the improved timings and respecting all of the RevProfileLog function methods except for the “Start Log” and “Stop Log” methods. They are ignored during static logging.

The RevProfile Log Analyzer form

This is a new form (called RTI_IDE_ANALYZE_PROFILELOG) that can parse a RevProfile log file and present the information in a format that is easy to use.

For example, here is the small log file example shown above processed and loaded into the form:

An image of the RevProfile Log Analyzer form (RTI_IDE_ANALYZE_PROFILELOG).

Using this form is fairly simple: just select the log file you want to analyze and wait for the form to parse and process the information. Once this has been done the data from the log is presented in two sections:

  1. The Call Trace Log (on the left), and
  2. The Stored Procedure Call Details (on the right)

The Call Trace Log

This is a TreeListBox control that shows the sequence of calls along with the time taken for that call. It mirrors the structure of the actual log file and displays text notes using a different icon (a green globe), rather than the blue one used for stored procedure calls.

Double-clicking on a stored procedure call selects it in the Stored Procedure Call Details section on the right.

The Stored Procedure Call Details

This section comprises two EditTable controls:

  • The top one contains a list of all the stored procedures found in the log, along with the number of times each was was executed and the total time spent executing.
  • The bottom one details the individual calls to the selected stored procedure – each entry in the table shows the index of the call in the Call Trace Log, the line number in the actual log file where the call was recorded, and the time taken by that call. Double-clicking a call selects the matching entry in the Call Trace Log opposite.

Things to note

  • Both edit tables support sorting via double-clicking on the appropriate column header.
  • Annotated stored procedure calls (i.e those with a note added to them via the RevProfileLog “Set Note” method) are separated from calls to the same stored procedure that are not annotated. This is to ensure that it is easy to isolate and find them in the output.

Very large log files – a cautionary note

RevProfile log files can grow rather large, especially the “static” log files that record the entire lifetime of the application. Whilst these files can be easily read and parsed in smaller chunks, representing their call trace structure in a something like a TreeListBox control can be challenging due to the time taken to load items. For example, something like a 15MB log file with nearly 200,000 calls may take several seconds to appear in the control once the log has been parsed and we set the control’s LIST property (i.e. “Loading call trace list …” appears in the progress bar), and the UI may appear frozen. This is not the case – if you are loading a very large file be sure to exercise a little patience before you reach for the Task Manager!


The new RevProfileLog function provides much better and much-needed profile logging functionality to OpenInsight, making the information much easier to use, and we’re sure it will help you improve the performance of your applications.

(This functionality is available in OpenInsight 10.2 from the Beta 3 release onwards)

A tour around the updated IDE Database Toolpanel

Contrary to popular belief, or indeed the evidence of your own eyes, this blog is still actually alive, so in the next few posts we’ll try and look some of the work that’s been going on behind the scenes for the next release. In this post we’ll take a quick tour around the IDE Database Toolpanel that’s had a much-needed face-lift to improve it’s usability:

New Database Toolpanel
Updated IDE Database ToolPanel

As you can see it looks a little different now – we’ve updated the artwork, and you can see that different table types have different icons:

  • Dictionary tables have a purple book overlay marker
  • Index tables have a green book overlay marker
  • The different data-source types (RTP57, SysColumns, DSBFS etc) have their own icons

We’ve also changed the layout and size of the toolbar buttons so there are five that fit much better into the IDE. From left to right these are:

  • New table
  • Add table
  • Alias table
  • Save database definition
  • View options

The View options button loads a dialog as a “dropdown panel” that defines what you see in the table list:

Database Toolpanel View Options

Most of these are self evident, but the “Group by table name” option is new – it simply controls how tables are sorted in the list – when the box is checked the data, dictionary and index tables appear together, when unchecked they appear in proper ascending alphabetical order (Implementing this dialog as a “dropdown panel” is an interesting exercise in it’s own right and we covered this here).

The filter box remains the same – simply start typing to restrict the list to those table names starting with the same string:

Database Toolpanel Filter

We’ve also given the context menu an overhaul, both visually and in terms of making it more context aware based on the table that you right-click on (only enable index options for index tables, verify options for LH tables and so on):

Database Toolpanel Context-menu

Underneath the hood there are a few other changes – including how this toolpanel is updated based on changes to the database, and when warnings about saving the database definition are given. Hopefully you’ll find using this part of the IDE easier in the next release.

Using Evaluate Notes in the IDE – making a “To-Do” list

One of the goals of OpenInsight 10 was support better integration between the development tools and the Repository, which is why we provided a separate “Repository” tab for entities when they are opened in the IDE, thereby making their attributes easier to view and edit.

This in turn allowed us to expose a Repository feature called “Evaluate Notes”, which has actually been part of OpenInsight since version 2, but was only really used by some system processes (mainly the old and deprecated “Impact Analysis” feature) and provided no user interface to allow editing.  This has now been rectified and is available from the Repository tab as you can see here:

Evaluation Notes

The Evaluate Notes functionality is composed of two parts – an “Evaluate” flag, and the notes themselves. The latter is simply a text field where you may record your notes and have them attached to the entity in question, e.g:

Evaluation Notes editor

The Evaluate flag, when set to True, adds the entity into one of the Repository indexes so that a list of entities with that flag can be obtained quickly.

It is then a simple matter to query this index and obtain a list of all entities flagged “in need of evaluation”, which you can actually treat as a “to-do” list if you wish.  We already provide this list in the IDE by means of the “Evaluate” tab in the “Quick Launch” tool panel as you can see below:

Quick Launch Evaluate Tab

Quick Launch Evaluate Tab

Hopefully this is a feature you find as useful as we do!