Hi all,
On Tuesday we talked a fair amount about NetLogger and logging APIs. I
also had a talk with Russell about his ideas for the API and behavior of
the logging.
I've written (or re-written) a NetLogger-based implementation of
Michelle's API. Right now it's at branches/DC1/src/log/, and it has
three components:
logd.py : This reads the policy file, spawns a forwarding daemon that
watches the local log file and forwards it to the central logging node,
and if this *is* the central node, spawns a listening daemon, too.
LSSTLog.py: My old Python module, which is a wrapper around NetLogger,
and which also now includes a function (outside of any class) called
log(message, priority=INFO, **extraData). This is compatible with
Michelle's API, but also adds the possibility of taking additional
parameters. See my suggestions on style below for how to use this.
nlogtopd.py: A daemon which parses 'top' and writes data to the log file.
(also, logging.policy in this directory controls logging behavior).
The two important changes are the following: logd.py *must* be run if
you are running on multiple machines. Without it, data is not
forwarded. This is a major point of contention with people - I've
talked to Tim and Russell about writing a smarter forwarding daemon
which will automatically run when LSSTLog is used, but I've heard
several ideas about how to do this (Singleton pattern, grep-ing "ps
-ef", talking to a known socket address and asking "are you my
daemon?", etc) but Tim and I have decided I need to work on other things
right now.
I added some fairly extensive information to LSSTLog.py's docstring,
explaining how to use log(...) for best effectiveness.
The long and short of it is this:
log("stageleader.moveData.start", priority=INFO, MPI_RANK='1')
will generate the following:
t DATE: 2006-08-10T23:05:22.836473
s LVL: INFO
s HOST: 141.142.41.82
s MPI_RANK: 1
s EVNT: stageleader.moveData.start
our visualization software can use this to correlate the program
running, the machine it's running on, and the time it entered a section
of the code called 'moveData'. Instrumenting code with messages like
"programName.majorFunction.start" and "programName.majorFunction.end"
will help us figure out where code is getting slowed down.
Since logging seems to be important to many people, I'd appreciate if
everyone would look at the code and say whether or not they feel
strongly about moving to this version before we make our next run on
TeraGrid. Since it's API-compatible, I could potentially just change
"LSSTLog" to "log" in the source and replace Michelle's code in the SVN
tree.
-jmyers
#!/usr/bin/env python
import nlforward
import os
import sys
import apps.fw.Policy.Policy as Policy
import log.LSSTLog as LSSTLog
ForwardInterval=5
def startListener(centralLogFile):
tmp = os.fork()
#start netlogd.py daemon.
if tmp == 0:
try:
os.execlpe('netlogd.py',
'netlogd.py',
"-o" + centralLogFile + "",
os.environ)
except OSError:
sys.stderr.write("nlogtopd: Couldn't find netlogd.py" +
" - listening daemon not started!")
if __name__ == "__main__":
# read Policy file to determine where to send log messages
logPolicy = Policy('./logging.policy')
logNode = logPolicy.Get ('logNode')
localLog = logPolicy.Get ('logFile')
centralLogFile = logPolicy.Get('centralLogFile')
fwdir, fwpat = os.path.split(localLog)
if fwdir == '':
localLog = './' + localLog
# because nlforward.py demands a directory component,
# *that's* why!
#if this *is* the server node, start listening!
if LSSTLog.nllite.get_host() == logNode:
startListener(centralLogFile)
#nlforward.py is not a daemon for some reason, so
# let's make it one!
# TO DO: Don't spawn another forwarding daemon if
# there is already one shown by ps -ef.
if os.fork()==0:
os.setsid()
sys.stdout=open("/dev/null", 'w')
sys.stdin=open("/dev/null", 'r')
if os.fork()==0:
#start a forwarding daemon for that log
try:
os.execlpe('nlforward.py',
'nlforward.py',
"-s " + str(ForwardInterval),
localLog,
"x-netlog://" + logNode,
os.environ)
sys.exit(0)
except OSError:
sys.stderr.write("logd: Couldn't find nlforward.py" +
" - forwarding daemon not started!")
sys.exit(-1)
#!/usr/bin/env python
"""LSSTLog is a thin wrapper around the NetLogger package
to allow simpler usage of the NetLogger package.
We intend to implement the NetLogger methodology
as described at http://dsd.lbl.gov/NetLogger/methodology.html.
Before running anything that uses LSSTLog, you *MUST*
run logd.py. logd.py spawns the daemons for
forwarding logs and receiving logs over the network.
*IF LOGD.PY IS NOT RUN, YOUR LOGS WILL NOT BE RECEIVED.*
This is the biggest change from Michelle's original
logging method. And of course, if you're just debugging,
you might not want to bother forwarding to a central log-
instead, you can always just read the local one.
Also, there is now an extra, optional parameter to log(...),
but that means that log remains backwards-compatible.
However, it is strongly recommended that you read style
suggestions below, as this will allow us to have an easier,
more useful time visualizing logs and extracting useful info.
log(message, priority=INFO, **extraData)
----------------------------------------
where priority is one of the constants defined in this
module and extraData are field-value pairs
(i.e. a variable number of parameters of the form
key1=value1, key2=value2,...)
These field-value pairs, along with the message (in NL
parlance, an 'event' - which has an implicit field-name
'EVENT') will be used for visualization.
STYLE SUGGESTONS
-----------------
Good message (event) names are ones like:
'myModule.doBigCalculation.start'
'myModule.doBigCalculation.end'
for diagnostics, or:
'myModule.MPI_Comm_World.err'
for an error.
Good field-value pairs might be:
MPI_ERROR_CODE=32,
ERR_MESSAGE='Looks like our MPI Universe is too small for spawning!' }
for an error log
or
LOOP_ITERATOR_VALUE=i, MY_MPI_RANK=mpiRank
in an very computationally-intensive loop on variable i
inside an MPI program.
Note that all logs will automatically include the calling node's hostname,
the current system time. And of course, bear in mind when writing
an error message, we can filter out any information we want,
but obviously cannot extract information that is not given!
code examples:
import LSSTLog
....
def main(argv):
LSSTLog.log('myModule.main.start', LSSTLog.INFO)
....
try:
for i in range(10):
LSSTLog.log('myModule.moveHugeDataSet.start',
LSSTLog.INFO,
HUGE_DATA_SET_INDEX=i)
moveHugeDataSet(i)
LSSTLog.log('myModule.moveHugeDataSet.end',
LSSTLog.INFO,
HUGE_DATA_SET_INDEX=i)
except e:
LSSTLog.log('myModule.main.err', LSSTLog.ERR,
ERR_MESSAGE=\"\"\"Got an exception
while moving huge data sets!\"\"\")
...
...
LSSTLog.log('myModule.main.end', LSSTLog.INFO)
return 0
Added by jmyers.
"""
from gov.lbl.dsd.netlogger import nllite
import os
import sys
import apps.fw.Policy.Policy as Policy
__author__="jmyers"
#For API compatibility with Michelle's version
#global GlobalLog
GlobalLog = None
#GlobalLogSetFlag = 0
CRIT = nllite.Level.FATAL
ERR = nllite.Level.ERROR
WARNING = nllite.Level.WARN
INFO = nllite.Level.INFO
DEBUG = nllite.Level.DEBUG
DefaultLogLevel = DEBUG
def log(message, priority=DefaultLogLevel, source="", **extraData):
"""log: Log a message. (with NetLogger!)
Please read LSSTLog.py's docstring for more info
on using this utility! You should really run logd.py first!
Inputs:
-message: an event which has occurred or error message.
-priority: message priority, one of:
- CRITICAL
- ERROR
- WARNING
- INFO
- DEBUG
The meanings are the same as for the syslog unix utility
-source: Optional, the name of your program.
-extraData: A Python Dictionary of field-value pairs
which should be used for specific data you would like to record.
Please see the LSSTLog module's docstring for much better
style and usage information on this one, it's very important!
-jmyers
"""
global GlobalLog
if GlobalLog == None:
# set up the global log
logPolicy = Policy('./logging.policy')
localLog = logPolicy.Get ('logFile')
GlobalLog = LSSTLog(localLog)
ed = extraData
if source != "":
ed['SOURCE'] = source
GlobalLog.write(message, extraData=ed, msgLevel=priority)
def withoutWhiteSpace(input):
returnVal = input
if isinstance(input, str):
returnVal = input.replace(' ', '_')
return returnVal
#### actual LSSTLog class
class LSSTLog:
"""LSSTLog is a thin wrapper around the NetLogger package
to allow (slightly) simpler, non-buffered logging for Python.
The LSSTLog class basically does the following for you:
-when instantiated:
-create an nllite (NetLogger) LogOutputStream
-sets the local logfile for the LogOutputStream
-sets the LogOutputStream loglevel to Debug3 (highest)
-if second parametre, centralLogNodeAddress is given to
__init__:
starts a nlforward daemon for the local logfile,
which watches the local log for activity and periodically
forwards data to the central log node. It is
suggested, however, that a single nlforward daemon is
and a single log file are used for the entire application.
-when writing, it also:
-always adds, if not present, a HOST='hostname' field/value
-flushes the buffer every time a message is written
Added by jmyers.
"""
def __init__(self, localLogfile):
"""Params:
localLogFile: temporary log file on local machine."""
global DefaultLogLevel
self.nlLOS = nllite.LogOutputStream(localLogfile)
self.nlLOS.setLevel(DefaultLogLevel) #report all logs
def getLogFile():
return self.nlLOS._logfile
def write(self,eventString,extraData={},msgLevel=INFO):
"""Writes the eventString to the log associated with this
object. Automatically includes the timestamp and the name
of the host in the log.
Optionally adds other FIELD=DATA pairs from the
extraData parameter.
Params:
eventString:
name of event, e.g. function foo should have
foo.start and foo.end as events written
at the start and end of the function,
and an error might have BAD_FILE_DESCRIPTOR
as an eventString.
msgLevel:
INFO by default, take one from the Level class
in the LSSTData module (FATAL, ERROR, WARN,
INFO, DEBUG, DEBUG1, DEBUG2, DEBUG3)
extraData:
A Python dictionary of field/value pairs
to be included in the log for analysis
purposes. E.G.:
{'ITERATION':'304', 'CURRENTFILE':'/tmp/3016'}
or
{'ERRNUM':'501', 'COREDUMPLOCATION':'~/doom'}"""
if 'HOST' not in extraData.keys():
extraData['HOST'] = nllite.get_host()
#remove spaces, NLV doesn't like them!
noSpaceEventString = withoutWhiteSpace(eventString)
noSpaceDict = {}
for i in extraData:
noSpaceDict[withoutWhiteSpace(i)] = withoutWhiteSpace(
extraData[i])
self.nlLOS.write(noSpaceEventString, noSpaceDict, level=msgLevel)
self.nlLOS.flush()
#!/usr/bin/env python
"""nlogtopd.py:
This program is intended to be run in the background.
It will manage most of the NetLogger-ly behavior, such as
reading the policy file, setting the local logfile accordingly,
setting up a forwarding daemon for the local file, and setting up
our logging utility to write to that file every time we call
log(message). Thus, it needs to be running on every machine which
does logging.
However, if it is not run, logs will all be written to stderr, and
a warning to this effect will be written to stdout when a log
is first written.
In addition, if nlogtopd is run, it will write handy top-style
system information to the log so we can monitor processes on
the local machine.
TODO: Make this actually use the policy file, not just constants!
Added by jmyers."""
import os
import time #for sleeping!
import sys
import commands
import log.LSSTLog as LSSTLog
import apps.fw.Policy.Policy as Policy
DEBUG=False
#parameters for handy future usage
TopFrequency=5
ForwardFrequency=5
__author__="jmyers"
def getCpuUsage(vmstat="/usr/bin/vmstat"):
"""Requires vmstat. Pretty much stolen from
nlcpu.py in the NetLogger 3 package.
Notably, vmstat on NCSA seems to constantly report
the same value. That's pretty odd.
"""
f = os.popen(vmstat)
f.readline()
f.readline()
line = f.readline()
vals = map(int,line.split()[-4:-1])
return vals[0] + vals[1] + vals[2]
def topProcessesDict(top="/usr/bin/top"):
"""topProcessesDict:
calls the program top, then parses the heck out of its
output to return a dictionary for logging. The dictionary
is of field/value pairs and includes things like
{
'PROCESS1_CMD':'foo'
'PROCESS1_%CPU':'85'
'PROCESS1_%MEM':'0.1'
'PROCESS1_USR':'jmyers'
'PROCESS2_CMD':'bar'
...}
Optional parameter:
top=/path/to/top
"""
returnDict = {}
f = commands.getoutput(top + " -b -n 1")
#-b = batch mode, noninteractive
#-n 1 = run just once, then exit
linesFromTop = f.split('\n') #split by newline
keyLineNum = -1
for i in range(20):
#look for a line that contains words like PID and COMMAND
lineFromTop = linesFromTop[i].split(None) #None = any whitespace
if "PID" in lineFromTop or "pid" in lineFromTop:
keyLineNum = i
break
if keyLineNum == -1: #no such line found! Panic!
sys.stderr.write("Error: The utility " + top + " on this machine was"
+ " very different from expected! Please inform jmyers.")
#this should probalby be logged, too! TODO
exit(-1)
key = linesFromTop[keyLineNum].split(None)
for j in range(3):
lineFromTop = linesFromTop[keyLineNum + j].split(None)
for k in range(len(key)):
if key[k] in ("%CPU", "COMMAND", "CMD", "USER", "USR", "%MEM",
"%cpu", "command", "user", "%mem"):
returnDict['PROCESS' + str(j) + '_' +
key[k]] = lineFromTop[k]
returnDict['TOTAL_%CPU'] = getCpuUsage()
return returnDict
def main():
#we might want to get this from the policy file eventually
global TopFreqency
# read Policy file to determine where to send log messages
logPolicy = Policy('./logging.policy')
localLog = logPolicy.Get ('logFile')
#create a new log object for us
myLogger = LSSTLog.LSSTLog(localLog)
#write to the log
while 1:
# get top processes, cpu usage,
# maybe even disk i/o stats
# using top and vmstat...
# then write them to the local log
# then sleep for interval seconds
dataToReport = topProcessesDict()
myLogger.write('TOP',
msgLevel=LSSTLog.Level.DEBUG,
extraData=dataToReport)
time.sleep(TopFrequency)
if __name__ == '__main__':
#daemonize!
if os.fork()==0:
os.setsid()
sys.stdout=open("/dev/null", 'w')
sys.stdin=open("/dev/null", 'r')
if os.fork()==0:
main()
exit(0)
_______________________________________________
LSST-data mailing list
[email protected]
http://www.lsstmail.org/mailman/listinfo/lsst-data
