QAR-907: svn merge -r 98908:98910 svn+ssh://svn/svn/linden/qa/sim-metrics/sim-metrics2-release-merge-98903 into release

meow-7.2.2
Don Kjer 2008-10-09 18:07:46 +00:00
parent b807e3df99
commit 4ff16b735f
17 changed files with 1516 additions and 82 deletions

View File

@ -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)

View File

@ -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()

View File

@ -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())

View File

@ -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())

View File

@ -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

View File

@ -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;
}
}
}

View File

@ -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:

View File

@ -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

View File

@ -83,15 +83,20 @@ void ms_sleep(U32 ms)
{
Sleep(ms);
}
#elif LL_LINUX || LL_SOLARIS || LL_DARWIN
void ms_sleep(U32 ms)
U32 micro_sleep(U64 us, U32 max_yields)
{
long mslong = ms; // tv_nsec is a long
struct timespec thiswait, nextwait;
// 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
static void _sleep_loop(struct timespec& thiswait)
{
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

View File

@ -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.

View File

@ -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)

View File

@ -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;
}

View File

@ -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)
{

View File

@ -35,6 +35,7 @@
#include "llerror.h"
#include "llthread.h"
#include "llstat.h"
#include "llvfs.h"
const S32 LLVFile::READ = 0x00000001;

View File

@ -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.

View File

@ -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;

View File

@ -77,6 +77,9 @@ public:
LLStat mSimAgentMsec;
LLStat mSimImagesMsec;
LLStat mSimScriptMsec;
LLStat mSimSpareMsec;
LLStat mSimSleepMsec;
LLStat mSimPumpIOMsec;
LLStat mSimMainAgents;
LLStat mSimChildAgents;