diff options
Diffstat (limited to 'indra')
| -rw-r--r-- | indra/cmake/GooglePerfTools.cmake | 2 | ||||
| -rwxr-xr-x | indra/lib/python/indra/util/llperformance.py | 158 | ||||
| -rwxr-xr-x | indra/lib/python/indra/util/simperf_host_xml_parser.py | 338 | ||||
| -rwxr-xr-x | indra/lib/python/indra/util/simperf_oprof_interface.py | 160 | ||||
| -rwxr-xr-x | indra/lib/python/indra/util/simperf_proc_interface.py | 164 | ||||
| -rw-r--r-- | indra/llcommon/llstat.cpp | 449 | ||||
| -rw-r--r-- | indra/llcommon/llstat.h | 113 | ||||
| -rw-r--r-- | indra/llcommon/llstatenums.h | 17 | ||||
| -rw-r--r-- | indra/llcommon/lltimer.cpp | 53 | ||||
| -rw-r--r-- | indra/llcommon/lltimer.h | 1 | ||||
| -rw-r--r-- | indra/llmessage/lliohttpserver.cpp | 5 | ||||
| -rw-r--r-- | indra/llmessage/llmessagetemplate.h | 2 | ||||
| -rw-r--r-- | indra/llmessage/llpumpio.cpp | 6 | ||||
| -rw-r--r-- | indra/llvfs/llvfile.cpp | 1 | ||||
| -rw-r--r-- | indra/newview/llstartup.cpp | 115 | ||||
| -rw-r--r-- | indra/newview/llviewermessage.cpp | 9 | ||||
| -rw-r--r-- | indra/newview/llviewerstats.h | 3 | 
17 files changed, 1515 insertions, 81 deletions
| diff --git a/indra/cmake/GooglePerfTools.cmake b/indra/cmake/GooglePerfTools.cmake index 9b3eca060f..05aefaf522 100644 --- a/indra/cmake/GooglePerfTools.cmake +++ b/indra/cmake/GooglePerfTools.cmake @@ -22,7 +22,7 @@ endif (GOOGLE_PERFTOOLS_FOUND)  if (USE_GOOGLE_PERFTOOLS)    set(TCMALLOC_FLAG -DLL_USE_TCMALLOC=1)    include_directories(${GOOGLE_PERFTOOLS_INCLUDE_DIR}) -  set(GOOGLE_PERFTOOLS_LIBRARIES ${TCMALLOC_LIBRARIES} ${STACKTRACE_LIBRARIES}) +  set(GOOGLE_PERFTOOLS_LIBRARIES ${TCMALLOC_LIBRARIES} ${STACKTRACE_LIBRARIES} ${PROFILER_LIBRARIES})  else (USE_GOOGLE_PERFTOOLS)    set(TCMALLOC_FLAG -ULL_USE_TCMALLOC)  endif (USE_GOOGLE_PERFTOOLS) diff --git a/indra/lib/python/indra/util/llperformance.py b/indra/lib/python/indra/util/llperformance.py new file mode 100755 index 0000000000..7c52730b5e --- /dev/null +++ b/indra/lib/python/indra/util/llperformance.py @@ -0,0 +1,158 @@ +#!/usr/bin/python + +# ------------------------------------------------ +# Sim metrics utility functions. + +import glob, os, time, sys, stat, exceptions + +from indra.base import llsd + +gBlockMap = {}              #Map of performance metric data with function hierarchy information. +gCurrentStatPath = "" + +gIsLoggingEnabled=False + +class LLPerfStat: +    def __init__(self,key): +        self.mTotalTime = 0 +        self.mNumRuns = 0 +        self.mName=key +        self.mTimeStamp = int(time.time()*1000) +        self.mUTCTime = time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime()) + +    def __str__(self): +        return "%f" %  self.mTotalTime + +    def start(self): +        self.mStartTime = int(time.time() * 1000000) +        self.mNumRuns += 1 + +    def stop(self): +        execution_time = int(time.time() * 1000000) - self.mStartTime +        self.mTotalTime += execution_time + +    def get_map(self): +        results={} +        results['name']=self.mName +        results['utc_time']=self.mUTCTime +        results['timestamp']=self.mTimeStamp +        results['us']=self.mTotalTime +        results['count']=self.mNumRuns +        return results + +class PerfError(exceptions.Exception): +    def __init__(self): +        return + +    def __Str__(self): +        print "","Unfinished LLPerfBlock" + +class LLPerfBlock: +    def __init__( self, key ): +        global gBlockMap +        global gCurrentStatPath +        global gIsLoggingEnabled + +        #Check to see if we're running metrics right now. +        if gIsLoggingEnabled: +            self.mRunning = True        #Mark myself as running. +     +            self.mPreviousStatPath = gCurrentStatPath +            gCurrentStatPath += "/" + key +            if gCurrentStatPath not in gBlockMap: +                gBlockMap[gCurrentStatPath] = LLPerfStat(key) + +            self.mStat = gBlockMap[gCurrentStatPath] +            self.mStat.start() +     +    def finish( self ): +        global gBlockMap +        global gIsLoggingEnabled + +        if gIsLoggingEnabled: +            self.mStat.stop() +            self.mRunning = False +            gCurrentStatPath = self.mPreviousStatPath + +#    def __del__( self ): +#        if self.mRunning: +#            #SPATTERS FIXME +#            raise PerfError + +class LLPerformance: +    #-------------------------------------------------- +    # Determine whether or not we want to log statistics + +    def __init__( self, process_name = "python" ): +        self.process_name = process_name +        self.init_testing() +        self.mTimeStamp = int(time.time()*1000) +        self.mUTCTime = time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime()) + +    def init_testing( self ): +        global gIsLoggingEnabled + +        host_performance_file = "/dev/shm/simperf/simperf_proc_config.llsd" +     +        #If file exists, open +        if os.path.exists(host_performance_file): +            file = open (host_performance_file,'r') +     +            #Read serialized LLSD from file. +            body = llsd.parse(file.read()) +     +            #Calculate time since file last modified. +            stats = os.stat(host_performance_file) +            now = time.time() +            mod = stats[stat.ST_MTIME] +            age = now - mod +     +            if age < ( body['duration'] ): +                gIsLoggingEnabled = True +     + +    def get ( self ): +        global gIsLoggingEnabled +        return gIsLoggingEnabled + +    #def output(self,ptr,path): +    #    if 'stats' in ptr: +    #        stats = ptr['stats'] +    #        self.mOutputPtr[path] = stats.get_map() + +    #    if 'children' in ptr: +    #        children=ptr['children'] + +    #        curptr = self.mOutputPtr +    #        curchildren={} +    #        curptr['children'] = curchildren + +    #        for key in children: +    #            curchildren[key]={} +    #            self.mOutputPtr = curchildren[key] +    #            self.output(children[key],path + '/' + key) +     +    def done(self): +        global gBlockMap + +        if not self.get(): +            return + +        output_name = "/dev/shm/simperf/%s_proc.%d.llsd" % (self.process_name, os.getpid()) +        output_file = open(output_name, 'w') +        process_info = { +            "name"  :   self.process_name, +            "pid"   :   os.getpid(), +            "ppid"  :   os.getppid(), +            "timestamp" :   self.mTimeStamp, +            "utc_time"  :   self.mUTCTime, +            } +        output_file.write(llsd.format_notation(process_info)) +        output_file.write('\n') + +        for key in gBlockMap.keys(): +            gBlockMap[key] = gBlockMap[key].get_map() +        output_file.write(llsd.format_notation(gBlockMap)) +        output_file.write('\n') +        output_file.close() + diff --git a/indra/lib/python/indra/util/simperf_host_xml_parser.py b/indra/lib/python/indra/util/simperf_host_xml_parser.py new file mode 100755 index 0000000000..b6084151c9 --- /dev/null +++ b/indra/lib/python/indra/util/simperf_host_xml_parser.py @@ -0,0 +1,338 @@ +#!/usr/bin/env python +"""\ +@file simperf_host_xml_parser.py +@brief Digest collector's XML dump and convert to simple dict/list structure + +$LicenseInfo:firstyear=2008&license=mit$ + +Copyright (c) 2008, Linden Research, Inc. + +Permission is hereby granted, free of charge, to any person obtaining a copy +of this software and associated documentation files (the "Software"), to deal +in the Software without restriction, including without limitation the rights +to use, copy, modify, merge, publish, distribute, sublicense, and/or sell +copies of the Software, and to permit persons to whom the Software is +furnished to do so, subject to the following conditions: + +The above copyright notice and this permission notice shall be included in +all copies or substantial portions of the Software. + +THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR +IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, +FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE +AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER +LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, +OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN +THE SOFTWARE. +$/LicenseInfo$ +""" + +import sys, os, getopt, time +import simplejson +from xml import sax + + +def usage(): +    print "Usage:" +    print sys.argv[0] + " [options]" +    print "  Convert RRD's XML dump to JSON.  Script to convert the simperf_host_collector-" +    print "  generated RRD dump into JSON.  Steps include converting selected named" +    print "  fields from GAUGE type to COUNTER type by computing delta with preceding" +    print "  values.  Top-level named fields are:" +    print  +    print "     lastupdate      Time (javascript timestamp) of last data sample" +    print "     step            Time in seconds between samples" +    print "     ds              Data specification (name/type) for each column" +    print "     database        Table of data samples, one time step per row" +    print  +    print "Options:" +    print "  -i, --in      Input settings filename.  (Default:  stdin)" +    print "  -o, --out     Output settings filename.  (Default:  stdout)" +    print "  -h, --help    Print this message and exit." +    print +    print "Example: %s -i rrddump.xml -o rrddump.json" % sys.argv[0] +    print +    print "Interfaces:" +    print "   class SimPerfHostXMLParser()         # SAX content handler" +    print "   def simperf_host_xml_fixup(parser)   # post-parse value fixup" + +class SimPerfHostXMLParser(sax.handler.ContentHandler): + +    def __init__(self): +        pass +         +    def startDocument(self): +        self.rrd_last_update = 0         # public +        self.rrd_step = 0                # public +        self.rrd_ds = []                 # public +        self.rrd_records = []            # public +        self._rrd_level = 0 +        self._rrd_parse_state = 0 +        self._rrd_chars = "" +        self._rrd_capture = False +        self._rrd_ds_val = {} +        self._rrd_data_row = [] +        self._rrd_data_row_has_nan = False +         +    def endDocument(self): +        pass + +    # Nasty little ad-hoc state machine to extract the elements that are +    # necessary from the 'rrdtool dump' XML output.  The same element +    # name '<ds>' is used for two different data sets so we need to pay +    # some attention to the actual structure to get the ones we want +    # and ignore the ones we don't. +     +    def startElement(self, name, attrs): +        self._rrd_level = self._rrd_level + 1 +        self._rrd_capture = False +        if self._rrd_level == 1: +            if name == "rrd" and self._rrd_parse_state == 0: +                self._rrd_parse_state = 1     # In <rrd> +                self._rrd_capture = True +                self._rrd_chars = "" +        elif self._rrd_level == 2: +            if self._rrd_parse_state == 1: +                if name == "lastupdate": +                    self._rrd_parse_state = 2         # In <rrd><lastupdate> +                    self._rrd_capture = True +                    self._rrd_chars = "" +                elif name == "step": +                    self._rrd_parse_state = 3         # In <rrd><step> +                    self._rrd_capture = True +                    self._rrd_chars = "" +                elif name == "ds": +                    self._rrd_parse_state = 4         # In <rrd><ds> +                    self._rrd_ds_val = {} +                    self._rrd_chars = "" +                elif name == "rra": +                    self._rrd_parse_state = 5         # In <rrd><rra> +        elif self._rrd_level == 3: +            if self._rrd_parse_state == 4: +                if name == "name": +                    self._rrd_parse_state = 6         # In <rrd><ds><name> +                    self._rrd_capture = True +                    self._rrd_chars = "" +                elif name == "type": +                    self._rrd_parse_state = 7         # In <rrd><ds><type> +                    self._rrd_capture = True +                    self._rrd_chars = "" +            elif self._rrd_parse_state == 5: +                if name == "database": +                    self._rrd_parse_state = 8         # In <rrd><rra><database> +        elif self._rrd_level == 4: +            if self._rrd_parse_state == 8: +                if name == "row": +                    self._rrd_parse_state = 9         # In <rrd><rra><database><row> +                    self._rrd_data_row = [] +                    self._rrd_data_row_has_nan = False +        elif self._rrd_level == 5: +            if self._rrd_parse_state == 9: +                if name == "v": +                    self._rrd_parse_state = 10        # In <rrd><rra><database><row><v> +                    self._rrd_capture = True +                    self._rrd_chars = "" + +    def endElement(self, name): +        self._rrd_capture = False +        if self._rrd_parse_state == 10: +            self._rrd_capture = self._rrd_level == 6 +            if self._rrd_level == 5: +                if self._rrd_chars == "NaN": +                    self._rrd_data_row_has_nan = True +                else: +                    self._rrd_data_row.append(self._rrd_chars) +                self._rrd_parse_state = 9              # In <rrd><rra><database><row> +        elif self._rrd_parse_state == 9: +            if self._rrd_level == 4: +                if not self._rrd_data_row_has_nan: +                    self.rrd_records.append(self._rrd_data_row) +                self._rrd_parse_state = 8              # In <rrd><rra><database> +        elif self._rrd_parse_state == 8: +            if self._rrd_level == 3: +                self._rrd_parse_state = 5              # In <rrd><rra> +        elif self._rrd_parse_state == 7: +            if self._rrd_level == 3: +                self._rrd_ds_val["type"] = self._rrd_chars +                self._rrd_parse_state = 4              # In <rrd><ds> +        elif self._rrd_parse_state == 6: +            if self._rrd_level == 3: +                self._rrd_ds_val["name"] = self._rrd_chars +                self._rrd_parse_state = 4              # In <rrd><ds> +        elif self._rrd_parse_state == 5: +            if self._rrd_level == 2: +                self._rrd_parse_state = 1              # In <rrd> +        elif self._rrd_parse_state == 4: +            if self._rrd_level == 2: +                self.rrd_ds.append(self._rrd_ds_val) +                self._rrd_parse_state = 1              # In <rrd> +        elif self._rrd_parse_state == 3: +            if self._rrd_level == 2: +                self.rrd_step = long(self._rrd_chars) +                self._rrd_parse_state = 1              # In <rrd> +        elif self._rrd_parse_state == 2: +            if self._rrd_level == 2: +                self.rrd_last_update = long(self._rrd_chars) +                self._rrd_parse_state = 1              # In <rrd> +        elif self._rrd_parse_state == 1: +            if self._rrd_level == 1: +                self._rrd_parse_state = 0              # At top +                 +        if self._rrd_level: +            self._rrd_level = self._rrd_level - 1 + +    def characters(self, content): +        if self._rrd_capture: +            self._rrd_chars = self._rrd_chars + content.strip() + +def _make_numeric(value): +    try: +        value = float(value) +    except: +        value = "" +    return value + +def simperf_host_xml_fixup(parser, filter_start_time = None, filter_end_time = None): +    # Fixup for GAUGE fields that are really COUNTS.  They +    # were forced to GAUGE to try to disable rrdtool's +    # data interpolation/extrapolation for non-uniform time +    # samples. +    fixup_tags = [ "cpu_user", +                   "cpu_nice", +                   "cpu_sys", +                   "cpu_idle", +                   "cpu_waitio", +                   "cpu_intr", +                   # "file_active", +                   # "file_free", +                   # "inode_active", +                   # "inode_free", +                   "netif_in_kb", +                   "netif_in_pkts", +                   "netif_in_errs", +                   "netif_in_drop", +                   "netif_out_kb", +                   "netif_out_pkts", +                   "netif_out_errs", +                   "netif_out_drop", +                   "vm_page_in", +                   "vm_page_out", +                   "vm_swap_in", +                   "vm_swap_out", +                   #"vm_mem_total", +                   #"vm_mem_used", +                   #"vm_mem_active", +                   #"vm_mem_inactive", +                   #"vm_mem_free", +                   #"vm_mem_buffer", +                   #"vm_swap_cache", +                   #"vm_swap_total", +                   #"vm_swap_used", +                   #"vm_swap_free", +                   "cpu_interrupts", +                   "cpu_switches", +                   "cpu_forks" ] + +    col_count = len(parser.rrd_ds) +    row_count = len(parser.rrd_records) + +    # Process the last row separately, just to make all values numeric. +    for j in range(col_count): +        parser.rrd_records[row_count - 1][j] = _make_numeric(parser.rrd_records[row_count - 1][j]) + +    # Process all other row/columns. +    last_different_row = row_count - 1 +    current_row = row_count - 2 +    while current_row >= 0: +        # Check for a different value than the previous row.  If everything is the same +        # then this is probably just a filler/bogus entry. +        is_different = False +        for j in range(col_count): +            parser.rrd_records[current_row][j] = _make_numeric(parser.rrd_records[current_row][j]) +            if parser.rrd_records[current_row][j] != parser.rrd_records[last_different_row][j]: +                # We're good.  This is a different row. +                is_different = True + +        if not is_different: +            # This is a filler/bogus entry.  Just ignore it. +            for j in range(col_count): +                parser.rrd_records[current_row][j] = float('nan') +        else: +            # Some tags need to be converted into deltas. +            for j in range(col_count): +                if parser.rrd_ds[j]["name"] in fixup_tags: +                    parser.rrd_records[last_different_row][j] = \ +                        parser.rrd_records[last_different_row][j] - parser.rrd_records[current_row][j] +            last_different_row = current_row + +        current_row -= 1 + +    # Set fixup_tags in the first row to 'nan' since they aren't useful anymore. +    for j in range(col_count): +        if parser.rrd_ds[j]["name"] in fixup_tags: +            parser.rrd_records[0][j] = float('nan') + +    # Add a timestamp to each row and to the catalog.  Format and name +    # chosen to match other simulator logging (hopefully). +    start_time = parser.rrd_last_update - (parser.rrd_step * (row_count - 1)) +    # Build a filtered list of rrd_records if we are limited to a time range. +    filter_records = False +    if filter_start_time is not None or filter_end_time is not None: +        filter_records = True +        filtered_rrd_records = [] +        if filter_start_time is None: +            filter_start_time = start_time * 1000 +        if filter_end_time is None: +            filter_end_time = parser.rrd_last_update * 1000 +         +    for i in range(row_count): +        record_timestamp = (start_time + (i * parser.rrd_step)) * 1000 +        parser.rrd_records[i].insert(0, record_timestamp) +        if filter_records: +            if filter_start_time <= record_timestamp and record_timestamp <= filter_end_time: +                filtered_rrd_records.append(parser.rrd_records[i]) + +    if filter_records: +        parser.rrd_records = filtered_rrd_records + +    parser.rrd_ds.insert(0, {"type": "GAUGE", "name": "javascript_timestamp"}) + + +def main(argv=None): +    opts, args = getopt.getopt(sys.argv[1:], "i:o:h", ["in=", "out=", "help"]) +    input_file = sys.stdin +    output_file = sys.stdout +    for o, a in opts: +        if o in ("-i", "--in"): +            input_file = open(a, 'r') +        if o in ("-o", "--out"): +            output_file = open(a, 'w') +        if o in ("-h", "--help"): +            usage() +            sys.exit(0) + +    # Using the SAX parser as it is at least 4X faster and far, far +    # smaller on this dataset than the DOM-based interface in xml.dom.minidom. +    # With SAX and a 5.4MB xml file, this requires about seven seconds of +    # wall-clock time and 32MB VSZ.  With the DOM interface, about 22 seconds +    # and over 270MB VSZ. + +    handler = SimPerfHostXMLParser() +    sax.parse(input_file, handler) +    if input_file != sys.stdin: +        input_file.close() + +    # Various format fixups:  string-to-num, gauge-to-counts, add +    # a time stamp, etc. +    simperf_host_xml_fixup(handler) +     +    # Create JSONable dict with interesting data and format/print it +    print >>output_file, simplejson.dumps({ "step" : handler.rrd_step, +                                            "lastupdate": handler.rrd_last_update * 1000, +                                            "ds" : handler.rrd_ds, +                                            "database" : handler.rrd_records }) + +    return 0 + +if __name__ == "__main__": +    sys.exit(main()) diff --git a/indra/lib/python/indra/util/simperf_oprof_interface.py b/indra/lib/python/indra/util/simperf_oprof_interface.py new file mode 100755 index 0000000000..a7e9a4cb32 --- /dev/null +++ b/indra/lib/python/indra/util/simperf_oprof_interface.py @@ -0,0 +1,160 @@ +#!/usr/bin/env python +"""\ +@file simperf_oprof_interface.py +@brief Manage OProfile data collection on a host + +$LicenseInfo:firstyear=2008&license=internal$ + +Copyright (c) 2008, Linden Research, Inc. + +The following source code is PROPRIETARY AND CONFIDENTIAL. Use of +this source code is governed by the Linden Lab Source Code Disclosure +Agreement ("Agreement") previously entered between you and Linden +Lab. By accessing, using, copying, modifying or distributing this +software, you acknowledge that you have been informed of your +obligations under the Agreement and agree to abide by those obligations. + +ALL LINDEN LAB SOURCE CODE IS PROVIDED "AS IS." LINDEN LAB MAKES NO +WARRANTIES, EXPRESS, IMPLIED OR OTHERWISE, REGARDING ITS ACCURACY, +COMPLETENESS OR PERFORMANCE. +$/LicenseInfo$ +""" + +import sys, os, getopt +import simplejson + + +def usage(): +    print "Usage:" +    print sys.argv[0] + " [options]" +    print "  Digest the OProfile report forms that come out of the" +    print "  simperf_oprof_ctl program's -r/--report command.  The result" +    print "  is an array of dictionaires with the following keys:" +    print  +    print "     symbol        Name of sampled, calling, or called procedure" +    print "     file          Executable or library where symbol resides" +    print "     percentage    Percentage contribution to profile, calls or called" +    print "     samples       Sample count" +    print "     calls         Methods called by the method in question (full only)" +    print "     called_by     Methods calling the method (full only)" +    print  +    print "  For 'full' reports the two keys 'calls' and 'called_by' are" +    print "  themselves arrays of dictionaries based on the first four keys." +    print +    print "Return Codes:" +    print "  None.  Aggressively digests everything.  Will likely mung results" +    print "  if a program or library has whitespace in its name." +    print +    print "Options:" +    print "  -i, --in      Input settings filename.  (Default:  stdin)" +    print "  -o, --out     Output settings filename.  (Default:  stdout)" +    print "  -h, --help    Print this message and exit." +    print +    print "Interfaces:" +    print "   class SimPerfOProfileInterface()" +     +class SimPerfOProfileInterface: +    def __init__(self): +        self.isBrief = True             # public +        self.isValid = False            # public +        self.result = []                # public + +    def parse(self, input): +        in_samples = False +        for line in input: +            if in_samples: +                if line[0:6] == "------": +                    self.isBrief = False +                    self._parseFull(input) +                else: +                    self._parseBrief(input, line) +                self.isValid = True +                return +            try: +                hd1, remain = line.split(None, 1) +                if hd1 == "samples": +                    in_samples = True +            except ValueError: +                pass + +    def _parseBrief(self, input, line1): +        try: +            fld1, fld2, fld3, fld4 = line1.split(None, 3) +            self.result.append({"samples" : fld1, +                                "percentage" : fld2, +                                "file" : fld3, +                                "symbol" : fld4.strip("\n")}) +        except ValueError: +            pass +        for line in input: +            try: +                fld1, fld2, fld3, fld4 = line.split(None, 3) +                self.result.append({"samples" : fld1, +                                    "percentage" : fld2, +                                    "file" : fld3, +                                    "symbol" : fld4.strip("\n")}) +            except ValueError: +                pass + +    def _parseFull(self, input): +        state = 0       # In 'called_by' section +        calls = [] +        called_by = [] +        current = {} +        for line in input: +            if line[0:6] == "------": +                if len(current): +                    current["calls"] = calls +                    current["called_by"] = called_by +                    self.result.append(current) +                state = 0 +                calls = [] +                called_by = [] +                current = {} +            else: +                try: +                    fld1, fld2, fld3, fld4 = line.split(None, 3) +                    tmp = {"samples" : fld1, +                           "percentage" : fld2, +                           "file" : fld3, +                           "symbol" : fld4.strip("\n")} +                except ValueError: +                    continue +                if line[0] != " ": +                    current = tmp +                    state = 1       # In 'calls' section +                elif state == 0: +                    called_by.append(tmp) +                else: +                    calls.append(tmp) +        if len(current): +            current["calls"] = calls +            current["called_by"] = called_by +            self.result.append(current) + + +def main(argv=None): +    opts, args = getopt.getopt(sys.argv[1:], "i:o:h", ["in=", "out=", "help"]) +    input_file = sys.stdin +    output_file = sys.stdout +    for o, a in opts: +        if o in ("-i", "--in"): +            input_file = open(a, 'r') +        if o in ("-o", "--out"): +            output_file = open(a, 'w') +        if o in ("-h", "--help"): +            usage() +            sys.exit(0) + +    oprof = SimPerfOProfileInterface() +    oprof.parse(input_file) +    if input_file != sys.stdin: +        input_file.close() + +    # Create JSONable dict with interesting data and format/print it +    print >>output_file, simplejson.dumps(oprof.result) + +    return 0 + +if __name__ == "__main__": +    sys.exit(main()) diff --git a/indra/lib/python/indra/util/simperf_proc_interface.py b/indra/lib/python/indra/util/simperf_proc_interface.py new file mode 100755 index 0000000000..62a63fa872 --- /dev/null +++ b/indra/lib/python/indra/util/simperf_proc_interface.py @@ -0,0 +1,164 @@ +#!/usr/bin/python + +# ---------------------------------------------------- +# Utility to extract log messages from *.<pid>.llsd +# files that contain performance statistics. + +# ---------------------------------------------------- +import sys, os + +if os.path.exists("setup-path.py"): +    execfile("setup-path.py") + +from indra.base import llsd + +DEFAULT_PATH="/dev/shm/simperf/" + + +# ---------------------------------------------------- +# Pull out the stats and return a single document +def parse_logfile(filename, target_column=None, verbose=False): +    full_doc = [] +    # Open source temp log file.  Let exceptions percolate up. +    sourcefile = open( filename,'r') +         +    if verbose: +        print "Reading " + filename   +     +    # Parse and output all lines from the temp file +    for line in sourcefile.xreadlines(): +        partial_doc = llsd.parse(line) +        if partial_doc is not None: +            if target_column is None: +                full_doc.append(partial_doc) +            else: +                trim_doc = { target_column: partial_doc[target_column] } +                if target_column != "fps": +                    trim_doc[ 'fps' ] = partial_doc[ 'fps' ] +                trim_doc[ '/total_time' ] = partial_doc[ '/total_time' ] +                trim_doc[ 'utc_time' ] = partial_doc[ 'utc_time' ] +                full_doc.append(trim_doc) + +    sourcefile.close() +    return full_doc + +# Extract just the meta info line, and the timestamp of the first/last frame entry. +def parse_logfile_info(filename, verbose=False): +    # Open source temp log file.  Let exceptions percolate up. +    sourcefile = open(filename, 'rU') # U is to open with Universal newline support +         +    if verbose: +        print "Reading " + filename   + +    # The first line is the meta info line. +    info_line = sourcefile.readline() +    if not info_line: +        sourcefile.close() +        return None + +    # The rest of the lines are frames.  Read the first and last to get the time range. +    info = llsd.parse( info_line ) +    info['start_time'] = None +    info['end_time'] = None +    first_frame = sourcefile.readline() +    if first_frame: +        try: +            info['start_time'] = int(llsd.parse(first_frame)['timestamp']) +        except: +            pass + +    # Read the file backwards to find the last two lines. +    sourcefile.seek(0, 2) +    file_size = sourcefile.tell() +    offset = 1024 +    num_attempts = 0 +    end_time = None +    if file_size < offset: +        offset = file_size +    while 1: +        sourcefile.seek(-1*offset, 2) +        read_str = sourcefile.read(offset) +        # Remove newline at the end +        if read_str[offset - 1] == '\n': +            read_str = read_str[0:-1] +        lines = read_str.split('\n') +        full_line = None +        if len(lines) > 2:  # Got two line +            try: +                end_time = llsd.parse(lines[-1])['timestamp'] +            except: +                # We couldn't parse this line.  Try once more. +                try: +                    end_time = llsd.parse(lines[-2])['timestamp'] +                except: +                    # Nope.  Just move on. +                    pass +            break +        if len(read_str) == file_size:   # Reached the beginning +            break +        offset += 1024 + +    info['end_time'] = int(end_time) + +    sourcefile.close() +    return info +     + +def parse_proc_filename(filename): +    try: +        name_as_list = filename.split(".") +        cur_stat_type = name_as_list[0].split("_")[0] +        cur_pid = name_as_list[1] +    except IndexError, ValueError: +        return (None, None) +    return (cur_pid, cur_stat_type) + +# ---------------------------------------------------- +def get_simstats_list(path=None): +    """ Return stats (pid, type) listed in <type>_proc.<pid>.llsd """ +    if path is None: +        path = DEFAULT_PATH +    simstats_list = [] +    for file_name in os.listdir(path): +        if file_name.endswith(".llsd") and file_name != "simperf_proc_config.llsd": +            simstats_info = parse_logfile_info(path + file_name) +            if simstats_info is not None: +                simstats_list.append(simstats_info) +    return simstats_list + +def get_log_info_list(pid=None, stat_type=None, path=None, target_column=None, verbose=False): +    """ Return data from all llsd files matching the pid and stat type """ +    if path is None: +        path = DEFAULT_PATH +    log_info_list = {} +    for file_name in os.listdir ( path ): +        if file_name.endswith(".llsd") and file_name != "simperf_proc_config.llsd": +            (cur_pid, cur_stat_type) = parse_proc_filename(file_name) +            if cur_pid is None: +                continue +            if pid is not None and pid != cur_pid: +                continue +            if stat_type is not None and stat_type != cur_stat_type: +                continue +            log_info_list[cur_pid] = parse_logfile(path + file_name, target_column, verbose) +    return log_info_list + +def delete_simstats_files(pid=None, stat_type=None, path=None): +    """ Delete *.<pid>.llsd files """ +    if path is None: +        path = DEFAULT_PATH +    del_list = [] +    for file_name in os.listdir(path): +        if file_name.endswith(".llsd") and file_name != "simperf_proc_config.llsd": +            (cur_pid, cur_stat_type) = parse_proc_filename(file_name) +            if cur_pid is None: +                continue +            if pid is not None and pid != cur_pid: +                continue +            if stat_type is not None and stat_type != cur_stat_type: +                continue +            del_list.append(cur_pid) +            # Allow delete related exceptions to percolate up if this fails. +            os.unlink(os.path.join(DEFAULT_PATH, file_name)) +    return del_list + diff --git a/indra/llcommon/llstat.cpp b/indra/llcommon/llstat.cpp index 80492d2e31..c825b50365 100644 --- a/indra/llcommon/llstat.cpp +++ b/indra/llcommon/llstat.cpp @@ -31,17 +31,288 @@  #include "linden_common.h"  #include "llstat.h" +#include "lllivefile.h" +#include "llerrorcontrol.h"  #include "llframetimer.h"  #include "timing.h" +#include "llsd.h" +#include "llsdserialize.h" +#include "llstl.h" +#include "u64.h" +// statics +BOOL            LLPerfBlock::sStatsEnabled = FALSE;    // Flag for detailed information +LLPerfBlock::stat_map_t    LLPerfBlock::sStatMap;    // Map full path string to LLStatTime objects, tracks all active objects +std::string        LLPerfBlock::sCurrentStatPath = "";    // Something like "/total_time/physics/physics step" -U64 LLStatAccum::sScaleTimes[IMPL_NUM_SCALES] = +//------------------------------------------------------------------------ +// Live config file to trigger stats logging +static const char    STATS_CONFIG_FILE_NAME[]            = "/dev/shm/simperf/simperf_proc_config.llsd"; +static const F32    STATS_CONFIG_REFRESH_RATE            = 5.0;        // seconds + +class LLStatsConfigFile : public LLLiveFile +{ +public: +    LLStatsConfigFile() +        : LLLiveFile(filename(), STATS_CONFIG_REFRESH_RATE), +        mChanged(false), mStatsp(NULL) { } + +    static std::string filename(); +     +protected: +    /* virtual */ void loadFile(); + +public: +    void init(LLPerfStats* statsp); +    static LLStatsConfigFile& instance(); +        // return the singleton stats config file + +    bool mChanged; + +protected: +    LLPerfStats*    mStatsp; +}; + +std::string LLStatsConfigFile::filename() +{ +    return STATS_CONFIG_FILE_NAME; +} + +void LLStatsConfigFile::init(LLPerfStats* statsp) +{ +    mStatsp = statsp; +} + +LLStatsConfigFile& LLStatsConfigFile::instance() +{ +    static LLStatsConfigFile the_file; +    return the_file; +} + + +/* virtual */ +// Load and parse the stats configuration file +void LLStatsConfigFile::loadFile() +{ +    if (!mStatsp) +    { +        llwarns << "Tries to load performance configure file without initializing LPerfStats" << llendl; +        return; +    } +    mChanged = true; +     +    LLSD stats_config; +    { +        llifstream file(filename().c_str()); +        if (file.is_open()) +        { +            LLSDSerialize::fromXML(stats_config, file); +            if (stats_config.isUndefined()) +            { +                llinfos << "Performance statistics configuration file ill-formed, not recording statistics" << llendl; +                mStatsp->setReportPerformanceDuration( 0.f ); +                return; +            } +        } +        else  +        {    // File went away, turn off stats if it was on +            if ( mStatsp->frameStatsIsRunning() ) +            { +                llinfos << "Performance statistics configuration file deleted, not recording statistics" << llendl; +                mStatsp->setReportPerformanceDuration( 0.f ); +            } +            return; +        } +    } + +    F32 duration = 0.f; +    F32 interval = 0.f; + +    const char * w = "duration"; +    if (stats_config.has(w)) +    { +        duration = (F32)stats_config[w].asReal(); +    }  +    w = "interval"; +    if (stats_config.has(w)) +    { +        interval = (F32)stats_config[w].asReal(); +    }  + +    mStatsp->setReportPerformanceDuration( duration ); +    mStatsp->setReportPerformanceInterval( interval ); + +    if ( duration > 0 ) +    { +        if ( interval == 0.f ) +        { +            llinfos << "Recording performance stats every frame for " << duration << " sec" << llendl; +        } +        else +        { +            llinfos << "Recording performance stats every " << interval << " seconds for " << duration << " seconds" << llendl; +        } +    } +    else +    { +        llinfos << "Performance stats recording turned off" << llendl; +    } +} + + +//------------------------------------------------------------------------ + +LLPerfStats::LLPerfStats(const std::string& process_name, S32 process_pid) :  +    mFrameStatsFileFailure(FALSE), +    mSkipFirstFrameStats(FALSE), +    mProcessName(process_name), +    mProcessPID(process_pid), +    mReportPerformanceStatInterval(1.f), +    mReportPerformanceStatEnd(0.0)  +{ } + +LLPerfStats::~LLPerfStats() +{ +    LLPerfBlock::clearDynamicStats(); +    mFrameStatsFile.close(); +} + +void LLPerfStats::init() +{ +    // Initialize the stats config file instance. +    (void) LLStatsConfigFile::instance().init(this); +    (void) LLStatsConfigFile::instance().checkAndReload(); +} + +// Open file for statistics +void    LLPerfStats::openPerfStatsFile() +{ +    if ( !mFrameStatsFile +        && !mFrameStatsFileFailure ) +    { +        std::string stats_file = llformat("/dev/shm/simperf/%s_proc.%d.llsd", mProcessName.c_str(), mProcessPID); +        mFrameStatsFile.close(); +        mFrameStatsFile.clear(); +        mFrameStatsFile.open(stats_file, llofstream::out); +        if ( mFrameStatsFile.fail() ) +        { +            llinfos << "Error opening statistics log file " << stats_file << llendl; +            mFrameStatsFileFailure = TRUE; +        } +        else +        { +            LLSD process_info = LLSD::emptyMap(); +            process_info["name"] = mProcessName; +            process_info["pid"] = (LLSD::Integer) mProcessPID; +            process_info["stat_rate"] = (LLSD::Integer) mReportPerformanceStatInterval; +            // Add process-specific info. +            addProcessHeaderInfo(process_info); + +            mFrameStatsFile << LLSDNotationStreamer(process_info) << std::endl;  +        } +    } +} + +// Dump out performance metrics over some time interval +void LLPerfStats::dumpIntervalPerformanceStats() +{ +    // Ensure output file is OK +    openPerfStatsFile(); + +    if ( mFrameStatsFile ) +    { +        LLSD stats = LLSD::emptyMap(); + +        LLStatAccum::TimeScale scale; +        if ( getReportPerformanceInterval() == 0.f ) +        { +            scale = LLStatAccum::SCALE_PER_FRAME; +        } +        else if ( getReportPerformanceInterval() < 0.5f ) +        { +            scale = LLStatAccum::SCALE_100MS; +        } +        else +        { +            scale = LLStatAccum::SCALE_SECOND; +        } + +        // Write LLSD into log +        stats["utc_time"] = (LLSD::String) LLError::utcTime(); +        stats["timestamp"] = U64_to_str((totalTime() / 1000) + (gUTCOffset * 1000));    // milliseconds since epoch +        stats["frame_number"] = (LLSD::Integer) LLFrameTimer::getFrameCount(); + +        // Add process-specific frame info. +        addProcessFrameInfo(stats, scale); +        LLPerfBlock::addStatsToLLSDandReset( stats, scale ); + +        mFrameStatsFile << LLSDNotationStreamer(stats) << std::endl;  +    } +} + +// Set length of performance stat recording +void    LLPerfStats::setReportPerformanceDuration( F32 seconds ) +{  +	if ( seconds <= 0.f ) +	{ +		mReportPerformanceStatEnd = 0.0; +		LLPerfBlock::setStatsEnabled( FALSE ); +		mFrameStatsFile.close(); +		LLPerfBlock::clearDynamicStats(); +	} +	else +	{ +		mReportPerformanceStatEnd = LLFrameTimer::getElapsedSeconds() + ((F64) seconds); +		// Clear failure flag to try and create the log file once +		mFrameStatsFileFailure = FALSE; +		LLPerfBlock::setStatsEnabled( TRUE ); +		mSkipFirstFrameStats = TRUE;		// Skip the first report (at the end of this frame) +	} +} + +void LLPerfStats::updatePerFrameStats() +{ +    (void) LLStatsConfigFile::instance().checkAndReload(); +	static LLFrameTimer performance_stats_timer; +	if ( frameStatsIsRunning() ) +	{ +		if ( mReportPerformanceStatInterval == 0 ) +		{	// Record info every frame +			if ( mSkipFirstFrameStats ) +			{	// Skip the first time - was started this frame +				mSkipFirstFrameStats = FALSE; +			} +			else +			{ +				dumpIntervalPerformanceStats(); +			} +		} +		else +		{ +			performance_stats_timer.setTimerExpirySec( getReportPerformanceInterval() ); +			if (performance_stats_timer.checkExpirationAndReset( mReportPerformanceStatInterval )) +			{ +				dumpIntervalPerformanceStats(); +			} +		} +		 +		if ( LLFrameTimer::getElapsedSeconds() > mReportPerformanceStatEnd ) +		{	// Reached end of time, clear it to stop reporting +			setReportPerformanceDuration(0.f);			// Don't set mReportPerformanceStatEnd directly	 +            llinfos << "Recording performance stats completed" << llendl; +		} +	} +} + + +//------------------------------------------------------------------------ + +U64 LLStatAccum::sScaleTimes[NUM_SCALES] =  {  	USEC_PER_SEC / 10,				// 100 millisec  	USEC_PER_SEC * 1,				// seconds  	USEC_PER_SEC * 60,				// minutes -	USEC_PER_SEC * 60 * 2			// two minutes  #if ENABLE_LONG_TIME_STATS  	// enable these when more time scales are desired  	USEC_PER_SEC * 60*60,			// hours @@ -71,7 +342,7 @@ void LLStatAccum::reset(U64 when)  	mRunning = TRUE;  	mLastTime = when; -	for (int i = 0; i < IMPL_NUM_SCALES; ++i) +	for (int i = 0; i < NUM_SCALES; ++i)  	{  		mBuckets[i].accum = 0.0;  		mBuckets[i].endTime = when + sScaleTimes[i]; @@ -104,7 +375,7 @@ void LLStatAccum::sum(F64 value, U64 when)  	// how long is this value for  	U64 timeSpan = when - mLastTime; -	for (int i = 0; i < IMPL_NUM_SCALES; ++i) +	for (int i = 0; i < NUM_SCALES; ++i)  	{  		Bucket& bucket = mBuckets[i]; @@ -150,7 +421,12 @@ F32 LLStatAccum::meanValue(TimeScale scale) const  	{  		return 0.0;  	} -	if (scale < 0 || scale >= IMPL_NUM_SCALES) +	if ( scale == SCALE_PER_FRAME ) +	{	// Per-frame not supported here +		scale = SCALE_100MS; +	} + +	if (scale < 0 || scale >= NUM_SCALES)  	{  		llwarns << "llStatAccum::meanValue called for unsupported scale: "  			<< scale << llendl; @@ -260,25 +536,34 @@ void LLStatMeasure::sample(F64 value)  // ------------------------------------------------------------------------ -LLStatTime::LLStatTime(bool use_frame_timer) -	: LLStatAccum(use_frame_timer), -	  mFrameNumber(0), -	  mTotalTimeInFrame(0) +LLStatTime::LLStatTime(const std::string & key) +	: LLStatAccum(false), +	  mFrameNumber(LLFrameTimer::getFrameCount()), +	  mTotalTimeInFrame(0), +	  mKey(key) +#if LL_DEBUG +	  , mRunning(FALSE) +#endif  { -	mFrameNumber = LLFrameTimer::getFrameCount();  }  void LLStatTime::start()  {  	// Reset frame accumluation if the frame number has changed  	U32 frame_number = LLFrameTimer::getFrameCount(); -	if ( frame_number != mFrameNumber) +	if ( frame_number != mFrameNumber )  	{  		mFrameNumber = frame_number;  		mTotalTimeInFrame = 0;  	}  	sum(0.0); + +#if LL_DEBUG +	// Shouldn't be running already +	llassert( !mRunning ); +	mRunning = TRUE; +#endif  }  void LLStatTime::stop() @@ -286,7 +571,149 @@ void LLStatTime::stop()  	U64 end_time = getCurrentUsecs();  	U64 duration = end_time - mLastTime;  	sum(F64(duration), end_time); +	//llinfos << "mTotalTimeInFrame incremented from  " << mTotalTimeInFrame << " to " << (mTotalTimeInFrame + duration) << llendl;   	mTotalTimeInFrame += duration; + +#if LL_DEBUG +	mRunning = FALSE; +#endif +} + +/* virtual */ F32 LLStatTime::meanValue(TimeScale scale) const +{ +    if ( LLStatAccum::SCALE_PER_FRAME == scale ) +    { +        return mTotalTimeInFrame; +    } +    else +    { +        return LLStatAccum::meanValue(scale); +    } +} + + +// ------------------------------------------------------------------------ + + +// Use this constructor for pre-defined LLStatTime objects +LLPerfBlock::LLPerfBlock(LLStatTime* stat ) : mPredefinedStat(stat), mDynamicStat(NULL) +{ +    if (mPredefinedStat) +    { +        // If dynamic stats are turned on, this will create a separate entry in the stat map. +        initDynamicStat(mPredefinedStat->mKey); + +        // Start predefined stats.  These stats are not part of the stat map. +        mPredefinedStat->start(); +    } +} + +// Use this constructor for dynamically created LLStatTime objects (not pre-defined) with a multi-part key. +// These are also turned on or off via the switch passed in +LLPerfBlock::LLPerfBlock( const char* key1, const char* key2 ) : mPredefinedStat(NULL), mDynamicStat(NULL) +{ +    if (!sStatsEnabled) return; + +    if (NULL == key2 || strlen(key2) == 0) +    { +        initDynamicStat(key1); +    } +    else +    { +        std::ostringstream key; +        key << key1 << "_" << key2; +        initDynamicStat(key.str()); +    } +} + +void LLPerfBlock::initDynamicStat(const std::string& key) +{ +    // Early exit if dynamic stats aren't enabled. +    if (!sStatsEnabled) return; + +    mLastPath = sCurrentStatPath;		// Save and restore current path +    sCurrentStatPath += "/" + key;		// Add key to current path + +    // See if the LLStatTime object already exists +    stat_map_t::iterator iter = sStatMap.find(sCurrentStatPath); +    if ( iter == sStatMap.end() ) +    { +        // StatEntry object doesn't exist, so create it +        mDynamicStat = new StatEntry( key ); +        sStatMap[ sCurrentStatPath ] = mDynamicStat;	// Set the entry for this path +    } +    else +    { +        // Found this path in the map, use the object there +        mDynamicStat = (*iter).second;		// Get StatEntry for the current path +    } + +    if (mDynamicStat) +    { +        mDynamicStat->mStat.start(); +        mDynamicStat->mCount++; +    } +    else +    { +        llwarns << "Initialized NULL dynamic stat at '" << sCurrentStatPath << "'" << llendl; +       sCurrentStatPath = mLastPath; +    } +} + + +// Destructor does the time accounting +LLPerfBlock::~LLPerfBlock() +{ +    if (mPredefinedStat) mPredefinedStat->stop(); +    if (mDynamicStat) +    { +        mDynamicStat->mStat.stop(); +        sCurrentStatPath = mLastPath;	// Restore the path in case sStatsEnabled changed during this block +    } +} + + +// Clear the map of any dynamic stats.  Static routine +void LLPerfBlock::clearDynamicStats() +{ +    std::for_each(sStatMap.begin(), sStatMap.end(), DeletePairedPointer()); +    sStatMap.clear(); +} + +// static - Extract the stat info into LLSD +void LLPerfBlock::addStatsToLLSDandReset( LLSD & stats, +										  LLStatAccum::TimeScale scale ) +{ +    // If we aren't in per-frame scale, we need to go from second to microsecond. +    U32 scale_adjustment = 1; +    if (LLStatAccum::SCALE_PER_FRAME != scale) +    { +        scale_adjustment = USEC_PER_SEC; +    } +	stat_map_t::iterator iter = sStatMap.begin(); +	for ( ; iter != sStatMap.end(); ++iter ) +	{	// Put the entry into LLSD "/full/path/to/stat/" = microsecond total time +		const std::string & stats_full_path = (*iter).first; + +		StatEntry * stat = (*iter).second; +		if (stat) +		{ +            if (stat->mCount > 0) +            { +                stats[stats_full_path] = LLSD::emptyMap(); +                stats[stats_full_path]["us"] = (LLSD::Integer) (scale_adjustment * stat->mStat.meanValue(scale)); +                if (stat->mCount > 1) +                { +                    stats[stats_full_path]["count"] = (LLSD::Integer) stat->mCount; +                } +                stat->mCount = 0; +            } +		} +		else +		{	// WTF?  Shouldn't have a NULL pointer in the map. +            llwarns << "Unexpected NULL dynamic stat at '" << stats_full_path << "'" << llendl; +		} +	}	  } diff --git a/indra/llcommon/llstat.h b/indra/llcommon/llstat.h index d4dcb3a961..a590d75120 100644 --- a/indra/llcommon/llstat.h +++ b/indra/llcommon/llstat.h @@ -33,9 +33,13 @@  #define LL_LLSTAT_H  #include <deque> +#include <map>  #include "lltimer.h"  #include "llframetimer.h" +#include "llfile.h" + +class	LLSD;  // Set this if longer stats are needed  #define ENABLE_LONG_TIME_STATS	0 @@ -58,19 +62,18 @@ public:  		SCALE_100MS,  		SCALE_SECOND,  		SCALE_MINUTE, -		SCALE_TWO_MINUTE,  #if ENABLE_LONG_TIME_STATS  		SCALE_HOUR,  		SCALE_DAY,  		SCALE_WEEK,  #endif -		NUM_SCALES +		NUM_SCALES,			// Use to size storage arrays +		SCALE_PER_FRAME		// For latest frame information - should be after NUM_SCALES since this doesn't go into the time buckets  	}; -	static const TimeScale IMPL_NUM_SCALES = (TimeScale)(SCALE_TWO_MINUTE + 1); -	static U64 sScaleTimes[IMPL_NUM_SCALES]; +	static U64 sScaleTimes[NUM_SCALES]; -	F32 meanValue(TimeScale scale) const; +	virtual F32 meanValue(TimeScale scale) const;  		// see the subclasses for the specific meaning of value  	F32 meanValueOverLast100ms()  const { return meanValue(SCALE_100MS);  } @@ -86,8 +89,8 @@ public:  		// Get current microseconds based on timer type  	BOOL	mUseFrameTimer; -  	BOOL	mRunning; +  	U64		mLastTime;  	struct Bucket @@ -99,7 +102,7 @@ public:  		F64		lastAccum;  	}; -	Bucket	mBuckets[IMPL_NUM_SCALES]; +	Bucket	mBuckets[NUM_SCALES];  	BOOL 	mLastSampleValid;  	F64 	mLastSampleValue; @@ -136,37 +139,115 @@ public:  }; -class LLTimeBlock; -  class LLStatTime : public LLStatAccum  	// gathers statistics about time spent in a block of code  	// measure average duration per second in the block  {  public: -	LLStatTime(bool use_frame_timer = false); +	LLStatTime( const std::string & key = "undefined" );  	U32		mFrameNumber;		// Current frame number  	U64		mTotalTimeInFrame;	// Total time (microseconds) accumulated during the last frame +	void	setKey( const std::string & key )		{ mKey = key;	}; + +	virtual F32 meanValue(TimeScale scale) const; +  private: -	void start(); +	void start();				// Start and stop measuring time block  	void stop(); -	friend class LLTimeBlock; + +	std::string		mKey;		// Tag representing this time block + +#if LL_DEBUG +	BOOL			mRunning;	// TRUE if start() has been called +#endif + +	friend class LLPerfBlock;  }; -class LLTimeBlock +// ---------------------------------------------------------------------------- + + +// Use this class on the stack to record statistics about an area of code +class LLPerfBlock  {  public: -	LLTimeBlock(LLStatTime& stat) : mStat(stat) { mStat.start(); } -	~LLTimeBlock()								{ mStat.stop(); } +    struct StatEntry +    { +            StatEntry(const std::string& key) : mStat(LLStatTime(key)), mCount(0) {} +            LLStatTime  mStat; +            U32         mCount; +    }; +    typedef std::map<std::string, StatEntry*>		stat_map_t; + +	// Use this constructor for pre-defined LLStatTime objects +	LLPerfBlock(LLStatTime* stat); + +	// Use this constructor for dynamically created LLStatTime objects (not pre-defined) with a multi-part key +	LLPerfBlock( const char* key1, const char* key2 = NULL); + + +	~LLPerfBlock(); + +	static void setStatsEnabled( BOOL enable )		{ sStatsEnabled = enable;	}; +	static S32  getStatsEnabled()					{ return sStatsEnabled;		}; + +	static void clearDynamicStats();		// Reset maps to clear out dynamic objects +	static void addStatsToLLSDandReset( LLSD & stats,		// Get current information and clear time bin +										LLStatAccum::TimeScale scale ); +  private: -	LLStatTime& mStat; +	// Initialize dynamically created LLStatTime objects +    void initDynamicStat(const std::string& key); + +	std::string				mLastPath;				// Save sCurrentStatPath when this is called +	LLStatTime * 			mPredefinedStat;		// LLStatTime object to get data +	StatEntry *				mDynamicStat;   		// StatEntryobject to get data + +	static BOOL				sStatsEnabled;			// Normally FALSE +    static stat_map_t		sStatMap;				// Map full path string to LLStatTime objects +	static std::string		sCurrentStatPath;		// Something like "frame/physics/physics step"  }; +// ---------------------------------------------------------------------------- +class LLPerfStats +{ +public: +    LLPerfStats(const std::string& process_name = "unknown", S32 process_pid = 0); +    virtual ~LLPerfStats(); + +    virtual void init();    // Reset and start all stat timers +    virtual void updatePerFrameStats(); +    // Override these function to add process-specific information to the performance log header and per-frame logging. +    virtual void addProcessHeaderInfo(LLSD& info) { /* not implemented */ } +    virtual void addProcessFrameInfo(LLSD& info, LLStatAccum::TimeScale scale) { /* not implemented */ } + +    // High-resolution frame stats +    BOOL    frameStatsIsRunning()                                { return (mReportPerformanceStatEnd > 0.);        }; +    F32     getReportPerformanceInterval() const                { return mReportPerformanceStatInterval;        }; +    void    setReportPerformanceInterval( F32 interval )        { mReportPerformanceStatInterval = interval;    }; +    void    setReportPerformanceDuration( F32 seconds ); +    void    setProcessName(const std::string& process_name) { mProcessName = process_name; } +    void    setProcessPID(S32 process_pid) { mProcessPID = process_pid; } + +protected: +    void    openPerfStatsFile();                    // Open file for high resolution metrics logging +    void    dumpIntervalPerformanceStats(); +    llofstream      mFrameStatsFile;            // File for per-frame stats +    BOOL            mFrameStatsFileFailure;        // Flag to prevent repeat opening attempts +    BOOL            mSkipFirstFrameStats;        // Flag to skip one (partial) frame report +    std::string     mProcessName; +    S32             mProcessPID; +private: +    F32 mReportPerformanceStatInterval;    // Seconds between performance stats +    F64 mReportPerformanceStatEnd;        // End time (seconds) for performance stats +}; +// ----------------------------------------------------------------------------  class LLStat  {  public: diff --git a/indra/llcommon/llstatenums.h b/indra/llcommon/llstatenums.h index 45c4fa986b..fd175d4430 100644 --- a/indra/llcommon/llstatenums.h +++ b/indra/llcommon/llstatenums.h @@ -33,38 +33,41 @@  enum  { -	LL_SIM_STAT_TIME_DILATION, +	LL_SIM_STAT_TIME_DILATION,				// 0  	LL_SIM_STAT_FPS,  	LL_SIM_STAT_PHYSFPS,  	LL_SIM_STAT_AGENTUPS,  	LL_SIM_STAT_FRAMEMS, -	LL_SIM_STAT_NETMS, +	LL_SIM_STAT_NETMS,						// 5  	LL_SIM_STAT_SIMOTHERMS,  	LL_SIM_STAT_SIMPHYSICSMS,  	LL_SIM_STAT_AGENTMS,  	LL_SIM_STAT_IMAGESMS, -	LL_SIM_STAT_SCRIPTMS, +	LL_SIM_STAT_SCRIPTMS,					// 10  	LL_SIM_STAT_NUMTASKS,  	LL_SIM_STAT_NUMTASKSACTIVE,  	LL_SIM_STAT_NUMAGENTMAIN,  	LL_SIM_STAT_NUMAGENTCHILD, -	LL_SIM_STAT_NUMSCRIPTSACTIVE, +	LL_SIM_STAT_NUMSCRIPTSACTIVE,			// 15  	LL_SIM_STAT_LSLIPS,  	LL_SIM_STAT_INPPS,  	LL_SIM_STAT_OUTPPS,  	LL_SIM_STAT_PENDING_DOWNLOADS, -	LL_SIM_STAT_PENDING_UPLOADS, +	LL_SIM_STAT_PENDING_UPLOADS,			// 20  	LL_SIM_STAT_VIRTUAL_SIZE_KB,  	LL_SIM_STAT_RESIDENT_SIZE_KB,  	LL_SIM_STAT_PENDING_LOCAL_UPLOADS,  	LL_SIM_STAT_TOTAL_UNACKED_BYTES, -	LL_SIM_STAT_PHYSICS_PINNED_TASKS, +	LL_SIM_STAT_PHYSICS_PINNED_TASKS,		// 25  	LL_SIM_STAT_PHYSICS_LOD_TASKS,  	LL_SIM_STAT_SIMPHYSICSSTEPMS,  	LL_SIM_STAT_SIMPHYSICSSHAPEMS,  	LL_SIM_STAT_SIMPHYSICSOTHERMS, -	LL_SIM_STAT_SIMPHYSICSMEMORY, +	LL_SIM_STAT_SIMPHYSICSMEMORY,			// 30  	LL_SIM_STAT_SCRIPT_EPS, +	LL_SIM_STAT_SIMSPARETIME, +	LL_SIM_STAT_SIMSLEEPTIME, +	LL_SIM_STAT_IOPUMPTIME,  };  #endif diff --git a/indra/llcommon/lltimer.cpp b/indra/llcommon/lltimer.cpp index 7570420d2c..2c34608064 100644 --- a/indra/llcommon/lltimer.cpp +++ b/indra/llcommon/lltimer.cpp @@ -83,15 +83,20 @@ void ms_sleep(U32 ms)  {  	Sleep(ms);  } + +U32 micro_sleep(U64 us, U32 max_yields) +{ +    // max_yields is unused; just fiddle with it to avoid warnings. +    max_yields = 0; +    ms_sleep(us / 1000); +    return 0; +}  #elif LL_LINUX || LL_SOLARIS || LL_DARWIN -void ms_sleep(U32 ms) +static void _sleep_loop(struct timespec& thiswait)  { -	long mslong = ms; // tv_nsec is a long -	struct timespec thiswait, nextwait; +	struct timespec nextwait;  	bool sleep_more = false; -	thiswait.tv_sec = ms / 1000; -	thiswait.tv_nsec = (mslong % 1000) * 1000000l;  	do {  		int result = nanosleep(&thiswait, &nextwait); @@ -127,6 +132,44 @@ void ms_sleep(U32 ms)  		}  	} while (sleep_more);  } + +U32 micro_sleep(U64 us, U32 max_yields) +{ +    U64 start = get_clock_count(); +    // This is kernel dependent.  Currently, our kernel generates software clock +    // interrupts at 250 Hz (every 4,000 microseconds). +    const U64 KERNEL_SLEEP_INTERVAL_US = 4000; + +    S32 num_sleep_intervals = (us - (KERNEL_SLEEP_INTERVAL_US >> 1)) / KERNEL_SLEEP_INTERVAL_US; +    if (num_sleep_intervals > 0) +    { +        U64 sleep_time = (num_sleep_intervals * KERNEL_SLEEP_INTERVAL_US) - (KERNEL_SLEEP_INTERVAL_US >> 1); +        struct timespec thiswait; +        thiswait.tv_sec = sleep_time / 1000000; +        thiswait.tv_nsec = (sleep_time % 1000000) * 1000l; +        _sleep_loop(thiswait); +    } + +    U64 current_clock = get_clock_count(); +    U32 yields = 0; +    while (    (yields < max_yields) +            && (current_clock - start < us) ) +    { +        sched_yield(); +        ++yields; +        current_clock = get_clock_count(); +    } +    return yields; +} + +void ms_sleep(U32 ms) +{ +	long mslong = ms; // tv_nsec is a long +	struct timespec thiswait; +	thiswait.tv_sec = ms / 1000; +	thiswait.tv_nsec = (mslong % 1000) * 1000000l; +    _sleep_loop(thiswait); +}  #else  # error "architecture not supported"  #endif diff --git a/indra/llcommon/lltimer.h b/indra/llcommon/lltimer.h index ea84f8ea2c..1916d67fda 100644 --- a/indra/llcommon/lltimer.h +++ b/indra/llcommon/lltimer.h @@ -117,6 +117,7 @@ void update_clock_frequencies();  // Sleep for milliseconds  void ms_sleep(U32 ms); +U32 micro_sleep(U64 us, U32 max_yields = 0xFFFFFFFF);  // Returns the correct UTC time in seconds, like time(NULL).  // Useful on the viewer, which may have its local clock set wrong. diff --git a/indra/llmessage/lliohttpserver.cpp b/indra/llmessage/lliohttpserver.cpp index 6d157206c8..b37126df38 100644 --- a/indra/llmessage/lliohttpserver.cpp +++ b/indra/llmessage/lliohttpserver.cpp @@ -47,6 +47,7 @@  #include "llpumpio.h"  #include "llsd.h"  #include "llsdserialize_xml.h" +#include "llstat.h"  #include "llstl.h"  #include "lltimer.h" @@ -171,22 +172,26 @@ LLIOPipe::EStatus LLHTTPPipe::process_impl(  		std::string verb = context[CONTEXT_REQUEST][CONTEXT_VERB];  		if(verb == HTTP_VERB_GET)  		{ +            LLPerfBlock getblock("http_get");     			mNode.get(LLHTTPNode::ResponsePtr(mResponse), context);  		}  		else if(verb == HTTP_VERB_PUT)  		{ +            LLPerfBlock putblock("http_put");  			LLSD input;  			LLSDSerialize::fromXML(input, istr);  			mNode.put(LLHTTPNode::ResponsePtr(mResponse), context, input);  		}  		else if(verb == HTTP_VERB_POST)  		{ +            LLPerfBlock postblock("http_post");  			LLSD input;  			LLSDSerialize::fromXML(input, istr);  			mNode.post(LLHTTPNode::ResponsePtr(mResponse), context, input);  		}  		else if(verb == HTTP_VERB_DELETE)  		{ +            LLPerfBlock delblock("http_delete");  			mNode.del(LLHTTPNode::ResponsePtr(mResponse), context);  		}		  		else if(verb == HTTP_VERB_OPTIONS) diff --git a/indra/llmessage/llmessagetemplate.h b/indra/llmessage/llmessagetemplate.h index 69040cc288..93755047b5 100644 --- a/indra/llmessage/llmessagetemplate.h +++ b/indra/llmessage/llmessagetemplate.h @@ -34,6 +34,7 @@  #include "lldarray.h"  #include "message.h" // TODO: babbage: Remove... +#include "llstat.h"  #include "llstl.h"  class LLMsgVarData @@ -370,6 +371,7 @@ public:  	{  		if (mHandlerFunc)  		{ +            LLPerfBlock msg_cb_time("msg_cb", mName);  			mHandlerFunc(msgsystem, mUserData);  			return TRUE;  		} diff --git a/indra/llmessage/llpumpio.cpp b/indra/llmessage/llpumpio.cpp index 284a7141d0..39e9a8b952 100644 --- a/indra/llmessage/llpumpio.cpp +++ b/indra/llmessage/llpumpio.cpp @@ -41,6 +41,7 @@  #include "llapr.h"  #include "llmemtype.h"  #include "llstl.h" +#include "llstat.h"  // These should not be enabled in production, but they can be  // intensely useful during development for finding certain kinds of @@ -521,7 +522,10 @@ void LLPumpIO::pump(const S32& poll_timeout)  		//llinfos << "polling" << llendl;  		S32 count = 0;  		S32 client_id = 0; -		apr_pollset_poll(mPollset, poll_timeout, &count, &poll_fd); +        { +            LLPerfBlock polltime("pump_poll"); +            apr_pollset_poll(mPollset, poll_timeout, &count, &poll_fd); +        }  		PUMP_DEBUG;  		for(S32 ii = 0; ii < count; ++ii)  		{ diff --git a/indra/llvfs/llvfile.cpp b/indra/llvfs/llvfile.cpp index bd4dfc2d78..c4318f2495 100644 --- a/indra/llvfs/llvfile.cpp +++ b/indra/llvfs/llvfile.cpp @@ -35,6 +35,7 @@  #include "llerror.h"  #include "llthread.h" +#include "llstat.h"  #include "llvfs.h"  const S32 LLVFile::READ			= 0x00000001; diff --git a/indra/newview/llstartup.cpp b/indra/newview/llstartup.cpp index 0668241f83..4f98c3b524 100644 --- a/indra/newview/llstartup.cpp +++ b/indra/newview/llstartup.cpp @@ -3549,7 +3549,7 @@ void init_stat_view()  	stat_barp->mDisplayBar = FALSE;  	stat_barp->mDisplayMean = FALSE; -	stat_barp = sim_time_viewp->addStat("Sim Time (Physics)", &(LLViewerStats::getInstance()->mSimSimPhysicsMsec)); +	stat_barp = sim_time_viewp->addStat("Physics Time", &(LLViewerStats::getInstance()->mSimSimPhysicsMsec));  	stat_barp->setUnitLabel("ms");  	stat_barp->mPrecision = 1;  	stat_barp->mMinBar = 0.f; @@ -3560,45 +3560,7 @@ void init_stat_view()  	stat_barp->mDisplayBar = FALSE;  	stat_barp->mDisplayMean = FALSE; -	LLStatView *physics_time_viewp; -	physics_time_viewp = new LLStatView("physics perf view", "Physics Details (ms)", "", rect); -	sim_time_viewp->addChildAtEnd(physics_time_viewp); -	{ -		stat_barp = physics_time_viewp->addStat("Physics Step", &(LLViewerStats::getInstance()->mSimSimPhysicsStepMsec)); -		stat_barp->setUnitLabel("ms"); -		stat_barp->mPrecision = 1; -		stat_barp->mMinBar = 0.f; -		stat_barp->mMaxBar = 40.f; -		stat_barp->mTickSpacing = 10.f; -		stat_barp->mLabelSpacing = 20.f; -		stat_barp->mPerSec = FALSE; -		stat_barp->mDisplayBar = FALSE; -		stat_barp->mDisplayMean = FALSE; - -		stat_barp = physics_time_viewp->addStat("Update Shapes", &(LLViewerStats::getInstance()->mSimSimPhysicsShapeUpdateMsec)); -		stat_barp->setUnitLabel("ms"); -		stat_barp->mPrecision = 1; -		stat_barp->mMinBar = 0.f; -		stat_barp->mMaxBar = 40.f; -		stat_barp->mTickSpacing = 10.f; -		stat_barp->mLabelSpacing = 20.f; -		stat_barp->mPerSec = FALSE; -		stat_barp->mDisplayBar = FALSE; -		stat_barp->mDisplayMean = FALSE; - -		stat_barp = physics_time_viewp->addStat("Other", &(LLViewerStats::getInstance()->mSimSimPhysicsOtherMsec)); -		stat_barp->setUnitLabel("ms"); -		stat_barp->mPrecision = 1; -		stat_barp->mMinBar = 0.f; -		stat_barp->mMaxBar = 40.f; -		stat_barp->mTickSpacing = 10.f; -		stat_barp->mLabelSpacing = 20.f; -		stat_barp->mPerSec = FALSE; -		stat_barp->mDisplayBar = FALSE; -		stat_barp->mDisplayMean = FALSE; -	} - -	stat_barp = sim_time_viewp->addStat("Sim Time (Other)", &(LLViewerStats::getInstance()->mSimSimOtherMsec)); +	stat_barp = sim_time_viewp->addStat("Simulation Time", &(LLViewerStats::getInstance()->mSimSimOtherMsec));  	stat_barp->setUnitLabel("ms");  	stat_barp->mPrecision = 1;  	stat_barp->mMinBar = 0.f; @@ -3642,6 +3604,79 @@ void init_stat_view()  	stat_barp->mDisplayBar = FALSE;  	stat_barp->mDisplayMean = FALSE; +	stat_barp = sim_time_viewp->addStat("Spare Time", &(LLViewerStats::getInstance()->mSimSpareMsec)); +	stat_barp->setUnitLabel("ms"); +	stat_barp->mPrecision = 1; +	stat_barp->mMinBar = 0.f; +	stat_barp->mMaxBar = 40.f; +	stat_barp->mTickSpacing = 10.f; +	stat_barp->mLabelSpacing = 20.f; +	stat_barp->mPerSec = FALSE; +	stat_barp->mDisplayBar = FALSE; +	stat_barp->mDisplayMean = FALSE; + +	 +	// 2nd level time blocks under 'Details' second +	LLStatView *detailed_time_viewp; +	detailed_time_viewp = new LLStatView("sim perf view", "Time Details (ms)", "", rect); +	sim_time_viewp->addChildAtEnd(detailed_time_viewp); +	{ +		stat_barp = detailed_time_viewp->addStat("  Physics Step", &(LLViewerStats::getInstance()->mSimSimPhysicsStepMsec)); +		stat_barp->setUnitLabel("ms"); +		stat_barp->mPrecision = 1; +		stat_barp->mMinBar = 0.f; +		stat_barp->mMaxBar = 40.f; +		stat_barp->mTickSpacing = 10.f; +		stat_barp->mLabelSpacing = 20.f; +		stat_barp->mPerSec = FALSE; +		stat_barp->mDisplayBar = FALSE; +		stat_barp->mDisplayMean = FALSE; + +		stat_barp = detailed_time_viewp->addStat("  Update Physics Shapes", &(LLViewerStats::getInstance()->mSimSimPhysicsShapeUpdateMsec)); +		stat_barp->setUnitLabel("ms"); +		stat_barp->mPrecision = 1; +		stat_barp->mMinBar = 0.f; +		stat_barp->mMaxBar = 40.f; +		stat_barp->mTickSpacing = 10.f; +		stat_barp->mLabelSpacing = 20.f; +		stat_barp->mPerSec = FALSE; +		stat_barp->mDisplayBar = FALSE; +		stat_barp->mDisplayMean = FALSE; + +		stat_barp = detailed_time_viewp->addStat("  Physics Other", &(LLViewerStats::getInstance()->mSimSimPhysicsOtherMsec)); +		stat_barp->setUnitLabel("ms"); +		stat_barp->mPrecision = 1; +		stat_barp->mMinBar = 0.f; +		stat_barp->mMaxBar = 40.f; +		stat_barp->mTickSpacing = 10.f; +		stat_barp->mLabelSpacing = 20.f; +		stat_barp->mPerSec = FALSE; +		stat_barp->mDisplayBar = FALSE; +		stat_barp->mDisplayMean = FALSE; + +		stat_barp = detailed_time_viewp->addStat("  Sleep Time", &(LLViewerStats::getInstance()->mSimSleepMsec)); +		stat_barp->setUnitLabel("ms"); +		stat_barp->mPrecision = 1; +		stat_barp->mMinBar = 0.f; +		stat_barp->mMaxBar = 40.f; +		stat_barp->mTickSpacing = 10.f; +		stat_barp->mLabelSpacing = 20.f; +		stat_barp->mPerSec = FALSE; +		stat_barp->mDisplayBar = FALSE; +		stat_barp->mDisplayMean = FALSE; + +		stat_barp = detailed_time_viewp->addStat("  Pump IO", &(LLViewerStats::getInstance()->mSimPumpIOMsec)); +		stat_barp->setUnitLabel("ms"); +		stat_barp->mPrecision = 1; +		stat_barp->mMinBar = 0.f; +		stat_barp->mMaxBar = 40.f; +		stat_barp->mTickSpacing = 10.f; +		stat_barp->mLabelSpacing = 20.f; +		stat_barp->mPerSec = FALSE; +		stat_barp->mDisplayBar = FALSE; +		stat_barp->mDisplayMean = FALSE; +	} +  	LLRect r = gDebugView->mFloaterStatsp->getRect();  	// Reshape based on the parameters we set. diff --git a/indra/newview/llviewermessage.cpp b/indra/newview/llviewermessage.cpp index 2278527bc9..8b81a2fe5a 100644 --- a/indra/newview/llviewermessage.cpp +++ b/indra/newview/llviewermessage.cpp @@ -3505,6 +3505,15 @@ void process_sim_stats(LLMessageSystem *msg, void **user_data)  		case LL_SIM_STAT_SIMPHYSICSMEMORY:  			LLViewerStats::getInstance()->mPhysicsMemoryAllocated.addValue(stat_value);  			break; +		case LL_SIM_STAT_SIMSPARETIME: +			LLViewerStats::getInstance()->mSimSpareMsec.addValue(stat_value); +			break; +		case LL_SIM_STAT_SIMSLEEPTIME: +			LLViewerStats::getInstance()->mSimSleepMsec.addValue(stat_value); +			break; +		case LL_SIM_STAT_IOPUMPTIME: +			LLViewerStats::getInstance()->mSimPumpIOMsec.addValue(stat_value); +			break;  		default:  			// Used to be a commented out warning.   			LL_DEBUGS("Messaging") << "Unknown stat id" << stat_id << LL_ENDL; diff --git a/indra/newview/llviewerstats.h b/indra/newview/llviewerstats.h index 446f8f026a..79b11cf484 100644 --- a/indra/newview/llviewerstats.h +++ b/indra/newview/llviewerstats.h @@ -77,6 +77,9 @@ public:  	LLStat mSimAgentMsec;  	LLStat mSimImagesMsec;  	LLStat mSimScriptMsec; +	LLStat mSimSpareMsec; +	LLStat mSimSleepMsec; +	LLStat mSimPumpIOMsec;  	LLStat mSimMainAgents;  	LLStat mSimChildAgents; | 
