Extensible Stats Diagnostics

Bounds Reports

A bounds report is used to call out any shaders that have inaccurate bounds. When displacement is done within a shader, a bound is used by PRMan to efficiently process the displacement. A bound that is too low can cause visual artifacts because geometry outside the bound may not be rendered. A bound that is too high will make the bounding volume too big and prevent efficient culling of the geometry from calculations, degrading performance. For each shader, the number of objects where the displacement is too high and too low is reported, along with the average ratio of actual displacement to the bounds provided. Detailed bounds reports can be viewed by opening the XML statistics file in an appropriate web browser.

Cache Reports

There are several caches used by PRMan to accelerate access to various assets. If the cache is too small, your hit-rate will go down, decreasing performance rapidly. The diagnostics script will use the statistics to estimate a hit-rate to detect these problems. The hit-rate estimate will remove compulsory hits when possible, so the best hit-rate is a full 100%. The cache classification is done for the following caches:

• GUT(Geometry) cache
• Texture cache
• Deep Shadow cache
• Point Cloud cache
• Octree Node cache
• BrickMap cache

Pushed Grids Report

This report compares the number of grids pushed to those diced. In the best case, a grid will be diced once and handled entirely in the bucket, resulting in a pushed to diced ratio of 0. If we assume that every grid doesn't quite fit into a single bucket, this could lead to pushing into each unprocessed neighbor bucket - on average about 4 pushes. Motion blur or extreme displacements can increase this number, but overly-conservative bounding boxes will also increase pushes. A ratio greater than 4 will be reported here, indicating that performance may be improved with a larger bucket size.

CPU Usage Report

This report compares the time spent by threads of the renderer doing computation to the actual wall-clock time of a render (times the number of threads). Any time not spent doing computation is time that a thread is waiting - it could be waiting for a disk read to complete, a lock to be acquired, or simply to be scheduled on the CPU while other processes/threads are running. If more than half of the render time is spent waiting, the value will be reported as wait bound.

Modules

The diagnostics are designed to be provided as modules. If no modules are provided on the command line, the default will be loaded from $RMANTREE/bin/diagnosticModules/defaultModule.py. You can create your own modules in Python and use them instead with the -M command line option. As an example, let's say we want to use two modules, one in:

$RMANTREE/bin/diagnosticModules/memMod.py

and the other in:

~/lib/myShaderMod.py

Assuming ~/lib/ is in your PYTHONPATH, you can use these modules with the command line:

statsdiag.py -M diagnosticModules/memMod:myShaderMod stats.xml

When loading a module, the statsdiag.py script looks for a method with the following signature and executes it:

def initializeExtension(options, filters, frameReports, globalReports, numFrames):

The options arg is the object that is the result of using the Python optparse library to parse the command line arguments. The filters, frameReports, and globalReports are used to customize the output. The numFrames argument provides the number of total frames that are in this XML file to be processed. The modules are initialized in the order given on the command line. To be composable, a module should only add to filters, frameReports, and globalReports, not remove or overwrite with new instances.

For each frame of the report, all of the filters are first run on the statistics for that frame in an unspecified order, then the per-frame reports are called to generate output in the order they are specified by the frameReports list. This two-pass approach allows you to collect statistics from several sub-trees and combine them in the output in a well-defined order. After all of the frame reports are generated, the global reports that can accumulate data across all frames are run in the order defined by the globalReports list.

The statistics XML file is parsed into data-structures like those described in Appendix B of Using XML Frame Statistics. They can be included in your module, along with other useful definitions, with the following import:

import diagnosticModules.util

Filters

A filter is used to gather data from sections of the statistics file. Users can specify the nodes to filter over by binding it in the filters dictionary. The dictionary is a map from node names (the name attribute in the XML statistics) to a list of filters that should be run on nodes of that name.

filters["<node name>"] = [myFilter1, myFilter2, myFilter3]

It is important to note that names of nodes are not guaranteed to be unique, so a filter may be run on multiple nodes in the same frame. Additionally, the filter will need to distinguish the nodes through some sort of processing.

Filters support the following methods:

newFrame(self)

summarize(self, node, options, frameNum)

Frame Reports

A frame report is used to output processed data on a frame-by-frame basis. It can use any local or global information available to generate output. It is recommended that you use diagnosticModules.util.printf, diagnosticModules.util.printstr or write to``sys.stdout`` to generate output that will print to the appropriate location. A frame report is guaranteed to run after all filters have been run on the current frame and after any frame reports that occur before it in the frameReports list. A frame report object can be added in initializeExtension like so:

frameReports.append(myReport)

A frame report can be any object that supports the following methods:

newFrame(self)

reportFrameResults(self, options, frameNum)

Global Reports

A global report is used to output processed data after all frames have been reported on. It can accumulate data across frames to produce a total report. As with frame reports, it is recommended that you used the provided printf, printstr or write to sys.stdout for output. It is guaranteed to run after all filters and frame reports for all frames have finished, and all reports that precede it in the globalReports list. A global report object can be added in initializeExtension like so:

globalReports.append(myGlobalReport)

A global report can be any object that supports the following methods:

accumulateFrame(self, options, frameNum)

reportGlobalResults(self, options)

Simple Line Report Module

The most basic customization involves leveraging a class called LineReport in util to create a module that prints out data per-frame, based on a format string and a list of statistics. Our module, dubbed customModule, will print out the frame number, the total number of frames in the XML file, the elapsed time, and the number of threads used to render. Here is the entire code for the module:

import diagnosticModules.util as util

def initializeExtension(options, filters, frameReports, globalReports,
                        numFrames):

    statsList = [("frameNumber", "frame-%d-"),
                 ("numberOfFrames", "(%d tot)"),
                 ("timers/totaltime.elapsed", "time %2.2f"),
                 ("options/threads", "threads %d")]

    reportFormatString = "%s of "+", ".join((len(statsList)-1)*["%10.10s"])+"\n"

    util.CreateLineReport(options, filters, frameReports, globalReports,
                        numFrames, statsList, reportFormatString)

Running this with (assuming it is saved in $RMANTREE/bin/diagnosticModules):

statsdiag.py -M diagnosticModules/customModule stats.xml

will produce something like:

frame-1- of    (3 tot), time 21.14, threads 16
frame-2- of    (3 tot), time 20.02, threads 16
frame-3- of    (3 tot),  time 6.16, threads 16

The first few lines are straightforward, importing the utility code and declaring the function that will be called by statsdiag.py.

The next two assignments are setting up arguments for the call to util.CreateLineReport, which does all the heavy lifting. CreateLineReport takes the options, filters, frameReports, globalReports, and numFrames passed in to the initializeExtension method. In addition, it takes a list of tuples and a string. The list is composed tuples describing statistics you want extract from the XML file, in the order you want them to appear in the report. Each tuple consists of a path to the statistic and a format string. For each frame the statistic will be extracted and formatted according to the format string. The path to the statistic does not need to be the entire path, but it does need to be long enough to uniquely identify the statistic to be extracted. In addition, there are two special values that can be used: frameNumber and numberOfFrames. These will be filled in with the number of the current frame being processed, and the number of frames total being processed. For multiple frames in a single file, the frame numbering will start at 1. If there is only a single frame, it will be numbered 0.

The reportFormatString argument specifies how each of the strings created from the extracted statistics will be combined together. The line shown is just an adjustable way of specifying the formatting string "%s of %10.10s, %10.10s, %10.10s\n".

By changing the format string, you can quickly re-target your data output for different applications. The above example is formatted for review, but it could easily be changed to ", ".join(len(statsList)*["%s"])+"\n" to create a comma separated value list to be used in a spreadsheet or plotting tool such as gnuplot. The data could even be formatted as an SQL database entry command using something like "INSERT INTO render_stats ("+ ", ".join(len(statsList)*["%s"])+")\n".

Basic Filter

To create your own custom filter, you have to define at least three things:

1. an initializeExtenstion function to add your custom filter and report
2. an object defining summarize to extract the data of interest, optionally with a newFrame method to reset the collection per frame
3. an object defining reportFrameResult to format and output the data

The second two can even be the same object, as demonstrated in this example, which extends two simple classes from the util package to provide the resetting and reporting functionality:

class BaseFrameInit:
    def __init__(self):self.newFrame()
    def newFrame(self):
        pass

class SimpleFrameReportSummary(BaseFrameInit):
    def newFrame(self):
        self.report=[""]
    def reportFrameResults(self, options, frameNum):
        reporttxt = "".join(self.report)
        printstr(reporttxt)

The BaseFrameInit class ensures that all data fields reset according to the per-frame reset mechanism on creation. The SimpleFrameReportSummary defines a reporting mechanism that uses a list of strings named report as a string buffer. This list of strings is concatenated into a single string and sent to the appropriate output using the printstr function, also part of util. Any class that inherits from SimpleFrameReportSummary simply needs to append output strings to the report variable, and it the output will be reported and cleared at the appropriate times.

The example is the full code for the example filter:

import diagnosticModules.util as util

PUSHED_PER_DICED_REPORT_THRESHOLD = 4

class PushedGridsSummary(util.SimpleFrameReportSummary):
    """
    Collects and reports the amount that grids are pushed across buckets.
    """
    def summarize(self, section, options, frameNum):
        statNames = ["nGridsPushed","nGridsDiced"]
        [pushed,diced] = util.readSimpleChildren(statNames, section)
        pushedThreshold = PUSHED_PER_DICED_REPORT_THRESHOLD
        if(diced!=None and diced>0):
            ratio = float(pushed)/float(diced)
            if(ratio>pushedThreshold):
                quality = "MEMORY INTENSIVE"
            else:
                quality = "GOOD"
            if(ratio>pushedThreshold or options.verbose):
                util.lprintf(self.report,"Grids Pushed to Diced Ratio: "
                        " %4.2f      %s\n",ratio,quality)
        else:
            if(options.verbose):
                util.lprintf(self.report,"Grids Pushed to Diced Ratio: "
                        "           NOT USED")

def initializeExtension(options, filters, frameReports, globalReports,
                        numFrames):
    # Create the filter
    pushedGrids = PushedGridsSummary()

    # Set up the section->filter mapping for extracting statistics
    filters["reyes"] = [pushedGrids]

    # Set up the per frame reports
    frameReports.append(pushedGrids)

The first line imports the utility module to make SimpleFrameReportSummary available for use. Next, the filter PushedGridsSummary is defined and relies on SimpleFrameReportSummary functionality to produce reports. This means that the filter only needs to extract the data and put formatted strings into the report field of the filter.

The purpose of this filter is to examine the number of grids that are being pushed into other buckets. The REYES algorithm works most efficiently when the scene is easily rendered a single bucket at a time, and so PRMan attempts to split the geometry down into grids that fit in a single bucket. However, grids near the edge may cross bucket boundaries, or a displacement may move the grid, resulting in a "push" to another bucket where the grid will actually appear. The nGridsDiced statistic, found in the reyes section of the statistics, provides a count of the number of grids created. The nGridsPushed statistic counts the number of times a grid is pushed into another bucket. A grid will be diced once, but may be pushed multiple times. A high number of pushes relative to the amount of dicing could indicate a frame that is challenging to render efficiently, and may render faster with larger buckets. This filter will check that ratio and report if it is above a threshold.

The filter uses the utility function readSimpleChildren. This function takes a list of statistic names and a section of the statistics (a StatsList object). It looks for statistics that are the immediate children of the section passed in and returns their values. Which statistics to look for and the return order are specified by the name list. Python's unpacking is used to store the values in pushed and diced. These values are used to compute a ratio that is checked against the threshold defined at the beginning of the code.

The options object is also passed in, and verbose is True when the user invokes the verbose flag on the command line. The filter here always prints the ratio out when verbose is True, but only reports ratios larger than the threshold otherwise.

The filter uses the utility function lprintf for output. This funcion is named to indicate it is a "list-printf". The first argument is the list that it should append the string to, the next argument is a Python formatting string, and the subsequent arguments are used to construct the formatted string, like a C-style printf.

The final block of code defines the module initialization function. First, a filter object is created. This object is added to the filters map under the reyes key because the nGridsPushed and nGridsDiced statistics are in the reyes section of the statistics. Each key must map to a list of filters to be run on that section, so we create a single element list containing our filter object. This object will handle both filtering and reporting, so it is also added to the end of the frameReports list, which is used by the script framework for creating the output report.

Combining Filter Results

The method used in the previous example works well when all of the data of interest fall in a single section in the XML statistics. Since that will not always be the case, this example demonstrates how to combine data from separate filters into a single report. This example is taken from the "wait-bound" report in the default filters. This report examines the amount of wall-clock time and compares it to the amount of CPU time used by the renderer. If the wall-clock time is greater than the CPU time, the time-difference between the two was spent waiting on something - I/O, locks, memory paging, et cetera - instead of actual render computation. In a multithreaded render, the computation time reported is accumulated across all threads, so the CPU time must be divided by the number of threads to make it comparable to the wall-clock time.

To create this report, we will have two filters - one for time and one for number of threads - and a per-frame report. The report will have access to both filters, and can pull the data required straight from them. Here is the source code for this example:

import diagnosticModules.util as util

DEFAULT_MIN_CPU_RATIO=.5

class ThreadSummary(util.BaseFrameInit):
    """
    Extracts the number of threads that were used for this execution.

    The number of threads is saved in numThreads.
    """
    def newFrame(self):
        self.numThreads = -1

    def summarize(self, section, options, frameNum):
        self.numThreads = section.value

class TotalFrameTimeSummary(util.BaseFrameInit):
    """
    Extracts the total time reported for each frame.

    The time is saved as a TimerStat object named totalTimer.
    """
    def newFrame(self):
        self.totalTimer = None

    def summarize(self, section, options, frameNum):
        for child in section:
            if child.name == "totaltime":
                self.totalTimer = child

class WaitBoundReport:
    def __init__(self, timeSummary, threadSummary):
        self.timeSummary = timeSummary
        self.threadSummary = threadSummary
    def reportFrameResults(self, options, frameNum):
        minCPURatio = DEFAULT_MIN_CPU_RATIO

        numThreads = float(self.threadSummary.numThreads)
        elapsed = float(self.timeSummary.totalTimer.elapsed)
        user = float(self.timeSummary.totalTimer.user)/numThreads
        system = float(self.timeSummary.totalTimer.system)/numThreads
        cpuRatio = (user+system)/elapsed
        if cpuRatio < minCPURatio:
            util.printf("CPU Report:  user-total ratio %4.2f"
                        "     LOW (Wait Bound)\n",cpuRatio)
        elif options.verbose:
            util.printf("CPU Report:  user-total ratio %4.2f"
                        "    GOOD (CPU Bound)\n",cpuRatio)

def initializeExtension(options, filters, frameReports, globalReports,
                        numFrames):
    totalFrameTimeSummary = TotalFrameTimeSummary()
    threadSummary = ThreadSummary()

    filters["timers"] = [totalFrameTimeSummary]
    filters["threads"] = [threadSummary]

    # Set up the per frame reports
    frameReports.append(WaitBoundReport(totalFrameTimeSummary,
                                        threadSummary))

The first two class definitions are basic filter definitions that only extract data of interest. The interesting sections for this example are the initializeExtension definition and the WaitBoundReport class. In initializeExtension, the two filters are created and placed in the filters map under the keys for their associated sections. Then, both of these filters are passed to the __init__ of the WaitBoundReport class, which saves the reference in the two object attributes timeSummary and threadSummary. This gives the WaitBoundReport access to the data collected by the two filters via their attributes. When the report is constructing the output, it pulls the number of threads from the numThreads attribute of the threadSummary filter, where it was stored when the filter ran. The timeSummary filter contains a TimerStat object, which holds the elapsed, user and system time for the run. The user and system time can be added and divided by the number of threads to obtain the average CPU-time per thread. The per-thread CPU-time to elapsed (wall-clock) time ratio is compared against the threshold value to generate the appropriate output report. The util.printf function is used which ensures the output is directed to the appropriate place - the console or a file depending on the options provided on the command line. Since the framework assures all filters for a frame are run before all reports, the data values will be available for the report if they exist.

Filter with Separate Global Report

Generating a global report is similar to generating a per-frame report. This example generates a report detailing the time usage across all frames in an XML statistics file, using the TotalFrameTimeSummary filter from the previous example. There are two snippets of code that need to be added to the previous example to create this new global report. The first is the definition of the global report:

class TotalGlobalTimeReport:
    def __init__(self, totalFrameTimeSummary):
        self.elapsed = 0
        self.user = 0
        self.system = 0
        self.totalFrameTimeSummary = totalFrameTimeSummary
    def accumulateFrame(self, options, frameNum):
        if self.totalFrameTimeSummary.totalTimer:
            tmr = self.totalFrameTimeSummary.totalTimer
            for attr in ["user", "elapsed", "system"]:
                oldVal = getattr(self, attr)
                frameVal = getattr(tmr, attr, 0)
                setattr(self, attr, oldVal + frameVal)

    def reportGlobalResults(self, options):
        util.printf("Total-time sums (user,sys,elapsed):  %f  %f  %f\n",
                    self.user, self.system, self.elapsed)

The __init__ clears some attributes that will be used to accumulate the total time and saves a reference to the filter for the total frame time. As each frame is processed, the framework will call the accumulateFrame method. Like the per-frame reports, the accumulate methods are called after all filters have been run for the given frame. This means that the filters user, elapsed, and system attributes will all have their values set for the current frame, ready to add to the global report's accumulators. The for loop shown leverages Python's dynamic attribute access functionality to avoid copy-and-paste code for accumulating the three values.

Finally, once all of the individual frames have been processed, the framework will run the reportGlobalResults method, formatting the accumulators nicely for output in this example. To ensure this happens for the filter, a TotalGlobalTimeReport object must be added to the globalReports list in the initializeExtension method. This is accomplished with the second code snippet:

globalReports.append(TotalGlobalTimeReport(totalFrameTimeSummary))

Notice that the constructor is given the totalFrameTimeSummary filter so that it will be able to accumulate the values as they are processed per-frame.

Creating Custom Expensive Item Reports

The previous examples demonstrated the basics of generating diagnostic reports based on render statistics. This example shows how to use another util feature, the BaseExpensiveReport class. As the name suggests, this base class is used to create all of the reports of the most expensive elements, complete with the ASCII-graphing functionality. This example describes the ExpensiveTextureReport class from the defaultModule.

An expensive item report is based on the idea that with a list of items and their cost, measured using some metric, the most expensive items can be printed until a significant fraction of usage is accounted for without printing the entire list. A report that uses BaseExpensiveReport will need three components: a global report class that extends BaseExpensiveReport, a class to hold the data records that consist of labels and costs of items, and a filter that generates the data records from the XML statistics is used to create the list of items.

This example will demonstrate building two reports of the most expensive shaders, measured both by time per point shaded and total time elapsed. Here is the entire source code, with explanations of individual portions to follow:

import diagnosticModules.util as util

class ShaderRPT:
    name = " "
    elapsed  = 0.0
    pointsShaded = 0
    type = ""

class ShaderSummary(util.BaseFrameInit):
    """
    Extracts reports of time elapsed and number of points shaded for shaders.

    All of the reports are ShaderRPT objects stored in the reports
    dictionary of this object, indexed by the shader name.  This combines
    all shader types into one dictionary, but the type can be retrieved via
    the ShaderRPT.type value.
    """
    def newFrame(self):
        self.reports = {}

    def summarize(self, section, options, frameNum):
        for childSection in section:
            # filter to known sections, because plug-ins may
            # add other sections
            if(childSection.name in ["displacement", "surface", "volume",
                                     "light", "method", "imager"]):
                for shaderEntry in childSection:
                    if isinstance(shaderEntry, util.StatsList):
                        rpt = ShaderRPT()
                        rpt.name = shaderEntry.name
                        rpt.type = childSection.name
                        hasTimer = False
                        hasPointsShaded = False
                        for valEntry in shaderEntry:
                            if(valEntry.name=="shaderTimer"):
                                rpt.elapsed = valEntry.elapsed
                                hasTimer = True
                            elif(valEntry.name=="pointsShaded"):
                                rpt.pointsShaded = valEntry.value
                                hasPointsShaded = True
                        if hasTimer and hasPointsShaded:
                            if not childSection.name in self.reports:
                                self.reports[childSection.name] = []
                            self.reports[childSection.name].append(rpt)

class ExpensiveShaderReport(util.BaseExpensiveReport):
    rptAttrs = ["elapsed","pointsShaded"]
    def __init__(self, shdSummary):
        self.shaderSummary = shdSummary
        self.accumRpts = {}
    def accumulateFrame(self, options, frameNum):
        for shClass,rptList in self.shaderSummary.reports.items():
            for rpt in rptList:
                self.accumulateReport(rpt,self.accumRpts,
                                      "%s[%1.1s]"%(rpt.name,rpt.type),
                                      ShaderRPT)

    def reportGlobalResults(self, options):
        self.reportMajorResults("Shader average time (microseconds) "
                      "per point shaded:",
                      options, self.accumRpts.values(),
                      lambda rpt: float(rpt.elapsed)/float(rpt.pointsShaded),
                      1000000, "us/pt", .5)

        self.reportMajorResults("Shader total time (seconds):",
                                options, self.accumRpts.values(),
                                lambda rpt: rpt.elapsed, 1.0, "s", .5)

def initializeExtension(options, filters, frameReports, globalReports,
                        numFrames):
    # Create some filters
    shaderSummary = ShaderSummary()

    # Set up the section->filter mapping for extracting statistics
    filters["shaders"] = [shaderSummary]

    # Set up the global reports
    globalReports.extend([ExpensiveShaderReport(shaderSummary)])

The ShaderRPT class is a straightforward data record which will store data for each shader that is needed to compute the time metrics.

The ShaderSummary class is the filter that will create the ShaderRPT objects from the XML statistics. The shader statistics are divided up by shader type, so this filter loops through the known shader types and aggregates all entries into a single list.

The ExpensiveShaderReport class is the global report derived from BaseExpensiveReport. During accumulateFrame, the individual records extracted by the ShaderSummary filter are accumulated with records from previous frames. This is done by calling the BaseExpensiveReport.accumulateFrame method:

self.accumulateReport(rpt,self.accumRpts,
                      "%s[%1.1s]"%(rpt.name,rpt.type),
                      ShaderRPT)

The arguments to this method are:

rpt

self.accumRpts

"%s[%1.1s]"%(rpt.name,rpt.type)

ShaderRPT

The accumulateFrame method dynamically retrieves the attributes on the record entries and accumulates them to matching attributes in the accumRpts map. Entries are indexed by the name given, and if an entry hasn't been created for a given entry name, it is dynamically created from the passed in class.

Once all of the individual entries are accumulated, the reportGlobalResults function generates two reports, the first based on time per point shaded and the second based on total shader time. The first call looks like this:

self.reportMajorResults("Shader average time (microseconds) "
              "per point shaded:",
              options, self.accumRpts.values(),
              lambda rpt: float(rpt.elapsed)/float(rpt.pointsShaded),
              1000000, "us/pt", .5)

The arguments are:

"Shader average time (microseconds) per point shaded:"

options

self.accumRpts.values()

lambda rpt: float(rpt.elapsed)/float(rpt.pointsShaded)

100000

"us/pt"

.5

By simply changing the scaling, units, and lambda function, the same data can be used to report the most expensive shaders based on total time:

self.reportMajorResults("Shader total time (seconds):",
                        options, self.accumRpts.values(),
                        lambda rpt: rpt.elapsed, 1.0, "s", .5)

There are some additional default options to reportMajorResults that can be used to adjust the plot output:

barWidth=10

plotHeight=5, plotWidth=75, plotStart=4,

reportWidth=80

This base provides a flexible starting point for quickly assessing items that are the most demanding in your renders.