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         if proc['vsize'] > 4096:
 360             proc['rss'] += 4 * ((proc['vsize'] - 1) / 4096)
 361
 362         if slices.has_key(proc['xid']):
 363             slice = slices[proc['xid']]
 364         else:
 365             slice = {'xid': proc['xid'], 'name': name, 'procs': [], 'vsize': 0, 'sz': 0, 'rss': 0}
 366
 367         slice['procs'].append(proc)
 368         slice['vsize'] += proc['vsize']
 369         slice['sz'] += proc['sz']
 370         slice['rss'] += proc['rss']
 371
 372         slices[proc['xid']] = slice
 373
 374     return slices
 375
 376 def memtotal():
 377     """
 378     Returns total physical and swap memory on the system in KiB.
 379     """
 380     mem = 0
 381     swap = 0
 382     meminfo = open("/proc/meminfo", "r")
 383     for line in meminfo.readlines():
 384         try:
 385             (name, value, kb) = line.split()
 386         except:
 387             continue
 388         if name == "MemTotal:":
 389             mem = int(value)
 390         elif name == "SwapTotal:":
 391             swap = int(value)
 392     meminfo.close()
 393     return (mem, swap)
 394
 395 def swap_used():
 396     """
 397     Returns swap utilization on the system as a whole percentage (0-100).
 398     """
 399     total_swap = 0
 400     total_used = 0
 401     try:
 402         swaps = open("/proc/swaps", "r")
 403         # Eat header line
 404         lines = swaps.readlines()[1:]
 405         swaps.close()
 406         for line in lines:
 407             # /dev/mapper/planetlab-swap partition 1048568 3740 -1
 408             (filename, type, size, used, priority) = line.strip().split()
 409             try:
 410                 total_swap += int(size)
 411                 total_used += int(used)
 412             except ValueEror, err:
 413                 pass
 414     except (IOError, KeyError), err:  pass
 415
 416     swapused = 100 * total_used / total_swap
 417     if debug: print "%s percent swap used" % swapused
 418     return swapused
 419
 420 def summary(slices = None, total_mem = None, total_swap = None):
 421     """
 422     Return a summary of memory usage by slice.
 423     """
 424     if not slices:  slices = slicestat()
 425     slicelist = slices.values()
 426     slicelist.sort(lambda a, b: b['sz'] - a['sz'])
 427     if total_mem is None or total_swap is None:
 428         (total_mem, total_swap) = memtotal()
 429
 430     table = "%-20s%10s%24s%24s\n\n" % ("Slice", "Processes", "Memory Usage", "Potential Usage")
 431     for slice in slicelist:
 432         table += "%-20s%10d%16s (%4.1f%%)%16s (%4.1f%%)\n" % \
 433                  (slice['name'], len(slice['procs']),
 434                   format_bytes(slice['rss'] * 1024, si = False),
 435                   100. * slice['rss'] / total_mem,
 436                   format_bytes(slice['sz'] * 1024, si = False),
 437                   100. * slice['sz'] / (total_mem + total_swap))
 438     return table
 439
 440 def formtable(slice, percent):
 441     '''
 442     Makes pretty message to email with human readable ps values.
 443     '''
 444     table = "%5s %10s %10s %10s %4s %4s %s\n\n" % \
 445         ("PID", "VIRT", "SZ", "RES", '%CPU', '%MEM', 'COMMAND')
 446     for proc in slice['procs']:
 447         table += "%5s %10s %10s %10s %4.1f %s\n" % \
 448             (proc['pid'],
 449             format_bytes(proc['vsize'] * 1024, si = False),
 450             format_bytes(proc['sz'] * 1024, si = False),
 451             format_bytes(proc['rss'] * 1024, si = False),
 452             proc['pmem'],
 453             proc['cmd'])
 454
 455     prettytable = {'hostname': socket.gethostname(),
 456              'date': time.asctime(time.gmtime()) + " GMT",
 457              'table': table,
 458              'slice': slice['name'],
 459              'rss': format_bytes(slice['rss'] * 1024, si = False),
 460              'sz': format_bytes(slice['sz'] * 1024, si = False),
 461              'percent': percent}
 462     return prettytable
 463
 464 def readdat():
 465     '''
 466     Return dictionary of vps (slicestat) from datfile left behind by OOM
 467     before rebooting.  If none file, just grab the latest dict (slicestat)
 468     and return that.  If dat file found, means we rebooted, send an email to
 469     pl_mom@pl.
 470     '''
 471     try:
 472         f = open(DATAFILE, "r+")
 473         if verbose:
 474             print "Loading %s" % DATAFILE
 475         (v, slices) = pickle.load(f)
 476         f.close()
 477         # Check version of data file
 478         if v != VERSION:
 479             print "Not using old version '%s' data file %s" % (v, DATAFILE)
 480             raise Exception
 481
 482         params = {'hostname': socket.gethostname(),
 483                   'date': time.asctime(time.gmtime()) + " GMT",
 484                   'table': summary(slices, total_mem, total_swap)}
 485         if debug:
 486             print rebooted_subject % params
 487             print rebooted_body % params
 488         else:
 489             slicemail(None, rebooted_subject % params, rebooted_body % params)
 490
 491         # Delete data file
 492         os.unlink(DATAFILE)
 493     except Exception:
 494         slices = slicestat()
 495
 496     return slices
 497
 498
 499 def writedat(slices):
 500     """
 501     Write (slices) to pickled datfile.
 502     """
 503     if verbose:  print "Saving %s" % DATAFILE
 504     f = open(DATAFILE, "w")
 505     pickle.dump((VERSION, slices), f)
 506     f.close()
 507
 508
 509 def main():
 510     # Defaults
 511     global debug, verbose, DATAFILE, VERSION
 512     global period, change_thresh, reset_thresh, reboot_thresh, rss_min, system_slices
 513     # All slices
 514     names = []
 515
 516     try:
 517         longopts = ["debug", "verbose", "file=", "slice=", "status", "help"]
 518         longopts += ["period=", "reset-thresh=", "reboot-thresh=", "min-thresh=", "system-slice="]
 519         (opts, argv) = getopt.getopt(sys.argv[1:], "dvf:s:ph", longopts)
 520     except getopt.GetoptError, err:
 521         print "Error: " + err.msg
 522         usage()
 523         sys.exit(1)
 524
 525     for (opt, optval) in opts:
 526         if opt == "-d" or opt == "--debug":
 527             debug = True
 528         elif opt == "-v" or opt == "--verbose":
 529             verbose += 1
 530         elif opt == "-f" or opt == "--file":
 531             DATAFILE = optval
 532         elif opt == "-s" or opt == "--slice":
 533             names.append(optval)
 534         elif opt == "-p" or opt == "--period":
 535             period = int(optval)
 536         elif opt == "--change-thresh":
 537             change_thresh = int(optval)
 538         elif opt == "--reset-thresh":
 539             reset_thresh = int(optval)
 540         elif opt == "--reboot-thresh":
 541             reboot_thresh = int(optval)
 542         elif opt == "--min-thresh":
 543             rss_min = int(optval)
 544         elif opt == "--system-slice":
 545             system_slices.append(optval)
 546         elif opt == "--status":
 547             print summary(slicestat(names))
 548             sys.exit(0)
 549         else:
 550             usage()
 551             sys.exit(0)
 552
 553     # Check if we are already running
 554     writepid("swapmon")
 555
 556     if not debug:
 557         daemonize()
 558         # Rewrite PID file
 559         writepid("swapmon")
 560         # Redirect stdout and stderr to syslog
 561         syslog.openlog("swapmon")
 562         sys.stdout = sys.stderr = Logger()
 563
 564     # Get total memory
 565     (total_mem, total_swap) = memtotal()
 566     slices = readdat()
 567
 568     # Query process table every 30 seconds, or when a large change in
 569     # swap utilization is detected.
 570     timer = period
 571     last_used = None
 572     used = None
 573
 574     # System slices that we have warned but could not reset
 575     warned = []
 576
 577     # Slices that were reset
 578     resetlist = {}
 579
 580     while True:
 581         used = swap_used()
 582         if last_used is None:  last_used = used
 583
 584         # If we've reset you recently, update timers.
 585         for resetslice in resetlist.keys():
 586             resetlist[resetslice].update()
 587             # If you've been good, remove you from our list.
 588             if resetlist[resetslice].killtimeleft == 0 and \
 589             resetlist[resetslice].resettimeleft == 0:
 590                 del resetlist[resetslice]
 591
 592         if used >= reboot_thresh:
 593             # Dump slice state before rebooting
 594             writedat(slices)
 595             # Goodbye, cruel world
 596             print "%d%% swap consumed, rebooting" % used
 597             if not debug:  bwlimit.run("/bin/sync; /sbin/reboot -f")
 598         elif used >= reset_thresh:
 599             # Try and find a hog
 600             slicelist = slices.values()
 601             # Puts largest on top.
 602             slicelist.sort(lambda a, b: b['rss'] - a['rss'])
 603             for slice in slicelist:
 604                 percent = 100. * slice['rss'] / total_mem
 605                 if slice['rss'] < rss_min: continue
 606                 print "%d%% swap consumed, slice %s is using %s (%d%%) of memory" % \
 607                     (used,
 608                     slice['name'],
 609                     format_bytes(slice['rss'] * 1024, si = False),
 610                     percent)
 611                 slice['procs'].sort(lambda a, b: b['rss'] - a['rss'])
 612                 # Make a pretty table.
 613                 params = formtable(slice, percent)
 614                 # Match slice name against system slice patterns
 615                 is_system_slice = filter(None,
 616                     [re.match(pattern, slice['name']) for pattern in system_slices])
 617
 618                 # Do not reset system slices, just warn once
 619                 if is_system_slice:
 620                     if slice['name'] not in warned:
 621                         warned.append(slice['name'])
 622                         print "Warning slice " + slice['name']
 623                         if debug:
 624                             print alarm_subject % params
 625                             print alarm_body % params
 626                         else:
 627                             slicemail(slice['name'], alarm_subject % params,
 628                               alarm_body % params)
 629                 else:
 630                     # Reset slice
 631                     if not resetlist.has_key(slice['name']):
 632                         resetlist[slice['name']] = Reset(slice['name'])
 633                     resetlist[slice['name']].reset(params)
 634
 635         # wait period vefore recalculating swap.  If in danger, recalc.
 636         if timer <= 0 or used >= (last_used + change_thresh):
 637             if used >= (last_used + change_thresh):
 638                 print "%d%% swap consumed, %d%% in last %d seconds" % \
 639                     (used, used - last_used, period - timer)
 640             # Get slice state
 641             slices = slicestat(names)
 642             # Reset timer
 643             timer = period
 644             # Keep track of large changes in swap utilization
 645             last_used = used
 646         timer -= 1
 647         time.sleep(1)
 648
 649     removepid("swapmon")
 650
 651 if __name__ == '__main__':
 652     main()