diff --git a/.github/workflows/main_ci.yml b/.github/workflows/main_ci.yml index 961fc81f9..de0984617 100644 --- a/.github/workflows/main_ci.yml +++ b/.github/workflows/main_ci.yml @@ -22,6 +22,13 @@ jobs: platform: [ubuntu-latest, macos-latest] python-version: ["3.6", "3.7", "3.8", "3.9", "3.10", "3.11"] + # see gh-851 + exclude: + - platform: ubuntu-latest + python-version: "3.10" + include: + - platform: ubuntu-22.04 + python-version: "3.10" runs-on: ${{ matrix.platform }} steps: - uses: actions/checkout@v3 diff --git a/darshan-runtime/lib/darshan-core.c b/darshan-runtime/lib/darshan-core.c index c0f02f470..337a4d71e 100644 --- a/darshan-runtime/lib/darshan-core.c +++ b/darshan-runtime/lib/darshan-core.c @@ -151,6 +151,12 @@ static int darshan_deflate_buffer( static void darshan_core_cleanup( struct darshan_core_runtime* core); static void darshan_core_fork_child_cb(void); +static void darshan_core_reduce_min_time( + void* in_time_v, void* inout_time_v, + int *len, MPI_Datatype *datatype); +static void darshan_core_reduce_max_time( + void* in_time_v, void* inout_time_v, + int *len, MPI_Datatype *datatype); #define DARSHAN_WARN(__err_str, ...) do { \ darshan_core_fprintf(stderr, "darshan_library_warning: " \ @@ -197,6 +203,7 @@ void darshan_core_initialize(int argc, char **argv) int jobid; int ret; int i; + struct timespec start_ts; /* setup darshan runtime if darshan is enabled and hasn't been initialized already */ if (__darshan_core != NULL || getenv("DARSHAN_DISABLE")) @@ -309,7 +316,9 @@ void darshan_core_initialize(int argc, char **argv) /* set known job-level metadata fields for the log file */ init_core->log_job_p->uid = getuid(); - init_core->log_job_p->start_time = time(NULL); + clock_gettime(CLOCK_REALTIME, &start_ts); + init_core->log_job_p->start_time_sec = (int64_t)start_ts.tv_sec; + init_core->log_job_p->start_time_nsec = (int64_t)start_ts.tv_nsec; init_core->log_job_p->nprocs = nprocs; init_core->log_job_p->jobid = (int64_t)jobid; @@ -390,6 +399,7 @@ void darshan_core_shutdown(int write_log) { struct darshan_core_runtime *final_core; double start_log_time; + struct timespec end_ts; int internal_timing_flag; double open1 = 0, open2 = 0; double job1 = 0, job2 = 0; @@ -408,6 +418,8 @@ void darshan_core_shutdown(int write_log) int i; int ret; #ifdef HAVE_MPI + MPI_Datatype ts_type; + MPI_Op ts_max_op, ts_min_op; darshan_record_id *shared_recs = NULL; darshan_record_id *mod_shared_recs = NULL; int shared_rec_cnt = 0; @@ -442,7 +454,9 @@ void darshan_core_shutdown(int write_log) PMPI_Barrier(final_core->mpi_comm); #endif start_log_time = darshan_core_wtime_absolute(); - final_core->log_job_p->end_time = time(NULL); + clock_gettime(CLOCK_REALTIME, &end_ts); + final_core->log_job_p->end_time_sec = (int64_t)end_ts.tv_sec; + final_core->log_job_p->end_time_nsec = (int64_t)end_ts.tv_nsec; internal_timing_flag = final_core->config.internal_timing_flag; @@ -476,22 +490,30 @@ void darshan_core_shutdown(int write_log) MPI_INT, MPI_SUM, final_core->mpi_comm); /* reduce to report first start and last end time across all ranks at rank 0 */ + /* NOTE: custom MPI max/min reduction operators required for sec/nsec time tuples */ + PMPI_Type_contiguous(2, MPI_INT64_T, &ts_type); + PMPI_Type_commit(&ts_type); + PMPI_Op_create(darshan_core_reduce_min_time, 1, &ts_min_op); + PMPI_Op_create(darshan_core_reduce_max_time, 1, &ts_max_op); if(my_rank == 0) { - PMPI_Reduce(MPI_IN_PLACE, &final_core->log_job_p->start_time, - 1, MPI_INT64_T, MPI_MIN, 0, final_core->mpi_comm); - PMPI_Reduce(MPI_IN_PLACE, &final_core->log_job_p->end_time, - 1, MPI_INT64_T, MPI_MAX, 0, final_core->mpi_comm); + PMPI_Reduce(MPI_IN_PLACE, &final_core->log_job_p->start_time_sec, + 1, ts_type, ts_min_op, 0, final_core->mpi_comm); + PMPI_Reduce(MPI_IN_PLACE, &final_core->log_job_p->end_time_sec, + 1, ts_type, ts_max_op, 0, final_core->mpi_comm); } else { - PMPI_Reduce(&final_core->log_job_p->start_time, - &final_core->log_job_p->start_time, - 1, MPI_INT64_T, MPI_MIN, 0, final_core->mpi_comm); - PMPI_Reduce(&final_core->log_job_p->end_time, - &final_core->log_job_p->end_time, - 1, MPI_INT64_T, MPI_MAX, 0, final_core->mpi_comm); + PMPI_Reduce(&final_core->log_job_p->start_time_sec, + &final_core->log_job_p->start_time_sec, + 1, ts_type, ts_min_op, 0, final_core->mpi_comm); + PMPI_Reduce(&final_core->log_job_p->end_time_sec, + &final_core->log_job_p->end_time_sec, + 1, ts_type, ts_max_op, 0, final_core->mpi_comm); } + PMPI_Type_free(&ts_type); + PMPI_Op_free(&ts_min_op); + PMPI_Op_free(&ts_max_op); /* get a list of records which are shared across all processes */ darshan_get_shared_records(final_core, &shared_recs, &shared_rec_cnt); @@ -1486,7 +1508,6 @@ static void darshan_get_logfile_name( jobid = core->log_job_p->jobid; pid = core->pid; - start_time = core->log_job_p->start_time; /* first, check if user specifies a complete logpath to use */ user_logfile_name = getenv("DARSHAN_LOGFILE"); @@ -1514,6 +1535,7 @@ static void darshan_get_logfile_name( logmod = darshan_hash((void*)hname,strlen(hname),hlevel); /* use human readable start time format in log filename */ + start_time = (time_t)core->log_job_p->start_time_sec; start_tm = localtime(&start_time); if(core->config.log_path_byenv) @@ -2262,6 +2284,84 @@ static int darshan_core_name_is_excluded(const char *name, darshan_module_id mod return(0); } +#ifdef HAVE_MPI +static void darshan_core_reduce_min_time(void* in_time_v, void* inout_time_v, + int *len, MPI_Datatype *datatype) +{ + int64_t tmp_sec, tmp_nsec; + int64_t *in_sec = in_time_v; + int64_t *in_nsec = in_sec+1; + int64_t *inout_sec = inout_time_v; + int64_t *inout_nsec = inout_sec+1; + int i; + + for(i=0; i<*len; i++) + { + /* min */ + if((*in_sec < *inout_sec) || + ((*in_sec == *inout_sec) && + (*in_nsec < *inout_nsec))) + { + tmp_sec = *in_sec; + tmp_nsec = *in_nsec; + } + else + { + tmp_sec = *inout_sec; + tmp_nsec = *inout_nsec; + } + + /* update pointers */ + *inout_sec = tmp_sec; + *inout_nsec = tmp_nsec; + inout_sec+=2; + inout_nsec+=2; + in_sec+=2; + in_nsec+=2; + } + + return; +} + +static void darshan_core_reduce_max_time(void* in_time_v, void* inout_time_v, + int *len, MPI_Datatype *datatype) +{ + int64_t tmp_sec, tmp_nsec; + int64_t *in_sec = in_time_v; + int64_t *in_nsec = in_sec+1; + int64_t *inout_sec = inout_time_v; + int64_t *inout_nsec = inout_sec+1; + int i; + + for(i=0; i<*len; i++) + { + /* max */ + if((*in_sec > *inout_sec) || + ((*in_sec == *inout_sec) && + (*in_nsec > *inout_nsec))) + { + tmp_sec = *in_sec; + tmp_nsec = *in_nsec; + } + else + { + tmp_sec = *inout_sec; + tmp_nsec = *inout_nsec; + } + + /* update pointers */ + *inout_sec = tmp_sec; + *inout_nsec = tmp_nsec; + inout_sec+=2; + inout_nsec+=2; + in_sec+=2; + in_nsec+=2; + } + + return; +} +#endif + /* crude benchmarking hook into darshan-core to benchmark Darshan * shutdown overhead using a variety of application I/O workloads */ diff --git a/darshan-util/darshan-analyzer.c b/darshan-util/darshan-analyzer.c index 293b7ef7c..f57ad7179 100644 --- a/darshan-util/darshan-analyzer.c +++ b/darshan-util/darshan-analyzer.c @@ -97,11 +97,7 @@ int process_log(const char *fname, double *io_ratio, int *used_mpio, int *used_p if (file->mod_map[DARSHAN_PNETCDF_FILE_MOD].len > 0 || file->mod_map[DARSHAN_PNETCDF_VAR_MOD].len > 0) *used_pnet += 1; - total_job_time = (double)job.end_time - (double)job.start_time; - if (total_job_time < 1.0) - { - total_job_time = 1.0; - } + darshan_log_get_job_runtime(file, job, &total_job_time); if (f_count > 0) { diff --git a/darshan-util/darshan-diff.c b/darshan-util/darshan-diff.c index e92f855d1..8e89c8d9e 100644 --- a/darshan-util/darshan-diff.c +++ b/darshan-util/darshan-diff.c @@ -133,16 +133,16 @@ int main(int argc, char *argv[]) if (job1.uid != job2.uid) print_int64_diff("# uid:", job1.uid, job2.uid); - if (job1.start_time != job2.start_time) - print_int64_diff("# start_time:", job1.start_time, job2.start_time); - if (job1.end_time != job2.end_time) - print_int64_diff("# end_time:", job1.end_time, job2.end_time); + if (job1.start_time_sec != job2.start_time_sec) + print_int64_diff("# start_time:", job1.start_time_sec, job2.start_time_sec); + if (job1.end_time_sec != job2.end_time_sec) + print_int64_diff("# end_time:", job1.end_time_sec, job2.end_time_sec); if (job1.nprocs != job2.nprocs) print_int64_diff("# nprocs:", job1.nprocs, job2.nprocs); - if ((job1.end_time-job1.start_time) != (job2.end_time - job2.start_time)) + if ((job1.end_time_sec-job1.start_time_sec) != (job2.end_time_sec-job2.start_time_sec)) print_int64_diff("# run time:", - (int64_t)(job1.end_time - job1.start_time + 1), - (int64_t)(job2.end_time - job2.start_time + 1)); + (int64_t)(job1.end_time_sec - job1.start_time_sec + 1), + (int64_t)(job2.end_time_sec - job2.start_time_sec + 1)); /* get hash of record ids to file names for each log */ ret = darshan_log_get_namehash(file1, &name_hash1); diff --git a/darshan-util/darshan-dxt-parser.c b/darshan-util/darshan-dxt-parser.c index 69b3db7e8..23007b92c 100644 --- a/darshan-util/darshan-dxt-parser.c +++ b/darshan-util/darshan-dxt-parser.c @@ -43,7 +43,7 @@ int main(int argc, char **argv) int mount_count; struct darshan_mnt_info *mnt_data_array; time_t tmp_time = 0; - int64_t run_time = 0; + double run_time; char *token; char *save; char buffer[DARSHAN_JOB_METADATA_LEN]; @@ -107,17 +107,16 @@ int main(int argc, char **argv) printf("# exe: %s\n", tmp_string); printf("# uid: %" PRId64 "\n", job.uid); printf("# jobid: %" PRId64 "\n", job.jobid); - printf("# start_time: %" PRId64 "\n", job.start_time); - tmp_time += job.start_time; + printf("# start_time: %" PRId64 "\n", job.start_time_sec); + tmp_time += job.start_time_sec; printf("# start_time_asci: %s", ctime(&tmp_time)); - printf("# end_time: %" PRId64 "\n", job.end_time); + printf("# end_time: %" PRId64 "\n", job.end_time_sec); tmp_time = 0; - tmp_time += job.end_time; + tmp_time += job.end_time_sec; printf("# end_time_asci: %s", ctime(&tmp_time)); printf("# nprocs: %" PRId64 "\n", job.nprocs); - if (job.end_time >= job.start_time) - run_time = job.end_time - job.start_time + 1; - printf("# run time: %" PRId64 "\n", run_time); + darshan_log_get_job_runtime(fd, job, &run_time); + printf("# run time: %.4lf\n", run_time); for (token = strtok_r(job.metadata, "\n", &save); token != NULL; token = strtok_r(NULL, "\n", &save)) diff --git a/darshan-util/darshan-logutils.c b/darshan-util/darshan-logutils.c index d1379a5b4..613d49f5d 100644 --- a/darshan-util/darshan-logutils.c +++ b/darshan-util/darshan-logutils.c @@ -270,8 +270,11 @@ darshan_fd darshan_log_create(const char *name, enum darshan_comp_type comp_type int darshan_log_get_job(darshan_fd fd, struct darshan_job *job) { struct darshan_fd_int_state *state; + int log_ver_maj, log_ver_min; char job_buf[DARSHAN_JOB_RECORD_SIZE] = {0}; int job_buf_sz = DARSHAN_JOB_RECORD_SIZE; + char *trailing_data; + int trailing_data_size; int ret; if(!fd) @@ -283,6 +286,14 @@ int darshan_log_get_job(darshan_fd fd, struct darshan_job *job) assert(state); assert(fd->job_map.len > 0 && fd->job_map.off > 0); + /* get major/minor version numbers */ + ret = darshan_log_get_format_version(fd->version, &log_ver_maj, &log_ver_min); + if(ret < 0) + { + fprintf(stderr, "Error: unable to parse log file format version.\n"); + return(-1); + } + /* read the compressed job data from the log file */ ret = darshan_log_dzread(fd, DARSHAN_JOB_REGION_ID, job_buf, job_buf_sz); if(ret <= (int)sizeof(*job)) @@ -291,24 +302,54 @@ int darshan_log_get_job(darshan_fd fd, struct darshan_job *job) return(-1); } - memcpy(job, job_buf, sizeof(*job)); + /* NOTE: job definition changed to include start/end time nsecs in ver 3.41 */ + if(((log_ver_maj == 3) && (log_ver_min >= 41)) || (log_ver_maj > 3)) + { + memcpy(job, job_buf, sizeof(*job)); + trailing_data = &job_buf[sizeof(*job)]; + trailing_data_size = DARSHAN_EXE_LEN+1; + } + else + { + /* backwards compatibility with prior of Darshan job struct, + * which does not have fields for start_time_nsec or + * end_time_nsec + */ + int64_t *tmp_ptr = (int64_t *)job_buf; + job->uid = *(tmp_ptr++); + job->start_time_sec = *(tmp_ptr++); + job->start_time_nsec = 0; + job->end_time_sec = *(tmp_ptr++); + job->end_time_nsec = 0; + job->nprocs = *(tmp_ptr++); + job->jobid = *(tmp_ptr++); + memcpy(job->metadata, tmp_ptr, DARSHAN_JOB_METADATA_LEN); + trailing_data = (char *)tmp_ptr + DARSHAN_JOB_METADATA_LEN; + trailing_data_size = DARSHAN_EXE_LEN+1+(2*sizeof(int64_t)); + } if(fd->swap_flag) { /* swap bytes if necessary */ DARSHAN_BSWAP64(&job->uid); - DARSHAN_BSWAP64(&job->start_time); - DARSHAN_BSWAP64(&job->end_time); + DARSHAN_BSWAP64(&job->start_time_sec); + DARSHAN_BSWAP64(&job->end_time_sec); + /* don't byte swap fields explicitly set during up-conversion */ + if(((log_ver_maj == 3) && (log_ver_min >= 41)) || (log_ver_maj > 3)) + { + DARSHAN_BSWAP64(&job->start_time_nsec); + DARSHAN_BSWAP64(&job->end_time_nsec); + } DARSHAN_BSWAP64(&job->nprocs); DARSHAN_BSWAP64(&job->jobid); } /* save trailing exe & mount information, so it can be retrieved later */ if(!(state->exe_mnt_data)) - state->exe_mnt_data = malloc(DARSHAN_EXE_LEN+1); + state->exe_mnt_data = malloc(trailing_data_size); if(!(state->exe_mnt_data)) return(-1); - memcpy(state->exe_mnt_data, &job_buf[sizeof(*job)], DARSHAN_EXE_LEN+1); + memcpy(state->exe_mnt_data, trailing_data, trailing_data_size); return(0); } @@ -893,6 +934,29 @@ char *darshan_log_get_lib_version(void) return darshan_util_lib_ver; } +int darshan_log_get_job_runtime(darshan_fd fd, struct darshan_job job, double *runtime) +{ + int log_ver_maj, log_ver_min; + int ret; + *runtime = 0; + + /* get major/minor version numbers */ + ret = darshan_log_get_format_version(fd->version, &log_ver_maj, &log_ver_min); + if(ret < 0) + { + fprintf(stderr, "Error: unable to parse log file format version.\n"); + return(-1); + } + + if(((log_ver_maj == 3) && (log_ver_min >= 41)) || (log_ver_maj > 3)) + *runtime = (double)((job.end_time_sec + (job.end_time_nsec / 1e9)) - + (job.start_time_sec + (job.start_time_nsec / 1e9))); + else + *runtime = (double)(job.end_time_sec - job.start_time_sec + 1); + + return(0); +} + /******************************************************** * internal helper functions * ********************************************************/ diff --git a/darshan-util/darshan-logutils.h b/darshan-util/darshan-logutils.h index f30976624..2cdbba7e3 100644 --- a/darshan-util/darshan-logutils.h +++ b/darshan-util/darshan-logutils.h @@ -211,6 +211,7 @@ int darshan_log_put_mod(darshan_fd fd, darshan_module_id mod_id, void darshan_log_close(darshan_fd file); void darshan_log_print_version_warnings(const char *version_string); char *darshan_log_get_lib_version(void); +int darshan_log_get_job_runtime(darshan_fd fd, struct darshan_job job, double *runtime); void darshan_log_get_modules(darshan_fd fd, struct darshan_mod_info **mods, int* count); void darshan_log_get_name_records(darshan_fd fd, diff --git a/darshan-util/darshan-merge.c b/darshan-util/darshan-merge.c index e7a41016c..ecc76d9b1 100644 --- a/darshan-util/darshan-merge.c +++ b/darshan-util/darshan-merge.c @@ -286,10 +286,20 @@ int main(int argc, char *argv[]) else { /* potentially update job timestamps using remaining logs */ - if(in_job.start_time < merge_job.start_time) - merge_job.start_time = in_job.start_time; - if(in_job.end_time > merge_job.end_time) - merge_job.end_time = in_job.end_time; + if((in_job.start_time_sec < merge_job.start_time_sec) || + ((in_job.start_time_sec == merge_job.start_time_sec) && + (in_job.start_time_nsec < merge_job.start_time_nsec))) + { + merge_job.start_time_sec = in_job.start_time_sec; + merge_job.start_time_nsec = in_job.start_time_nsec; + } + if((in_job.end_time_sec > merge_job.end_time_sec) || + ((in_job.end_time_sec == merge_job.end_time_sec) && + (in_job.end_time_nsec > merge_job.end_time_nsec))) + { + merge_job.end_time_sec = in_job.end_time_sec; + merge_job.end_time_nsec = in_job.end_time_nsec; + } } /* read the hash of ids->names for the input log */ @@ -329,7 +339,10 @@ int main(int argc, char *argv[]) /* if a job end time was passed in, apply it to the output job */ if(job_end_time > 0) - merge_job.end_time = job_end_time; + { + merge_job.end_time_sec = job_end_time; + merge_job.end_time_nsec = 0; /* no nsec precision for manually specified end */ + } /* create the output "merged" log */ merge_fd = darshan_log_create(outlog_path, DARSHAN_ZLIB_COMP, 1); diff --git a/darshan-util/darshan-parser.c b/darshan-util/darshan-parser.c index f2c847dbf..83c97eefc 100644 --- a/darshan-util/darshan-parser.c +++ b/darshan-util/darshan-parser.c @@ -140,7 +140,7 @@ int main(int argc, char **argv) int mount_count; struct darshan_mnt_info *mnt_data_array; time_t tmp_time = 0; - int64_t run_time = 0; + double run_time; char *token; char *save; char buffer[DARSHAN_JOB_METADATA_LEN]; @@ -206,17 +206,16 @@ int main(int argc, char **argv) printf("# exe: %s\n", tmp_string); printf("# uid: %" PRId64 "\n", job.uid); printf("# jobid: %" PRId64 "\n", job.jobid); - printf("# start_time: %" PRId64 "\n", job.start_time); - tmp_time += job.start_time; + printf("# start_time: %" PRId64 "\n", job.start_time_sec); + tmp_time += job.start_time_sec; printf("# start_time_asci: %s", ctime(&tmp_time)); - printf("# end_time: %" PRId64 "\n", job.end_time); + printf("# end_time: %" PRId64 "\n", job.end_time_sec); tmp_time = 0; - tmp_time += job.end_time; + tmp_time += job.end_time_sec; printf("# end_time_asci: %s", ctime(&tmp_time)); printf("# nprocs: %" PRId64 "\n", job.nprocs); - if(job.end_time >= job.start_time) - run_time = job.end_time - job.start_time + 1; - printf("# run time: %" PRId64 "\n", run_time); + darshan_log_get_job_runtime(fd, job, &run_time); + printf("# run time: %.4lf\n", run_time); for(token=strtok_r(job.metadata, "\n", &save); token != NULL; token=strtok_r(NULL, "\n", &save)) diff --git a/darshan-util/pydarshan/darshan/backend/api_def_c.py b/darshan-util/pydarshan/darshan/backend/api_def_c.py index c3ab61d08..5fce60b5e 100644 --- a/darshan-util/pydarshan/darshan/backend/api_def_c.py +++ b/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); diff --git a/darshan-util/pydarshan/darshan/backend/cffi_backend.py b/darshan-util/pydarshan/darshan/backend/cffi_backend.py index 62c9f11b0..982fb2e86 100644 --- a/darshan-util/pydarshan/darshan/backend/cffi_backend.py +++ b/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... diff --git a/darshan-util/pydarshan/darshan/cli/summary.py b/darshan-util/pydarshan/darshan/cli/summary.py index b166c2389..7d9c0944c 100644 --- a/darshan-util/pydarshan/darshan/cli/summary.py +++ b/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 diff --git a/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-HDF5_id438090-438090_11-9-41522-17417065676046418211_1.darshan b/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-HDF5_id438090-438090_11-9-41522-17417065676046418211_1.darshan new file mode 100644 index 000000000..45f6f8d57 Binary files /dev/null and b/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-HDF5_id438090-438090_11-9-41522-17417065676046418211_1.darshan differ diff --git a/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-HDF5_id545128-545128_9-7-60657-7307669767025130365_1.darshan b/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-HDF5_id545128-545128_9-7-60657-7307669767025130365_1.darshan deleted file mode 100644 index 0f01b258a..000000000 Binary files a/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-HDF5_id545128-545128_9-7-60657-7307669767025130365_1.darshan and /dev/null differ diff --git a/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-PNETCDF_id438100-438100_11-9-41525-10280033558448664385_1.darshan b/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-PNETCDF_id438100-438100_11-9-41525-10280033558448664385_1.darshan new file mode 100644 index 000000000..67fe1bf1e Binary files /dev/null and b/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-PNETCDF_id438100-438100_11-9-41525-10280033558448664385_1.darshan differ diff --git a/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-PNETCDF_id864223-864223_10-27-46849-11258636277699483231_1.darshan b/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-PNETCDF_id864223-864223_10-27-46849-11258636277699483231_1.darshan deleted file mode 100644 index 29d843987..000000000 Binary files a/darshan-util/pydarshan/darshan/examples/example_logs/shane_ior-PNETCDF_id864223-864223_10-27-46849-11258636277699483231_1.darshan and /dev/null differ diff --git a/darshan-util/pydarshan/darshan/experimental/aggregators/create_dxttimeline.py b/darshan-util/pydarshan/darshan/experimental/aggregators/create_dxttimeline.py index 3f4e4c8e6..92b244821 100644 --- a/darshan-util/pydarshan/darshan/experimental/aggregators/create_dxttimeline.py +++ b/darshan-util/pydarshan/darshan/experimental/aggregators/create_dxttimeline.py @@ -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'] ) diff --git a/darshan-util/pydarshan/darshan/experimental/plots/plot_dxt_heatmap.py b/darshan-util/pydarshan/darshan/experimental/plots/plot_dxt_heatmap.py index 00c228918..464585624 100644 --- a/darshan-util/pydarshan/darshan/experimental/plots/plot_dxt_heatmap.py +++ b/darshan-util/pydarshan/darshan/experimental/plots/plot_dxt_heatmap.py @@ -38,10 +38,7 @@ 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`` @@ -49,13 +46,11 @@ def determine_hmap_runtime(report: darshan.DarshanReport) -> Tuple[float, float] 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 diff --git a/darshan-util/pydarshan/darshan/experimental/plots/plot_io_cost.py b/darshan-util/pydarshan/darshan/experimental/plots/plot_io_cost.py index 89c23867b..9e4bdd229 100644 --- a/darshan-util/pydarshan/darshan/experimental/plots/plot_io_cost.py +++ b/darshan-util/pydarshan/darshan/experimental/plots/plot_io_cost.py @@ -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 diff --git a/darshan-util/pydarshan/darshan/report.py b/darshan-util/pydarshan/darshan/report.py index afdc4c683..17b0e0e3c 100644 --- a/darshan-util/pydarshan/darshan/report.py +++ b/darshan-util/pydarshan/darshan/report.py @@ -476,8 +476,8 @@ def read_metadata(self, read_all=False): self.metadata['job'] = backend.log_get_job(self.log) self.metadata['exe'] = backend.log_get_exe(self.log) - self.start_time = datetime.datetime.fromtimestamp(self.metadata['job']['start_time']) - self.end_time = datetime.datetime.fromtimestamp(self.metadata['job']['end_time']) + self.start_time = datetime.datetime.fromtimestamp(self.metadata['job']['start_time_sec']) + self.end_time = datetime.datetime.fromtimestamp(self.metadata['job']['end_time_sec']) self.data['mounts'] = backend.log_get_mounts(self.log) self.mounts = self.data['mounts'] @@ -991,13 +991,13 @@ def info(self, metadata=False): """ print("Filename: ", self.filename, sep="") - tdelta = self.end_time - self.start_time - print("Times: ", self.start_time, " to ", self.end_time, " (Duration ", tdelta, ")", sep="") - if 'exe' in self.metadata: - print("Executable: ", self.metadata['exe'], sep="") + print("Executable: ", self.metadata['exe'], sep="") + + print("Times: ", self.start_time, " to ", self.end_time, sep="") if 'job' in self.metadata: + print("Run time: %.4f (s)" % self.metadata['job']['run_time'], sep="") print("Processes: ", self.metadata['job']['nprocs'], sep="") print("JobID: ", self.metadata['job']['jobid'], sep="") print("UID: ", self.metadata['job']['uid'], sep="") diff --git a/darshan-util/pydarshan/darshan/tests/test_plot_dxt_heatmap.py b/darshan-util/pydarshan/darshan/tests/test_plot_dxt_heatmap.py index b889d3405..24e3d307b 100644 --- a/darshan-util/pydarshan/darshan/tests/test_plot_dxt_heatmap.py +++ b/darshan-util/pydarshan/darshan/tests/test_plot_dxt_heatmap.py @@ -41,24 +41,24 @@ def jointgrid(): np.linspace(0.0, 348.956244, 10), np.around(np.linspace(0, 1.0, 10), decimals=2), ), - ("dxt.darshan", 2, np.linspace(0.0, 100.023116, 2), [0, 1468]), + ("dxt.darshan", 2, np.linspace(0.0, 100.091252, 2), [0, 1469]), ( "dxt.darshan", 4, - np.linspace(0.0, 100.023116, 4), - [0, 489, 978, 1468], + np.linspace(0.0, 100.091252, 4), + [0, 489, 979, 1469], ), ( "dxt.darshan", 6, - np.linspace(0.0, 100.023116, 6), - [0, 293, 587, 880, 1174, 1468], + np.linspace(0.0, 100.091252, 6), + [0, 293, 587, 881, 1175, 1469], ), ( "dxt.darshan", 10, - np.linspace(0.0, 100.023116, 10), - [0, 163, 326, 489, 652, 815, 978, 1141, 1304, 1468], + np.linspace(0.0, 100.091252, 10), + [0, 163, 326, 489, 652, 816, 979, 1142, 1305, 1469], ), ("sample-dxt-simple.darshan", 2, np.linspace(0.0, 959.403244, 2), [0.0, 1.0]), ( @@ -98,7 +98,7 @@ def test_set_x_axis_ticks_and_labels( data = [[4, 1.03378843, 1.03387713, 0], [4000, 1.04216653, 1.04231459, 0]] cols = ["length", "start_time", "end_time", "rank"] agg_df = pd.DataFrame(data=data, columns=cols) - runtime = 1 + runtime = 2 else: filepath = get_log_path(filepath) @@ -107,12 +107,9 @@ def test_set_x_axis_ticks_and_labels( agg_df = heatmap_handling.get_aggregate_data( report=report, mod="DXT_POSIX", ops=["read", "write"] ) - runtime = report.metadata["job"]["end_time"] - report.metadata["job"]["start_time"] + runtime = report.metadata["job"]["run_time"] - runtime = max(runtime, 1) tmax_dxt = float(agg_df["end_time"].max()) - if tmax_dxt > runtime: - runtime += 1 # the jointgrid fixture has 100 xbins xbins = 100 diff --git a/darshan-util/pydarshan/darshan/tests/test_plot_exp_common.py b/darshan-util/pydarshan/darshan/tests/test_plot_exp_common.py index 3f381d1fc..96e056461 100644 --- a/darshan-util/pydarshan/darshan/tests/test_plot_exp_common.py +++ b/darshan-util/pydarshan/darshan/tests/test_plot_exp_common.py @@ -125,7 +125,7 @@ 'H5D Flush', 'H5F Open', 'H5F Flush'], ), ( - "shane_ior-PNETCDF_id864223-864223_10-27-46849-11258636277699483231_1.darshan", + "shane_ior-PNETCDF_id438100-438100_11-9-41525-10280033558448664385_1.darshan", "PNETCDF_FILE", plot_opcounts, ['Var Ind Read', 'Var Ind Write', 'Var Open', 'Var Coll Read', @@ -133,7 +133,7 @@ 'File Ind Waits', 'File Coll Waits'], ), ( - "shane_ior-PNETCDF_id864223-864223_10-27-46849-11258636277699483231_1.darshan", + "shane_ior-PNETCDF_id438100-438100_11-9-41525-10280033558448664385_1.darshan", "PNETCDF_VAR", plot_opcounts, ['Var Ind Read', 'Var Ind Write', 'Var Open', 'Var Coll Read', @@ -366,13 +366,13 @@ def test_xticks_and_labels(log_path, func, expected_xticklabels, mod): [0, 3, 3, 0, 0, 0], ), ( - "shane_ior-PNETCDF_id864223-864223_10-27-46849-11258636277699483231_1.darshan", + "shane_ior-PNETCDF_id438100-438100_11-9-41525-10280033558448664385_1.darshan", "PNETCDF_FILE", plot_opcounts, [0, 0, 0, 0, 0, 0, 0, 8, 0, 0, 0], ), ( - "shane_ior-PNETCDF_id864223-864223_10-27-46849-11258636277699483231_1.darshan", + "shane_ior-PNETCDF_id438100-438100_11-9-41525-10280033558448664385_1.darshan", "PNETCDF_VAR", plot_opcounts, [16, 16, 8, 0, 0, 0, 0, 8, 0, 0, 0], diff --git a/darshan-util/pydarshan/darshan/tests/test_plot_io_cost.py b/darshan-util/pydarshan/darshan/tests/test_plot_io_cost.py index e5f6a7598..53c22fa5d 100644 --- a/darshan-util/pydarshan/darshan/tests/test_plot_io_cost.py +++ b/darshan-util/pydarshan/darshan/tests/test_plot_io_cost.py @@ -42,13 +42,13 @@ ), ), ( - "shane_ior-PNETCDF_id864223-864223_10-27-46849-11258636277699483231_1.darshan", + "shane_ior-PNETCDF_id438100-438100_11-9-41525-10280033558448664385_1.darshan", pd.DataFrame( np.array([ - [0.000444889069, 0.006031095982, 0.000148117542], - [0.000467121601, 0.006095588207, 0.003371536732], - [0.000423729420, 0.006246685982, 0.004460096359], - [0.000000000000, 0.000153362751, 0.000000000000], + [0.000378787518, 0.002514898777, 0.000068306923], + [0.000397562981, 0.002540826797, 0.001559376717], + [0.000402510166, 0.002579867840, 0.001994967461], + [0.000000000000, 0.000120997429, 0.000000000000], ]), ["POSIX", "MPIIO", "PNETCDF", "STDIO"], ["Read", "Write", "Meta"], @@ -71,19 +71,19 @@ def test_get_io_cost_df(logname, expected_df): ), ( "sample-badost.darshan", - [0.0, 779.0], + [0.0, 780.0], ), ( "dxt.darshan", - [0.0, 1468.0], + [0.0, 1469.0], ), ( "noposix.darshan", - [0.0, 39212.0], + [0.0, 39213.0], ), ( "noposixopens.darshan", - [0.0, 1110.0], + [0.0, 1111.0], ), ], ) @@ -110,7 +110,7 @@ def test_plot_io_cost_ylims(logname, expected_ylims): ), ( "sample-badost.darshan", - [0.0, 155.8, 311.6, 467.4, 623.2, 779.0], + [0, 156, 312, 468, 624, 780], ), ], ) diff --git a/darshan-util/pydarshan/darshan/tests/test_report.py b/darshan-util/pydarshan/darshan/tests/test_report.py index 680cbf9cb..55617b663 100644 --- a/darshan-util/pydarshan/darshan/tests/test_report.py +++ b/darshan-util/pydarshan/darshan/tests/test_report.py @@ -503,8 +503,8 @@ def test_heatmap_df_invalid_operation(): def test_pnetcdf_hdf5_match(): # test for some equivalent (f)counters between similar # HDF5 and PNETCDF-enabled runs of ior - pnetcdf_ior_report = darshan.DarshanReport(get_log_path("shane_ior-PNETCDF_id864223-864223_10-27-46849-11258636277699483231_1.darshan")) - hdf5_ior_report = darshan.DarshanReport(get_log_path("shane_ior-HDF5_id545128-545128_9-7-60657-7307669767025130365_1.darshan")) + pnetcdf_ior_report = darshan.DarshanReport(get_log_path("shane_ior-PNETCDF_id438100-438100_11-9-41525-10280033558448664385_1.darshan")) + hdf5_ior_report = darshan.DarshanReport(get_log_path("shane_ior-HDF5_id438090-438090_11-9-41522-17417065676046418211_1.darshan")) pnetcdf_ior_report.mod_read_all_records("PNETCDF_FILE") pnetcdf_ior_report.mod_read_all_records("PNETCDF_VAR") hdf5_ior_report.mod_read_all_records("H5F") diff --git a/darshan-util/pydarshan/darshan/tests/test_summary.py b/darshan-util/pydarshan/darshan/tests/test_summary.py index a4fb5a791..4b4374014 100644 --- a/darshan-util/pydarshan/darshan/tests/test_summary.py +++ b/darshan-util/pydarshan/darshan/tests/test_summary.py @@ -282,14 +282,14 @@ def test_header_and_footer(self, log_name, expected_header): "sample.darshan", pd.DataFrame( index=[ - "Job ID", "User ID", "# Processes", "Runtime (s)", + "Job ID", "User ID", "# Processes", "Run time (s)", "Start Time", "End Time", "Command Line", ], data=[ "4478544", "69615", "2048", - "116", + "117.0000", str(datetime.fromtimestamp(1490000867)), str(datetime.fromtimestamp(1490000983)), ( @@ -305,14 +305,14 @@ def test_header_and_footer(self, log_name, expected_header): "noposix.darshan", pd.DataFrame( index=[ - "Job ID", "User ID", "# Processes", "Runtime (s)", + "Job ID", "User ID", "# Processes", "Run time (s)", "Start Time", "End Time", "Command Line", ], data=[ "83017637", "996599276", "512", - "39212", + "39213.0000", str(datetime.fromtimestamp(1514923055)), str(datetime.fromtimestamp(1514962267)), "Anonymized", @@ -323,14 +323,14 @@ def test_header_and_footer(self, log_name, expected_header): "sample-dxt-simple.darshan", pd.DataFrame( index=[ - "Job ID", "User ID", "# Processes", "Runtime (s)", + "Job ID", "User ID", "# Processes", "Run time (s)", "Start Time", "End Time", "Command Line", ], data=[ "4233209", "28751", "16", - "< 1", + "1.0000", str(datetime.fromtimestamp(1619109091)), str(datetime.fromtimestamp(1619109091)), ( @@ -538,13 +538,12 @@ def test_get_full_command(self, logname, expected_cmd): @pytest.mark.parametrize( "logname, expected_runtime", [ - ("sample.darshan", "116",), - ("noposix.darshan", "39212"), - ("noposixopens.darshan", "1110"), - ("sample-badost.darshan", "779",), - ("sample-goodost.darshan", "4",), - # special case where the calculated run time is 0 - ("sample-dxt-simple.darshan", "< 1",), + ("sample.darshan", "117.0000",), + ("noposix.darshan", "39213.0000"), + ("noposixopens.darshan", "1111.0000"), + ("sample-badost.darshan", "780.0000",), + ("sample-goodost.darshan", "5.0000",), + ("sample-dxt-simple.darshan", "1.0000",), ], ) def test_get_runtime(self, logname, expected_runtime): diff --git a/include/darshan-log-format.h b/include/darshan-log-format.h index 7b7f21c06..4fbf37b53 100644 --- a/include/darshan-log-format.h +++ b/include/darshan-log-format.h @@ -83,8 +83,10 @@ struct darshan_header 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[DARSHAN_JOB_METADATA_LEN];