PyDarshan changes for new job timestamps

* new logutils function (`darshan_log_get_job_runtime`) to
  calculate job runtime as a floating point value
  * for pre 3.41 logs, this is end-start+1 (i.e., runtime
    rounded up to nearest integer)
  * for 3.41+ logs, this is exact runtime to nsec precision
* CFFI definition updates of job types, type sizes
* CFFI bindings updates to extract new job timers and runtime
* updates to summary and report interfaces to use new job timers
  and runtime values
* updates to plotting code to use new job timers and runtime
  values
  * `plot_dxt_heatmap.py` in particular had some code removed
    that tried to correct for a calculated runtime of 0
* updates to tests to accommodate new changes to various
  interfaces and record formats
  * `test_plot_dxt_heatmap.py` has changes to avoid need for
    rounding up calculated runtime
  * new ior-PNETCF/ior-HDF5 log files are included as previous
    ones are no longer valid due to log format changes

Author: Shane Snyder

darshan-util/pydarshan/darshan/backend/api_def_c.py

@@ -10,8 +10,8 @@
 header = """/* from darshan-logutils.h */
 struct darshan_mnt_info
 {
-    char mnt_type[3031];
-    char mnt_path[3031];
+    char mnt_type[3015];
+    char mnt_path[3015];
 };
 
 struct darshan_mod_info
@@ -29,8 +29,10 @@
 struct darshan_job
 {
     int64_t uid;
-    int64_t start_time;
-    int64_t end_time;
+    int64_t start_time_sec;
+    int64_t start_time_nsec;
+    int64_t end_time_sec;
+    int64_t end_time_nsec;
     int64_t nprocs;
     int64_t jobid;
     char metadata[1024];
@@ -167,6 +169,7 @@
 void darshan_log_get_modules(void*, struct darshan_mod_info **, int*);
 int darshan_log_get_record(void*, int, void **);
 char* darshan_log_get_lib_version(void);
+int darshan_log_get_job_runtime(void *, struct darshan_job job, double *runtime);
 void darshan_free(void *);
 
 int darshan_log_get_namehash(void*, struct darshan_name_record_ref **hash);

darshan-util/pydarshan/darshan/backend/cffi_backend.py

@@ -126,11 +126,17 @@ def log_get_job(log):
     libdutil.darshan_log_get_job(log['handle'], jobrec)
 
     job['uid'] = jobrec[0].uid
-    job['start_time'] = jobrec[0].start_time
-    job['end_time'] = jobrec[0].end_time
+    job['start_time_sec'] = jobrec[0].start_time_sec
+    job['start_time_nsec'] = jobrec[0].start_time_nsec
+    job['end_time_sec'] = jobrec[0].end_time_sec
+    job['end_time_nsec'] = jobrec[0].end_time_nsec
     job['nprocs'] = jobrec[0].nprocs
     job['jobid'] = jobrec[0].jobid
 
+    runtime = ffi.new("double *")
+    libdutil.darshan_log_get_job_runtime(log['handle'], jobrec[0], runtime)
+    job['run_time'] = runtime[0]
+
     # dirty hack to get log format version -- we know it's currently stored at the
     # very beginning of the log handle structure, so we just cast the struct
     # pointer as a string...

darshan-util/pydarshan/darshan/cli/summary.py

@@ -178,16 +178,9 @@ def get_runtime(report: darshan.report.DarshanReport) -> str:
         runtime : the calculated executable run time.
 
         """
-        # calculate the run time
-        runtime_val = int(
-            report.metadata["job"]["end_time"] - report.metadata["job"]["start_time"]
-        )
-        if runtime_val < 1:
-            # to prevent the displayed run time from being 0 seconds
-            # label anything under 1 second as less than 1
-            runtime = "< 1"
-        else:
-            runtime = str(runtime_val)
+        # get the run time string
+        runtime_val = report.metadata["job"]["run_time"]
+        runtime = f'{runtime_val:.4f}'
         return runtime
 
     def get_header(self):
@@ -200,7 +193,7 @@ def get_header(self):
         else:
             app_name = os.path.basename(command.split()[0])
         # collect the date from the time stamp
-        date = datetime.date.fromtimestamp(self.report.metadata["job"]["start_time"])
+        date = datetime.date.fromtimestamp(self.report.metadata["job"]["start_time_sec"])
         # the header is the application name and the log date
         self.header = f"{app_name} ({date})"
 
@@ -222,9 +215,9 @@ def get_metadata_table(self):
             "Job ID": job_data["jobid"],
             "User ID": job_data["uid"],
             "# Processes": job_data["nprocs"],
-            "Runtime (s)": self.get_runtime(report=self.report),
-            "Start Time": datetime.datetime.fromtimestamp(job_data["start_time"]),
-            "End Time": datetime.datetime.fromtimestamp(job_data["end_time"]),
+            "Run time (s)": self.get_runtime(report=self.report),
+            "Start Time": datetime.datetime.fromtimestamp(job_data["start_time_sec"]),
+            "End Time": datetime.datetime.fromtimestamp(job_data["end_time_sec"]),
             "Command Line": self.get_full_command(report=self.report),
         }
         # convert the dictionary into a dataframe

darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-HDF5_id438090-438090_11-9-41522-17417065676046418211_1.darshan

@@ -22,7 +22,7 @@ def create_dxttimeline(self, group_by='rank', mode="append"):
     items = ctx['items']
 
 
-    start_time = datetime.datetime.fromtimestamp( self.data['metadata']['job']['start_time'] )
+    start_time = datetime.datetime.fromtimestamp( self.data['metadata']['job']['start_time_sec'] )
 
 
 

darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-HDF5_id545128-545128_9-7-60657-7307669767025130365_1.darshan

@@ -38,24 +38,19 @@ def determine_hmap_runtime(report: darshan.DarshanReport) -> Tuple[float, float]
     or both module types are available, to achieve a common
     max displayed runtime.
 
-    In some cases, this may mean that the time value is
-    rounded up from the actual runtime.
-
-    Paramaters
+    Parameters
     ----------
 
     report: a ``darshan.DarshanReport``
 
     Returns
     -------
 
-    A tuple containing `tmax`, (rounded) `runtime` floats.
+    A tuple containing `tmax`, `runtime` floats.
 
     """
-    # calculate the elapsed runtime
-    runtime = report.metadata["job"]["end_time"] - report.metadata["job"]["start_time"]
-    # ensure a minimum runtime value of 1 second
-    runtime = max(runtime, 1)
+    # get the elapsed runtime
+    runtime = report.metadata["job"]["run_time"]
     # leverage higher resolution DXT timing
     # data if available
     if ("DXT_POSIX" in report.modules or
@@ -69,10 +64,6 @@ def determine_hmap_runtime(report: darshan.DarshanReport) -> Tuple[float, float]
                 tmax_dxt = float(agg_df["end_time"].max())
                 if tmax_dxt > tmax:
                     tmax = tmax_dxt
-        # if the data max time exceeds the runtime, buffer by 1 second
-        # until our timer precision improves to prevent truncation
-        if tmax > runtime:
-            runtime += 1
     else:
         tmax = runtime
     return tmax, runtime

darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-PNETCDF_id438100-438100_11-9-41525-10280033558448664385_1.darshan

@@ -148,12 +148,8 @@ def plot_io_cost(report: darshan.DarshanReport) -> Any:
     stacked bar graph of the average read, write, and metadata times.
 
     """
-    # calculate the run time from the report metadata
-    runtime = report.metadata["job"]["end_time"] - report.metadata["job"]["start_time"]
-    if runtime == 0:
-        # for cases where runtime is < 1, just set it
-        # to 1 like the original perl code
-        runtime = 1
+    # get the run time from the report metadata
+    runtime = report.metadata["job"]["run_time"]
     # get the I/O cost dataframe
     io_cost_df = get_io_cost_df(report=report)
     # generate a figure with 2 y axes