Performance Log Viewer - Intergraph Smart 3D - Troubleshooting

Intergraph Smart 3D Troubleshooting Reference

Language
English
Product
Intergraph Smart 3D
Subproduct
Troubleshooting
Search by Category
Troubleshooting
Smart 3D Version
11 (2016)

The Performance Log Viewer is a tool that displays timing data from contributing components of the software. These components include symbols such as naming rules, reports, drawings, labels, and IFC rules. These components contain PerfTrace trace statements that bracket code that has been deemed as important for measuring performance. Hence the components are themselves responsible for generating the performance timing information. When critical methods are invoked on these components, timing information is gathered and written to a log file. The Performance Log Viewer reads this file and displays the performance information as shown in the following illustration:

The performance information can be displayed for the entire file (which corresponds to a single invocation of the software). You can also select a specific interval and see the performance information that was logged during that interval.

Important classes of components that log performance data are known as content, to distinguish them from the software executable. Examples of content are symbols, naming rules, reports, and drawings. A major motivation for creating the Performance Log Viewer was to provide a way to identify any content code that might be significantly impacting performance.

Operation

Start Performance Log Viewer by locating the executable in C:\Program Files\SmartPlant\3D\Core\Tools\Administrator\Bin\Assemblies\Release

To run the log, double-click PerfLogViewer.exe, and open a performance log file (.plg) by clicking Browse. By default the software saves these files in the %TEMP% folder. The four types of intervals that the Performance Log Viewer shows are:

  • AppInterval - Corresponds to the entire file.

  • Command - Corresponds to the time a specific command was active. Different invocations of the same command create separate intervals for each invocation.

  • Workflow - This is an interval defined by markers in the file. It determines the performance timing over a group of operations.

  • UserWorkflow - This is an ad hoc interval that is created and controlled by the end user. You can identify an interval and associate it with some set of operations that are subsequently performed.

    Creating user workflows is not supported in the initial release.

When you click on an interval, the Sorted times grid displays all the components that logged information during that interval. If you select a single row in the Sorted times grid, then the methods associated with that component are displayed in the Details grid. It displays the number of calls for each method, the total time spent in the method, and the average time per call.

Only a single interval may be selected at a time.

If you select multiple rows in the Sorted times grid, you can use CTRL+C to copy the displayed information and paste it in an Microsoft Excel spreadsheet, complete with headers for the columns. Also, when you select multiple rows, you can right-click the mouse to use the Copy command. This feature is also enabled for any multiple row selection in the Details grid.

Time vs. Log Time

An interval has a Time and a Log Time. Time refers to the wall-clock time that elapsed for the interval. During this wall-clock time, components might have logged time for certain operations or methods. The sum of all the time logged during an interval is called the Log Time for the interval. It is generally much less than the wall-clock time.

Components only log methods and operations that might have potential impact on performance. The total Log Time for an interval reveals how much time was spent on computationally intensive operations, and is a better indicator of potential problems.

Categories

Different components that log performance information belong to one of a set of pre-defined categories. This list is multi-select. When you select a set of categories, the Sorted times grid and the Details grid are redrawn to show only components that are in the selected categories. Some of the categories are NameRule, StyleRule, Symbol, CAD, Lable, Report, RefDataRule, SmartOccurrence, Drawings, and IFC.

Interval

The Interval grid displays the interval Name, the Time (length) of the interval, and the Log Time for the interval. Log Time refers to the total amount of time logged by components during the interval. Time is the wall clock time consumed by the interval. For example, if the interval is a command (say, WrkSpDefCmd, the Define Workspace command), then Time will be the total time taken to run the command. Log Time will only consist of the time logged by all the components activated during the command (WrkSpDefCmd), (and these would normally only log their performance data after OK is clicked).

It is possible for some intervals to be nested within other intervals. Some intervals are created to gather performance data for a specific set of processing. If one of these intervals starts during a command interval, then it appears as nested within the command interval. To show this, Performance Log Viewer indents the nested interval, preceding the nested interval name with a “+” for each level of nesting. Because all intervals are nested within the over-arching AppInterval, there is a nesting indicator on very interval. For example,

AppInterval
+ Command: WrkSpDefCmd
++ DefineWorkSpace: Full Update
+ Command: CCAppRefreshView

Sorted times

The Sorted times grid displays information for a specific component that has logged performance information during the selected interval. The information displayed is:

  • Component - This is usually the ProgID of a COM component (for instance, a Symbol or a NameRule). It might also be the name supplied by a developer for a coordinated unit of processing. For example, in the Drawings category, Drawings developers have component names like “Prepare Document” and “Run Annotation”.

  • Category - The category this component is associated with.

  • Total Time Logged - This is the sum of all time logged for this component during the selected interval. Generally, this figure should be equal to the sum of all method listed for this component in the Details grid.

  • % Intrvl Time - This is the percentage of time the component consumed of the wall-clock time for the interval. Thus, if the interval Time (not Logged Time) was 100 seconds, and this component had logged 1 second during the interval, % Intrvl Time would be 1%.

  • % Log Time - This is the percentage of time the component consumed of the logged time for the interval. Thus, if the interval Logged Time (not just Time) were 10 seconds, and this component had logged 1 second during the interval, % Log Time would be 10%. % Log Time is generally more important than % Intrvl Time, it reveals how much components contributed to the real processing performed during the interval.

When you click one of the headers in the Sorted times grid, the entries are ordered based on the values in that column. For example, clicking on Component alphabetizes the entries, clicking on Total Time Logged orders them according to how much time each component logged. Clicking the header again reverses the ordering (descending to ascending and vice-versa). By default, the components are ordered by descending values in the Total Time Logged column. The next time you run the program, Performance Log Viewer uses the same order you used the last time.

Details

The Details grid displays performance information for all the methods of the selected component that logged during the interval. The information presented is the Method Name, the Total Time consumed by all calls to that method during the interval, the # Calls that were made for this method and the Avg. Time for each call.

Like the Sorted times grid, when you click one of the headers in the grid, the entries are ordered based on the values in that column, and you can also control whether the values are presented in descending or ascending order.

When Performance Log Viewer is running in End User mode, the methods shown are restricted to those relevant to an end user. In Development mode, all logged methods are shown.

Options

Click Options to displays the PerfLog Viewer Options dialog box.

In this dialog box you can:

  • Enable/Disable performance logging.

  • Set the base file name of the performance log file

  • Toggle whether commands intervals are displayed. By default, they are displayed.

  • Toggle whether View Commands are displayed. By default, they are not displayed.

The performance log file is always written into the %TEMP% folder. Each invocation of the software creates a new file, and the file name reflects the time it was created. However, you can specify the base portion of the file name. The intent is to create a base file name corresponding to some scenario for which you want to measure performance. For example, if you specified “MDRPerformance” as the base file name, then an individual performance log file (11 Nov 2011) might be named “MDRPerformance_2011_11_11_15_59_56.plg”.

By default, command intervals are displayed, because many interesting performance-related operations take place during the execution of individual commands. You can also disable the display of command intervals. This might be useful, in case you are interested in IFC performance parameters, which are not tied to specific commands.

View Commands, on the other hand, do not generally result in useful performance-related data, because components are not usually invoked during a view manipulation. Instead, the display engine merely manipulates the display artifacts on the screen. The underlying software components are not involved. So by default, View Commands are not displayed.