swapmon.py

   1 #!/usr/bin/python
   2 #
   3 # Swap monitoring daemon. Every 30 seconds, checks process memory
   4 # usage. At 90% utilization, resets the slice that is consuming the
   5 # most physical memory. At 95% utilization, reboots the machine to
   6 # avoid a crash.
   7 #
   8 # Mark Huang <mlhuang@cs.princeton.edu>
   9 # Andy Bavier <acb@cs.princeton.edu>
  10 # Faiyaz Ahmed <faiyaza@cs.princeton.edu>
  11 # Copyright (C) 2004-2006 The Trustees of Princeton University
  12 #
  13 # $Id$
  14 #
  15
  16 import syslog
  17 import os
  18 import sys
  19 import getopt
  20 import re
  21 import pickle
  22 import socket
  23 import time
  24
  25 # util-vserver/python/vserver.py allows us to control slices directly
  26 # from Python
  27 from vserver import VServer
  28
  29 # bwlimit exports a few useful functions like run(), get_xid(), and get_slice()
  30 import bwlimit
  31
  32 # Utility functions
  33 from pl_mom import *
  34
  35 # Defaults
  36 debug = False
  37 verbose = 0
  38 DATAFILE = "/var/lib/misc/swapmon.dat"
  39 VERSION = "$Id$"
  40 # Seconds between process analysis
  41 period = 30
  42
  43 # Minimum change in swap utilization over 30 seconds that will trigger
  44 # early process analysis.
  45 change_thresh = 5
  46
  47 # Swap utilization at which the largest consumer of physical memory is reset
  48 reset_thresh = 80
  49
  50 # Swap utilization at which the machine is rebooted
  51 reboot_thresh = 95
  52
  53 # Time to wait before checking slice again after reset
  54 reset_timeout = 25
  55
  56 # Number of strikes before killing (strike, strike, kill)
  57 kill_thresh = 2
  58
  59 # Time to wait before removing slice from kill queue (probation)
  60 kill_timeout = 120
  61
  62 # Don't email the same message more than once in the same emailtimeout interval
  63 email_timeout = 1800
  64
  65 # Physical size threshold to be considered a consumer.  Rationale is if there are no procs
  66 # with a size at least as large as this, then there is a slow leaker;  better to just reboot.
  67 rss_min = 150 * 1024
  68
  69 # System slices that should not be reset (regexps)
  70 system_slices = ['root', PLC_SLICE_PREFIX + '_']
  71
  72 # Message sent after a critical reboot
  73 rebooted_subject = "pl_mom rebooted %(hostname)s"
  74 rebooted_body = \
  75 """
  76 Sometime before %(date)s, swap space was
  77 nearly exhausted on %(hostname)s, so pl_mom rebooted it.
  78
  79 Slices active prior to reboot are listed below. Memory usage
  80 statistics are not entirely accurate due to threading.
  81
  82 %(table)s
  83
  84 %(date)s %(hostname)s reboot
  85 """.lstrip()
  86
  87 # Message sent after a hog is reset
  88 reset_subject = "pl_mom reset slice %(slice)s on %(hostname)s"
  89 reset_body = \
  90 """
  91 Sometime before %(date)s, swap space was
  92 nearly exhausted on %(hostname)s.
  93
  94 Slice %(slice)s was reset since it was the largest consumer of
  95 physical memory at %(rss)s (%(percent)4.1f%%) (%(sz)s writable).
  96
  97 Please reply to this message explaining the nature of your experiment,
  98 and what you are doing to address the problem.
  99
 100 http://summer.cs.princeton.edu/status/tabulator.cgi?table=slices/table_%(slice)s
 101
 102 %(slice)s processes prior to reset:
 103
 104 %(table)s
 105
 106 %(date)s %(hostname)s reset %(slice)s
 107 """.lstrip()
 108
 109 # Message sent to system slices that should not be reset
 110 alarm_subject = "pl_mom alarm slice %(slice)s on %(hostname)s"
 111 alarm_body = \
 112 """
 113 Sometime before %(date)s, swap space was
 114 nearly exhausted on %(hostname)s.
 115
 116 System slice %(slice)s was the largest consumer of physical memory at
 117 %(rss)s (%(percent)4.1f%%) (%(sz)s writable). It was not reset,
 118 but please verify its behavior.
 119
 120 %(slice)s processes prior to alarm:
 121
 122 %(table)s
 123
 124 %(date)s %(hostname)s alarm %(slice)s
 125 """.lstrip()
 126
 127 # Message sent after a slice has been killed
 128 kill_subject = "pl_mom killed slice %(slice)s on %(hostname)s"
 129 kill_body = \
 130 """
 131 Sometime before %(date)s, swap space was
 132 nearly exhausted on %(hostname)s.
 133
 134 Slice %(slice)s was killed since it was the largest consumer of
 135 physical memory at %(rss)s (%(percent)4.1f%%) (%(sz)s writable)
 136 after repeated restarts.
 137
 138 Please reply to this message explaining the nature of your experiment,
 139 and what you are doing to address the problem.
 140
 141 %(slice)s processes prior to reset:
 142
 143 %(table)s
 144
 145 %(date)s %(hostname)s reset %(slice)s
 146 """.lstrip()
 147
 148
 149
 150 class Reset:
 151     """
 152     Keeps track of state information for resets and kills
 153
 154     resettimeleft - timeout before checking for next reset
 155     resetcount - number of strikes
 156     killtimeleft - time out before removing from kill queue
 157     {kill,reset}mail - Time of last email
 158     kill - State of kill.  If slice is already being killed, wait before retry.
 159     """
 160
 161     def __init__(self,name):
 162         self.name = name
 163         self.resettimeleft = reset_timeout
 164         self.resetcount = 0
 165         self.resetmail = 0
 166         self.killtimeleft = kill_timeout
 167         self.killmail = 0
 168
 169     def __repr__(self):
 170         return self.name
 171
 172     def update(self):
 173         # Count down for next check of reset slice.
 174         if self.resettimeleft > 0:
 175            self.resettimeleft -= 1
 176            if debug and verbose:  print "%s has %s seconds in probation" \
 177                                     %(self.name, self.killtimeleft)
 178         if self.killtimeleft > 0:
 179             # Count down kill probation timer (killtimeleft)
 180             self.killtimeleft -= 1
 181             if self.killtimeleft == 1:
 182                 print "%s is out of probation" % self.name
 183         else:
 184             # Once out of probation period (killtimeleft), remove strikes
 185             self.resetcount = 0
 186
 187
 188     # Check to see if a slice needs to be killed.  If it has been killed more
 189     # than kill_thresh in the probation period (kill_timeout) send an email, kill the slice.
 190     def checkkill(self,params):
 191         if self.killtimeleft > 0 and self.resetcount >= kill_thresh:
 192             if debug:
 193                 print kill_subject % params
 194                 print kill_body % params
 195             try:
 196                 pid = os.fork()
 197                 if pid == 0:
 198                    print "Slice %s is being killed." % self.name
 199                    vserver = VServer(self.name)
 200                    vserver.stop()
 201                    # ignore initscripts.  Don't run anything at start.
 202                    vserver.INITSCRIPTS = []
 203                    vserver.start()
 204                    os._exit(0)
 205                 else:
 206                     os.waitpid(pid,0)
 207             except Exception, err:
 208                 print "Warning: Exception received while killing slice %s: %s" \
 209                    % (self.name, err)
 210             if (time.time() - self.killmail) > email_timeout:
 211                 slicemail(self.name, kill_subject % params, kill_body % params)
 212                 print "Sending KILL email for slice %s" % self.name
 213                 self.killmail = time.time()
 214             return True
 215         return False
 216
 217     # Reset slice after checking to see if slice is out of timeout.
 218     # Increment resetcount, check to see if larger than kill_thresh.
 219     def reset(self, params):
 220         # If its the first reset (came back after kill)
 221         # or if its been reset before
 222         # and we are out of the reset timeout.
 223         if self.resetcount == 0 or self.resettimeleft == 0:
 224             # Do we need to kill this slice?  Check history first.
 225             if self.checkkill(params):  return
 226             # Update counters
 227             self.resetcount += 1
 228             self.killtimeleft = kill_timeout
 229             self.resettimeleft = reset_timeout
 230             print "%s has %s seconds to die and has been reset %s times" \
 231                 %(self.name, self.resettimeleft, self.resetcount)
 232             if debug:
 233                 print reset_subject % params
 234                 print reset_body % params
 235             try:
 236                 pid = os.fork()
 237                 if pid == 0:
 238                     print "Resetting slice " + self.name
 239                     vserver = VServer(self.name)
 240                     vserver.stop()
 241                     vserver.start()
 242                     os._exit(0)
 243                 else:
 244                     os.waitpid(pid,0)
 245             except Exception, err:
 246                 print "Warning: Exception received while resetting slice %s:" \
 247                         % self.name, err
 248             if (time.time() - self.resetmail) > email_timeout:
 249                 slicemail(self.name, reset_subject % params, reset_body % params)
 250                 print "Sending Reset email for slice %s" % self.name
 251                 self.resetmail = time.time()
 252
 253 def usage():
 254     print """
 255 Usage: %s [OPTIONS]...
 256
 257 Options:
 258         -d, --debug             Enable debugging (default: %s)
 259         -v, --verbose           Increase verbosity level (default: %d)
 260         -f, --file=FILE         Data file (default: %s)
 261         -s, --slice=SLICE       Constrain monitoring to these slices (default: all)
 262         -p, --period=SECONDS    Seconds between normal process analysis (default: %s)
 263         --reset-thresh=PERCENT  Swap utilization at which slice reset is attempted
 264         --reboot-thresh=PERCENT Swap utilization at which the machine is rebooted
 265         --min-thresh=PERCENT    Minimum physical memory utilization to be considered a hog
 266         --system-slice=SLICE    System slice that should not be reset
 267         --status                Print memory usage statistics and exit
 268         -h, --help              This message
 269 """.lstrip() % (sys.argv[0], debug, verbose, DATAFILE, format_period(period))
 270
 271 def slicestat(names = None):
 272     """
 273     Get status of specified slices (if names is None or empty, all
 274     slices). vsize, sz, and rss are in KiB. Returns
 275     PID CONTEXT             VSZ    SZ   RSS %MEM CMD
 276     {xid: {'xid': slice_id,
 277             'name': slice_name,
 278             'procs': [{'pid': pid, 'xid': slice_id, 'cmd': command,
 279                       'vsize': virtual_kib, 'sz': potential_kib, 'rss': physical_kib,
 280                       'pcpu': cpu_percent, 'pmem': mem_percent}]
 281             'vsize': total_virtual_kib,
 282             'sz': total_potential_kib,
 283             'rss': total_physical_kib}}
 284     """
 285
 286     # Mandatory fields. xid is a virtual field inserted by vps. Make
 287     # sure cmd is last so that it does not get truncated
 288     # automatically.
 289     fields = ['pid', 'xid', 'vsize', 'sz', 'rss', 'pmem', 'cmd']
 290
 291     # vps inserts xid after pid in the output, but ps doesn't know
 292     # what the field means.
 293     ps_fields = list(fields)
 294     ps_fields.remove('xid')
 295
 296     slices = {}
 297
 298     # Eat the header line. vps depends on the header to figure out
 299     # which column is the PID column, so we can't just tell ps not to
 300     # print it.
 301     for line in bwlimit.run("/usr/sbin/vps -e -o " + ":16,".join(ps_fields))[1:]:
 302         # Chomp newline
 303         line = line.strip()
 304
 305         # Replace "0 MAIN" and "1 ALL_PROC" (the special monikers that
 306         # vps uses to denote the root context and the "all contexts"
 307         # context) with "0" so that we can just split() on whitespace.
 308         line = line.replace("0 MAIN", "0").replace("1 ALL_PROC", "0")
 309
 310         # Represent process as a dict of fields
 311         values = line.split(None, len(fields) - 1)
 312         if len(values) != len(fields):
 313             continue
 314         proc = dict(zip(fields, values))
 315
 316         # Convert ints and floats
 317         for field in proc:
 318             try:
 319                 proc[field] = int(proc[field])
 320             except ValueError:
 321                 try:
 322                     proc[field] = float(proc[field])
 323                 except ValueError:
 324                     pass
 325
 326         # vps sometimes prints ERR or the name of the slice
 327             # instead of a context ID if it
 328         # cannot identify the context of an orphaned (usually dying)
 329         # process. Skip these processes.
 330         if (type(proc['xid']) != int) or (type(proc['vsize']) !=int):
 331             continue
 332
 333         # Assign (pl_)sshd processes to slice instead of root
 334         m = re.search(r"sshd: ([a-zA-Z_]+)", proc['cmd'])
 335
 336         if m is not None:
 337             xid = bwlimit.get_xid(m.group(1))
 338             if xid is not None:
 339                 proc['xid'] = xid
 340
 341         name = bwlimit.get_slice(proc['xid'])
 342         if name is None:
 343             # Orphaned (not associated with a slice) class
 344             name = "%d?" % proc['xid']
 345
 346         # Monitor only the specified slices
 347         if names and name not in names:
 348             continue
 349
 350         # Additional overhead calculations from slicestat
 351
 352         # Include 12 KiB of process overhead =
 353         # 4 KiB top-level page table +
 354         # 4 KiB kernel structure +
 355         # 4 KiB basic page table
 356         proc['rss'] += 12
 357
 358         # Include additional page table overhead
 359         try:
 360             if proc['vsize'] > 4096:
 361                 proc['rss'] += 4 * ((proc['vsize'] - 1) / 4096)
 362         except: pass
 363
 364         if slices.has_key(proc['xid']):
 365             slice = slices[proc['xid']]
 366         else:
 367             slice = {'xid': proc['xid'], 'name': name, 'procs': [], 'vsize': 0, 'sz': 0, 'rss': 0}
 368
 369         slice['procs'].append(proc)
 370         slice['vsize'] += proc['vsize']
 371         slice['sz'] += proc['sz']
 372         slice['rss'] += proc['rss']
 373
 374         slices[proc['xid']] = slice
 375
 376     return slices
 377
 378 def memtotal():
 379     """
 380     Returns total physical and swap memory on the system in KiB.
 381     """
 382     mem = 0
 383     swap = 0
 384     meminfo = open("/proc/meminfo", "r")
 385     for line in meminfo.readlines():
 386         try:
 387             (name, value, kb) = line.split()
 388         except:
 389             continue
 390         if name == "MemTotal:":
 391             mem = int(value)
 392         elif name == "SwapTotal:":
 393             swap = int(value)
 394     meminfo.close()
 395     return (mem, swap)
 396
 397 def swap_used():
 398     """
 399     Returns swap utilization on the system as a whole percentage (0-100).
 400     """
 401     total_swap = 0
 402     total_used = 0
 403     try:
 404         swaps = open("/proc/swaps", "r")
 405         # Eat header line
 406         lines = swaps.readlines()[1:]
 407         swaps.close()
 408         for line in lines:
 409             # /dev/mapper/planetlab-swap partition 1048568 3740 -1
 410             (filename, type, size, used, priority) = line.strip().split()
 411             try:
 412                 total_swap += int(size)
 413                 total_used += int(used)
 414             except ValueEror, err:
 415                 pass
 416     except (IOError, KeyError), err:  pass
 417
 418     swapused = 100 * total_used / total_swap
 419     if debug: print "%s percent swap used" % swapused
 420     return swapused
 421
 422 def summary(slices = None, total_mem = None, total_swap = None):
 423     """
 424     Return a summary of memory usage by slice.
 425     """
 426     if not slices:  slices = slicestat()
 427     slicelist = slices.values()
 428     slicelist.sort(lambda a, b: b['sz'] - a['sz'])
 429     if total_mem is None or total_swap is None:
 430         (total_mem, total_swap) = memtotal()
 431
 432     table = "%-20s%10s%24s%24s\n\n" % ("Slice", "Processes", "Memory Usage", "Potential Usage")
 433     for slice in slicelist:
 434         table += "%-20s%10d%16s (%4.1f%%)%16s (%4.1f%%)\n" % \
 435                  (slice['name'], len(slice['procs']),
 436                   format_bytes(slice['rss'] * 1024, si = False),
 437                   100. * slice['rss'] / total_mem,
 438                   format_bytes(slice['sz'] * 1024, si = False),
 439                   100. * slice['sz'] / (total_mem + total_swap))
 440     return table
 441
 442 def formtable(slice, percent):
 443     '''
 444     Makes pretty message to email with human readable ps values.
 445     '''
 446     table = "%5s %10s %10s %10s %4s %4s %s\n\n" % \
 447         ("PID", "VIRT", "SZ", "RES", '%CPU', '%MEM', 'COMMAND')
 448     for proc in slice['procs']:
 449         table += "%5s %10s %10s %10s %4.1f %s\n" % \
 450             (proc['pid'],
 451             format_bytes(proc['vsize'] * 1024, si = False),
 452             format_bytes(proc['sz'] * 1024, si = False),
 453             format_bytes(proc['rss'] * 1024, si = False),
 454             proc['pmem'],
 455             proc['cmd'])
 456
 457     prettytable = {'hostname': socket.gethostname(),
 458              'date': time.asctime(time.gmtime()) + " GMT",
 459              'table': table,
 460              'slice': slice['name'],
 461              'rss': format_bytes(slice['rss'] * 1024, si = False),
 462              'sz': format_bytes(slice['sz'] * 1024, si = False),
 463              'percent': percent}
 464     return prettytable
 465
 466 def readdat():
 467     '''
 468     Return dictionary of vps (slicestat) from datfile left behind by OOM
 469     before rebooting.  If none file, just grab the latest dict (slicestat)
 470     and return that.  If dat file found, means we rebooted, send an email to
 471     pl_mom@pl.
 472     '''
 473     try:
 474         f = open(DATAFILE, "r+")
 475         if verbose:
 476             print "Loading %s" % DATAFILE
 477         (v, slices) = pickle.load(f)
 478         f.close()
 479         # Check version of data file
 480         if v != VERSION:
 481             print "Not using old version '%s' data file %s" % (v, DATAFILE)
 482             raise Exception
 483
 484         params = {'hostname': socket.gethostname(),
 485                   'date': time.asctime(time.gmtime()) + " GMT",
 486                   'table': summary(slices, total_mem, total_swap)}
 487         if debug:
 488             print rebooted_subject % params
 489             print rebooted_body % params
 490         else:
 491             slicemail(None, rebooted_subject % params, rebooted_body % params)
 492
 493         # Delete data file
 494         os.unlink(DATAFILE)
 495     except Exception:
 496         slices = slicestat()
 497
 498     return slices
 499
 500
 501 def writedat(slices):
 502     """
 503     Write (slices) to pickled datfile.
 504     """
 505     if verbose:  print "Saving %s" % DATAFILE
 506     f = open(DATAFILE, "w")
 507     pickle.dump((VERSION, slices), f)
 508     f.close()
 509
 510
 511 def main():
 512     # Defaults
 513     global debug, verbose, DATAFILE, VERSION
 514     global period, change_thresh, reset_thresh, reboot_thresh, rss_min, system_slices
 515     # All slices
 516     names = []
 517
 518     try:
 519         longopts = ["debug", "verbose", "file=", "slice=", "status", "help"]
 520         longopts += ["period=", "reset-thresh=", "reboot-thresh=", "min-thresh=", "system-slice="]
 521         (opts, argv) = getopt.getopt(sys.argv[1:], "dvf:s:ph", longopts)
 522     except getopt.GetoptError, err:
 523         print "Error: " + err.msg
 524         usage()
 525         sys.exit(1)
 526
 527     for (opt, optval) in opts:
 528         if opt == "-d" or opt == "--debug":
 529             debug = True
 530         elif opt == "-v" or opt == "--verbose":
 531             verbose += 1
 532         elif opt == "-f" or opt == "--file":
 533             DATAFILE = optval
 534         elif opt == "-s" or opt == "--slice":
 535             names.append(optval)
 536         elif opt == "-p" or opt == "--period":
 537             period = int(optval)
 538         elif opt == "--change-thresh":
 539             change_thresh = int(optval)
 540         elif opt == "--reset-thresh":
 541             reset_thresh = int(optval)
 542         elif opt == "--reboot-thresh":
 543             reboot_thresh = int(optval)
 544         elif opt == "--min-thresh":
 545             rss_min = int(optval)
 546         elif opt == "--system-slice":
 547             system_slices.append(optval)
 548         elif opt == "--status":
 549             print summary(slicestat(names))
 550             sys.exit(0)
 551         else:
 552             usage()
 553             sys.exit(0)
 554
 555     # Check if we are already running
 556     writepid("swapmon")
 557
 558     if not debug:
 559         daemonize()
 560         # Rewrite PID file
 561         writepid("swapmon")
 562         # Redirect stdout and stderr to syslog
 563         syslog.openlog("swapmon")
 564         sys.stdout = sys.stderr = Logger()
 565
 566     # Get total memory
 567     (total_mem, total_swap) = memtotal()
 568     slices = readdat()
 569
 570     # Query process table every 30 seconds, or when a large change in
 571     # swap utilization is detected.
 572     timer = period
 573     last_used = None
 574     used = None
 575
 576     # System slices that we have warned but could not reset
 577     warned = []
 578
 579     # Slices that were reset
 580     resetlist = {}
 581
 582     while True:
 583         used = swap_used()
 584         if last_used is None:  last_used = used
 585
 586         # If we've reset you recently, update timers.
 587         for resetslice in resetlist.keys():
 588             resetlist[resetslice].update()
 589             # If you've been good, remove you from our list.
 590             if resetlist[resetslice].killtimeleft == 0 and \
 591             resetlist[resetslice].resettimeleft == 0:
 592                 del resetlist[resetslice]
 593
 594         if used >= reboot_thresh:
 595             # Dump slice state before rebooting
 596             writedat(slices)
 597             # Goodbye, cruel world
 598             print "%d%% swap consumed, rebooting" % used
 599             if not debug:  bwlimit.run("/bin/sync; /sbin/reboot -f")
 600         elif used >= reset_thresh:
 601             # Try and find a hog
 602             slicelist = slices.values()
 603             # Puts largest on top.
 604             slicelist.sort(lambda a, b: b['rss'] - a['rss'])
 605             for slice in slicelist:
 606                 percent = 100. * slice['rss'] / total_mem
 607                 if slice['rss'] < rss_min: continue
 608                 print "%d%% swap consumed, slice %s is using %s (%d%%) of memory" % \
 609                     (used,
 610                     slice['name'],
 611                     format_bytes(slice['rss'] * 1024, si = False),
 612                     percent)
 613                 slice['procs'].sort(lambda a, b: b['rss'] - a['rss'])
 614                 # Make a pretty table.
 615                 params = formtable(slice, percent)
 616                 # Match slice name against system slice patterns
 617                 is_system_slice = filter(None,
 618                     [re.match(pattern, slice['name']) for pattern in system_slices])
 619
 620                 # Do not reset system slices, just warn once
 621                 if is_system_slice:
 622                     if slice['name'] not in warned:
 623                         warned.append(slice['name'])
 624                         print "Warning slice " + slice['name']
 625                         if debug:
 626                             print alarm_subject % params
 627                             print alarm_body % params
 628                         else:
 629                             slicemail(slice['name'], alarm_subject % params,
 630                               alarm_body % params)
 631                 else:
 632                     # Reset slice
 633                     if not resetlist.has_key(slice['name']):
 634                         resetlist[slice['name']] = Reset(slice['name'])
 635                     resetlist[slice['name']].reset(params)
 636
 637         # wait period vefore recalculating swap.  If in danger, recalc.
 638         if timer <= 0 or used >= (last_used + change_thresh):
 639             if used >= (last_used + change_thresh):
 640                 print "%d%% swap consumed, %d%% in last %d seconds" % \
 641                     (used, used - last_used, period - timer)
 642             # Get slice state
 643             slices = slicestat(names)
 644             # Reset timer
 645             timer = period
 646             # Keep track of large changes in swap utilization
 647             last_used = used
 648         timer -= 1
 649         time.sleep(1)
 650
 651     removepid("swapmon")
 652
 653 if __name__ == '__main__':
 654     main()