demo/builtin/bert/BERT_DEMO.ipynb

{
  "cells": [
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {
        "colab_type": "text",
        "id": "view-in-github"
      },
      "source": [
        "[![open in colab](https://colab.research.google.com/assets/colab-badge.svg)](https://colab.research.google.com/github/intel/e2eAIOK/blob/main/demo/builtin/bert/BERT_DEMO.ipynb)"
      ]
    },
    {
      "cell_type": "markdown",
      "metadata": {
        "id": "cmmfinEiCZqi"
      },
      "source": [
        "# BERT Demo\n",
        "This demo mainly introduces how to apply Intel® End-to-End AI Optimization Kit on BERT, which mainly includes distributed training, early stop with Lamb optimization and SDA, and is expected to improve the E2E performance of BERT."
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {
        "id": "5lt44-DBCZqm"
      },
      "source": [
        "# Content\n",
        "* [Overview](#overview)\n",
        "    * [Model Architecture](#model-architecture)\n",
        "    * [Optimizations](#optimizations)\n",
        "    * [Performance](#performance)\n",
        "* [Getting Started](#getting-started)\n",
        "    * [1. Environment Setup](#1-environment-setup)\n",
        "    * [2. Workflow Prepare](#2-workflow-prepare)\n",
        "    * [3. Data Prepare](#3-data-prepare)\n",
        "    * [4. Train](#4-train)"
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {
        "id": "pS__BjqrCZqn"
      },
      "source": [
        "# Overview"
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {
        "id": "UcunRFksCZqn"
      },
      "source": [
        "## Model Architecture\n",
        "\n",
        "### Natural Language Processing\n",
        "\n",
        "<img src=\"https://github.com/intel/e2eAIOK/blob/main/demo/builtin/bert/img/QA.png?raw=1\" width=\"400\"/><figure>Question Answer Task</figure>\n",
        "\n",
        "* Natural language processing (NLP) is the intersection of computer science, linguistics and machine learning, where the pre-trained language model BERT is the most representive model in a wide area of NLP tasks, like question and answer.\n",
        "* The end-to-end NLP system is a BERT-based network that uses the pretrained model weight for the downstream question answer task SQuAD (v1.1). In the question-answer task, given the input question and paragraph/context sequence, the BERT aims to predict the start/end index in the paragraph to indicate the answer span.\n",
        "\n",
        "### Model\n",
        "\n",
        "<img src=\"https://github.com/intel/e2eAIOK/blob/main/demo/builtin/bert/img/TransformerEncoder.png?raw=1\" width=\"400\"/><figure>Transformer Architecture</figure>\n",
        "\n",
        "[Transformer](https://arxiv.org/pdf/1706.03762.pdf) includes two separate mechanisms — an encoder that reads the text input and a decoder that produces a prediction for the task. Since BERT’s goal is to generate a language model, only the encoder mechanism is necessary. \n",
        "\n",
        "BERT’s model architecture is a multi-layer bidirectional Transformer encoder, where an attention mechanism that learns contextual relations between words (or sub-words) in a text. The input is a sequence of word tokens, which are first embedded into vectors and then processed in each Transformer layer (the multi-head attention layer and feed-forward layer).\n",
        "\n",
        "In the question-answer task, the output hidden state of the last Tranformer layer in the BERT is feed into one specific output layer to learn the beginning and the end index in the paragraph to indicate the answer span.\n"
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {
        "id": "Quj-d90JCZqo"
      },
      "source": [
        "## Optimizations"
      ]
    },
    {
      "cell_type": "markdown",
      "metadata": {
        "id": "XxXWVkCECZqo"
      },
      "source": [
        "For BERT model democratization, we enabled distributed training with horovod and oneCCL to scale out model training on multi nodes, added early stop when reaching the target F1 score and avoiding over training, added lamb optimization to accept larger batch size, and SDA to fine tune the parameters."
      ]
    },
    {
      "cell_type": "markdown",
      "metadata": {
        "id": "z_nscJJwCZqo"
      },
      "source": [
        "### Distributed training\n",
        "Using data parallelism can split a large batch of data into small pieces and send them to each node so as to reduce computation cost per node, where oneCCL and horovod provide a straightforward approach to apply the model distributed in different nodes.\n",
        "<img src=\"https://github.com/intel/e2eAIOK/blob/main/demo/builtin/bert/img/Horovod.png?raw=1\" width=\"600\"/><figure>Data Parallel</figure>\n",
        "\n",
        "* cmd shell\n",
        "\n",
        "``` shell\n",
        "horovodrun --binding-args='-map-by socket' python -np {num_mpi_processes} -H {host_addr} --network-interface {network_interface} HOROVOD_CPU_OPERATIONS=CCL CCL_ATL_TRANSPORT=mpi run_squad.py\n",
        "```\n",
        "* python script\n",
        "\n",
        "``` python\n",
        "# data parallel\n",
        "if hvd.size():\n",
        "    hooks = [hvd.BroadcastGlobalVariablesHook(0)]\n",
        "...\n",
        "...\n",
        "...\n",
        "if hvd.size():\n",
        "    import horovod.tensorflow as hvd\n",
        "    optimizer = hvd.DistributedOptimizer(optimizer, sparse_as_dense=True)\n",
        "```\n",
        "<img src=\"https://github.com/intel/e2eAIOK/blob/main/demo/builtin/bert/img/SingleProcess.png?raw=1\" width=\"400\"/><figure>w/o Distributed Training</figure>\n",
        "<img src=\"https://github.com/intel/e2eAIOK/blob/main/demo/builtin/bert/img/DistributedTraining.png?raw=1\" width=\"400\"/><figure>w/ Distributed Training</figure>\n",
        "\n",
        "As shown in the above figure, distributed training \"w/ Distributed Training\" helps to reduce the burden of one single node as compared with \"w/o Distributed Training\"."
      ]
    },
    {
      "cell_type": "markdown",
      "metadata": {
        "id": "KVsFxeuRCZqp"
      },
      "source": [
        "### Add early stop and validation mechanism with Lamb optimizer\n",
        "\n",
        "1. Early Stop and Validation\n",
        "\n",
        "Adding early stop and validation mechanism can help reduce the over training:\n",
        "* Subsample 10% test data as validation data (reduce validation time)\n",
        "* Add early stop when reaching the target F1 90.874\n",
        "\n",
        "``` python\n",
        "def should_stop_fn(predictions_results):\n",
        "        global_step = estimator.get_variable_value(\"global_step\")\n",
        "        global_step_int = int(global_step)\n",
        "        if global_step_int >= FLAGS.step_threshold or float(predictions_results[\"f1\"]) > FLAGS.f1_threshold:\n",
        "            return True\n",
        "...\n",
        "...\n",
        "...\n",
        "early_stopping_hook = tf.compat.v1.estimator.experimental.make_early_stopping_hook(\n",
        "        estimator=estimator,\n",
        "        should_stop_fn=should_stop_fn,\n",
        "        run_every_secs=None,\n",
        "        run_every_steps=FLAGS.num_to_evaluate)\n",
        "```\n",
        "\n",
        "2. Add lamb optimization\n",
        "\n",
        "Training with large batch size using lamb optimizer (ref: [LARGE BATCH OPTIMIZATION FOR DEEP LEARNING: TRAINING BERT IN 76 MINUTES](https://arxiv.org/abs/1904.00962)), where its algorithm is shown as below:\n",
        "\n",
        "<img src=\"https://github.com/intel/e2eAIOK/blob/main/demo/builtin/bert/img/Lamb.png?raw=1\" width=\"400\"/><figure>Lamb optimization</figure>\n",
        "\n",
        "As shown in the below figure, \"w/ Early Stop\" enables BERT to stop training at the proper step 600 as compared with the long step 7299 in \"w/o Early Stop\".\n",
        "\n",
        "<img src=\"https://github.com/intel/e2eAIOK/blob/main/demo/builtin/bert/img/WOEarlystop.png?raw=1\" width=\"1000\"/><figure>w/o Early Stop</figure>\n",
        "<img src=\"https://github.com/intel/e2eAIOK/blob/main/demo/builtin/bert/img/WEarlystop.png?raw=1\" width=\"1000\"/><figure>w/ Early Stop</figure>\n"
      ]
    },
    {
      "cell_type": "markdown",
      "metadata": {
        "id": "7SEC_OA_CZqp"
      },
      "source": [
        "### HPO with SDA (Smart Democratization Advisor)\n",
        "\n",
        "SDA can assit BERT to do hyper-parameter optimization such as the \"learning rate\" ranging from 3e-5 to 3e-4, \"warmup_rate\" ranging from 0.1 to 0.3, \"batch_size\" selected from \\[12, 16, 24, 96, 128\\], etc., which is useful to select the proper hyper-parameter for improving the BERT performance.\n",
        "\n",
        "SDA config\n",
        "\n",
        "```\n",
        "Parameters for SDA auto optimization:\n",
        "  - learning_rate: 3.0e-5~3.0e-4 # learning rate for optimizer\n",
        "  - warmup_rate: 0.1~0.3 # warmup rate for learning\n",
        "  - batch_size: [12, 16, 24, 96, 128] # batch size for training\n",
        "metrics:\n",
        "- name: training_time\n",
        "  objective: minimize\n",
        "  threshold: 10000\n",
        "- name: F1\n",
        "  objective: maxmize\n",
        "  threshold: 90.87\n",
        " ```\n",
        "\n",
        "request suggestions from SDA\n",
        "\n",
        "```python\n",
        "suggestion = self.conn.experiments(self.experiment.id).suggestions().create()\n",
        "```\n"
      ]
    },
    {
      "cell_type": "markdown",
      "metadata": {
        "id": "slHrPz3rCZqq"
      },
      "source": [
        "<img src=\"https://github.com/intel/e2eAIOK/blob/main/demo/builtin/bert/img/WOSDA.png?raw=1\" width=\"800\"/><figure>w/o SDA</figure>\n",
        "<img src=\"https://github.com/intel/e2eAIOK/blob/main/demo/builtin/bert/img/WSDA.png?raw=1\" width=\"800\"/><figure>w/ SDA</figure>\n",
        "\n",
        "As shown in the above figure, SDA helps BERT handle more samples per second (3.1 examples/sec of \"w/ SDA\" vs 2.85 examples/sec of \"w/o SDA\")."
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {},
      "source": [
        "## Performance\n",
        "<center>\n",
        "<img src=\"./img/Performance.png\" width=\"800\"/><figure>SDA BERT Performance</figure>\n",
        "</center>\n",
        "\n",
        "* Distributed training with HW scaling delivered 3.42x speedup from 1 node to 4 nodes\n",
        "    * Within 1% F1 score gap (90.48 vs. 90.874)\n",
        "* Early stop and sampled validation dataset delivered 1.37x speedup, and 4.70x speedup over baseline\n",
        "    * Within 1% F1 score gap (90.85 vs. 90.874)\n",
        "* HPO with SDA (a component of AIOK, smart democratization advisor) delivered 2.15x speedup, and 10.10x speedup over baseline\n",
        "    * Within 1% F1 score gap (90.14 vs. 90.874)\n",
        "* Baseline converged and stopped at 2 epoch, optimized model converged and stopped at 2 epoch\n"
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {},
      "source": [
        "# Getting Started\n",
        "Noted: Need to download dataset and pretrained model manually to run this demo.\n",
        "\n",
        "## 1. Environment Setup\n",
        "\n",
        "### (Option 1) Use Pip install"
      ]
    },
    {
      "cell_type": "code",
      "execution_count": null,
      "metadata": {},
      "outputs": [],
      "source": [
        "! pip install e2eAIOK-sda --pre\n",
        "! pip install intel-tensorflow==2.10"
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {},
      "source": [
        "### (Option 2) Use Docker\n",
        "\n",
        "Step1. prepare code\n",
        "``` bash\n",
        "git clone https://github.com/intel/e2eAIOK.git\n",
        "mv e2eAIOK e2eaiok\n",
        "cd e2eaiok\n",
        "git submodule update --init --recursive\n",
        "```\n",
        "\n",
        "Step2. build docker image\n",
        "```bash\n",
        "python3 scripts/start_e2eaiok_docker.py -b tensorflow -w ${host0} ${host1} ${host2} ${host3} --proxy \"\"\n",
        "```\n",
        "\n",
        "Step3. run docker and start conda env\n",
        "```bash\n",
        "sshpass -p docker ssh ${host0} -p 12344\n",
        "```"
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {
        "id": "uVpvYKQ5CZqq"
      },
      "source": [
        "## 2. Workflow Prepare\n",
        "\n",
        "* Prepare model codes\n",
        "``` bash\n",
        "cd /home/vmagent/app/e2eaiok/modelzoo/bert\n",
        "sh patch_bert.sh\n",
        "```\n",
        "\n",
        "* Download pre-trained model\n",
        "\n",
        "Download and extract one of BERT large-uncased pretrained models from [Google BERT repository](https://github.com/google-research/bert#pre-trained-models) to /home/vmagent/app/dataset/SQuAD/pre-trained-model/bert-large-uncased/"
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {},
      "source": [
        "## 3. Data Prepare\n",
        "\n",
        "* Download Dataset\n",
        "\n",
        "Stanford Question Answering Dataset (SQuAD) is a reading comprehension dataset, consisting of questions posed by crowdworkers on a set of Wikipedia articles, where the answer to every question is a segment of text, or span, from the corresponding reading passage, or the question might be unanswerable. SQuAD 1.1 contains 100,000+ question-answer pairs on 500+ articles.\n",
        "\n",
        "* Download from below path to /home/vmagent/app/dataset/SQuAD\n",
        "\n",
        "    * Train Data: [train-v1.1.json](https://rajpurkar.github.io/SQuAD-explorer/dataset/train-v1.1.json)\n",
        "    * Test Data: [dev-v1.1.json](https://rajpurkar.github.io/SQuAD-explorer/dataset/dev-v1.1.json)\n",
        "    * Data Format:\n",
        "\n",
        "``` bash\n",
        "{\n",
        "    \"answers\": {\n",
        "        \"answer_start\": [1],\n",
        "        \"text\": [\"This is a test text\"]\n",
        "    },\n",
        "    \"context\": \"This is a test context.\",\n",
        "    \"id\": \"1\",\n",
        "    \"question\": \"Is this a test?\",\n",
        "    \"title\": \"train test\"\n",
        "}"
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {
        "id": "tR5KteX5CZqr"
      },
      "source": [
        "## 4. Train"
      ]
    },
    {
      "attachments": {},
      "cell_type": "markdown",
      "metadata": {},
      "source": [
        "Launch SDA training process on NLP domain BERT, and will produce the fine-tuned BERT performance on SQuADv1.1 task.\n",
        "\n",
        "Noted: Below performance result is using sample dataset and small iterations to demonstrate its function. The actual performance result please refers to the [performance section](#performance)."
      ]
    },
    {
      "cell_type": "code",
      "execution_count": null,
      "metadata": {
        "id": "YqT5kRpbCZqr",
        "outputId": "b87fe847-d3e1-4248-c0e5-f282e3da0f59",
        "scrolled": false
      },
      "outputs": [
        {
          "name": "stdout",
          "output_type": "stream",
          "text": [
            "data format is binary\n",
            "\n",
            "===============================================\n",
            "***    Best Trained Model    ***\n",
            "===============================================\n",
            "  Model Type: bert\n",
            "  Model Saved Path: \n",
            "  Sigopt Experiment id is None\n",
            "  === Result Metrics ===\n",
            "===============================================\n",
            "2022-10-31 18:57:44,290 - E2EAIOK - INFO - Above info is history record of this model\n",
            "2022-10-31 18:57:44,290 - E2EAIOK.SDA - INFO - ### Ready to submit current task  ###\n",
            "2022-10-31 18:57:44,290 - E2EAIOK.SDA - INFO - Model Advisor created\n",
            "2022-10-31 18:57:44,290 - E2EAIOK.SDA - INFO - model parameter initialized\n",
            "2022-10-31 18:57:44,290 - E2EAIOK.SDA - INFO - start to launch training\n",
            "training launch command: PYTHONPATH=$PYTHONPATH:/home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/ /opt/intel/oneapi/intelpython/latest/envs/tensorflow/bin//python /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/launch_benchmark.py --model-name=bert_large --precision=fp32 --mode=training --framework=tensorflow --batch-size=24 --output-dir /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d --host_file=$MODEL_DIR/hosts --num-intra-threads 36 --num-inter-threads 2 --train_option=SQuAD vocab_file=$CHECKPOINT_DIR/vocab.txt config_file=$CHECKPOINT_DIR/bert_config.json init_checkpoint=$CHECKPOINT_DIR/bert_model.ckpt do_train=True train_file=$DATASET_DIR/train-v1.1.json do_predict=True predict_file=$DATASET_DIR/dev-v1.1.json test_file=$DATASET_DIR/test-v1.1.json data_dir=$DATASET_DIR num_to_evaluate=50 step_threshold=100000 f1_threshold=90.87 num_train_epochs=2 max_seq_length=384 doc_stride=128 optimized_softmax=True experimental_gelu=False do_lower_case=True num_hidden_layers=24 learning_rate=3e-5 attention_probs_dropout_prob=0.1 hidden_dropout_prob=0.1 warmup_proportion=0.1 \n",
            "Running with parameters:\n",
            "    USE_CASE: language_modeling\n",
            "    FRAMEWORK: tensorflow\n",
            "    WORKSPACE: /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/common/tensorflow\n",
            "    DATASET_LOCATION: \n",
            "    CHECKPOINT_DIRECTORY: \n",
            "    BACKBONE_MODEL_DIRECTORY: \n",
            "    IN_GRAPH: \n",
            "    MOUNT_INTELAI_MODELS_COMMON_SOURCE_DIR: /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/../models/common/tensorflow\n",
            "    Mounted volumes:\n",
            "        /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks mounted on: /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks\n",
            "        None mounted on: None\n",
            "        /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/../models/language_modeling/tensorflow/bert_large mounted on: /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/../models/language_modeling/tensorflow/bert_large\n",
            "        None mounted on: \n",
            "        None mounted on: \n",
            "        None mounted on: \n",
            "    SOCKET_ID: -1\n",
            "    MODEL_NAME: bert_large\n",
            "    MODE: training\n",
            "    PRECISION: fp32\n",
            "    BATCH_SIZE: 24\n",
            "    NUM_CORES: -1\n",
            "    BENCHMARK_ONLY: True\n",
            "    ACCURACY_ONLY: False\n",
            "    OUTPUT_RESULTS: False\n",
            "    DISABLE_TCMALLOC: True\n",
            "    TCMALLOC_LARGE_ALLOC_REPORT_THRESHOLD: 2147483648\n",
            "    NOINSTALL: True\n",
            "    OUTPUT_DIR: /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d\n",
            "    MPI_NUM_PROCESSES: None\n",
            "    MPI_NUM_PEOCESSES_PER_SOCKET: 1\n",
            "    MPI_HOSTNAMES: None\n",
            "    NUMA_CORES_PER_INSTANCE: None\n",
            "    PYTHON_EXE: /opt/intel/oneapi/intelpython/latest/envs/tensorflow/bin//python\n",
            "    PYTHONPATH: /home/spark-3.2.1-bin-hadoop3.2/python/lib/py4j-0.10.9.3-src.zip:/home/spark-3.2.1-bin-hadoop3.2/python/:/opt/intel/oneapi/advisor/2021.4.0/pythonapi:/home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/\n",
            "    DRY_RUN: \n",
            "Running on \"Ubuntu\" version \"18.04\" is supported.\n",
            "2022:10:31-18:57:46:(83727) |WARN| did not find MPI-launcher specific variables, switch to ATL/OFI, to force enable ATL/MPI set CCL_ATL_TRANSPORT=mpi\n",
            "INFO:tensorflow:batch_size: 24, learning_rate: 3e-05, num_hidden_layers: 24, attention_probs_dropout_prob: 0.1, hidden_dropout_prob: 0.1\n",
            "I1031 18:57:46.889105 140537919225600 run_squad.py:1251] batch_size: 24, learning_rate: 3e-05, num_hidden_layers: 24, attention_probs_dropout_prob: 0.1, hidden_dropout_prob: 0.1\n",
            "WARNING:tensorflow:From /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/../models/language_modeling/tensorflow/bert_large/training/fp32/run_squad.py:1284: The name tf.estimator.tpu.InputPipelineConfig is deprecated. Please use tf.compat.v1.estimator.tpu.InputPipelineConfig instead.\n",
            "\n",
            "W1031 18:57:47.263630 140537919225600 module_wrapper.py:155] From /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/../models/language_modeling/tensorflow/bert_large/training/fp32/run_squad.py:1284: The name tf.estimator.tpu.InputPipelineConfig is deprecated. Please use tf.compat.v1.estimator.tpu.InputPipelineConfig instead.\n",
            "\n",
            "WARNING:tensorflow:Estimator's model_fn (<function model_fn_builder.<locals>.model_fn at 0x7fcfdd7bd680>) includes params argument, but params are not passed to Estimator.\n",
            "W1031 18:57:47.309260 140537919225600 estimator.py:2013] Estimator's model_fn (<function model_fn_builder.<locals>.model_fn at 0x7fcfdd7bd680>) includes params argument, but params are not passed to Estimator.\n",
            "INFO:tensorflow:Using config: {'_model_dir': '/home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d', '_tf_random_seed': 12345, '_save_summary_steps': 100, '_save_checkpoints_steps': 50, '_save_checkpoints_secs': None, '_session_config': intra_op_parallelism_threads: 36\n",
            "inter_op_parallelism_threads: 2\n",
            "allow_soft_placement: true\n",
            ", '_keep_checkpoint_max': 1, '_keep_checkpoint_every_n_hours': 10000, '_log_step_count_steps': None, '_train_distribute': None, '_device_fn': None, '_protocol': None, '_eval_distribute': None, '_experimental_distribute': None, '_experimental_max_worker_delay_secs': None, '_session_creation_timeout_secs': 7200, '_checkpoint_save_graph_def': True, '_service': None, '_cluster_spec': ClusterSpec({}), '_task_type': 'worker', '_task_id': 0, '_global_id_in_cluster': 0, '_master': '', '_evaluation_master': '', '_is_chief': True, '_num_ps_replicas': 0, '_num_worker_replicas': 1, '_tpu_config': TPUConfig(iterations_per_loop=1000, num_shards=8, num_cores_per_replica=None, per_host_input_for_training=3, tpu_job_name=None, initial_infeed_sleep_secs=None, input_partition_dims=None, eval_training_input_configuration=2, experimental_host_call_every_n_steps=1, experimental_allow_per_host_v2_parallel_get_next=False, experimental_feed_hook=None), '_cluster': None}\n",
            "I1031 18:57:47.309767 140537919225600 estimator.py:191] Using config: {'_model_dir': '/home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d', '_tf_random_seed': 12345, '_save_summary_steps': 100, '_save_checkpoints_steps': 50, '_save_checkpoints_secs': None, '_session_config': intra_op_parallelism_threads: 36\n",
            "inter_op_parallelism_threads: 2\n",
            "allow_soft_placement: true\n",
            ", '_keep_checkpoint_max': 1, '_keep_checkpoint_every_n_hours': 10000, '_log_step_count_steps': None, '_train_distribute': None, '_device_fn': None, '_protocol': None, '_eval_distribute': None, '_experimental_distribute': None, '_experimental_max_worker_delay_secs': None, '_session_creation_timeout_secs': 7200, '_checkpoint_save_graph_def': True, '_service': None, '_cluster_spec': ClusterSpec({}), '_task_type': 'worker', '_task_id': 0, '_global_id_in_cluster': 0, '_master': '', '_evaluation_master': '', '_is_chief': True, '_num_ps_replicas': 0, '_num_worker_replicas': 1, '_tpu_config': TPUConfig(iterations_per_loop=1000, num_shards=8, num_cores_per_replica=None, per_host_input_for_training=3, tpu_job_name=None, initial_infeed_sleep_secs=None, input_partition_dims=None, eval_training_input_configuration=2, experimental_host_call_every_n_steps=1, experimental_allow_per_host_v2_parallel_get_next=False, experimental_feed_hook=None), '_cluster': None}\n",
            "INFO:tensorflow:_TPUContext: eval_on_tpu True\n",
            "I1031 18:57:47.309996 140537919225600 tpu_context.py:271] _TPUContext: eval_on_tpu True\n",
            "WARNING:tensorflow:eval_on_tpu ignored because use_tpu is False.\n",
            "W1031 18:57:47.310091 140537919225600 tpu_context.py:273] eval_on_tpu ignored because use_tpu is False.\n",
            "INFO:tensorflow:***** Running training *****\n",
            "I1031 18:57:47.310156 140537919225600 run_squad.py:1356] ***** Running training *****\n",
            "INFO:tensorflow:  Num orig examples = 1027\n",
            "I1031 18:57:47.310192 140537919225600 run_squad.py:1357]   Num orig examples = 1027\n",
            "INFO:tensorflow:  Batch size = 24\n",
            "I1031 18:57:47.310275 140537919225600 run_squad.py:1358]   Batch size = 24\n",
            "INFO:tensorflow:  Num steps = 85\n",
            "I1031 18:57:47.310307 140537919225600 run_squad.py:1359]   Num steps = 85\n",
            "WARNING:tensorflow:From /opt/intel/oneapi/intelpython/latest/envs/tensorflow/lib/python3.7/site-packages/tensorflow/python/training/training_util.py:236: Variable.initialized_value (from tensorflow.python.ops.variables) is deprecated and will be removed in a future version.\n",
            "Instructions for updating:\n",
            "Use Variable.read_value. Variables in 2.X are initialized automatically both in eager and graph (inside tf.defun) contexts.\n",
            "W1031 18:57:47.314865 140537919225600 deprecation.py:336] From /opt/intel/oneapi/intelpython/latest/envs/tensorflow/lib/python3.7/site-packages/tensorflow/python/training/training_util.py:236: Variable.initialized_value (from tensorflow.python.ops.variables) is deprecated and will be removed in a future version.\n",
            "Instructions for updating:\n",
            "Use Variable.read_value. Variables in 2.X are initialized automatically both in eager and graph (inside tf.defun) contexts.\n",
            "WARNING:tensorflow:From /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/../models/language_modeling/tensorflow/bert_large/training/fp32/run_squad.py:823: map_and_batch (from tensorflow.python.data.experimental.ops.batching) is deprecated and will be removed in a future version.\n",
            "Instructions for updating:\n",
            "Use `tf.data.Dataset.map(map_func, num_parallel_calls)` followed by `tf.data.Dataset.batch(batch_size, drop_remainder)`. Static tf.data optimizations will take care of using the fused implementation.\n",
            "W1031 18:57:47.338313 140537919225600 deprecation.py:336] From /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/../models/language_modeling/tensorflow/bert_large/training/fp32/run_squad.py:823: map_and_batch (from tensorflow.python.data.experimental.ops.batching) is deprecated and will be removed in a future version.\n",
            "Instructions for updating:\n",
            "Use `tf.data.Dataset.map(map_func, num_parallel_calls)` followed by `tf.data.Dataset.batch(batch_size, drop_remainder)`. Static tf.data optimizations will take care of using the fused implementation.\n"
          ]
        },
        {
          "name": "stdout",
          "output_type": "stream",
          "text": [
            "INFO:tensorflow:Calling model_fn.\n",
            "I1031 18:57:47.453577 140537919225600 estimator.py:1162] Calling model_fn.\n",
            "INFO:tensorflow:Running train on CPU/GPU\n",
            "I1031 18:57:47.453701 140537919225600 tpu_estimator.py:3198] Running train on CPU/GPU\n",
            "WARNING:tensorflow:From /opt/intel/oneapi/intelpython/latest/envs/tensorflow/lib/python3.7/site-packages/tensorflow/python/ops/array_ops.py:5049: calling gather (from tensorflow.python.ops.array_ops) with validate_indices is deprecated and will be removed in a future version.\n",
            "Instructions for updating:\n",
            "The `validate_indices` argument has no effect. Indices are always validated on CPU and never validated on GPU.\n",
            "W1031 18:57:47.459250 140537919225600 deprecation.py:534] From /opt/intel/oneapi/intelpython/latest/envs/tensorflow/lib/python3.7/site-packages/tensorflow/python/ops/array_ops.py:5049: calling gather (from tensorflow.python.ops.array_ops) with validate_indices is deprecated and will be removed in a future version.\n",
            "Instructions for updating:\n",
            "The `validate_indices` argument has no effect. Indices are always validated on CPU and never validated on GPU.\n",
            "/opt/intel/oneapi/intelpython/latest/envs/tensorflow/lib/python3.7/site-packages/tensorflow/python/keras/legacy_tf_layers/core.py:171: UserWarning: `tf.layers.dense` is deprecated and will be removed in a future version. Please use `tf.keras.layers.Dense` instead.\n",
            "  warnings.warn('`tf.layers.dense` is deprecated and '\n",
            "/opt/intel/oneapi/intelpython/latest/envs/tensorflow/lib/python3.7/site-packages/tensorflow/python/keras/engine/base_layer_v1.py:1692: UserWarning: `layer.apply` is deprecated and will be removed in a future version. Please use `layer.__call__` method instead.\n",
            "  warnings.warn('`layer.apply` is deprecated and '\n",
            "INFO:tensorflow:Done calling model_fn.\n",
            "I1031 18:58:04.846139 140537919225600 estimator.py:1164] Done calling model_fn.\n",
            "INFO:tensorflow:Create CheckpointSaverHook.\n",
            "I1031 18:58:04.847015 140537919225600 basic_session_run_hooks.py:546] Create CheckpointSaverHook.\n",
            "INFO:tensorflow:Graph was finalized.\n",
            "I1031 18:58:10.070029 140537919225600 monitored_session.py:247] Graph was finalized.\n",
            "2022-10-31 18:58:10.070385: I tensorflow/core/platform/cpu_feature_guard.cc:142] This TensorFlow binary is optimized with oneAPI Deep Neural Network Library (oneDNN) to use the following CPU instructions in performance-critical operations:  AVX2 AVX512F FMA\n",
            "To enable them in other operations, rebuild TensorFlow with the appropriate compiler flags.\n",
            "2022-10-31 18:58:11.163640: I tensorflow/core/platform/profile_utils/cpu_utils.cc:114] CPU Frequency: 2600000000 Hz\n",
            "INFO:tensorflow:Running local_init_op.\n",
            "I1031 18:58:17.722917 140537919225600 session_manager.py:531] Running local_init_op.\n",
            "INFO:tensorflow:Done running local_init_op.\n",
            "I1031 18:58:17.996238 140537919225600 session_manager.py:534] Done running local_init_op.\n",
            "INFO:tensorflow:Calling checkpoint listeners before saving checkpoint 0...\n",
            "I1031 18:58:28.847211 140537919225600 basic_session_run_hooks.py:614] Calling checkpoint listeners before saving checkpoint 0...\n",
            "INFO:tensorflow:Saving checkpoints for 0 into /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/model.ckpt.\n",
            "I1031 18:58:28.865137 140537919225600 basic_session_run_hooks.py:618] Saving checkpoints for 0 into /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/model.ckpt.\n",
            "INFO:tensorflow:Calling checkpoint listeners after saving checkpoint 0...\n",
            "I1031 18:58:34.843199 140537919225600 basic_session_run_hooks.py:626] Calling checkpoint listeners after saving checkpoint 0...\n",
            "2022-10-31 18:58:35.306368: I tensorflow/compiler/mlir/mlir_graph_optimization_pass.cc:176] None of the MLIR Optimization Passes are enabled (registered 2)\n",
            "\n",
            "User settings:\n",
            "\n",
            "   KMP_AFFINITY=granularity=fine,compact,1,0\n",
            "   KMP_BLOCKTIME=1\n",
            "   KMP_SETTINGS=1\n",
            "   OMP_NUM_THREADS=36\n",
            "\n",
            "Effective settings:\n",
            "\n",
            "   KMP_ABORT_DELAY=0\n",
            "   KMP_ADAPTIVE_LOCK_PROPS='1,1024'\n",
            "   KMP_ALIGN_ALLOC=64\n",
            "   KMP_ALL_THREADPRIVATE=288\n",
            "   KMP_ATOMIC_MODE=2\n",
            "   KMP_BLOCKTIME=1\n",
            "   KMP_CPUINFO_FILE: value is not defined\n",
            "   KMP_DETERMINISTIC_REDUCTION=false\n",
            "   KMP_DEVICE_THREAD_LIMIT=2147483647\n",
            "   KMP_DISP_NUM_BUFFERS=7\n",
            "   KMP_DUPLICATE_LIB_OK=false\n",
            "   KMP_ENABLE_TASK_THROTTLING=true\n",
            "   KMP_FORCE_REDUCTION: value is not defined\n",
            "   KMP_FOREIGN_THREADS_THREADPRIVATE=true\n",
            "   KMP_FORKJOIN_BARRIER='2,2'\n",
            "   KMP_FORKJOIN_BARRIER_PATTERN='hyper,hyper'\n",
            "   KMP_GTID_MODE=3\n",
            "   KMP_HANDLE_SIGNALS=false\n",
            "   KMP_HOT_TEAMS_MAX_LEVEL=1\n",
            "   KMP_HOT_TEAMS_MODE=0\n",
            "   KMP_INIT_AT_FORK=true\n",
            "   KMP_LIBRARY=throughput\n",
            "   KMP_LOCK_KIND=queuing\n",
            "   KMP_MALLOC_POOL_INCR=1M\n",
            "   KMP_NUM_LOCKS_IN_BLOCK=1\n",
            "   KMP_PLAIN_BARRIER='2,2'\n",
            "   KMP_PLAIN_BARRIER_PATTERN='hyper,hyper'\n",
            "   KMP_REDUCTION_BARRIER='1,1'\n",
            "   KMP_REDUCTION_BARRIER_PATTERN='hyper,hyper'\n",
            "   KMP_SCHEDULE='static,balanced;guided,iterative'\n",
            "   KMP_SETTINGS=true\n",
            "   KMP_SPIN_BACKOFF_PARAMS='4096,100'\n",
            "   KMP_STACKOFFSET=64\n",
            "   KMP_STACKPAD=0\n",
            "   KMP_STACKSIZE=8M\n",
            "   KMP_STORAGE_MAP=false\n",
            "   KMP_TASKING=2\n",
            "   KMP_TASKLOOP_MIN_TASKS=0\n",
            "   KMP_TASK_STEALING_CONSTRAINT=1\n",
            "   KMP_TEAMS_THREAD_LIMIT=72\n",
            "   KMP_TOPOLOGY_METHOD=all\n",
            "   KMP_USE_YIELD=1\n",
            "   KMP_VERSION=false\n",
            "   KMP_WARNINGS=true\n",
            "   OMP_AFFINITY_FORMAT='OMP: pid %P tid %i thread %n bound to OS proc set {%A}'\n",
            "   OMP_ALLOCATOR=omp_default_mem_alloc\n",
            "   OMP_CANCELLATION=false\n",
            "   OMP_DEFAULT_DEVICE=0\n",
            "   OMP_DISPLAY_AFFINITY=false\n",
            "   OMP_DISPLAY_ENV=false\n",
            "   OMP_DYNAMIC=false\n",
            "   OMP_MAX_ACTIVE_LEVELS=1\n",
            "   OMP_MAX_TASK_PRIORITY=0\n",
            "   OMP_NESTED: deprecated; max-active-levels-var=1\n",
            "   OMP_NUM_THREADS='36'\n",
            "   OMP_PLACES: value is not defined\n",
            "   OMP_PROC_BIND='intel'\n",
            "   OMP_SCHEDULE='static'\n",
            "   OMP_STACKSIZE=8M\n",
            "   OMP_TARGET_OFFLOAD=DEFAULT\n",
            "   OMP_THREAD_LIMIT=2147483647\n",
            "   OMP_WAIT_POLICY=PASSIVE\n",
            "   KMP_AFFINITY='noverbose,warnings,respect,granularity=fine,compact,1,0'\n",
            "\n",
            "INFO:tensorflow:\t Loss  = 6.0394125, \t Step  = 0\n",
            "I1031 18:59:16.732210 140537919225600 basic_session_run_hooks.py:262] \t Loss  = 6.0394125, \t Step  = 0\n",
            "INFO:tensorflow:global_step/sec: 0.0257812\n",
            "I1031 18:59:55.521626 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0257812\n",
            "INFO:tensorflow:examples/sec: 0.618749\n",
            "I1031 18:59:55.522847 140537919225600 tpu_estimator.py:2403] examples/sec: 0.618749\n",
            "INFO:tensorflow:global_step/sec: 0.0714596\n",
            "I1031 19:00:09.515324 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0714596\n",
            "INFO:tensorflow:examples/sec: 1.71503\n",
            "I1031 19:00:09.515866 140537919225600 tpu_estimator.py:2403] examples/sec: 1.71503\n",
            "INFO:tensorflow:\t Loss  = 5.988244, \t Step  = 4 (92.967 sec)\n",
            "I1031 19:00:49.699281 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.988244, \t Step  = 4 (92.967 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0248845\n",
            "I1031 19:00:49.700942 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0248845\n",
            "INFO:tensorflow:examples/sec: 0.597229\n",
            "I1031 19:00:49.701081 140537919225600 tpu_estimator.py:2403] examples/sec: 0.597229\n",
            "INFO:tensorflow:global_step/sec: 0.0749037\n",
            "I1031 19:01:03.051336 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0749037\n",
            "INFO:tensorflow:examples/sec: 1.79769\n",
            "I1031 19:01:03.051871 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79769\n",
            "WARNING:tensorflow:It seems that global step (tf.train.get_global_step) has not been increased. Current value (could be stable): 4 vs previous value: 4. You could increase the global step by passing tf.train.get_global_step() to Optimizer.apply_gradients or Optimizer.minimize.\n",
            "W1031 19:01:03.051994 140537919225600 basic_session_run_hooks.py:734] It seems that global step (tf.train.get_global_step) has not been increased. Current value (could be stable): 4 vs previous value: 4. You could increase the global step by passing tf.train.get_global_step() to Optimizer.apply_gradients or Optimizer.minimize.\n",
            "INFO:tensorflow:global_step/sec: 0.0744958\n",
            "I1031 19:01:16.476217 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0744958\n",
            "INFO:tensorflow:examples/sec: 1.7879\n",
            "I1031 19:01:16.477803 140537919225600 tpu_estimator.py:2403] examples/sec: 1.7879\n",
            "INFO:tensorflow:\t Loss  = 6.0981054, \t Step  = 7 (40.297 sec)\n",
            "I1031 19:01:29.996195 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 6.0981054, \t Step  = 7 (40.297 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0739525\n",
            "I1031 19:01:29.997093 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0739525\n",
            "INFO:tensorflow:examples/sec: 1.77486\n",
            "I1031 19:01:29.997217 140537919225600 tpu_estimator.py:2403] examples/sec: 1.77486\n"
          ]
        },
        {
          "name": "stdout",
          "output_type": "stream",
          "text": [
            "INFO:tensorflow:global_step/sec: 0.0750579\n",
            "I1031 19:01:43.320894 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0750579\n",
            "INFO:tensorflow:examples/sec: 1.80139\n",
            "I1031 19:01:43.322280 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80139\n",
            "WARNING:tensorflow:It seems that global step (tf.train.get_global_step) has not been increased. Current value (could be stable): 7 vs previous value: 7. You could increase the global step by passing tf.train.get_global_step() to Optimizer.apply_gradients or Optimizer.minimize.\n",
            "W1031 19:01:43.322602 140537919225600 basic_session_run_hooks.py:734] It seems that global step (tf.train.get_global_step) has not been increased. Current value (could be stable): 7 vs previous value: 7. You could increase the global step by passing tf.train.get_global_step() to Optimizer.apply_gradients or Optimizer.minimize.\n",
            "INFO:tensorflow:global_step/sec: 0.0735472\n",
            "I1031 19:01:56.916933 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0735472\n",
            "INFO:tensorflow:examples/sec: 1.76513\n",
            "I1031 19:01:56.917140 140537919225600 tpu_estimator.py:2403] examples/sec: 1.76513\n",
            "INFO:tensorflow:\t Loss  = 5.868999, \t Step  = 10 (40.672 sec)\n",
            "I1031 19:02:10.668398 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.868999, \t Step  = 10 (40.672 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0727112\n",
            "I1031 19:02:10.670051 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0727112\n",
            "INFO:tensorflow:examples/sec: 1.74507\n",
            "I1031 19:02:10.670331 140537919225600 tpu_estimator.py:2403] examples/sec: 1.74507\n",
            "INFO:tensorflow:global_step/sec: 0.0755373\n",
            "I1031 19:02:23.909123 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0755373\n",
            "INFO:tensorflow:examples/sec: 1.81289\n",
            "I1031 19:02:23.910567 140537919225600 tpu_estimator.py:2403] examples/sec: 1.81289\n",
            "WARNING:tensorflow:It seems that global step (tf.train.get_global_step) has not been increased. Current value (could be stable): 10 vs previous value: 10. You could increase the global step by passing tf.train.get_global_step() to Optimizer.apply_gradients or Optimizer.minimize.\n",
            "W1031 19:02:23.910814 140537919225600 basic_session_run_hooks.py:734] It seems that global step (tf.train.get_global_step) has not been increased. Current value (could be stable): 10 vs previous value: 10. You could increase the global step by passing tf.train.get_global_step() to Optimizer.apply_gradients or Optimizer.minimize.\n",
            "INFO:tensorflow:global_step/sec: 0.0746584\n",
            "I1031 19:02:37.302735 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0746584\n",
            "INFO:tensorflow:examples/sec: 1.7918\n",
            "I1031 19:02:37.302936 140537919225600 tpu_estimator.py:2403] examples/sec: 1.7918\n",
            "INFO:tensorflow:\t Loss  = 5.7880545, \t Step  = 13 (40.200 sec)\n",
            "I1031 19:02:50.868343 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.7880545, \t Step  = 13 (40.200 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0737113\n",
            "I1031 19:02:50.869132 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0737113\n",
            "INFO:tensorflow:examples/sec: 1.76907\n",
            "I1031 19:02:50.869492 140537919225600 tpu_estimator.py:2403] examples/sec: 1.76907\n",
            "INFO:tensorflow:global_step/sec: 0.0745595\n",
            "I1031 19:03:04.281528 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0745595\n",
            "INFO:tensorflow:examples/sec: 1.78943\n",
            "I1031 19:03:04.281992 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78943\n",
            "WARNING:tensorflow:It seems that global step (tf.train.get_global_step) has not been increased. Current value (could be stable): 13 vs previous value: 13. You could increase the global step by passing tf.train.get_global_step() to Optimizer.apply_gradients or Optimizer.minimize.\n",
            "W1031 19:03:04.282115 140537919225600 basic_session_run_hooks.py:734] It seems that global step (tf.train.get_global_step) has not been increased. Current value (could be stable): 13 vs previous value: 13. You could increase the global step by passing tf.train.get_global_step() to Optimizer.apply_gradients or Optimizer.minimize.\n",
            "INFO:tensorflow:global_step/sec: 0.0742298\n",
            "I1031 19:03:17.752972 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0742298\n",
            "INFO:tensorflow:examples/sec: 1.78152\n",
            "I1031 19:03:17.753150 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78152\n",
            "INFO:tensorflow:\t Loss  = 5.74716, \t Step  = 16 (40.207 sec)\n",
            "I1031 19:03:31.075742 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.74716, \t Step  = 16 (40.207 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.075054\n",
            "I1031 19:03:31.076658 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.075054\n",
            "INFO:tensorflow:examples/sec: 1.8013\n",
            "I1031 19:03:31.076882 140537919225600 tpu_estimator.py:2403] examples/sec: 1.8013\n",
            "INFO:tensorflow:global_step/sec: 0.0743527\n",
            "I1031 19:03:44.526340 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0743527\n",
            "INFO:tensorflow:examples/sec: 1.78447\n",
            "I1031 19:03:44.527091 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78447\n",
            "WARNING:tensorflow:It seems that global step (tf.train.get_global_step) has not been increased. Current value (could be stable): 16 vs previous value: 16. You could increase the global step by passing tf.train.get_global_step() to Optimizer.apply_gradients or Optimizer.minimize.\n",
            "W1031 19:03:44.527207 140537919225600 basic_session_run_hooks.py:734] It seems that global step (tf.train.get_global_step) has not been increased. Current value (could be stable): 16 vs previous value: 16. You could increase the global step by passing tf.train.get_global_step() to Optimizer.apply_gradients or Optimizer.minimize.\n",
            "INFO:tensorflow:global_step/sec: 0.0737393\n",
            "I1031 19:03:58.087387 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0737393\n",
            "INFO:tensorflow:examples/sec: 1.76974\n",
            "I1031 19:03:58.087767 140537919225600 tpu_estimator.py:2403] examples/sec: 1.76974\n",
            "INFO:tensorflow:\t Loss  = 5.7036123, \t Step  = 19 (40.419 sec)\n",
            "I1031 19:04:11.494781 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.7036123, \t Step  = 19 (40.419 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.07458\n",
            "I1031 19:04:11.495748 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.07458\n",
            "INFO:tensorflow:examples/sec: 1.78992\n",
            "I1031 19:04:11.496037 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78992\n",
            "INFO:tensorflow:global_step/sec: 0.0758017\n",
            "I1031 19:04:24.689176 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0758017\n",
            "INFO:tensorflow:examples/sec: 1.81924\n",
            "I1031 19:04:24.690609 140537919225600 tpu_estimator.py:2403] examples/sec: 1.81924\n",
            "INFO:tensorflow:global_step/sec: 0.0741041\n",
            "I1031 19:04:38.182681 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0741041\n",
            "INFO:tensorflow:examples/sec: 1.7785\n",
            "I1031 19:04:38.183121 140537919225600 tpu_estimator.py:2403] examples/sec: 1.7785\n",
            "INFO:tensorflow:\t Loss  = 5.6267233, \t Step  = 22 (39.924 sec)\n",
            "I1031 19:04:51.418498 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.6267233, \t Step  = 22 (39.924 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0755477\n",
            "I1031 19:04:51.419223 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0755477\n",
            "INFO:tensorflow:examples/sec: 1.81315\n",
            "I1031 19:04:51.419424 140537919225600 tpu_estimator.py:2403] examples/sec: 1.81315\n",
            "INFO:tensorflow:global_step/sec: 0.0747433\n",
            "I1031 19:05:04.799142 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0747433\n",
            "INFO:tensorflow:examples/sec: 1.79384\n",
            "I1031 19:05:04.799892 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79384\n",
            "INFO:tensorflow:global_step/sec: 0.0740254\n",
            "I1031 19:05:18.307303 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0740254\n",
            "INFO:tensorflow:examples/sec: 1.77661\n",
            "I1031 19:05:18.307618 140537919225600 tpu_estimator.py:2403] examples/sec: 1.77661\n",
            "INFO:tensorflow:\t Loss  = 5.5229807, \t Step  = 25 (40.387 sec)\n",
            "I1031 19:05:31.805741 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.5229807, \t Step  = 25 (40.387 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0740784\n",
            "I1031 19:05:31.806452 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0740784\n",
            "INFO:tensorflow:examples/sec: 1.77788\n",
            "I1031 19:05:31.806648 140537919225600 tpu_estimator.py:2403] examples/sec: 1.77788\n",
            "INFO:tensorflow:global_step/sec: 0.0753578\n",
            "I1031 19:05:45.076801 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0753578\n",
            "INFO:tensorflow:examples/sec: 1.80859\n",
            "I1031 19:05:45.077491 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80859\n"
          ]
        },
        {
          "name": "stdout",
          "output_type": "stream",
          "text": [
            "INFO:tensorflow:global_step/sec: 0.0738676\n",
            "I1031 19:05:58.614260 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0738676\n",
            "INFO:tensorflow:examples/sec: 1.77282\n",
            "I1031 19:05:58.614543 140537919225600 tpu_estimator.py:2403] examples/sec: 1.77282\n",
            "INFO:tensorflow:\t Loss  = 5.538436, \t Step  = 28 (40.215 sec)\n",
            "I1031 19:06:12.021176 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.538436, \t Step  = 28 (40.215 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0745841\n",
            "I1031 19:06:12.021905 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0745841\n",
            "INFO:tensorflow:examples/sec: 1.79002\n",
            "I1031 19:06:12.022136 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79002\n",
            "INFO:tensorflow:global_step/sec: 0.074834\n",
            "I1031 19:06:25.385033 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.074834\n",
            "INFO:tensorflow:examples/sec: 1.79602\n",
            "I1031 19:06:25.385593 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79602\n",
            "INFO:tensorflow:global_step/sec: 0.0744085\n",
            "I1031 19:06:38.824194 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0744085\n",
            "INFO:tensorflow:examples/sec: 1.7858\n",
            "I1031 19:06:38.824493 140537919225600 tpu_estimator.py:2403] examples/sec: 1.7858\n",
            "INFO:tensorflow:\t Loss  = 5.5118847, \t Step  = 31 (40.081 sec)\n",
            "I1031 19:06:52.101892 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.5118847, \t Step  = 31 (40.081 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0753099\n",
            "I1031 19:06:52.102617 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0753099\n",
            "INFO:tensorflow:examples/sec: 1.80744\n",
            "I1031 19:06:52.102824 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80744\n",
            "INFO:tensorflow:global_step/sec: 0.0743031\n",
            "I1031 19:07:05.561285 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0743031\n",
            "INFO:tensorflow:examples/sec: 1.78327\n",
            "I1031 19:07:05.561884 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78327\n",
            "INFO:tensorflow:global_step/sec: 0.0741364\n",
            "I1031 19:07:19.049714 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0741364\n",
            "INFO:tensorflow:examples/sec: 1.77927\n",
            "I1031 19:07:19.050018 140537919225600 tpu_estimator.py:2403] examples/sec: 1.77927\n",
            "INFO:tensorflow:\t Loss  = 5.460881, \t Step  = 34 (40.303 sec)\n",
            "I1031 19:07:32.405147 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.460881, \t Step  = 34 (40.303 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0748715\n",
            "I1031 19:07:32.405874 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0748715\n",
            "INFO:tensorflow:examples/sec: 1.79692\n",
            "I1031 19:07:32.406076 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79692\n",
            "INFO:tensorflow:global_step/sec: 0.0737529\n",
            "I1031 19:07:45.965172 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0737529\n",
            "INFO:tensorflow:examples/sec: 1.77007\n",
            "I1031 19:07:45.966041 140537919225600 tpu_estimator.py:2403] examples/sec: 1.77007\n",
            "INFO:tensorflow:global_step/sec: 0.0742982\n",
            "I1031 19:07:59.424115 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0742982\n",
            "INFO:tensorflow:examples/sec: 1.78316\n",
            "I1031 19:07:59.424641 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78316\n",
            "INFO:tensorflow:\t Loss  = 5.3644495, \t Step  = 37 (40.475 sec)\n",
            "I1031 19:08:12.879788 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.3644495, \t Step  = 37 (40.475 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0743089\n",
            "I1031 19:08:12.881400 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0743089\n",
            "INFO:tensorflow:examples/sec: 1.78341\n",
            "I1031 19:08:12.881708 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78341\n",
            "INFO:tensorflow:global_step/sec: 0.0750323\n",
            "I1031 19:08:26.208865 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0750323\n",
            "INFO:tensorflow:examples/sec: 1.80078\n",
            "I1031 19:08:26.209128 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80078\n",
            "INFO:tensorflow:global_step/sec: 0.0749506\n",
            "I1031 19:08:39.550990 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0749506\n",
            "INFO:tensorflow:examples/sec: 1.79881\n",
            "I1031 19:08:39.551243 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79881\n",
            "INFO:tensorflow:\t Loss  = 5.371481, \t Step  = 40 (40.023 sec)\n",
            "I1031 19:08:52.902822 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.371481, \t Step  = 40 (40.023 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0748878\n",
            "I1031 19:08:52.904419 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0748878\n",
            "INFO:tensorflow:examples/sec: 1.79731\n",
            "I1031 19:08:52.904549 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79731\n",
            "INFO:tensorflow:global_step/sec: 0.0751006\n",
            "I1031 19:09:06.219770 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0751006\n",
            "INFO:tensorflow:examples/sec: 1.80242\n",
            "I1031 19:09:06.220047 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80242\n",
            "INFO:tensorflow:global_step/sec: 0.0744349\n",
            "I1031 19:09:19.654335 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0744349\n",
            "INFO:tensorflow:examples/sec: 1.78644\n",
            "I1031 19:09:19.654605 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78644\n",
            "INFO:tensorflow:\t Loss  = 5.2711782, \t Step  = 43 (40.106 sec)\n",
            "I1031 19:09:33.008702 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.2711782, \t Step  = 43 (40.106 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0748732\n",
            "I1031 19:09:33.010662 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0748732\n",
            "INFO:tensorflow:examples/sec: 1.79696\n",
            "I1031 19:09:33.010931 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79696\n",
            "INFO:tensorflow:global_step/sec: 0.074549\n",
            "I1031 19:09:46.424262 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.074549\n",
            "INFO:tensorflow:examples/sec: 1.78918\n",
            "I1031 19:09:46.424581 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78918\n",
            "INFO:tensorflow:global_step/sec: 0.0743965\n",
            "I1031 19:09:59.865720 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0743965\n",
            "INFO:tensorflow:examples/sec: 1.78552\n",
            "I1031 19:09:59.866062 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78552\n",
            "INFO:tensorflow:\t Loss  = 5.136049, \t Step  = 46 (40.154 sec)\n",
            "I1031 19:10:13.162661 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.136049, \t Step  = 46 (40.154 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0751968\n",
            "I1031 19:10:13.164284 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0751968\n",
            "INFO:tensorflow:examples/sec: 1.80472\n",
            "I1031 19:10:13.164594 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80472\n",
            "INFO:tensorflow:global_step/sec: 0.075217\n",
            "I1031 19:10:26.459038 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.075217\n",
            "INFO:tensorflow:examples/sec: 1.80521\n",
            "I1031 19:10:26.459322 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80521\n",
            "INFO:tensorflow:global_step/sec: 0.0750064\n",
            "I1031 19:10:39.791325 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0750064\n",
            "INFO:tensorflow:examples/sec: 1.80015\n",
            "I1031 19:10:39.791628 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80015\n",
            "INFO:tensorflow:\t Loss  = 5.1063886, \t Step  = 49 (39.804 sec)\n",
            "I1031 19:10:52.966849 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.1063886, \t Step  = 49 (39.804 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0758924\n",
            "I1031 19:10:52.968214 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0758924\n",
            "INFO:tensorflow:examples/sec: 1.82142\n",
            "I1031 19:10:52.968464 140537919225600 tpu_estimator.py:2403] examples/sec: 1.82142\n",
            "INFO:tensorflow:Calling checkpoint listeners before saving checkpoint 50...\n",
            "I1031 19:11:06.132069 140537919225600 basic_session_run_hooks.py:614] Calling checkpoint listeners before saving checkpoint 50...\n",
            "INFO:tensorflow:Saving checkpoints for 50 into /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/model.ckpt.\n",
            "I1031 19:11:06.132256 140537919225600 basic_session_run_hooks.py:618] Saving checkpoints for 50 into /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/model.ckpt.\n",
            "WARNING:tensorflow:From /opt/intel/oneapi/intelpython/latest/envs/tensorflow/lib/python3.7/site-packages/tensorflow/python/training/saver.py:971: remove_checkpoint (from tensorflow.python.training.checkpoint_management) is deprecated and will be removed in a future version.\n",
            "Instructions for updating:\n",
            "Use standard file APIs to delete files with this prefix.\n",
            "W1031 19:11:09.895852 140537919225600 deprecation.py:336] From /opt/intel/oneapi/intelpython/latest/envs/tensorflow/lib/python3.7/site-packages/tensorflow/python/training/saver.py:971: remove_checkpoint (from tensorflow.python.training.checkpoint_management) is deprecated and will be removed in a future version.\n",
            "Instructions for updating:\n",
            "Use standard file APIs to delete files with this prefix.\n"
          ]
        },
        {
          "name": "stdout",
          "output_type": "stream",
          "text": [
            "INFO:tensorflow:Calling checkpoint listeners after saving checkpoint 50...\n",
            "I1031 19:11:12.664677 140537919225600 basic_session_run_hooks.py:626] Calling checkpoint listeners after saving checkpoint 50...\n",
            "INFO:tensorflow:global_step/sec: 0.0507644\n",
            "I1031 19:11:12.677465 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0507644\n",
            "INFO:tensorflow:examples/sec: 1.21835\n",
            "I1031 19:11:12.677664 140537919225600 tpu_estimator.py:2403] examples/sec: 1.21835\n",
            "INFO:tensorflow:global_step/sec: 0.0738109\n",
            "I1031 19:11:26.214749 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0738109\n",
            "INFO:tensorflow:examples/sec: 1.77146\n",
            "I1031 19:11:26.214953 140537919225600 tpu_estimator.py:2403] examples/sec: 1.77146\n",
            "INFO:tensorflow:\t Loss  = 5.108763, \t Step  = 52 (46.314 sec)\n",
            "I1031 19:11:39.280578 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.108763, \t Step  = 52 (46.314 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0765258\n",
            "I1031 19:11:39.282430 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0765258\n",
            "INFO:tensorflow:examples/sec: 1.83662\n",
            "I1031 19:11:39.282578 140537919225600 tpu_estimator.py:2403] examples/sec: 1.83662\n",
            "INFO:tensorflow:global_step/sec: 0.0755138\n",
            "I1031 19:11:52.524892 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0755138\n",
            "INFO:tensorflow:examples/sec: 1.81233\n",
            "I1031 19:11:52.525350 140537919225600 tpu_estimator.py:2403] examples/sec: 1.81233\n",
            "INFO:tensorflow:global_step/sec: 0.0745451\n",
            "I1031 19:12:05.939587 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0745451\n",
            "INFO:tensorflow:examples/sec: 1.78908\n",
            "I1031 19:12:05.940215 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78908\n",
            "INFO:tensorflow:\t Loss  = 5.052855, \t Step  = 55 (39.982 sec)\n",
            "I1031 19:12:19.262746 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.052855, \t Step  = 55 (39.982 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0750486\n",
            "I1031 19:12:19.264403 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0750486\n",
            "INFO:tensorflow:examples/sec: 1.80117\n",
            "I1031 19:12:19.264723 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80117\n",
            "INFO:tensorflow:global_step/sec: 0.0748836\n",
            "I1031 19:12:32.618301 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0748836\n",
            "INFO:tensorflow:examples/sec: 1.79721\n",
            "I1031 19:12:32.618571 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79721\n",
            "INFO:tensorflow:global_step/sec: 0.075476\n",
            "I1031 19:12:45.867562 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.075476\n",
            "INFO:tensorflow:examples/sec: 1.81142\n",
            "I1031 19:12:45.867833 140537919225600 tpu_estimator.py:2403] examples/sec: 1.81142\n",
            "INFO:tensorflow:\t Loss  = 4.965616, \t Step  = 58 (39.994 sec)\n",
            "I1031 19:12:59.256456 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 4.965616, \t Step  = 58 (39.994 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0746713\n",
            "I1031 19:12:59.260166 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0746713\n",
            "INFO:tensorflow:examples/sec: 1.79211\n",
            "I1031 19:12:59.260737 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79211\n",
            "INFO:tensorflow:global_step/sec: 0.0746184\n",
            "I1031 19:13:12.661108 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0746184\n",
            "INFO:tensorflow:examples/sec: 1.79084\n",
            "I1031 19:13:12.661542 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79084\n",
            "INFO:tensorflow:global_step/sec: 0.0747699\n",
            "I1031 19:13:26.035648 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0747699\n",
            "INFO:tensorflow:examples/sec: 1.79448\n",
            "I1031 19:13:26.036168 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79448\n",
            "INFO:tensorflow:\t Loss  = 4.7593803, \t Step  = 61 (40.430 sec)\n",
            "I1031 19:13:39.686251 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 4.7593803, \t Step  = 61 (40.430 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0732481\n",
            "I1031 19:13:39.687828 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0732481\n",
            "INFO:tensorflow:examples/sec: 1.75795\n",
            "I1031 19:13:39.688092 140537919225600 tpu_estimator.py:2403] examples/sec: 1.75795\n",
            "INFO:tensorflow:global_step/sec: 0.0755059\n",
            "I1031 19:13:52.931721 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0755059\n",
            "INFO:tensorflow:examples/sec: 1.81214\n",
            "I1031 19:13:52.932008 140537919225600 tpu_estimator.py:2403] examples/sec: 1.81214\n",
            "INFO:tensorflow:global_step/sec: 0.0744074\n",
            "I1031 19:14:06.371235 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0744074\n",
            "INFO:tensorflow:examples/sec: 1.78578\n",
            "I1031 19:14:06.371499 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78578\n",
            "INFO:tensorflow:\t Loss  = 4.9382877, \t Step  = 64 (39.991 sec)\n",
            "I1031 19:14:19.677085 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 4.9382877, \t Step  = 64 (39.991 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0751469\n",
            "I1031 19:14:19.678641 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0751469\n",
            "INFO:tensorflow:examples/sec: 1.80353\n",
            "I1031 19:14:19.678931 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80353\n",
            "INFO:tensorflow:global_step/sec: 0.0737284\n",
            "I1031 19:14:33.241795 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0737284\n",
            "INFO:tensorflow:examples/sec: 1.76948\n",
            "I1031 19:14:33.242054 140537919225600 tpu_estimator.py:2403] examples/sec: 1.76948\n",
            "INFO:tensorflow:global_step/sec: 0.0752542\n",
            "I1031 19:14:46.530123 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0752542\n",
            "INFO:tensorflow:examples/sec: 1.8061\n",
            "I1031 19:14:46.530407 140537919225600 tpu_estimator.py:2403] examples/sec: 1.8061\n",
            "INFO:tensorflow:\t Loss  = 4.9799604, \t Step  = 67 (40.218 sec)\n",
            "I1031 19:14:59.894602 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 4.9799604, \t Step  = 67 (40.218 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0748172\n",
            "I1031 19:14:59.896129 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0748172\n",
            "INFO:tensorflow:examples/sec: 1.79561\n",
            "I1031 19:14:59.896398 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79561\n",
            "INFO:tensorflow:global_step/sec: 0.0751849\n",
            "I1031 19:15:13.196741 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0751849\n",
            "INFO:tensorflow:examples/sec: 1.80444\n",
            "I1031 19:15:13.197245 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80444\n",
            "INFO:tensorflow:global_step/sec: 0.0743758\n",
            "I1031 19:15:26.642293 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0743758\n",
            "INFO:tensorflow:examples/sec: 1.78502\n",
            "I1031 19:15:26.642966 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78502\n",
            "INFO:tensorflow:\t Loss  = 4.845747, \t Step  = 70 (40.038 sec)\n",
            "I1031 19:15:39.932459 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 4.845747, \t Step  = 70 (40.038 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.075233\n",
            "I1031 19:15:39.934005 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.075233\n",
            "INFO:tensorflow:examples/sec: 1.80559\n",
            "I1031 19:15:39.934406 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80559\n",
            "INFO:tensorflow:global_step/sec: 0.0747266\n",
            "I1031 19:15:53.316126 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0747266\n",
            "INFO:tensorflow:examples/sec: 1.79344\n",
            "I1031 19:15:53.316560 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79344\n",
            "INFO:tensorflow:global_step/sec: 0.0746584\n",
            "I1031 19:16:06.710533 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0746584\n",
            "INFO:tensorflow:examples/sec: 1.7918\n",
            "I1031 19:16:06.710945 140537919225600 tpu_estimator.py:2403] examples/sec: 1.7918\n",
            "INFO:tensorflow:\t Loss  = 4.775161, \t Step  = 73 (40.017 sec)\n",
            "I1031 19:16:19.949261 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 4.775161, \t Step  = 73 (40.017 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0755304\n",
            "I1031 19:16:19.949978 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0755304\n",
            "INFO:tensorflow:examples/sec: 1.81273\n",
            "I1031 19:16:19.950204 140537919225600 tpu_estimator.py:2403] examples/sec: 1.81273\n",
            "INFO:tensorflow:global_step/sec: 0.0749826\n",
            "I1031 19:16:33.286589 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0749826\n",
            "INFO:tensorflow:examples/sec: 1.79958\n",
            "I1031 19:16:33.287080 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79958\n",
            "INFO:tensorflow:global_step/sec: 0.0747383\n",
            "I1031 19:16:46.666735 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0747383\n",
            "INFO:tensorflow:examples/sec: 1.79372\n",
            "I1031 19:16:46.667402 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79372\n",
            "INFO:tensorflow:\t Loss  = 4.7404146, \t Step  = 76 (40.160 sec)\n",
            "I1031 19:17:00.109490 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 4.7404146, \t Step  = 76 (40.160 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0743839\n",
            "I1031 19:17:00.110200 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0743839\n",
            "INFO:tensorflow:examples/sec: 1.78521\n",
            "I1031 19:17:00.110392 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78521\n"
          ]
        },
        {
          "name": "stdout",
          "output_type": "stream",
          "text": [
            "INFO:tensorflow:global_step/sec: 0.0746215\n",
            "I1031 19:17:13.511189 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0746215\n",
            "INFO:tensorflow:examples/sec: 1.79092\n",
            "I1031 19:17:13.511489 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79092\n",
            "INFO:tensorflow:global_step/sec: 0.0745354\n",
            "I1031 19:17:26.927915 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0745354\n",
            "INFO:tensorflow:examples/sec: 1.78885\n",
            "I1031 19:17:26.928602 140537919225600 tpu_estimator.py:2403] examples/sec: 1.78885\n",
            "INFO:tensorflow:\t Loss  = 4.8659067, \t Step  = 79 (40.402 sec)\n",
            "I1031 19:17:40.511939 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 4.8659067, \t Step  = 79 (40.402 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0736104\n",
            "I1031 19:17:40.512654 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0736104\n",
            "INFO:tensorflow:examples/sec: 1.76665\n",
            "I1031 19:17:40.512849 140537919225600 tpu_estimator.py:2403] examples/sec: 1.76665\n",
            "INFO:tensorflow:global_step/sec: 0.0751762\n",
            "I1031 19:17:53.814895 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0751762\n",
            "INFO:tensorflow:examples/sec: 1.80423\n",
            "I1031 19:17:53.815383 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80423\n",
            "INFO:tensorflow:global_step/sec: 0.0746576\n",
            "I1031 19:18:07.209447 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0746576\n",
            "INFO:tensorflow:examples/sec: 1.79178\n",
            "I1031 19:18:07.210040 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79178\n",
            "INFO:tensorflow:\t Loss  = 5.0739765, \t Step  = 82 (40.021 sec)\n",
            "I1031 19:18:20.532963 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 5.0739765, \t Step  = 82 (40.021 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0750473\n",
            "I1031 19:18:20.534301 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0750473\n",
            "INFO:tensorflow:examples/sec: 1.80114\n",
            "I1031 19:18:20.534699 140537919225600 tpu_estimator.py:2403] examples/sec: 1.80114\n",
            "INFO:tensorflow:global_step/sec: 0.0746282\n",
            "I1031 19:18:33.933968 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0746282\n",
            "INFO:tensorflow:examples/sec: 1.79108\n",
            "I1031 19:18:33.934270 140537919225600 tpu_estimator.py:2403] examples/sec: 1.79108\n",
            "INFO:tensorflow:global_step/sec: 0.0762145\n",
            "I1031 19:18:47.054999 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0762145\n",
            "INFO:tensorflow:examples/sec: 1.82915\n",
            "I1031 19:18:47.055573 140537919225600 tpu_estimator.py:2403] examples/sec: 1.82915\n",
            "INFO:tensorflow:\t Loss  = 4.770326, \t Step  = 85 (40.079 sec)\n",
            "I1031 19:19:00.612168 140537919225600 basic_session_run_hooks.py:260] \t Loss  = 4.770326, \t Step  = 85 (40.079 sec)\n",
            "INFO:tensorflow:global_step/sec: 0.0737573\n",
            "I1031 19:19:00.612745 140537919225600 tpu_estimator.py:2402] global_step/sec: 0.0737573\n",
            "INFO:tensorflow:examples/sec: 1.77017\n",
            "I1031 19:19:00.612930 140537919225600 tpu_estimator.py:2403] examples/sec: 1.77017\n",
            "INFO:tensorflow:Calling checkpoint listeners before saving checkpoint 85...\n",
            "I1031 19:19:00.613240 140537919225600 basic_session_run_hooks.py:614] Calling checkpoint listeners before saving checkpoint 85...\n",
            "INFO:tensorflow:Saving checkpoints for 85 into /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/model.ckpt.\n",
            "I1031 19:19:00.613308 140537919225600 basic_session_run_hooks.py:618] Saving checkpoints for 85 into /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/model.ckpt.\n",
            "INFO:tensorflow:Calling checkpoint listeners after saving checkpoint 85...\n",
            "I1031 19:19:07.228856 140537919225600 basic_session_run_hooks.py:626] Calling checkpoint listeners after saving checkpoint 85...\n",
            "INFO:tensorflow:Loss for final step: 4.770326.\n",
            "I1031 19:19:07.860724 140537919225600 estimator.py:350] Loss for final step: 4.770326.\n",
            "INFO:tensorflow:training_loop marked as finished\n",
            "I1031 19:19:07.861308 140537919225600 error_handling.py:115] training_loop marked as finished\n",
            "INFO:tensorflow:Total Training Time:1280.5504348278046\n",
            "I1031 19:19:07.861386 140537919225600 run_squad.py:1464] Total Training Time:1280.5504348278046\n",
            "INFO:tensorflow:***** Running predictions *****\n",
            "I1031 19:19:11.496114 140537919225600 run_squad.py:1491] ***** Running predictions *****\n",
            "INFO:tensorflow:  Num orig examples = 1680\n",
            "I1031 19:19:11.496287 140537919225600 run_squad.py:1492]   Num orig examples = 1680\n",
            "INFO:tensorflow:  Num split examples = 1703\n",
            "I1031 19:19:11.496336 140537919225600 run_squad.py:1493]   Num split examples = 1703\n",
            "INFO:tensorflow:  Batch size = 8\n",
            "I1031 19:19:11.496384 140537919225600 run_squad.py:1494]   Batch size = 8\n",
            "INFO:tensorflow:Calling model_fn.\n",
            "I1031 19:19:11.523006 140537919225600 estimator.py:1162] Calling model_fn.\n",
            "INFO:tensorflow:Running infer on CPU/GPU\n",
            "I1031 19:19:11.523217 140537919225600 tpu_estimator.py:3198] Running infer on CPU/GPU\n",
            "INFO:tensorflow:Done calling model_fn.\n",
            "I1031 19:19:17.490505 140537919225600 estimator.py:1164] Done calling model_fn.\n",
            "INFO:tensorflow:Graph was finalized.\n",
            "I1031 19:19:18.286080 140537919225600 monitored_session.py:247] Graph was finalized.\n",
            "INFO:tensorflow:Restoring parameters from /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/model.ckpt-85\n",
            "I1031 19:19:18.286481 140537919225600 saver.py:1298] Restoring parameters from /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/model.ckpt-85\n",
            "INFO:tensorflow:Running local_init_op.\n",
            "I1031 19:19:19.658776 140537919225600 session_manager.py:531] Running local_init_op.\n",
            "INFO:tensorflow:Done running local_init_op.\n",
            "I1031 19:19:19.710041 140537919225600 session_manager.py:534] Done running local_init_op.\n",
            "INFO:tensorflow:Processing example: 0\n",
            "I1031 19:19:23.787974 140537919225600 run_squad.py:1509] Processing example: 0\n",
            "INFO:tensorflow:Processing example: 1000\n",
            "I1031 19:23:11.200668 140537919225600 run_squad.py:1509] Processing example: 1000\n",
            "INFO:tensorflow:prediction_loop marked as finished\n",
            "I1031 19:25:48.420168 140537919225600 error_handling.py:115] prediction_loop marked as finished\n",
            "INFO:tensorflow:prediction_loop marked as finished\n",
            "I1031 19:25:48.420504 140537919225600 error_handling.py:115] prediction_loop marked as finished\n",
            "INFO:tensorflow:Total Evaluation Time: 396.9241063594818, Average Thoughput: 4.290492748398723\n",
            "I1031 19:25:48.420686 140537919225600 run_squad.py:1524] Total Evaluation Time: 396.9241063594818, Average Thoughput: 4.290492748398723\n",
            "INFO:tensorflow:Writing predictions to: /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/predictions.json\n",
            "I1031 19:25:48.420753 140537919225600 run_squad.py:838] Writing predictions to: /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/predictions.json\n",
            "INFO:tensorflow:Writing nbest to: /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/nbest_predictions.json\n",
            "I1031 19:25:48.420806 140537919225600 run_squad.py:839] Writing nbest to: /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/nbest_predictions.json\n",
            "INFO:tensorflow:exact_match: 2.5595238095238093, f1: 9.091953263048236\n",
            "I1031 19:25:54.795833 140537919225600 run_squad.py:1536] exact_match: 2.5595238095238093, f1: 9.091953263048236\n",
            "INFO:tensorflow:Total Time:1687.907425403595\n",
            "I1031 19:25:54.796309 140537919225600 run_squad.py:1542] Total Time:1687.907425403595\n",
            "is_mpi:1, rank:0\n",
            "INFO:Running SQuAD...!\n",
            "----------------------------Run command-------------------------------------\n",
            "/opt/intel/oneapi/intelpython/latest/envs/tensorflow/bin//python /home/vmagent/app/e2eaiok/modelzoo/bert/benchmarks/../models/language_modeling/tensorflow/bert_large/training/fp32/run_squad.py \\\n",
            " --output_dir=/home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d \\\n",
            " --bert_config_file=/home/vmagent/app/dataset/SQuAD/pre-trained-model/bert-large-uncased/wwm_uncased_L-24_H-1024_A-16/bert_config.json \\\n",
            " --do_train=True \\\n",
            " --train_batch_size=24 \\\n",
            " --accum_steps=1 \\\n",
            " --learning_rate=3e-05 \\\n",
            " --max_seq_length=384 \\\n",
            " --use_tpu=False \\\n",
            " --precision=fp32 \\\n",
            " --intra_op_parallelism_threads=36 \\\n",
            " --inter_op_parallelism_threads=2 \\\n",
            " --profile=False \\\n",
            " --do_lower_case=True \\\n",
            " --experimental_gelu=False \\\n",
            " --mpi_workers_sync_gradients=False \\\n",
            "--num_hidden_layers=24 \\\n",
            "--attention_probs_dropout_prob=0.1 \\\n",
            "--hidden_dropout_prob=0.1 \\\n",
            " --vocab_file=/home/vmagent/app/dataset/SQuAD/pre-trained-model/bert-large-uncased/wwm_uncased_L-24_H-1024_A-16/vocab.txt \\\n",
            " --train_file=/home/vmagent/app/dataset/SQuAD/train-v1.1.json \\\n",
            " --predict_file=/home/vmagent/app/dataset/SQuAD/dev-v1.1.json \\\n",
            " --do_predict=True \\\n",
            " --num_train_epochs=2.0 \\\n",
            " --init_checkpoint=/home/vmagent/app/dataset/SQuAD/pre-trained-model/bert-large-uncased/wwm_uncased_L-24_H-1024_A-16/bert_model.ckpt \\\n",
            " --doc_stride=128 \\\n",
            " --data_dir=/home/vmagent/app/dataset/SQuAD \\\n",
            " --test_file=/home/vmagent/app/dataset/SQuAD/test-v1.1.json \\\n",
            " --num_to_evaluate=50 \\\n",
            " --f1_threshold=90.87 \\\n",
            " --step_threshold=100000\n",
            "\n",
            "------------------------------------------------------------------------\n",
            "Ran training with batch size 24\n",
            "Log file location: /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d/benchmark_bert_large_training_fp32_20221031_185744.log\n"
          ]
        },
        {
          "name": "stdout",
          "output_type": "stream",
          "text": [
            "2022-10-31 19:25:57,309 - sigopt - INFO - Training completed based in sigopt suggestion, took 1687.907425403595 secs\r\n",
            "2022-10-31 19:25:57,310 - E2EAIOK.SDA - INFO - training script completed\r\n",
            "\r\n",
            "We found the best model! Here is the model explaination\r\n",
            "\r\n",
            "===============================================\r\n",
            "***    Best Trained Model    ***\r\n",
            "===============================================\r\n",
            "  Model Type: bert\r\n",
            "  Model Saved Path: /home/vmagent/app/e2eaiok/result/1526042db72aeb23ba4ab6ddd4d4074d\r\n",
            "  Sigopt Experiment id is None\r\n",
            "  === Result Metrics ===\r\n",
            "    f1: 9.091953263048236\r\n",
            "    training_time: 1687.907425403595\r\n",
            "===============================================\r\n"
          ]
        }
      ],
      "source": [
        "import os\n",
        "from e2eAIOK.SDA.SDA import SDA\n",
        "\n",
        "settings = dict()\n",
        "settings[\"train_script\"] = os.path.join(os.getcwd(), \"e2eaiok/modelzoo/bert/benchmarks/launch_benchmark.py\")\n",
        "settings[\"current_path\"] = os.path.join(os.getcwd(), \"e2eaiok\")\n",
        "settings[\"data_path\"] = \"/home/vmagent/app/dataset/SQuAD/\"\n",
        "settings[\"train_dataset_path\"] = \"/home/vmagent/app/dataset/SQuAD/\"\n",
        "settings[\"data_path\"] = \"/home/vmagent/app/dataset/SQuAD/\"\n",
        "settings[\"mpi_num_processes\"] = 1\n",
        "settings[\"enable_sigopt\"] = False\n",
        "settings[\"python_path\"] = \"/opt/intel/oneapi/intelpython/latest/envs/tensorflow/bin\"\n",
        "settings[\"num_epochs\"] = 2\n",
        "settings[\"metric\"] = \"f1\"\n",
        "settings[\"metric_objective\"] = \"maximize\"\n",
        "settings[\"metric_threshold\"] = 90.874\n",
        "settings[\"step_threshold\"] = 100000\n",
        "\n",
        "sda = SDA(model=\"BERT\", settings=settings) # default settings\n",
        "sda.launch()\n",
        "\n",
        "hydro_model = sda.snapshot()\n",
        "hydro_model.explain()"
      ]
    }
  ],
  "metadata": {
    "colab": {
      "include_colab_link": true,
      "provenance": []
    },
    "kernelspec": {
      "display_name": "Python 3 (ipykernel)",
      "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.7.11"
    }
  },
  "nbformat": 4,
  "nbformat_minor": 0
}