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