diff options
author | Don Kjer <don@lindenlab.com> | 2008-10-09 18:07:46 +0000 |
---|---|---|
committer | Don Kjer <don@lindenlab.com> | 2008-10-09 18:07:46 +0000 |
commit | 4ff16b735f59326514ad92ec38e3261cd996e05c (patch) | |
tree | 170416c912dc272e7e171f156494946e05444e55 | |
parent | b807e3df990e6fad25cd0bca94d2959dac042b13 (diff) |
QAR-907: svn merge -r 98908:98910 svn+ssh://svn/svn/linden/qa/sim-metrics/sim-metrics2-release-merge-98903 into release
-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; |