sagemaker-debugger/debugger_interactive_analysis_profiling/interactive_analysis_profiling_data.ipynb

{
 "cells": [
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "# Monitor System Bottlenecks and Profile Framework Operators using Amazon Debugger\n"
   ]
  },
  {
   "attachments": {},
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "---\n",
    "\n",
    "This notebook's CI test result for us-west-2 is as follows. CI test results in other regions can be found at the end of the notebook. \n",
    "\n",
    "![This us-west-2 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/us-west-2/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "---"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "\n",
    "This notebook provides an introduction to interactive analysis of the data captured by SageMaker Debugger."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Table of Contents\n",
    "\n",
    "* [1. Install and import the latest SageMaker Python SDK](#1)<br>\n",
    "    * [1.1. Import Debugger classes for deep profiling](#1-1)<br>\n",
    "    * [1.2. Configure the profiler configuration parameter](#1-2)<br>\n",
    "* [2. Access profiled data for analysis](#2)<br>\n",
    "* [3. Analysis by training job phase](#analysis)<br>\n",
    "    * [3.1. Initialization](#initialization)<br>\n",
    "    * [3.2. Training loop](#training)<br>\n",
    "    * [3.3. Finalization](#finalization)<br>\n",
    "* [Conclusion](#conclusion)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<a class=\"anchor\" id=\"1\"></a>\n",
    "\n",
    "## 1. Import SageMaker and configure Debugger for deep profiling\n",
    "\n",
    "To use the new Debugger profiling features, ensure that you have the latest versions of SageMaker (2.19.0 or later) and SMDebug libraries installed."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<a class=\"anchor\" id=\"1-1\"></a>\n",
    "\n",
    "### 1.1. Import SageMaker and Debugger classes for deep profiling\n",
    "\n",
    "In this notebook example, we will run a TensorFlow training job to demonstrate how to use the Debugger profiling feature and the SMDebug analysis tools. To get started, let's import the SageMaker TensorFlow estimator class and the new Debugger classes for profiling configuration."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "import sagemaker\n",
    "from sagemaker.tensorflow import TensorFlow\n",
    "from sagemaker.debugger import (\n",
    "    ProfilerConfig,\n",
    "    FrameworkProfile,\n",
    "    DetailedProfilingConfig,\n",
    "    DataloaderProfilingConfig,\n",
    "    PythonProfilingConfig,\n",
    ")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Check the current SageMaker IAM role and AWS Region."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "import boto3\n",
    "\n",
    "role = sagemaker.get_execution_role()\n",
    "print(\"RoleArn:\", role)\n",
    "\n",
    "session = boto3.session.Session()\n",
    "region = session.region_name\n",
    "print(\"Region:\", region)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<a class=\"anchor\" id=\"1-2\"></a>\n",
    "### 1.2. Configure the `profiler_config` parameter\n",
    "\n",
    "In the following code cell, we configure the framework profiling options using the `ProfilerConfig` class. There are two parameters to pass to the `ProfilerConfig` class: `system_monitor_interval_millis` and `framework_profile_params`. The `system_monitor_interval_millis` is to adjust saving intervals for system metrics, and the `framework_profile_params` parameter is to configure how to save framework metrics. For more information about Debugger profiling configurations, see [Configure Debugger Using Amazon SageMaker Python SDK](https://docs.aws.amazon.com/sagemaker/latest/dg/debugger-configuration.html) in the [Amazon SageMaker Debugger developer guide](https://docs.aws.amazon.com/sagemaker/latest/dg/train-debugger.html)."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "profiler_config = ProfilerConfig(\n",
    "    system_monitor_interval_millis=500,\n",
    "    framework_profile_params=FrameworkProfile(\n",
    "        local_path=\"/opt/ml/output/profiler/\",\n",
    "        detailed_profiling_config=DetailedProfilingConfig(start_step=5, num_steps=3),\n",
    "        dataloader_profiling_config=DataloaderProfilingConfig(start_step=5, num_steps=2),\n",
    "        python_profiling_config=PythonProfilingConfig(start_step=9, num_steps=1),\n",
    "    ),\n",
    ")"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "estimator = TensorFlow(\n",
    "    role=sagemaker.get_execution_role(),\n",
    "    image_uri=f\"763104351884.dkr.ecr.{region}.amazonaws.com/tensorflow-training:2.3.1-gpu-py37-cu110-ubuntu18.04\",\n",
    "    instance_count=1,\n",
    "    instance_type=\"ml.p3.8xlarge\",\n",
    "    entry_point=\"train_tf.py\",\n",
    "    profiler_config=profiler_config,\n",
    ")"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "estimator.fit(wait=False)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<a class=\"anchor\" id=\"2\"></a>\n",
    "\n",
    "## 2. Access profiled data for analysis"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Once the training job initiates, SageMaker Debugger starts collecting system and framework metrics. The SMDebug library provides tools to access and analyze the profiling data. The following code cells are to set up a `TrainingJob` object to retrieve the system and framework metrics when they become available in the default S3 bucket. Once the metrics are available, you can query, plot, and analyze the profiling metrics data throughout this notebook."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "training_job_name = estimator.latest_training_job.job_name"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "import sys\n",
    "\n",
    "!{sys.executable} -m pip install \"smdebug==1.0.3\"\n",
    "!{sys.executable} -m pip install \"bokeh==2.3.0\""
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "from smdebug.profiler.analysis.notebook_utils.training_job import TrainingJob\n",
    "\n",
    "tj = TrainingJob(training_job_name, region)\n",
    "\n",
    "tj.wait_for_sys_profiling_data_to_be_available()\n",
    "tj.wait_for_framework_profiling_data_to_be_available()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "The following SMDebug PandasFrame class converts the profiled data into Pandas frames."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "from smdebug.profiler.analysis.utils.profiler_data_to_pandas import PandasFrame\n",
    "\n",
    "pf = PandasFrame(tj.profiler_s3_output_path)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Load the data into the following `system_metrics_df` and `framework_metrics` objects. \n",
    "\n",
    "**Note**: This loads the profiled data into memory of your Studio app or Notebook instance. If using the basic instance (ml.t3.medium) and having out of memory issue throughout the notebook,, consider to increase the instance size."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "system_metrics_df = pf.get_all_system_metrics()\n",
    "framework_metrics_df = pf.get_all_framework_metrics(\n",
    "    selected_framework_metrics=[\"Step:ModeKeys.TRAIN\", \"Step:ModeKeys.GLOBAL\"]\n",
    ")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<a id='analysis'></a>\n",
    "\n",
    "## 3. Analysis profiled data at different training phases"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Analysis on the profiled data is framework-specific because the operation IDs, names, and annotations are different across the deep learning frameworks. In this notebook example, we focus on TensorFlow framework profiling.\n",
    "\n",
    "Import utility classes for visualization and analysis from the SMDebug library."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "import os\n",
    "from IPython.display import IFrame, display, Markdown\n",
    "from smdebug.profiler.python_profile_utils import StepPhase, PythonProfileModes\n",
    "from smdebug.profiler.analysis.utils.python_profile_analysis_utils import Metrics\n",
    "from smdebug.profiler.analysis.python_profile_analysis import PyinstrumentAnalysis, cProfileAnalysis\n",
    "from smdebug.profiler.analysis.utils.pandas_data_analysis import (\n",
    "    PandasFrameAnalysis,\n",
    "    StatsBy,\n",
    "    Resource,\n",
    ")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### Create a Pandas frame analysis object for the profiled data"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "pf_analysis = PandasFrameAnalysis(system_metrics_df, framework_metrics_df)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### Identifying the time interval of each phase\n",
    "\n",
    "The following `get_job_statistics()` function retrieves training start and end time, duration of the initialization, training, and finalization stages."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "job_statistics = pf_analysis.get_job_statistics()\n",
    "\n",
    "initialization_start = job_statistics[\"start_time\"]\n",
    "initialization_end = job_statistics[\"training_loop_start\"]\n",
    "\n",
    "training_start = job_statistics[\"training_loop_start\"]\n",
    "training_end = job_statistics[\"training_loop_end\"]\n",
    "\n",
    "finalization_start = job_statistics[\"training_loop_end\"]\n",
    "finalization_end = job_statistics[\"end_time\"]"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "job_statistics"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<a id='initialization'></a>\n",
    "\n",
    "### 3.1 Initialization"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "This phase of the training job marks the time interval from the start of the training job in SageMaker to the start of the training loop."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### Python profiling"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Let's look at the python profiling stats for functions that were called during initialization."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### Download Python stats data\n",
    "\n",
    "Retrieve the Debugger profiling configuration of the training job."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "tj.profiler_config[\"ProfilingParameters\"]"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Pick up the Python profiling configuration and create an object that takes the configuration JSON strings."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "python_stats_dir = \"python_stats\"\n",
    "os.makedirs(python_stats_dir, exist_ok=True)\n",
    "python_profiling_config_tj = eval(\n",
    "    tj.profiler_config[\"ProfilingParameters\"].get(\"PythonProfilingConfig\")\n",
    ")"
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "python_profiling_config_tj"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Set an object that automatically detects which Python profiler is used for the training job."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "use_pyinstrument = (\n",
    "    False if python_profiling_config_tj.get(\"ProfilerName\") == \"cprofile\" else True\n",
    ")  # Set to True if you used Pyinstrument for Python profiling option."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "If you profiled with `cProfile`, you will see the function stats for the top 10 functions with greatest cumulative time spent. If you prefer to use a different metric or a different `n`, modify the `display_python_profile_stats` function defined in the following cell. If you profiled with `Pyinstrument`, you will see the stats separated by each phase of the step."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "def display_python_profile_stats(stats):\n",
    "    if use_pyinstrument:\n",
    "        if stats:\n",
    "            for step_stats in stats:\n",
    "                display(IFrame(src=step_stats.html_file_path, width=1000, height=500))\n",
    "    else:\n",
    "        if stats:\n",
    "            stats.print_top_n_functions(Metrics.CUMULATIVE_TIME, n=10)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "The `cProfileAnalysis` and `PyinstrumentAnalysis` classes have functionality to download the Python stats data from the S3 bucket to a specified local directory. The following cell saves the Python stats data into `python_stats` folder under your current working directory, and lists the head of the Python stats data."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "python_analysis_class = PyinstrumentAnalysis if use_pyinstrument else cProfileAnalysis\n",
    "python_analysis = python_analysis_class(\n",
    "    local_profile_dir=python_stats_dir, s3_path=tj.profiler_s3_output_path\n",
    ")\n",
    "step_stats_df = python_analysis.list_profile_stats()\n",
    "step_stats_df.head()"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "The following `fetch_pre_step_zero_profile_stats` function of the `python_analysis` object retrieves profiled data from the pre-step (denoted as start_step `-1` in the output data)."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "stats = python_analysis.fetch_pre_step_zero_profile_stats()\n",
    "display_python_profile_stats(stats)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<a id='training'></a>\n",
    "\n",
    "### 3.2 Training loop"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "This phase of the training job is time spent solely on training. It includes the data loading process, forward and backward pass, and synchronization.\n",
    "\n",
    "#### Utilization histograms\n",
    "\n",
    "`MetricHistogram` computes a histogram on GPU and CPU utilization values. Bins are between 0 and 100. Good system utilization means that the center of the distribtuon should be between 80 to 90. \n",
    "\n",
    "The following cell will plot the histograms per metric. In order to only plot specific metrics define the list  `select_dimensions` and `select_events`. A dimension can be CPUUtilization, GPUUtilization, GPUMemoryUtilization, and IOPS (IO per second). If no event is specified, CPU uiltization histograms for each single core and total cpu usage will be plotted. In case of GPU, it will visualize utilization and memory for each GPU. In case of IOPS, it will plot IO wait time per cpu. If `select_events` is specified, only those metrics that match the name in `select_metrics` will be shown. If neither `select_dimensions` nor `select_events` are specified, all available metrics will be visualized."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "from smdebug.profiler.analysis.notebook_utils.metrics_histogram import MetricsHistogram\n",
    "\n",
    "system_metrics_reader = tj.get_systems_metrics_reader()\n",
    "system_metrics_reader.refresh_event_file_list()\n",
    "\n",
    "metrics_histogram = MetricsHistogram(system_metrics_reader)\n",
    "metrics_histogram.plot(\n",
    "    starttime=0,\n",
    "    endtime=system_metrics_reader.get_timestamp_of_latest_available_file(),\n",
    "    select_dimensions=[\"CPU\", \"GPU\"],\n",
    "    # select_events=[\"total\"]\n",
    ")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### Step durations over time\n",
    "\n",
    "SageMaker Debugger records the durations of each step, which is the time spent in one forward and backward pass. The following code cell plots step durations (y-axis) over training job duration (x-axis). Typically it's expected that the step durations should be similar across the training run. Signficant step duration outliers indicate that there might be bottleneck issues related to those steps. `StepTimelineChart` helps to identify if such outliers happen in regular intervals."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "import time\n",
    "from smdebug.profiler.analysis.notebook_utils.step_timeline_chart import StepTimelineChart\n",
    "\n",
    "tj.wait_for_sys_profiling_data_to_be_available()\n",
    "tj.wait_for_framework_profiling_data_to_be_available()\n",
    "\n",
    "time.sleep(30)\n",
    "\n",
    "framework_metrics_reader = tj.get_framework_metrics_reader()\n",
    "framework_metrics_reader.refresh_event_file_list()\n",
    "\n",
    "time.sleep(30)\n",
    "\n",
    "view_step_timeline_chart = StepTimelineChart(framework_metrics_reader)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### Python profiling"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Let's now look at the python profiling stats for functions that were called during the first step profiled. From the Python profiling configuration JSON of your training job, call the start step of profiled data from the training loop."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "python_profiling_config_tj[\"StartStep\"]"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Display a list of Python operators executed during the profiled step."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "if python_profiling_config_tj == {}:\n",
    "    step = 9\n",
    "else:\n",
    "    step = int(python_profiling_config_tj[\"StartStep\"])\n",
    "phase = StepPhase.STEP_START\n",
    "mode = PythonProfileModes.TRAIN\n",
    "python_step_stats = python_analysis.fetch_profile_stats_by_step(\n",
    "    start_step=step, end_step=step + 1, start_phase=phase, end_phase=phase, mode=mode\n",
    ")\n",
    "display_python_profile_stats(python_step_stats)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "If detailed profiling was enabled and cProfile was used as the Python profiler, we can also just look at the stats for the training loop as a whole."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "if use_pyinstrument:\n",
    "    print(\"Pyinstrument was used as the Python profiler, no training loop stats are available.\")\n",
    "else:\n",
    "    python_job_stats = python_analysis.fetch_profile_stats_by_job_phase()\n",
    "    training_loop_stats = python_job_stats[\"training_loop\"]\n",
    "    display_python_profile_stats(training_loop_stats)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### CPU/GPU utilization\n",
    "\n",
    "SageMaker Debugger also records system metrics (resource utilization) for the training job. The following timeline charts depict the utilization per core and GPU. It shows the last 1000 datapoints. You can inspect previous datapoints by zooming out of the chart."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "from smdebug.profiler.analysis.notebook_utils.timeline_charts import TimelineCharts\n",
    "\n",
    "system_metrics_reader = tj.get_systems_metrics_reader()\n",
    "framework_metrics_reader.refresh_event_file_list()\n",
    "system_metrics_reader.refresh_event_file_list()\n",
    "\n",
    "view_timeline_charts = TimelineCharts(\n",
    "    system_metrics_reader,\n",
    "    framework_metrics_reader,\n",
    "    select_dimensions=[\"CPU\", \"GPU\"],\n",
    "    select_events=[\"total\"],\n",
    ")"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### Drill down by choosing a target range, get the exact time range you chose, and output correlated framework metrics"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "To drill down into an interested time range you want to investigate further, you can choose a range on the preceeding graphs and get the exact time range. As shown in the following animated screenshot, copy the time range that you chose and paste to the following two cells. \n",
    "<IMG src=images/select_range_drilldown_framework_metrics.gif/>"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "1. Find time annotation of every framework operation."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {
    "scrolled": true
   },
   "outputs": [],
   "source": [
    "# Note change index range below with selected index range from above cell\n",
    "view_timeline_charts.find_time_annotations([400, 440])"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "2. Plot timeline chart of the framework metrics for the selected time range. To avoid issues with out of memory, it will only plot the first 1000 datapoints."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "# Note change index range below with selected index range from above cell\n",
    "view_timeline_charts.plot_detailed_profiler_data([400, 440])"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### Identifying CPU bottlenecks\n",
    "\n",
    "A heatmap is a representation where each row corresponds to one metric (CPU core and GPU utilizations) and x-axis is the duration of the training job. It allows to more easily spot CPU bottlenecks e.g. if utilization on GPU is low but a utilization of one or more cores is high. \n",
    "\n",
    "In the below heatmap, Yellow indicates maximum utilization, purple means that utilization was 0. GPUs have frequent stalled cycles where utilization is dropping to 0 while at the same time utilization on CPU cores is at a maximum. This is a clear indication of a CPU bottleneck where GPUs are waiting for the data to arrive. Such a bottleneck can be caused for instance by a compute-heavy pre-processing."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "from smdebug.profiler.analysis.notebook_utils.heatmap import Heatmap\n",
    "\n",
    "system_metrics_reader.refresh_event_file_list()\n",
    "view_heatmap = Heatmap(system_metrics_reader, plot_height=450)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### Merging all the trace events \n",
    "\n",
    "Debugger captures events from different sources, such as framework, debugger hook, Horovod (if applicable). Putting them together, aligning the events and visualizing, will give an idea of events occurring in different components of the training job, and identify potential issues. The merge_timeline() API below combines the different types of trace event files into one trace event file, which can then be viewed in the browser.\n",
    "\n",
    "Below, we merge the events that occurred between step 1 and 10. You can modifying this step interval, or alternatively, merge events within a time interval."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {
    "scrolled": true
   },
   "outputs": [],
   "source": [
    "from smdebug.profiler.analysis.utils.merge_timelines import MergedTimeline, MergeUnit\n",
    "\n",
    "start_step, end_step = 1, 10\n",
    "combined_timeline = MergedTimeline(tj.profiler_s3_output_path, output_directory=\"./\")\n",
    "combined_timeline.merge_timeline(start_step, end_step, unit=MergeUnit.STEP)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "As shown in the following animated screenshot, do the followings:\n",
    "\n",
    "1. Browse the current working directory to find the combined timeline file.\n",
    "2. Open a Chrome browser tracing app at [chrome://tracing](chrome://tracing), and load the JSON file.\n",
    "3. Use the mouse motion tool box to shift or zoom in and out the timeline. You can also use `W`, `A`, `S`, and `D` keys to browse the timeline.\n",
    "\n",
    "<IMG src=images/merged_timeline.gif>"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "Next, since data loading is one of the most compute-intensive parts of the training process, we dive deep into analysing profiler data related to data loading."
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "#### Profiling TensorFlow data loader processes<a id='dataloading'></a>"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "List the top 10 `Step` metrics from the profiled data. From the output of the following cell, you can find out the time spent on each step and operations executed at each step in detail."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "from smdebug.profiler.analysis.notebook_utils.training_job import TrainingJob\n",
    "\n",
    "tj = TrainingJob(training_job_name, region)\n",
    "tj.wait_for_sys_profiling_data_to_be_available()\n",
    "system_metrics_reader = tj.get_systems_metrics_reader()\n",
    "\n",
    "tj.wait_for_framework_profiling_data_to_be_available()\n",
    "framework_metrics_reader = tj.get_framework_metrics_reader()\n",
    "framework_metrics_reader.refresh_event_file_list()\n",
    "\n",
    "from smdebug.profiler.analysis.utils.profiler_data_to_pandas import PandasFrame\n",
    "\n",
    "pf = PandasFrame(tj.profiler_s3_output_path)\n",
    "system_metrics_df = pf.get_all_system_metrics()\n",
    "\n",
    "step_metrics_df = pf.get_all_framework_metrics(selected_framework_metrics=[\"Step:ModeKeys.TRAIN\"])\n",
    "\n",
    "step_metrics_df.head(10)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "List the top 10 data loader process operators. We filter data loading events of using the `GeneratorDatasetOp::Dataset::Iterator::GetNext` regex from a given train step. Measuring the time span of these events are useful to evaluate how the data loading processes are efficient."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "iterator_metrics = pf.get_all_framework_metrics(\n",
    "    selected_framework_metrics=[\"tensorflow::data::GeneratorDatasetOp::Dataset::Iterator::GetNext\"]\n",
    ")\n",
    "iterator_metrics.head(10)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "The following cell prints the time taken by first 10 time steps to perform data loading. It also lists the number of workers processed for the data loading."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "for i in range(10):\n",
    "    cur_step = step_metrics_df.iloc[i]\n",
    "    step_pid = cur_step[\"pid\"]\n",
    "    step_tid = cur_step[\"tid\"]\n",
    "    cur_step_number = cur_step[\"step\"]\n",
    "    step_start_time = cur_step[\"start_time_us\"]\n",
    "    step_end_time = cur_step[\"end_time_us\"]\n",
    "    step_duration = step_end_time - step_start_time\n",
    "\n",
    "    data_iter_cur_step = iterator_metrics.loc[\n",
    "        (iterator_metrics[\"start_time_us\"] >= step_start_time)\n",
    "        & (iterator_metrics[\"end_time_us\"] <= step_end_time)\n",
    "    ]\n",
    "    num_workers = data_iter_cur_step.shape[0]\n",
    "    dl_time_mean = (\n",
    "        data_iter_cur_step[\"end_time_us\"].mean() - data_iter_cur_step[\"start_time_us\"].mean()\n",
    "    )\n",
    "    print(\n",
    "        f\"Step number: {cur_step_number}, time taken by train step: {step_duration}, Number of dataloading workers: {num_workers}, Average dataloading time of all the workers: {dl_time_mean} microseconds\"\n",
    "    )"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<a id='finalization'></a>\n",
    "\n",
    "### 3.3 Finalization"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "The finalization phase of the training job marks the time interval from the end of the training loop to the end of the training job in SageMaker. The following cell returns the python profiling stats for functions that were called during finalization."
   ]
  },
  {
   "cell_type": "code",
   "execution_count": null,
   "metadata": {},
   "outputs": [],
   "source": [
    "stats = python_analysis.fetch_post_hook_close_profile_stats()\n",
    "display_python_profile_stats(stats)"
   ]
  },
  {
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "<a id='conclusion'></a>\n",
    "\n",
    "## Conclusion\n",
    "\n",
    "In this notebook, we explored the full functionality of the new Debugger profiling features. SageMaker Debugger initiates training job with your preferred profiling settings. The SMDebug client library provides the analysis tools that you can drill down to the profiled data. You can profile each training job phases, watch which steps make bottlenecks and slowdowns at different training phases, and retrieve a list of operations at the target step or time range. To deep dive and learn more about SageMaker Debugger, see the [Amazon SageMaker Debugger developer guide](https://docs.aws.amazon.com/sagemaker/latest/dg/train-debugger.html)."
   ]
  },
  {
   "attachments": {},
   "cell_type": "markdown",
   "metadata": {},
   "source": [
    "## Notebook CI Test Results\n",
    "\n",
    "This notebook was tested in multiple regions. The test results are as follows, except for us-west-2 which is shown at the top of the notebook.\n",
    "\n",
    "![This us-east-1 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/us-east-1/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This us-east-2 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/us-east-2/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This us-west-1 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/us-west-1/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This ca-central-1 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/ca-central-1/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This sa-east-1 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/sa-east-1/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This eu-west-1 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/eu-west-1/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This eu-west-2 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/eu-west-2/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This eu-west-3 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/eu-west-3/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This eu-central-1 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/eu-central-1/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This eu-north-1 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/eu-north-1/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This ap-southeast-1 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/ap-southeast-1/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This ap-southeast-2 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/ap-southeast-2/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This ap-northeast-1 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/ap-northeast-1/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This ap-northeast-2 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/ap-northeast-2/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n",
    "\n",
    "![This ap-south-1 badge failed to load. Check your device's internet connectivity, otherwise the service is currently unavailable](https://prod.us-west-2.tcx-beacon.docs.aws.dev/sagemaker-nb/ap-south-1/sagemaker-debugger|debugger_interactive_analysis_profiling|interactive_analysis_profiling_data.ipynb)\n"
   ]
  }
 ],
 "metadata": {
  "kernelspec": {
   "display_name": "conda_tensorflow2_p36",
   "language": "python",
   "name": "conda_tensorflow2_p36"
  },
  "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.13"
  }
 },
 "nbformat": 4,
 "nbformat_minor": 4
}