notebooks/debt_visualizer.ipynb

{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "JVMQuake GCLog Analyzer\n",
    "=======================\n",
    "\n",
    "This notebook displayes the GC debt algorithm that `jvmquake` uses and will parse the file `gclog` assuming it is a standard Java GC file from a JVM running with `-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps  -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime` that contains lines that look like:\n",
    "\n",
    "```\n",
    "2019-03-05T02:41:44.826+0000: 7.395: Total time for which application threads were stopped: 0.0001693 seconds, Stopping threads took: 0.0000766 seconds\n",
    "2019-03-05T02:41:44.935+0000: 7.504: Application time: 0.1087838 seconds        \n",
    "2019-03-05T02:41:44.935+0000: 7.504: Total time for which application threads were stopped: 0.0002082 seconds, Stopping threads took: 0.0000504 seconds\n",
    "2019-03-05T02:41:45.058+0000: 7.627: Application time: 0.1229325 seconds        \n",
    "2019-03-05T02:41:45.058+0000: 7.627: Total time for which application threads were stopped: 0.0002039 seconds, Stopping threads took: 0.0000656 seconds\n",
    "2019-03-05T02:41:45.400+0000: 7.969: Application time: 0.3417643 seconds        \n",
    "2019-03-05T02:41:45.400+0000: 7.969: Total time for which application threads were stopped: 0.0002733 seconds, Stopping threads took: 0.0000479 seconds\n",
    "2019-03-05T02:41:46.400+0000: 8.969: Application time: 1.0001321 seconds        \n",
    "2019-03-05T02:41:46.671+0000: 9.240: Total time for which application threads were stopped: 0.2710559 seconds, Stopping threads took: 0.2709677 seconds\n",
    "2019-03-05T02:41:46.691+0000: 9.260: Application time: 0.0201782 seconds        \n",
    "2019-03-05T02:41:46.692+0000: 9.261: Total time for which application threads were stopped: 0.0002705 seconds, Stopping threads took: 0.0000955 seconds\n",
    "```\n",
    "\n",
    "Based on this data it will show when `jvmquake` would step in and detect a spiral of death.\n"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "import re\n",
    "import datetime\n",
    "\n",
    "runtimes = []\n",
    "pauses = []\n",
    "safepoints = []\n",
    "\n",
    "float_regex = \"[-+]?(\\d+(\\.\\d*)?|\\.\\d+)([eE][-+]?\\d+)?\"\n",
    "runtime_match = re.compile(\"Application time: {0} seconds\".format(float_regex))\n",
    "pause_match = re.compile(\"Total time for which application threads were stopped: {0} seconds, \"\n",
    "                         \"Stopping threads took: {0} seconds\".format(float_regex))\n",
    "timestamp_match = re.compile(\"(\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}.\\d{3})\\+\\d{4}\")\n",
    "\n",
    "# NOTE: If you want a different gclog, either symlink to gclog or change this file\n",
    "with open('gclog') as gclog:\n",
    "    for line in gclog:\n",
    "        timestamp = timestamp_match.search(line)\n",
    "        if timestamp is None:\n",
    "            continue\n",
    "        dt = datetime.datetime.strptime(timestamp.groups(0)[0], '%Y-%m-%dT%H:%M:%S.%f')\n",
    "        runtime = runtime_match.search(line)\n",
    "        pause_time = pause_match.search(line)\n",
    "        if runtime:\n",
    "            runtimes.append((dt, float(runtime.groups(0)[0])))\n",
    "        elif pause_time:\n",
    "            pauses.append((dt, float(pause_time.groups(0)[0])))\n",
    "            safepoints.append((dt, float(pause_time.groups(0)[3])))\n",
    "            \n",
    "print(\"Found {} runtimes and {} pauses\".format(len(runtimes), len(pauses)))\n",
    "# A proper GC log should have roughly equal runtimes to pauses\n",
    "assert abs(len(runtimes) - len(pauses)) < 2\n",
    "# A proper GC log should have equal numbers of safepoint datapoints and gc latencies\n",
    "assert len(safepoints) == len(pauses)"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "# The bucket for keeping track of relative running and paused time\n",
    "token_bucket = 0\n",
    "# The amount of weight to give running seconds over GCing seconds. This defines\n",
    "# our expected application throughput\n",
    "runtime_weight = 4\n",
    "# The amount of time that we must exceed the expected throughput by before\n",
    "# triggering the signal and death actions\n",
    "gc_threshold = 30\n",
    "    \n",
    "adj_runtimes = []\n",
    "token_bucket_values = []\n",
    "kill_pos = []\n",
    "kill_times = []\n",
    "\n",
    "for i in range(min(len(runtimes), len(pauses))):\n",
    "    dt, runtime = runtimes[i]\n",
    "    if (token_bucket - (runtime * runtime_weight)) < 0:\n",
    "        adj_runtimes.append((dt, token_bucket))\n",
    "    else:\n",
    "        adj_runtimes.append((dt, runtime))\n",
    "        \n",
    "    token_bucket = max(0, token_bucket - (runtime * runtime_weight))\n",
    "    token_bucket_values.append((dt, token_bucket))\n",
    "    \n",
    "    dt, pause_time = pauses[i]\n",
    "    token_bucket += pause_time\n",
    "    if token_bucket > gc_threshold - 1:\n",
    "        print('WARNING: Would have killed process at {0} with debt {1}'.format(dt, token_bucket))\n",
    "        kill_times.append(dt)\n",
    "        kill_pos.append(i)\n",
    "    token_bucket_values.append((dt, token_bucket))"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "import matplotlib\n",
    "import matplotlib.pyplot as plt\n",
    "import matplotlib.style as style\n",
    "import numpy as np\n",
    "\n",
    "style.use('tableau-colorblind10')\n",
    "matplotlib.rcParams.update({'font.size': 16})"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "sample_x = [i for i in range(min(len(adj_runtimes), len(pauses)))]\n",
    "pause_y = [i[1] for i in pauses]\n",
    "safepoint_y = [i[1] for i in safepoints]\n",
    "runtime_y = [-1 * float(i[1]) for i in adj_runtimes]\n",
    "\n",
    "fig1, ax = plt.subplots(figsize=(12,8))\n",
    "plt.stem(sample_x, pause_y, linefmt='C0-', markerfmt='C0^', basefmt=' ', label='Pause debt')\n",
    "plt.stem(sample_x, safepoint_y, linefmt='C7-', markerfmt='C7^', basefmt=' ', label='Safepoint debt')\n",
    "plt.stem(sample_x, runtime_y, linefmt='C1-', markerfmt='C1v', basefmt=' ', label='Runtime credit')\n",
    "\n",
    "if kill_pos:\n",
    "    plt.axvline(x=kill_pos[0], linestyle='--', color='k', label='jvmquake trigger')\n",
    "    \n",
    "plt.hlines(gc_threshold, sample_x[0], sample_x[-1], label='Pause threshold')    \n",
    "    \n",
    "plt.yscale('symlog', linthreshy=2, subsy=[2,3,4,5,6,7,8,9])\n",
    "plt.title('Simulated jvmquake debt')\n",
    "plt.xlabel('Pause/Runtime Events')\n",
    "plt.ylabel('Seconds of Debt')\n",
    "plt.ylim(-10, 40)\n",
    "plt.minorticks_on()\n",
    "\n",
    "plt.grid(which='major', linestyle=':', linewidth='0.4', color='black')\n",
    "plt.grid(which='minor', linestyle=':', linewidth='0.4', color='black')\n",
    "plt.legend(loc='upper right', bbox_to_anchor=(0.4, 0.9),\n",
    "           facecolor='C6')\n",
    "plt.show()"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "xmin = min([min(i[0] for i in runtimes), min(i[0] for i in pauses)])\n",
    "xmax = max([max(i[0] for i in runtimes), max(i[0] for i in pauses)])\n",
    "\n",
    "pause_x = [i[0] for i in pauses]\n",
    "safepoint_x = [i[0] for i in safepoints]\n",
    "runtime_x = [i[0] for i in adj_runtimes]\n",
    "\n",
    "fig1, ax = plt.subplots(figsize=(12,8))\n",
    "plt.stem(pause_x, pause_y, linefmt='C0-', markerfmt='C0^', basefmt=' ', label='Pause debt')\n",
    "plt.stem(safepoint_x, safepoint_y, linefmt='C7-', markerfmt='C7^', basefmt=' ', label='Safepoint debt')\n",
    "plt.stem(runtime_x, runtime_y, linefmt='C1-', markerfmt='C1v', basefmt=' ', label='Runtime credit')\n",
    "\n",
    "if kill_times:\n",
    "    plt.axvline(x=kill_times[0], linestyle='--', color='k', label='jvmquake trigger')\n",
    "    \n",
    "plt.hlines(gc_threshold, xmin, xmax, label='Pause threshold')    \n",
    "    \n",
    "plt.yscale('symlog', linthreshy=2, subsy=[2,3,4,5,6,7,8,9])\n",
    "plt.title('Simulated jvmquake debt')\n",
    "plt.xlabel('Time')\n",
    "plt.ylabel('Seconds of Debt')\n",
    "plt.ylim(-10, 40)\n",
    "plt.minorticks_on()\n",
    "\n",
    "plt.grid(which='major', linestyle=':', linewidth='0.4', color='black')\n",
    "plt.grid(which='minor', linestyle=':', linewidth='0.4', color='black')\n",
    "plt.legend(loc='lower right', facecolor='C6')\n",
    "plt.show()"
   ]
  }
 ],
 "metadata": {
  "kernelspec": {
   "display_name": "Python 3",
   "language": "python",
   "name": "python3"
  },
  "language_info": {
   "codemirror_mode": {
    "name": "ipython",
    "version": 3
   },
   "file_extension": ".py",
   "mimetype": "text/x-python",
   "name": "python",
   "nbconvert_exporter": "python",
   "pygments_lexer": "ipython3",
   "version": "3.6.7"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 2
}