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
  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                    os._exit(0)
 202                 else:
 203                     os.waitpid(pid,0)
 204             except Exception, err:
 205                 print "Warning: Exception received while killing slice %s: %s" \
 206                    % (self.name, err)
 207             if (time.time() - self.killmail) > email_timeout:
 208                 slicemail(self.name, kill_subject % params, kill_body % params)
 209                 print "Sending KILL email for slice %s" % self.name
 210                 self.killmail = time.time()
 211             return True
 212         return False
 213
 214     # Reset slice after checking to see if slice is out of timeout.
 215     # Increment resetcount, check to see if larger than kill_thresh.
 216     def reset(self, params):
 217         # If its the first reset (came back after kill)
 218         # or if its been reset before
 219         # and we are out of the reset timeout.
 220         if self.resetcount == 0 or self.resettimeleft == 0:
 221             # Do we need to kill this slice?  Check history first.
 222             if self.checkkill(params):  return
 223             # Update counters
 224             self.resetcount += 1
 225             self.killtimeleft = kill_timeout
 226             self.resettimeleft = reset_timeout
 227             print "%s has %s seconds to die and has been reset %s times" \
 228                 %(self.name, self.resettimeleft, self.resetcount)
 229             if debug:
 230                 print reset_subject % params
 231                 print reset_body % params
 232                 try:
 233                     pid = os.fork()
 234                     if pid == 0:
 235                         print "Resetting slice " + self.name
 236                         vserver = VServer(self.name)
 237                         vserver.stop()
 238                         vserver.start(wait = False)
 239                         os._exit(0)
 240                     else:
 241                         os.waitpid(pid,0)
 242                 except Exception, err:
 243                     print "Warning: Exception received while resetting slice %s:" \
 244                         % self.name, err
 245             if (time.time() - self.resetmail) > email_timeout:
 246                 slicemail(self.name, reset_subject % params, reset_body % params)
 247                 print "Sending Reset email for slice %s" % self.name
 248                 self.resetmail = time.time()
 249
 250 def usage():
 251     print """
 252 Usage: %s [OPTIONS]...
 253
 254 Options:
 255         -d, --debug             Enable debugging (default: %s)
 256         -v, --verbose           Increase verbosity level (default: %d)
 257         -f, --file=FILE         Data file (default: %s)
 258         -s, --slice=SLICE       Constrain monitoring to these slices (default: all)
 259         -p, --period=SECONDS    Seconds between normal process analysis (default: %s)
 260         --reset-thresh=PERCENT  Swap utilization at which slice reset is attempted
 261         --reboot-thresh=PERCENT Swap utilization at which the machine is rebooted
 262         --min-thresh=PERCENT    Minimum physical memory utilization to be considered a hog
 263         --system-slice=SLICE    System slice that should not be reset
 264         --status                Print memory usage statistics and exit
 265         -h, --help              This message
 266 """.lstrip() % (sys.argv[0], debug, verbose, datafile, format_period(period))
 267
 268 def slicestat(names = None):
 269     """
 270     Get status of specified slices (if names is None or empty, all
 271     slices). vsize, sz, and rss are in KiB. Returns
 272
 273     {xid: {'xid': slice_id,
 274             'name': slice_name,
 275             'procs': [{'pid': pid, 'xid': slice_id, 'user', username, 'cmd': command,
 276                       'vsize': virtual_kib, 'sz': potential_kib, 'rss': physical_kib,
 277                       'pcpu': cpu_percent, 'pmem': mem_percent}]
 278             'vsize': total_virtual_kib,
 279             'sz': total_potential_kib,
 280             'rss': total_physical_kib}}
 281     """
 282
 283     # Mandatory fields. xid is a virtual field inserted by vps. Make
 284     # sure cmd is last so that it does not get truncated
 285     # automatically.
 286     fields = ['pid', 'xid', 'user', 'vsize', 'sz', 'rss', 'pcpu', 'pmem', 'cmd']
 287
 288     # vps inserts xid after pid in the output, but ps doesn't know
 289     # what the field means.
 290     ps_fields = list(fields)
 291     ps_fields.remove('xid')
 292
 293     slices = {}
 294
 295     # Eat the header line. vps depends on the header to figure out
 296     # which column is the PID column, so we can't just tell ps not to
 297     # print it.
 298     for line in bwlimit.run("/usr/sbin/vps -e -o " + ",".join(ps_fields))[1:]:
 299         # Chomp newline
 300         line = line.strip()
 301
 302         # Replace "0 MAIN" and "1 ALL_PROC" (the special monikers that
 303         # vps uses to denote the root context and the "all contexts"
 304         # context) with "0" so that we can just split() on whitespace.
 305         line = line.replace("0 MAIN", "0").replace("1 ALL_PROC", "0")
 306
 307         # Represent process as a dict of fields
 308         values = line.split(None, len(fields) - 1)
 309         if len(values) != len(fields):
 310             continue
 311         proc = dict(zip(fields, values))
 312
 313         # Convert ints and floats
 314         for field in proc:
 315             try:
 316                 proc[field] = int(proc[field])
 317             except ValueError:
 318                 try:
 319                     proc[field] = float(proc[field])
 320                 except ValueError:
 321                     pass
 322
 323         # vps sometimes prints ERR instead of a context ID if it
 324         # cannot identify the context of an orphaned (usually dying)
 325         # process. Skip these processes.
 326         if type(proc['xid']) != int:
 327             continue
 328
 329         # Assign (pl_)sshd processes to slice instead of root
 330         m = re.search(r"sshd: ([a-zA-Z_]+)", proc['cmd'])
 331         if m is not None:
 332             xid = bwlimit.get_xid(m.group(1))
 333             if xid is not None:
 334                 proc['xid'] = xid
 335
 336         name = bwlimit.get_slice(proc['xid'])
 337         if name is None:
 338             # Orphaned (not associated with a slice) class
 339             name = "%d?" % proc['xid']
 340
 341         # Monitor only the specified slices
 342         if names and name not in names:
 343             continue
 344
 345         # Additional overhead calculations from slicestat
 346
 347         # Include 12 KiB of process overhead =
 348         # 4 KiB top-level page table +
 349         # 4 KiB kernel structure +
 350         # 4 KiB basic page table
 351         proc['rss'] += 12
 352
 353         # Include additional page table overhead
 354         if proc['vsize'] > 4096:
 355             proc['rss'] += 4 * ((proc['vsize'] - 1) / 4096)
 356
 357         if slices.has_key(proc['xid']):
 358             slice = slices[proc['xid']]
 359         else:
 360             slice = {'xid': proc['xid'], 'name': name, 'procs': [], 'vsize': 0, 'sz': 0, 'rss': 0}
 361
 362         slice['procs'].append(proc)
 363         slice['vsize'] += proc['vsize']
 364         slice['sz'] += proc['sz']
 365         slice['rss'] += proc['rss']
 366
 367         slices[proc['xid']] = slice
 368
 369     return slices
 370
 371 def memtotal():
 372     """
 373     Returns total physical and swap memory on the system in KiB.
 374     """
 375     mem = 0
 376     swap = 0
 377     meminfo = open("/proc/meminfo", "r")
 378     for line in meminfo.readlines():
 379         try:
 380             (name, value, kb) = line.split()
 381         except:
 382             continue
 383         if name == "MemTotal:":
 384             mem = int(value)
 385         elif name == "SwapTotal:":
 386             swap = int(value)
 387     meminfo.close()
 388     return (mem, swap)
 389
 390 def swap_used():
 391     """
 392     Returns swap utilization on the system as a whole percentage (0-100).
 393     """
 394     total_swap = 0
 395     total_used = 0
 396     try:
 397         swaps = open("/proc/swaps", "r")
 398         # Eat header line
 399         lines = swaps.readlines()[1:]
 400         swaps.close()
 401         for line in lines:
 402             # /dev/mapper/planetlab-swap partition 1048568 3740 -1
 403             (filename, type, size, used, priority) = line.strip().split()
 404             try:
 405                 total_swap += int(size)
 406                 total_used += int(used)
 407             except ValueEror, err:
 408                 pass
 409     except (IOError, KeyError), err:  pass
 410
 411     swapused = 100 * total_used / total_swap
 412     if debug: print "%s percent swap used" % swapused
 413     return swapused
 414
 415 def summary(slices = None, total_mem = None, total_swap = None):
 416     """
 417     Return a summary of memory usage by slice.
 418     """
 419     if not slices:  slices = slicestat()
 420     slicelist = slices.values()
 421     slicelist.sort(lambda a, b: b['sz'] - a['sz'])
 422     if total_mem is None or total_swap is None:
 423         (total_mem, total_swap) = memtotal()
 424
 425     table = "%-20s%10s%24s%24s\n\n" % ("Slice", "Processes", "Memory Usage", "Potential Usage")
 426     for slice in slicelist:
 427         table += "%-20s%10d%16s (%4.1f%%)%16s (%4.1f%%)\n" % \
 428                  (slice['name'], len(slice['procs']),
 429                   format_bytes(slice['rss'] * 1024, si = False),
 430                   100. * slice['rss'] / total_mem,
 431                   format_bytes(slice['sz'] * 1024, si = False),
 432                   100. * slice['sz'] / (total_mem + total_swap))
 433     return table
 434
 435 def formtable(slice, percent):
 436     '''
 437     Makes pretty message to email with human readable ps values.
 438     '''
 439     table = "%5s %10s %10s %10s %4s %4s %s\n\n" % \
 440         ("PID", "VIRT", "SZ", "RES", '%CPU', '%MEM', 'COMMAND')
 441     for proc in slice['procs']:
 442         table += "%5s %10s %10s %10s %4.1f %4.1f %s\n" % \
 443             (proc['pid'],
 444             format_bytes(proc['vsize'] * 1024, si = False),
 445             format_bytes(proc['sz'] * 1024, si = False),
 446             format_bytes(proc['rss'] * 1024, si = False),
 447             proc['pcpu'],
 448             proc['pmem'],
 449             proc['cmd'])
 450
 451     prettytable = {'hostname': socket.gethostname(),
 452              'date': time.asctime(time.gmtime()) + " GMT",
 453              'table': table,
 454              'slice': slice['name'],
 455              'rss': format_bytes(slice['rss'] * 1024, si = False),
 456              'sz': format_bytes(slice['sz'] * 1024, si = False),
 457              'percent': percent}
 458     return prettytable
 459
 460 def readdat():
 461     '''
 462     Return dictionary of vps (slicestat) from datfile left behind by OOM
 463     before rebooting.  If none file, just grab the latest dict (slicestat)
 464     and return that.  If dat file found, means we rebooted, send an email to
 465     pl_mom@pl.
 466     '''
 467     try:
 468         f = open(datafile, "r+")
 469         if verbose:
 470             print "Loading %s" % datafile
 471         (version, slices) = pickle.load(f)
 472         f.close()
 473         # Check version of data file
 474         if version != "$Id$":
 475             print "Not using old version '%s' data file %s" % (version, datafile)
 476             raise Exception
 477
 478         params = {'hostname': socket.gethostname(),
 479                   'date': time.asctime(time.gmtime()) + " GMT",
 480                   'table': summary(slices, total_mem, total_swap)}
 481         if debug:
 482             print rebooted_subject % params
 483             print rebooted_body % params
 484         else:
 485             slicemail(None, rebooted_subject % params, rebooted_body % params)
 486
 487         # Delete data file
 488         os.unlink(datafile)
 489     except Exception:
 490         version = "$Id$"
 491         slices = slicestat()
 492
 493     return slices
 494
 495
 496 def writedat(slices):
 497     """
 498     Write (slices) to pickled datfile.
 499     """
 500     if verbose:  print "Saving %s" % datafile
 501     f = open(datafile, "w")
 502     pickle.dump((version, slices), f)
 503     f.close()
 504
 505
 506 def main():
 507     # Defaults
 508     global debug, verbose, datafile
 509     global period, change_thresh, reset_thresh, reboot_thresh, rss_min, system_slices
 510     # All slices
 511     names = []
 512
 513     try:
 514         longopts = ["debug", "verbose", "file=", "slice=", "status", "help"]
 515         longopts += ["period=", "reset-thresh=", "reboot-thresh=", "min-thresh=", "system-slice="]
 516         (opts, argv) = getopt.getopt(sys.argv[1:], "dvf:s:ph", longopts)
 517     except getopt.GetoptError, err:
 518         print "Error: " + err.msg
 519         usage()
 520         sys.exit(1)
 521
 522     for (opt, optval) in opts:
 523         if opt == "-d" or opt == "--debug":
 524             debug = True
 525         elif opt == "-v" or opt == "--verbose":
 526             verbose += 1
 527         elif opt == "-f" or opt == "--file":
 528             datafile = optval
 529         elif opt == "-s" or opt == "--slice":
 530             names.append(optval)
 531         elif opt == "-p" or opt == "--period":
 532             period = int(optval)
 533         elif opt == "--change-thresh":
 534             change_thresh = int(optval)
 535         elif opt == "--reset-thresh":
 536             reset_thresh = int(optval)
 537         elif opt == "--reboot-thresh":
 538             reboot_thresh = int(optval)
 539         elif opt == "--min-thresh":
 540             rss_min = int(optval)
 541         elif opt == "--system-slice":
 542             system_slices.append(optval)
 543         elif opt == "--status":
 544             print summary(slicestat(names))
 545             sys.exit(0)
 546         else:
 547             usage()
 548             sys.exit(0)
 549
 550     # Check if we are already running
 551     writepid("swapmon")
 552
 553     if not debug:
 554         daemonize()
 555         # Rewrite PID file
 556         writepid("swapmon")
 557         # Redirect stdout and stderr to syslog
 558         syslog.openlog("swapmon")
 559         sys.stdout = sys.stderr = Logger()
 560
 561     # Get total memory
 562     (total_mem, total_swap) = memtotal()
 563     slices = readdat()
 564
 565     # Query process table every 30 seconds, or when a large change in
 566     # swap utilization is detected.
 567     timer = period
 568     last_used = None
 569     used = None
 570
 571     # System slices that we have warned but could not reset
 572     warned = []
 573
 574     # Slices that were reset
 575     resetlist = {}
 576
 577     while True:
 578         used = swap_used()
 579         if last_used is None:  last_used = used
 580
 581         # If we've reset you recently, update timers.
 582         for resetslice in resetlist.keys():
 583             resetlist[resetslice].update()
 584             # If you've been good, remove you from our list.
 585             if resetlist[resetslice].killtimeleft == 0 and \
 586             resetlist[resetslice].resettimeleft == 0:
 587                 del resetlist[resetslice]
 588
 589         if verbose:  print "%d%% swap consumed" % used
 590
 591         if used >= reboot_thresh:
 592             # Dump slice state before rebooting
 593             writedat(slices)
 594             # Goodbye, cruel world
 595             print "%d%% swap consumed, rebooting" % used
 596             if not debug:  bwlimit.run("/bin/sync; /sbin/reboot -f")
 597         elif used >= reset_thresh:
 598             # Try and find a hog
 599             slicelist = slices.values()
 600             # Puts largest on top.
 601             slicelist.sort(lambda a, b: b['rss'] - a['rss'])
 602             for slice in slicelist:
 603                 percent = 100. * slice['rss'] / total_mem
 604                 if slice['rss'] < rss_min: continue
 605                 print "%d%% swap consumed, slice %s is using %s (%d%%) of memory" % \
 606                     (used,
 607                     slice['name'],
 608                     format_bytes(slice['rss'] * 1024, si = False),
 609                     percent)
 610                 slice['procs'].sort(lambda a, b: b['rss'] - a['rss'])
 611                 # Make a pretty table.
 612                 params = formtable(slice, percent)
 613                 # Match slice name against system slice patterns
 614                 is_system_slice = filter(None,
 615                     [re.match(pattern, slice['name']) for pattern in system_slices])
 616
 617                 # Do not reset system slices, just warn once
 618                 if is_system_slice:
 619                     if slice['name'] not in warned:
 620                         warned.append(slice['name'])
 621                         print "Warning slice " + slice['name']
 622                         if debug:
 623                             print alarm_subject % params
 624                             print alarm_body % params
 625                         else:
 626                             slicemail(slice['name'], alarm_subject % params,
 627                               alarm_body % params)
 628                 else:
 629                     # Reset slice
 630                     if not resetlist.has_key(slice['name']):
 631                         resetlist[slice['name']] = Reset(slice['name'])
 632                     resetlist[slice['name']].reset(params)
 633
 634         # wait period vefore recalculating swap.  If in danger, recalc.
 635         if timer <= 0 or used >= (last_used + change_thresh):
 636             if used >= (last_used + change_thresh):
 637                 print "%d%% swap consumed, %d%% in last %d seconds" % \
 638                     (used, used - last_used, period - timer)
 639             # Get slice state
 640             slices = slicestat(names)
 641             # Reset timer
 642             timer = period
 643             # Keep track of large changes in swap utilization
 644             last_used = used
 645         timer -= 1
 646         time.sleep(1)
 647
 648     removepid("swapmon")
 649
 650 if __name__ == '__main__':
 651     main()