From 5ad6193fe60533c2184409325d9b6fdf3f5a2a8d Mon Sep 17 00:00:00 2001
From: ahmedk <karim.ahmed@xfel.eu>
Date: Tue, 24 Oct 2023 16:42:39 +0200
Subject: [PATCH 1/3] use step time with most of cells

---
 .../Characterize_AGIPD_Gain_Darks_NBC.ipynb   | 56 ++++++++++++++++---
 1 file changed, 47 insertions(+), 9 deletions(-)

diff --git a/notebooks/AGIPD/Characterize_AGIPD_Gain_Darks_NBC.ipynb b/notebooks/AGIPD/Characterize_AGIPD_Gain_Darks_NBC.ipynb
index 36d88640f..913498240 100644
--- a/notebooks/AGIPD/Characterize_AGIPD_Gain_Darks_NBC.ipynb
+++ b/notebooks/AGIPD/Characterize_AGIPD_Gain_Darks_NBC.ipynb
@@ -110,6 +110,7 @@
     "\n",
     "import iCalibrationDB\n",
     "import matplotlib.pyplot as plt\n",
+    "from cal_tools import step_timing\n",
     "from cal_tools.agipdlib import AgipdCtrlRuns\n",
     "from cal_tools.enums import BadPixels\n",
     "from cal_tools.plotting import (\n",
@@ -185,7 +186,9 @@
     "\n",
     "print(f\"Detector in use is {karabo_id}\")\n",
     "print(f\"Instrument {instrument}\")\n",
-    "print(f\"Detector instance {dinstance}\")"
+    "print(f\"Detector instance {dinstance}\")\n",
+    "\n",
+    "step_timer = step_timing.StepTimer()"
    ]
   },
   {
@@ -194,6 +197,8 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
+    "\n",
     "# Create out_folder if it doesn't exist.\n",
     "Path(out_folder).mkdir(parents=True, exist_ok=True)\n",
     "\n",
@@ -232,7 +237,7 @@
     "modules = [m for m in modules if m not in missing_modules]\n",
     "karabo_da = create_karabo_da_list(modules)\n",
     "\n",
-    "print(f\"Will process data of ({sum(mod_image_size):.02f} GB).\")"
+    "step_timer.done_step(f\"Will process data of ({sum(mod_image_size):.02f} GB).\")"
    ]
   },
   {
@@ -248,6 +253,8 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
+    "\n",
     "# Read slow data from 1st channel only.\n",
     "# Read all modules in one notebook and validate the conditions across detectors?\n",
     "# Currently slurm jobs run per one module.\n",
@@ -282,7 +289,8 @@
     "    gain_setting = agipd_ctrl_dark.get_gain_setting()\n",
     "\n",
     "if integration_time == -1:\n",
-    "    integration_time = agipd_ctrl_dark.get_integration_time()"
+    "    integration_time = agipd_ctrl_dark.get_integration_time()\n",
+    "step_timer.done_step(f\"Read operating conditions.\")"
    ]
   },
   {
@@ -471,10 +479,14 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
+    "\n",
     "with multiprocessing.Pool(processes=parallel_num_procs) as pool:\n",
     "    results = pool.starmap(\n",
     "        characterize_module, itertools.product(modules, list(enumerate(run_numbers))))\n",
     "\n",
+    "step_timer.done_step(\"Processing dark from the 3 runs.\")\n",
+    "\n",
     "# mapped values for processing 2 modules example:\n",
     "# [(0, (0, 9013))\n",
     "#     0, (0, run-high),\n",
@@ -633,6 +645,8 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
+    "\n",
     "md = None\n",
     "\n",
     "for qm in res:\n",
@@ -655,7 +669,9 @@
     "print(f\"• memory_cells: {mem_cells}\\n• bias_voltage: {bias_voltage}\\n\"\n",
     "      f\"• acquisition_rate: {acq_rate}\\n• gain_setting: {gain_setting}\\n\"\n",
     "      f\"• gain_mode: {fixed_gain_mode}\\n• integration_time: {integration_time}\\n\"\n",
-    "      f\"• creation_time: {md.calibration_constant_version.begin_at if md is not None else creation_time}\\n\")"
+    "      f\"• creation_time: {md.calibration_constant_version.begin_at if md is not None else creation_time}\\n\")\\\n",
+    "\n",
+    "step_timer.done_step(\"Inject calibration constants to the database.\")"
    ]
   },
   {
@@ -749,6 +765,8 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
+    "\n",
     "cell = 3\n",
     "gain = 0\n",
     "show_overview(res, cell, gain, infix=\"{}-{}-{}\".format(*run_numbers))"
@@ -787,7 +805,9 @@
    "source": [
     "cell = 3\n",
     "gain = 2\n",
-    "show_overview(res, cell, gain, infix=\"{}-{}-{}\".format(*run_numbers))"
+    "show_overview(res, cell, gain, infix=\"{}-{}-{}\".format(*run_numbers))\n",
+    "\n",
+    "step_timer.done_step(\"Single-Cell Overviews.\")"
    ]
   },
   {
@@ -843,6 +863,8 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
+    "\n",
     "create_constant_overview(offset_g, \"Offset (ADU)\", mem_cells, 4000, 8000,\n",
     "                         badpixels=[badpix_g, np.nan])"
    ]
@@ -875,7 +897,9 @@
     "                             badpixels=[bp_thresh, np.nan],\n",
     "                             gmap=['HG-MG Threshold', 'MG-LG Threshold', 'High gain', 'Medium gain', 'low gain'],\n",
     "                             marker=['d','d','','','']\n",
-    "                             )"
+    "                             )\n",
+    "\n",
+    "step_timer.done_step(\"Aggregate values, and per Cell behaviour.\")"
    ]
   },
   {
@@ -948,9 +972,17 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
+    "\n",
     "table = []\n",
     "gain_names = ['High', 'Medium', 'Low']\n",
-    "bits = [BadPixels.NOISE_OUT_OF_THRESHOLD, BadPixels.OFFSET_OUT_OF_THRESHOLD, BadPixels.OFFSET_NOISE_EVAL_ERROR, BadPixels.GAIN_THRESHOLDING_ERROR]\n",
+    "bits = [\n",
+    "    BadPixels.NOISE_OUT_OF_THRESHOLD,\n",
+    "    BadPixels.OFFSET_OUT_OF_THRESHOLD,\n",
+    "    BadPixels.OFFSET_NOISE_EVAL_ERROR,\n",
+    "    BadPixels.GAIN_THRESHOLDING_ERROR,\n",
+    "]\n",
+    "\n",
     "for qm in badpix_g.keys():\n",
     "    for gain in range(3):\n",
     "        l_data = []\n",
@@ -996,7 +1028,9 @@
     "if len(table)>0:\n",
     "    md = display(Latex(tabulate.tabulate(table, tablefmt='latex',\n",
     "                                         headers=[\"Pixel type\", \"Threshold\",\n",
-    "                                                  \"New constant\", \"Old constant\"])))"
+    "                                                  \"New constant\", \"Old constant\"])))\n",
+    "\n",
+    "step_timer.done_step(\"Create badpixels table.\")"
    ]
   },
   {
@@ -1005,6 +1039,8 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
+    "\n",
     "header = ['Parameter',\n",
     "          \"New constant\", \"Old constant \",\n",
     "          \"New constant\", \"Old constant \",\n",
@@ -1076,7 +1112,9 @@
     "\n",
     "for (const, qm), table in zip(constants_x_qms, tables):\n",
     "    display(Markdown(f\"### {qm}: {const} [ADU], good pixels only\"))\n",
-    "    display(Latex(tabulate.tabulate(table, tablefmt='latex', headers=header)))"
+    "    display(Latex(tabulate.tabulate(table, tablefmt='latex', headers=header)))\n",
+    "\n",
+    "step_timer.done_step(\"Computing comparison tables.\")"
    ]
   }
  ],
-- 
GitLab


From cc7aabe2d4bbc64553f2761045e90c51fb869106 Mon Sep 17 00:00:00 2001
From: ahmedk <karim.ahmed@xfel.eu>
Date: Wed, 25 Oct 2023 09:11:05 +0200
Subject: [PATCH 2/3] Add timings for overall darks summary notebook

---
 .../overallmodules_Darks_Summary_NBC.ipynb    | 33 ++++++++++++++-----
 1 file changed, 25 insertions(+), 8 deletions(-)

diff --git a/notebooks/generic/overallmodules_Darks_Summary_NBC.ipynb b/notebooks/generic/overallmodules_Darks_Summary_NBC.ipynb
index 27e384a37..bb68d8443 100644
--- a/notebooks/generic/overallmodules_Darks_Summary_NBC.ipynb
+++ b/notebooks/generic/overallmodules_Darks_Summary_NBC.ipynb
@@ -49,6 +49,7 @@
     "%matplotlib inline\n",
     "import extra_geom\n",
     "import tabulate\n",
+    "from cal_tools import step_timing\n",
     "from cal_tools.ana_tools import get_range\n",
     "from cal_tools.enums import BadPixels\n",
     "from cal_tools.plotting import show_processed_modules\n",
@@ -220,6 +221,7 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer = step_timing.StepTimer()\n",
     "out_folder = Path(out_folder)\n",
     "metadata = CalibrationMetadata(metadata_folder or out_folder)\n",
     "mod_mapping = metadata.setdefault(\"modules-mapping\", {})\n",
@@ -271,6 +273,7 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
     "# Get shape, dtype, and number of files for each constant.\n",
     "# Also build lists of the files involved, to be loaded in parallel in a later cell.\n",
     "const_shape_and_dtype = {}\n",
@@ -318,7 +321,8 @@
     "prev_const = {\n",
     "    cname: psh.alloc((nmods_found,) + module_const_shape, dtype=dt, fill=0)\n",
     "    for cname, (module_const_shape, dt) in const_shape_and_dtype.items()\n",
-    "}"
+    "}\n",
+    "step_timer.done_step(\"Preparing arrays for old and new constants.\")"
    ]
   },
   {
@@ -327,6 +331,7 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
     "# Load the constant data in parallel\n",
     "found_module_nums = sorted(found_module_nums)\n",
     "mod_names = [module_index_to_qm(n) for n in found_module_nums]\n",
@@ -349,7 +354,8 @@
     "        f[h5path]['data'].read_direct(prev_const[cname][mod_ix])\n",
     "\n",
     "psh.map(load_piece_prev, pieces_to_load_prev)\n",
-    "print(f\"Loaded previous constant data from {len(pieces_to_load_prev)} files\")"
+    "print(f\"Loaded previous constant data from {len(pieces_to_load_prev)} files\")\n",
+    "step_timer.done_step(\"Loading constants data.\")"
    ]
   },
   {
@@ -463,6 +469,8 @@
    },
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
+    "\n",
     "gainstages = 1\n",
     "\n",
     "for const_name, const in constants.items():\n",
@@ -513,7 +521,8 @@
     "\n",
     "        plot_const_and_delta(stacked_const, stacked_delta, const_name, glabel)\n",
     "\n",
-    "        plt.show()"
+    "        plt.show()\n",
+    "step_timer.done_step(\"Plotting constants and relative differences.\")"
    ]
   },
   {
@@ -525,6 +534,7 @@
    "outputs": [],
    "source": [
     "# Loop over modules and constants\n",
+    "step_timer.start()\n",
     "for const_name, const in constants.items():\n",
     "    if const_name == 'BadPixelsDark':\n",
     "        continue  # Displayed separately below\n",
@@ -609,7 +619,8 @@
     "                            legend='outside-top-ncol6-frame', legend_size='18%',\n",
     "                            legend_pad=0.00)\n",
     "\n",
-    "        plt.show()"
+    "        plt.show()\n",
+    "step_timer.done_step(\"Plotting summary across modules.\")"
    ]
   },
   {
@@ -619,6 +630,7 @@
    "outputs": [],
    "source": [
     "if 'BadPixelsDark' in constants:\n",
+    "    step_timer.start()\n",
     "    display(Markdown(f'### Summary across Modules - BadPixelsDark'))\n",
     "\n",
     "    bad_px_dark = constants['BadPixelsDark']\n",
@@ -656,7 +668,8 @@
     "                            legend='outside-top-ncol6-frame', legend_size='18%',\n",
     "                            legend_pad=0.00)\n",
     "\n",
-    "        plt.show()"
+    "        plt.show()\n",
+    "    step_timer.done_step(\"Summary across modules for BadPixels.\")"
    ]
   },
   {
@@ -687,6 +700,7 @@
    "metadata": {},
    "outputs": [],
    "source": [
+    "step_timer.start()\n",
     "head = ['Module', 'High gain', 'Medium gain', 'Low gain']\n",
     "head_th = ['Module', 'HG_MG threshold', 'MG_LG threshold']\n",
     "for const_name, const in constants.items():\n",
@@ -732,7 +746,8 @@
     "    display(Markdown(label))\n",
     "    header = head_th if const_name == 'ThresholdsDark' else head\n",
     "    md = display(Latex(tabulate.tabulate(\n",
-    "        table, tablefmt='latex', headers=header)))"
+    "        table, tablefmt='latex', headers=header)))\n",
+    "step_timer.done_step(\"Summary tables across modules.\")"
    ]
   },
   {
@@ -742,7 +757,8 @@
    "outputs": [],
    "source": [
     "# Bad pixels summary table\n",
-    "if 'BadPixelsDark' in constants:    \n",
+    "if 'BadPixelsDark' in constants:\n",
+    "    step_timer.start()\n",
     "    bad_px_dark = constants['BadPixelsDark']\n",
     "\n",
     "    table = []\n",
@@ -766,7 +782,8 @@
     "\n",
     "    display(Markdown(label))\n",
     "    md = display(Latex(tabulate.tabulate(\n",
-    "        table, tablefmt='latex', headers=head)))"
+    "        table, tablefmt='latex', headers=head)))\n",
+    "    step_timer.done_step(\"Summary table across modules for BadPixels.\")"
    ]
   }
  ],
-- 
GitLab


From 7b3a148b3b5749b16b5611f7d32a19381012cccb Mon Sep 17 00:00:00 2001
From: ahmedk <karim.ahmed@xfel.eu>
Date: Thu, 26 Oct 2023 14:03:33 +0200
Subject: [PATCH 3/3] improve timing message based on MR suggestion and record
 timing for async constant retrieval

---
 .../Characterize_AGIPD_Gain_Darks_NBC.ipynb   | 22 +++++++++++++------
 1 file changed, 15 insertions(+), 7 deletions(-)

diff --git a/notebooks/AGIPD/Characterize_AGIPD_Gain_Darks_NBC.ipynb b/notebooks/AGIPD/Characterize_AGIPD_Gain_Darks_NBC.ipynb
index 913498240..cc60547a5 100644
--- a/notebooks/AGIPD/Characterize_AGIPD_Gain_Darks_NBC.ipynb
+++ b/notebooks/AGIPD/Characterize_AGIPD_Gain_Darks_NBC.ipynb
@@ -236,8 +236,8 @@
     "# Update modules and karabo_da lists based on available modules to processes.\n",
     "modules = [m for m in modules if m not in missing_modules]\n",
     "karabo_da = create_karabo_da_list(modules)\n",
-    "\n",
-    "step_timer.done_step(f\"Will process data of ({sum(mod_image_size):.02f} GB).\")"
+    "print(f\"Will process data of ({sum(mod_image_size):.02f} GB).\")\n",
+    "step_timer.done_step(\"Checking the data size and availability.\")"
    ]
   },
   {
@@ -692,6 +692,11 @@
     "\n",
     "\n",
     "def retrieve_old_constant(qm, const):\n",
+    "\n",
+    "    import time\n",
+    "\n",
+    "    st = time.time()\n",
+    "\n",
     "    dconst = getattr(iCalibrationDB.Constants.AGIPD, const)()\n",
     "\n",
     "    data, mdata = get_from_db(\n",
@@ -718,15 +723,15 @@
     "            mdata.calibration_constant_version.filename\n",
     "        )\n",
     "        h5path = mdata.calibration_constant_version.h5path\n",
-    "\n",
-    "    return data, timestamp, filepath, h5path\n",
+    "    \n",
+    "    return data, timestamp, filepath, h5path, time.time() - st\n",
     "\n",
     "\n",
     "old_retrieval_pool = multiprocessing.Pool()\n",
     "old_retrieval_res = old_retrieval_pool.starmap_async(\n",
     "    retrieve_old_constant, qm_x_const\n",
     ")\n",
-    "old_retrieval_pool.close()"
+    "old_retrieval_pool.close()\n"
    ]
   },
   {
@@ -934,13 +939,16 @@
     "old_mdata = {}\n",
     "old_retrieval_res.wait()\n",
     "\n",
-    "for (qm, const), (data, timestamp, filepath, h5path) in zip(qm_x_const, old_retrieval_res.get()):\n",
+    "timings = []\n",
+    "for (qm, const), (data, timestamp, filepath, h5path, timing) in zip(qm_x_const, old_retrieval_res.get()):\n",
     "    old_const.setdefault(qm, {})[const] = data\n",
     "    old_mdata.setdefault(qm, {})[const] = {\n",
     "        \"timestamp\": timestamp,\n",
     "        \"filepath\": filepath,\n",
     "        \"h5path\": h5path\n",
-    "    }"
+    "    }\n",
+    "    timings.append(timing)\n",
+    "print(f\"Retrieving old constant took around {np.asarray(timings).mean():.01f} s\")"
    ]
   },
   {
-- 
GitLab