diff --git a/ARCHITECTURE.md b/ARCHITECTURE.md index 8af4f8b..71582bd 100644 --- a/ARCHITECTURE.md +++ b/ARCHITECTURE.md @@ -376,6 +376,12 @@ the exchange buildable and testable without OpenFAST. carry `app/utf8_code_page.manifest`, which makes UTF-8 the process code page, so the Fortran runtime opens any name as written; a GNU build falls back to 8.3 short names for characters outside the system ANSI code page. +- **Run-time profile** (`CableDyn_Profile`): with `CABLEDYN_PROFILE` set, the standalone + driver charges its wall time to the phase that is running. Every time march marks where its + fluid update, step, checks, output and progress report begin, so a run that stops with an + error keeps its time in the phase it stopped in. The driver counts the `EI = 0` line steps and + Newton iterations in `CD_Step_Model`, and reports them with the finite-EI step counters of + `CableDyn_HermiteCableDynamic`. Unarmed, each mark is one test of a flag. - **C-ABI handles** (`cabledyn_mutex.c`): the handle registry is guarded by a spin-yield lock and deck initialisation by an input lock; operating on a handle while closing it from another thread is outside the API contract. @@ -395,6 +401,7 @@ src/ cabledyn_mutex.c C-ABI registry and initialisation locks cabledyn_crt_locale.c MinGW-w64 guard for libgfortran's locale restore CableDyn_FatalReport.f90 abnormal-end report of the driver (time reached) + CableDyn_Profile.f90 opt-in run-time profile of the driver (CABLEDYN_PROFILE) cabledyn_fatal.c interrupt, fault and stack-overflow handlers of the driver EI = 0 cable path: diff --git a/CHANGELOG.md b/CHANGELOG.md index b67c720..4bba097 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,18 @@ All notable changes to CableDyn are recorded in this file. The format follows ## [Unreleased] +### Added + +- Run-time profile of the standalone driver. With the environment variable + `CABLEDYN_PROFILE=1`, the driver prints at the end of the run how its wall time divides + between input parsing, initialisation and statics, and the dynamic march. The march is split + into the fluid sampled by the driver, the line, cable and object steps, the checks, the + outputs, and the progress report. The profile also gives the committed steps and the time per + step, the tension-only line steps and their Newton iterations, and (outside the mixed + `EI = 0` + finite-EI route) the finite-EI cable steps with their residual, tangent and solve + counts and times. Every output file is the same with and without it. See the manual's + command-line page (Run-time profile). + ### Changed - Faster wave kinematics of directional and multi-train seas (`wavetrain` rows, spectral diff --git a/CMakeLists.txt b/CMakeLists.txt index 14bdab4..83eb7c1 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -332,6 +332,7 @@ add_library(cabledyn_obj OBJECT src/cabledyn_fatal.c src/CableDyn_Precision.f90 src/CableDyn_FatalReport.f90 + src/CableDyn_Profile.f90 src/CableDyn_PathIO.f90 src/CableDyn_Banner.f90 src/CableDyn_Linalg.f90 @@ -1899,6 +1900,43 @@ add_test( set_tests_properties(driver_repeat_exit PROPERTIES LABELS "fortran;driver;integration;static") +# Run-time profile module: phase partition, a failed run's time kept in its phase, and exact +# line-step counts under OpenMP. +add_executable(test_profile tests/test_profile.f90) +target_link_libraries(test_profile PRIVATE cabledyn_core) +add_test(NAME profile COMMAND test_profile) +set_tests_properties(profile PROPERTIES LABELS "fortran;unit;driver" + ENVIRONMENT "OMP_NUM_THREADS=4") + +# Run-time profile (CABLEDYN_PROFILE): printed only when requested, before the success line, +# with its phase rows and counts, and without changing any output file. One EI = 0 deck with +# waves (fluid, steps and line counts) and one finite-EI deck on the cubic-Hermite route. +add_test( + NAME driver_profile_ei0 + COMMAND ${CMAKE_COMMAND} + -DDRIVER=$ + -DDECK=${CMAKE_CURRENT_SOURCE_DIR}/examples/dynamic_chain_waves.dat + -DOUTPUT_ROOT=${CMAKE_CURRENT_BINARY_DIR}/driver_profile_ei0 + "-DEXPECT=\n EI = 0 line steps: [1-9][0-9]* \\(substeps and retries included\\), Newton iterations: [1-9]" + -P ${CMAKE_CURRENT_SOURCE_DIR}/tests/check_driver_profile.cmake) +add_test( + NAME driver_profile_finite_ei + COMMAND ${CMAKE_COMMAND} + -DDRIVER=$ + -DDECK=${CMAKE_CURRENT_SOURCE_DIR}/tests/data/held_start_gomex80_power_cable.dat + -DOUTPUT_ROOT=${CMAKE_CURRENT_BINARY_DIR}/driver_profile_finite_ei + "-DEXPECT=\n Finite-EI cable steps: [1-9][0-9]*, residual evaluations: [1-9]" + -P ${CMAKE_CURRENT_SOURCE_DIR}/tests/check_driver_profile.cmake) +add_test( + NAME driver_profile_failure + COMMAND ${CMAKE_COMMAND} + -DDRIVER=$ + -DDECK=${CMAKE_CURRENT_SOURCE_DIR}/tests/data/nonconvergent_motion.dat + -DOUTPUT_ROOT=${CMAKE_CURRENT_BINARY_DIR}/driver_profile_failure + -P ${CMAKE_CURRENT_SOURCE_DIR}/tests/check_driver_profile_failure.cmake) +set_tests_properties(driver_profile_ei0 driver_profile_finite_ei driver_profile_failure PROPERTIES + LABELS "fortran;driver;integration;dynamic") + # Command-line contract: unknown options, an output root whose .out would overwrite # the deck, and an unwritable output directory all fail before any solve. configure_file(${CMAKE_CURRENT_SOURCE_DIR}/tests/data/nonconvergent_motion.dat diff --git a/app/cabledyn.f90 b/app/cabledyn.f90 index 5da8af1..1f20b56 100644 --- a/app/cabledyn.f90 +++ b/app/cabledyn.f90 @@ -34,6 +34,12 @@ PROGRAM cabledyn USE CableDyn_Banner, ONLY: CD_Print_Banner USE CableDyn_Linalg, ONLY: CD_Blas_Runtime_Check, CD_LINALG_OK USE CableDyn_FatalReport, ONLY: CD_Fatal_Report_Install, CD_Fatal_Report_Time + USE CableDyn_Profile, ONLY: CD_Profile_Requested, CD_Profile_Arm, CD_Profile_Armed, CD_Profile_Enter, & + CD_Profile_Flush, CD_Profile_Step, CD_Profile_Seconds, CD_Profile_Counts, & + CD_PROF_INPUT, CD_PROF_INIT, CD_PROF_FLUID, CD_PROF_SOLVE, CD_PROF_CHECK, & + CD_PROF_OUTPUT, CD_PROF_PROGRESS, CD_PROF_FINAL, CD_PROF_NPHASE + USE CableDyn_HermiteCableDynamic, ONLY: CD_HermiteCable_Dyn_Reset_Profile, CD_HermiteCable_Dyn_Get_Profile, & + CD_HermiteCable_Dyn_Recovery_Reset, CD_HermiteCable_Dyn_Recovery_Count USE, INTRINSIC :: ISO_FORTRAN_ENV, ONLY: error_unit, output_unit, int64 IMPLICIT NONE TYPE :: StandaloneProgress @@ -56,6 +62,8 @@ PROGRAM cabledyn INTEGER :: nargs, ErrStat, n_ei0, n_finite_ei, iarg REAL(wp) :: dtM, tmax LOGICAL :: converged, has_dtm, has_tmax, has_motion_file, has_line_outputs, has_objects + ! the run-time profile includes the finite-EI cable step counters (not on the mixed route) + LOGICAL :: profile_cable_detail = .FALSE. ! Sized for the aggregate and deck-driver messages it relays (512-character buffers ! plus deck-line context), so no diagnostic is cut short. CHARACTER(1024) :: ErrMsg @@ -117,10 +125,24 @@ PROGRAM cabledyn ! without a word. Installed after the LAPACK runtime has loaded, so its handlers are the ! process's own. CALL CD_Fatal_Report_Install() + ! Opt-in run-time profile (environment variable CABLEDYN_PROFILE), printed before the last + ! stdout line. + IF (CD_Profile_Requested()) THEN + CALL CD_Profile_Arm() + CALL CD_HermiteCable_Dyn_Recovery_Reset() + WRITE (output_unit, '(A)') ' Run-time profile armed by CABLEDYN_PROFILE.' + END IF CALL CD_Deck_Query_dtM(TRIM(deck_path), dtM, has_dtm, ErrStat, ErrMsg, tmax=tmax, & has_tmax=has_tmax, n_ei0=n_ei0, n_finite_ei=n_finite_ei, & has_motion_file=has_motion_file, standalone_scan=.TRUE., & has_line_outputs=has_line_outputs, input_files=input_files, has_objects=has_objects) + IF (ErrStat == CD_DECKDRV_OK .AND. CD_Profile_Armed()) THEN + ! The finite-EI step counters are process-global, so the aggregate of the mixed route steps + ! its cables one after another while they are armed. That route keeps its cables concurrent + ! and reports no finite-EI step detail; every other route steps its cables in turn anyway. + profile_cable_detail = .NOT. (n_ei0 > 0 .AND. n_finite_ei > 0 .AND. .NOT. has_objects) + IF (profile_cable_detail) CALL CD_HermiteCable_Dyn_Reset_Profile() + END IF IF (ErrStat == CD_DECKDRV_OK) THEN DO iarg = 1, SIZE(input_files) CALL check_input_not_output(TRIM(input_files(iarg)), TRIM(out_root), root_native, 'input file') @@ -154,6 +176,7 @@ PROGRAM cabledyn END IF CALL stop_run(2) END IF + CALL print_profile() WRITE (output_unit, '(A,A,A)') PROG//': converged run written to ', TRIM(out_root), '.out' CONTAINS @@ -164,6 +187,7 @@ SUBROUTINE stop_run(code) !! a caller can tell such an exit from a process ended from outside (Task Manager, !! `taskkill /F`, `kill -9`), which runs no code of the driver and leaves no closing line. INTEGER, INTENT(IN) :: code + CALL print_profile() WRITE (error_unit, '(A,I0)') PROG//': ended with exit code ', code FLUSH (error_unit) STOP code, QUIET = .TRUE. @@ -472,6 +496,8 @@ SUBROUTINE run_mixed_held_deck(deck, root, dt, has_dt, run_time, has_run_time, h END IF mixed_run: BLOCK + ! the aggregate parses the deck again with its models: initialisation from here + CALL CD_Profile_Enter(CD_PROF_INIT) ALLOCATE (aggregate, STAT=ios) IF (ios /= 0) THEN run_stat = CD_DECKDRV_SOLVEFAIL @@ -555,11 +581,14 @@ SUBROUTINE run_mixed_held_deck(deck, root, dt, has_dt, run_time, has_run_time, h max_consecutive_miss = 0 first_miss_time = CD_ZERO last_miss_time = CD_ZERO + ! the march (no fluid sampled by the driver on this route) or, without one, finalisation + CALL CD_Profile_Enter(MERGE(CD_PROF_SOLVE, CD_PROF_FINAL, nstep > 0)) IF (nstep > 0) CALL start_standalone_progress(progress, nstep, step_dt) DO step = 1, nstep time = REAL(step, wp)*step_dt CALL CD_AGG_Step_Moving(aggregate, step_dt, position, velocity, acceleration, step_converged, stalled, & n_iter, es, em, t_committed=time) + CALL CD_Profile_Enter(CD_PROF_CHECK) IF (es /= CD_AGG_OK) THEN CALL set_aggregate_error(es, em, run_stat, run_msg) EXIT mixed_run @@ -577,6 +606,9 @@ SUBROUTINE run_mixed_held_deck(deck, root, dt, has_dt, run_time, has_run_time, h ELSE consecutive_miss = 0 END IF + ! a committed step: count it, then its outputs + CALL CD_Profile_Step() + CALL CD_Profile_Enter(CD_PROF_OUTPUT) CALL CD_AGG_CalcOutput(aggregate, es, em) IF (es /= CD_AGG_OK) THEN CALL set_aggregate_error(es, em, run_stat, run_msg) @@ -588,6 +620,7 @@ SUBROUTINE run_mixed_held_deck(deck, root, dt, has_dt, run_time, has_run_time, h CALL set_aggregate_error(es, em, run_stat, run_msg) EXIT mixed_run END IF + CALL CD_Profile_Enter(CD_PROF_PROGRESS) CALL update_standalone_progress(progress, step, time) END DO @@ -800,22 +833,98 @@ SUBROUTINE update_standalone_progress(progress, step, simulated_time) CHARACTER(16) :: elapsed_text, remaining_text ! Every committed step: the time an abnormal end of the process reports. CALL CD_Fatal_Report_Time(simulated_time) - IF (step < progress%nstep .AND. MOD(step, progress%stride) /= 0) RETURN - CALL SYSTEM_CLOCK(now) - elapsed = CD_ZERO - IF (progress%count_rate > 0_int64 .AND. now >= progress%start_count) & - elapsed = REAL(now - progress%start_count, wp)/REAL(progress%count_rate, wp) - remaining = CD_ZERO - IF (step < progress%nstep .AND. elapsed > CD_ZERO) & - remaining = elapsed*REAL(progress%nstep - step, wp)/REAL(step, wp) - percent = 100.0_wp*REAL(step, wp)/REAL(progress%nstep, wp) - elapsed_text = format_wall_time(elapsed) - remaining_text = format_wall_time(remaining) - WRITE (output_unit, '(A,F6.1,A,F12.3,A,A,A,A)') ' Progress: ', percent, '% | t = ', & - simulated_time, ' s | elapsed ', TRIM(elapsed_text), ' | ETA ', TRIM(remaining_text) - FLUSH (output_unit) + IF (step >= progress%nstep .OR. MOD(step, progress%stride) == 0) THEN + CALL SYSTEM_CLOCK(now) + elapsed = CD_ZERO + IF (progress%count_rate > 0_int64 .AND. now >= progress%start_count) & + elapsed = REAL(now - progress%start_count, wp)/REAL(progress%count_rate, wp) + remaining = CD_ZERO + IF (step < progress%nstep .AND. elapsed > CD_ZERO) & + remaining = elapsed*REAL(progress%nstep - step, wp)/REAL(step, wp) + percent = 100.0_wp*REAL(step, wp)/REAL(progress%nstep, wp) + elapsed_text = format_wall_time(elapsed) + remaining_text = format_wall_time(remaining) + WRITE (output_unit, '(A,F6.1,A,F12.3,A,A,A,A)') ' Progress: ', percent, '% | t = ', & + simulated_time, ' s | elapsed ', TRIM(elapsed_text), ' | ETA ', TRIM(remaining_text) + FLUSH (output_unit) + END IF + ! the next step, or after the last step the finalisation + CALL CD_Profile_Enter(MERGE(CD_PROF_FINAL, CD_PROF_SOLVE, step >= progress%nstep)) END SUBROUTINE update_standalone_progress + SUBROUTINE print_profile() + !! The run-time profile requested with CABLEDYN_PROFILE (CableDyn_Profile): the wall time + !! of each phase of the run, the step counts and the Newton iterations, and the interior of + !! the finite-EI cable steps. Printed once, on stdout, at the end of the run. + LOGICAL, SAVE :: printed = .FALSE. + REAL(wp) :: seconds(CD_PROF_NPHASE), total, march, t_step, t_resid, t_eff, t_solve, t_am, t_tan + INTEGER(int64) :: march_steps, line_steps, line_iterations + INTEGER :: line_max_iterations, n_step, n_resid, n_solve, n_am, n_alloc, n_tan, k + IF (printed .OR. .NOT. CD_Profile_Armed()) RETURN + printed = .TRUE. + ! the running phase up to now: the finalisation of a completed run, or the phase in which a + ! failed run stopped + CALL CD_Profile_Flush() + DO k = 1, CD_PROF_NPHASE + seconds(k) = CD_Profile_Seconds(k) + END DO + total = SUM(seconds) + march = SUM(seconds(CD_PROF_FLUID:CD_PROF_PROGRESS)) + CALL CD_Profile_Counts(march_steps, line_steps, line_iterations, line_max_iterations) + WRITE (output_unit, '(A)') ' Run-time profile (CABLEDYN_PROFILE), wall-clock time:' + CALL profile_row('input parsing', seconds(CD_PROF_INPUT), total) + CALL profile_row('initialisation and statics', seconds(CD_PROF_INIT), total) + CALL profile_row('dynamic march', march, total) + CALL profile_row(' fluid sampled by the driver', seconds(CD_PROF_FLUID), total) + CALL profile_row(' line, cable and object steps', seconds(CD_PROF_SOLVE), total) + CALL profile_row(' checks and line failures', seconds(CD_PROF_CHECK), total) + CALL profile_row(' outputs', seconds(CD_PROF_OUTPUT), total) + CALL profile_row(' progress and bookkeeping', seconds(CD_PROF_PROGRESS), total) + CALL profile_row('finalisation', seconds(CD_PROF_FINAL), total) + CALL profile_row('total', total, total) + IF (march_steps > 0_int64) WRITE (output_unit, '(A,I0,A,A,A)') ' March: ', march_steps, & + ' committed step(s), ', fixed(1.0e3_wp*march/REAL(march_steps, wp), 4), ' ms per step.' + IF (line_steps > 0_int64) WRITE (output_unit, '(A,I0,A,I0,A,A,A,I0,A)') ' EI = 0 line steps: ', & + line_steps, ' (substeps and retries included), Newton iterations: ', line_iterations, ' (', & + fixed(REAL(line_iterations, wp)/REAL(line_steps, wp), 3), ' per line step, at most ', line_max_iterations, ').' + CALL CD_HermiteCable_Dyn_Get_Profile(n_step, n_resid, n_solve, n_am, n_alloc, t_step, t_resid, t_eff, & + t_solve, t_am, n_tan, t_tan) + IF (n_step > 0) THEN + WRITE (output_unit, '(A,I0,A,I0,A,I0,A,I0,A,I0,A)') ' Finite-EI cable steps: ', n_step, & + ', residual evaluations: ', n_resid, ', tangent assemblies: ', n_tan, ', linear solves: ', n_solve, & + ', intervals recovered by substeps: ', CD_HermiteCable_Dyn_Recovery_Count(), '.' + WRITE (output_unit, '(13A)') ' Finite-EI cable step time (s): residual ', fixed(t_resid, 3), & + ', tangent ', fixed(t_tan, 3), ', effective matrix ', fixed(t_eff, 3), ', linear solve ', & + fixed(t_solve, 3), ', added mass ', fixed(t_am, 3), ', other ', & + fixed(MAX(0.0_wp, t_step - (t_resid + t_tan + t_eff + t_solve + t_am)), 3), '.' + ELSE IF (.NOT. profile_cable_detail .AND. n_finite_ei > 0) THEN + WRITE (output_unit, '(A)') ' Finite-EI cable steps: not counted on the mixed EI = 0 + finite-EI route, '// & + 'whose cables step concurrently.' + END IF + FLUSH (output_unit) + END SUBROUTINE print_profile + + FUNCTION fixed(value, digits) RESULT(text) + !! value in fixed-point notation with the given decimals and a leading zero below one. + REAL(wp), INTENT(IN) :: value + INTEGER, INTENT(IN) :: digits + CHARACTER(:), ALLOCATABLE :: text + CHARACTER(32) :: buffer + CHARACTER(16) :: form + WRITE (form, '(A,I0,A)') '(F32.', digits, ')' + WRITE (buffer, form) value + text = TRIM(ADJUSTL(buffer)) + END FUNCTION fixed + + SUBROUTINE profile_row(label, seconds, total) + CHARACTER(*), INTENT(IN) :: label + REAL(wp), INTENT(IN) :: seconds, total + REAL(wp) :: share + share = 0.0_wp + IF (total > 0.0_wp) share = 100.0_wp*seconds/total + WRITE (output_unit, '(4X,A,T40,F12.3,A,F7.1,A)') label, seconds, ' s', share, ' %' + END SUBROUTINE profile_row + PURE FUNCTION format_wall_time(seconds) RESULT(text) REAL(wp), INTENT(IN) :: seconds CHARACTER(16) :: text diff --git a/doc/cli.rst b/doc/cli.rst index 1dd9f59..d9f0ec0 100644 --- a/doc/cli.rst +++ b/doc/cli.rst @@ -132,7 +132,8 @@ Standard streams - the initialisation report on mixed ``EI = 0`` + finite-EI decks; dynamic progress (``Dynamic simulation: …`` and ``Progress: …% | t = … s | elapsed … | ETA …``, at 5 % intervals); ``Recovery audit: …`` and ``Tensile monitor: …`` summaries; - ``CableDyn: FAILURE …`` event lines; and, last, the success line + ``CableDyn: FAILURE …`` event lines; the run-time profile when ``CABLEDYN_PROFILE`` is + set (:ref:`cli-profile`); and, last, the success line The formats of the report and progress records are shown in :doc:`outputs`. On success the final stdout line is exactly:: @@ -143,6 +144,71 @@ stdout is a human-readable log, not a machine-parseable stream: its records vary and the route. Automation should rely on the **exit status** and read results from the output files. To keep only the stdout records, discard stderr (``2>/dev/null`` or ``2>$null``). +.. _cli-profile: + +Run-time profile +~~~~~~~~~~~~~~~~ + +Set the environment variable ``CABLEDYN_PROFILE`` to ``1`` to see where the wall time of a run +goes. The driver then prints ``Run-time profile armed by CABLEDYN_PROFILE.`` at the start and, +at the end of the run (before the success line, or before the closing line of a failed run), a +breakdown such as: + +.. code-block:: text + + Run-time profile (CABLEDYN_PROFILE), wall-clock time: + input parsing 0.002 s 0.0 % + initialisation and statics 0.233 s 3.1 % + dynamic march 7.232 s 96.8 % + fluid sampled by the driver 0.050 s 0.7 % + line, cable and object steps 7.168 s 96.0 % + checks and line failures 0.001 s 0.0 % + outputs 0.013 s 0.2 % + progress and bookkeeping 0.000 s 0.0 % + finalisation 0.000 s 0.0 % + total 7.467 s 100.0 % + March: 600 committed step(s), 12.0528 ms per step. + EI = 0 line steps: 3621 (substeps and retries included), Newton iterations: 4661 (1.287 per line step, at most 2). + Finite-EI cable steps: 4849, residual evaluations: 21255, tangent assemblies: 10391, linear solves: 10391, intervals recovered by substeps: 0. + Finite-EI cable step time (s): residual 1.416, tangent 2.674, effective matrix 0.136, linear solve 0.943, added mass 0.167, other 0.457. + +The phases add up to the total, which runs from the start of the deck parse to the report. If the +run stops with an error, the time up to the stop counts to the phase in which it stopped, and +finalisation stays at zero. + +* **Input parsing** covers reading the deck and its auxiliary files. +* **Initialisation and statics** covers the synthesis of the deck's waves, building the models, + the static equilibrium, any modal analysis, and the initial output rows. For a static deck it + also covers writing the output + files. On the mixed ``EI = 0`` + finite-EI route it includes the deck parse that builds the + models. +* **Fluid sampled by the driver** is the deck wave and current field that the driver samples at + the nodes before each step. A finite-EI cable evaluates the wave kinematics inside its + element loads, and a ``motionFile`` Rigid6 or rod march samples the fluid within its step. On + those routes, that work counts as **line, cable and object steps**. +* **Outputs** covers the output channels, the per-line files, and the range-graph samples. + +The counts follow the march: + +* **EI = 0 line steps** counts every step of every tension-only line, including recovery + substeps, retries and, on the body marches, each re-step of a line within the body + iterations. **Newton iterations** is their total. +* **Finite-EI cable steps** counts the same for the cubic-Hermite cables. A cable clamped to a + body is re-stepped in every body iteration, so the count can exceed the number of march + steps. + +An unset or empty variable, or ``0``, leaves the profile off. The driver reads the variable once, +when it starts. + +The profile only reads the clock and never changes a result: every output file is identical +with and without it. Its cost is a few clock reads per step. + +On the mixed ``EI = 0`` + finite-EI route the cables step concurrently, so the profile does not +count the finite-EI cable steps there. It says so in their place, and leaves that route's +execution exactly as in an unprofiled run. + +``openfast.exe`` reads the same variable for its own module profile (see :doc:`faq`). + Exit codes ~~~~~~~~~~ diff --git a/doc/faq.rst b/doc/faq.rst index b83b517..226b305 100644 --- a/doc/faq.rst +++ b/doc/faq.rst @@ -104,7 +104,8 @@ OpenFAST coupling benchmark does **not** imply a fast coupled run: OpenFAST may call ``CalcOutput`` several times per physical step with different trial kinematics. Set the environment variable ``CABLEDYN_PROFILE=1`` before running ``openfast.exe`` to separate CableDyn solve, SeaState - sampling, output-probe, and native-I/O time. Keep ``ModCoupling`` fixed while + sampling, output-probe, and native-I/O time; the standalone driver reads the same variable + and prints its own breakdown (:ref:`cli-profile`). Keep ``ModCoupling`` fixed while comparing configurations. Do not switch to loose coupling merely to meet a wall-clock target; on the IEA-15MW reference model it materially changed platform and tension responses. Test ``OMP_NUM_THREADS=1`` as well as the intended threaded setting: three short lines can be too diff --git a/src/CableDyn_DeckDriver.f90 b/src/CableDyn_DeckDriver.f90 index 38b28db..fb5d855 100644 --- a/src/CableDyn_DeckDriver.f90 +++ b/src/CableDyn_DeckDriver.f90 @@ -142,6 +142,8 @@ MODULE CableDyn_DeckDriver CD_RIGID_NEWMARK_BETA USE CableDyn_SO3, ONLY: CD_Log_SO3, CD_Exp_SO3 USE CableDyn_PathIO, ONLY: CD_Open_Input, CD_Native_Path, CD_Strip_BOM + USE CableDyn_Profile, ONLY: CD_Profile_Enter, CD_Profile_Step, CD_PROF_INPUT, CD_PROF_INIT, CD_PROF_FLUID, & + CD_PROF_SOLVE, CD_PROF_CHECK, CD_PROF_OUTPUT, CD_PROF_PROGRESS, CD_PROF_FINAL USE, INTRINSIC :: IEEE_ARITHMETIC, ONLY: IEEE_IS_FINITE USE, INTRINSIC :: ISO_FORTRAN_ENV, ONLY: error_unit, output_unit, int64 IMPLICIT NONE @@ -6168,12 +6170,16 @@ SUBROUTINE run_deck_driver(deck_path, out_root, converged, ErrStat, ErrMsg) CALL fail(ErrStat, ErrMsg, 'FAILURE deck does not support seabed friction (the dynamic-point rule)'); RETURN END IF END IF + ! the wave synthesis or stream-function solve is initialisation; the bathymetry file read input + CALL CD_Profile_Enter(CD_PROF_INIT) CALL precompute_deck_wave(opts, ErrStat, ErrMsg) IF (ErrStat /= 0) RETURN IF (opts%has_bathymetry_file) THEN + CALL CD_Profile_Enter(CD_PROF_INPUT) CALL load_bathymetry_file(path_join(deck_dir(deck_path), opts%bathymetry_file), bathymetry, ErrStat, ErrMsg, & points=points) IF (ErrStat /= 0) RETURN + CALL CD_Profile_Enter(CD_PROF_INIT) END IF CALL print_static_input_warnings(types, points, lines, sections, opts) ! free Rigid6 bodies and rods (jointly with Free/Connect points) start at their static @@ -6503,6 +6509,8 @@ SUBROUTINE run_deck_driver(deck_path, out_root, converged, ErrStat, ErrMsg) CALL write_out(out_root, channels, lines, points, ne, q_all, q_off, ten_all, ten_off, converged, ErrStat, ErrMsg, & end_ten=end_all, end_force=end_vec, opts=opts, bathymetry=bathymetry) + ! a failed static run stays in initialisation, where it stopped + IF (ErrStat == CD_DECKDRV_OK .AND. converged) CALL CD_Profile_Enter(CD_PROF_FINAL) IF (opts%has_bathymetry_file) CALL CD_End_Bathymetry(bathymetry) IF (ErrStat /= 0) RETURN IF (.NOT. converged) THEN @@ -14336,6 +14344,7 @@ SUBROUTINE write_dynamic_out(out_root, channels, lines, points, opts, models, co RETURN END IF END IF + CALL CD_Profile_Enter(CD_PROF_SOLVE) IF (opts%has_motion_file) THEN CALL step_motion_models(models, lines, points, motion, step + 1, opts%dtM, & opts%recovery_max_substeps, step_converged, stalled, n_iter, step_substeps, & @@ -14344,6 +14353,7 @@ SUBROUTINE write_dynamic_out(out_root, channels, lines, points, opts, models, co CALL step_held_models(models, opts%dtM, opts%recovery_max_substeps, step_converged, stalled, & n_iter, step_substeps, es, em, step_work) END IF + CALL CD_Profile_Enter(CD_PROF_CHECK) IF (step_substeps > 1) THEN recovery_event_count = recovery_event_count + 1 recovery_max_substeps_used = MAX(recovery_max_substeps_used, step_substeps) @@ -14373,6 +14383,8 @@ SUBROUTINE write_dynamic_out(out_root, channels, lines, points, opts, models, co ErrMsg = TRIM(ErrMsg)//INSPECTION_NOTE RETURN END IF + CALL CD_Profile_Step() + CALL CD_Profile_Enter(CD_PROF_OUTPUT) IF (opts%has_motion_file) THEN CALL write_model_row(unit, t, channels, lines, points, models, output_work, ErrStat, ErrMsg, motion, step + 1) ELSE @@ -14389,6 +14401,7 @@ SUBROUTINE write_dynamic_out(out_root, channels, lines, points, opts, models, co CALL close_dynamic_line_outputs(pos_units, ten_units) RETURN END IF + CALL CD_Profile_Enter(CD_PROF_PROGRESS) CALL update_driver_progress(progress, step, t) END DO CLOSE (unit) @@ -14498,7 +14511,9 @@ SUBROUTINE write_system_dynamic_out(out_root, channels, lines, points, opts, sys ErrMsg = em RETURN END IF + CALL CD_Profile_Enter(CD_PROF_SOLVE) CALL CD_Step_System_DynamicPoints(system, opts%dtM, step_converged, stalled, n_iter, es, em) + CALL CD_Profile_Enter(CD_PROF_CHECK) IF (es /= CD_SYSTEM_OK) THEN CLOSE (unit) CALL close_dynamic_line_outputs(pos_units, ten_units) @@ -14534,6 +14549,8 @@ SUBROUTINE write_system_dynamic_out(out_root, channels, lines, points, opts, sys RETURN END IF END IF + CALL CD_Profile_Step() + CALL CD_Profile_Enter(CD_PROF_OUTPUT) CALL write_system_model_row(unit, t, channels, lines, points, system, output_work, ErrStat, ErrMsg) IF (ErrStat /= CD_DECKDRV_OK) THEN CLOSE (unit) @@ -14546,6 +14563,7 @@ SUBROUTINE write_system_dynamic_out(out_root, channels, lines, points, opts, sys CALL close_dynamic_line_outputs(pos_units, ten_units) RETURN END IF + CALL CD_Profile_Enter(CD_PROF_PROGRESS) CALL update_driver_progress(progress, step, t) END DO CLOSE (unit) @@ -14858,6 +14876,7 @@ SUBROUTINE write_rigid6_dynamic_out(out_root, channels, bodies, lines, points, o DO step = 1, nstep t = REAL(step, wp)*opts%dtM IF (use_prescribed_rigid6) THEN + CALL CD_Profile_Enter(CD_PROF_SOLVE) CALL step_prescribed_rigid6_system(system, points, opts, motion, rigid, step + 1, t, opts%dtM, & step_converged, stalled, n_iter, es, em, step_work, hydro_work) ELSE @@ -14869,9 +14888,11 @@ SUBROUTINE write_rigid6_dynamic_out(out_root, channels, bodies, lines, points, o ErrMsg = em RETURN END IF + CALL CD_Profile_Enter(CD_PROF_SOLVE) CALL step_rigid6_system(system, points, opts, rigid, t, opts%dtM, step_converged, stalled, n_iter, & es, em, step_work, bathymetry) END IF + CALL CD_Profile_Enter(CD_PROF_CHECK) IF (es /= CD_DECKDRV_OK) THEN CLOSE (unit) CALL close_dynamic_line_outputs(pos_units, ten_units) @@ -14906,6 +14927,8 @@ SUBROUTINE write_rigid6_dynamic_out(out_root, channels, bodies, lines, points, o RETURN END IF END IF + CALL CD_Profile_Step() + CALL CD_Profile_Enter(CD_PROF_OUTPUT) CALL write_system_model_row(unit, t, channels, lines, points, system, output_work, ErrStat, ErrMsg, & rigid=rigid, opts=opts, bathymetry=bathymetry) IF (ErrStat /= CD_DECKDRV_OK) THEN @@ -14919,6 +14942,7 @@ SUBROUTINE write_rigid6_dynamic_out(out_root, channels, bodies, lines, points, o CALL close_dynamic_line_outputs(pos_units, ten_units) RETURN END IF + CALL CD_Profile_Enter(CD_PROF_PROGRESS) CALL update_driver_progress(progress, step, t) END DO CLOSE (unit) @@ -15038,6 +15062,7 @@ SUBROUTINE write_rod_dynamic_out(out_root, channels, rod_types, rods, lines, poi DO step = 1, nstep t = REAL(step, wp)*opts%dtM IF (use_prescribed_rods) THEN + CALL CD_Profile_Enter(CD_PROF_SOLVE) CALL step_prescribed_rod_system(system, points, opts, motion, rod_state, step + 1, t, opts%dtM, & step_converged, stalled, n_iter, es, em, step_work, hydro_work, bathymetry) ELSE @@ -15050,9 +15075,11 @@ SUBROUTINE write_rod_dynamic_out(out_root, channels, rod_types, rods, lines, poi ErrMsg = em RETURN END IF + CALL CD_Profile_Enter(CD_PROF_SOLVE) CALL step_rod_system(system, points, opts, rod_state, t, opts%dtM, step_converged, stalled, n_iter, & es, em, step_work, bathymetry) END IF + CALL CD_Profile_Enter(CD_PROF_CHECK) IF (es /= CD_DECKDRV_OK) THEN CLOSE (unit) CALL close_dynamic_line_outputs(pos_units, ten_units) @@ -15080,6 +15107,8 @@ SUBROUTINE write_rod_dynamic_out(out_root, channels, rod_types, rods, lines, poi converged = .FALSE. RETURN END IF + CALL CD_Profile_Step() + CALL CD_Profile_Enter(CD_PROF_OUTPUT) CALL write_system_model_row(unit, t, channels, lines, points, system, output_work, ErrStat, ErrMsg, & rods=rod_state, opts=opts, bathymetry=bathymetry) IF (ErrStat /= CD_DECKDRV_OK) THEN @@ -15102,6 +15131,7 @@ SUBROUTINE write_rod_dynamic_out(out_root, channels, rod_types, rods, lines, poi CALL close_dynamic_rod_outputs(rod_pos_units) RETURN END IF + CALL CD_Profile_Enter(CD_PROF_PROGRESS) CALL update_driver_progress(progress, step, t) END DO CLOSE (unit) @@ -16063,6 +16093,7 @@ SUBROUTINE write_objects_dynamic_out(out_root, channels, bodies, rod_types, rods nstep = NINT(opts%tmax/opts%dtM) CALL start_driver_progress(progress, nstep, opts%dtM) DO step = 1, nstep + CALL CD_Profile_Enter(CD_PROF_SOLVE) t = REAL(step, wp)*opts%dtM old_rigid = rigid old_rst = rst @@ -16111,12 +16142,17 @@ SUBROUTINE write_objects_dynamic_out(out_root, channels, bodies, rod_types, rods CALL pin_rod(rst(k)) END DO END IF - IF (ErrStat == CD_DECKDRV_OK) CALL write_row(t) + IF (ErrStat == CD_DECKDRV_OK) THEN + CALL CD_Profile_Step() + CALL CD_Profile_Enter(CD_PROF_OUTPUT) + CALL write_row(t) + END IF IF (ErrStat /= CD_DECKDRV_OK) THEN converged = .FALSE. CLOSE (unit) RETURN END IF + CALL CD_Profile_Enter(CD_PROF_PROGRESS) CALL update_driver_progress(progress, step, t) END DO CLOSE (unit) @@ -16549,7 +16585,9 @@ SUBROUTINE write_multibody_dynamic_out(deck_path, out_root, channels, types, bod t = REAL(step, wp)*opts%dtM CALL mb_hydro(t, .FALSE.) IF (ErrStat /= CD_DECKDRV_OK) GOTO 800 + CALL CD_Profile_Enter(CD_PROF_SOLVE) CALL mb_step(mb, points, opts, t, opts%dtM, step_converged, stalled, n_iter, es, em, bathymetry) + CALL CD_Profile_Enter(CD_PROF_CHECK) IF (es /= CD_DECKDRV_OK) THEN ErrStat = es ErrMsg = em @@ -16569,9 +16607,12 @@ SUBROUTINE write_multibody_dynamic_out(deck_path, out_root, channels, types, bod GOTO 800 END IF END IF + CALL CD_Profile_Step() + CALL CD_Profile_Enter(CD_PROF_OUTPUT) CALL mb_outputs(t) IF (ErrStat /= CD_DECKDRV_OK) GOTO 800 IF (ALLOCATED(probe_rec) .AND. probe_armed) CALL probe_record(step, t) + CALL CD_Profile_Enter(CD_PROF_PROGRESS) CALL update_driver_progress(progress, step, t) END DO IF (mb%implicit .AND. mb%n_steps_imp > 0) THEN @@ -23697,6 +23738,7 @@ SUBROUTINE write_hermite_dynamic_out(out_root, channels, lines, points, opts, ca t = REAL(step, wp)*opts%dtM CALL update_hermite_deck_fluid(cables, opts, t, ErrStat, ErrMsg) IF (ErrStat /= CD_DECKDRV_OK) EXIT + CALL CD_Profile_Enter(CD_PROF_SOLVE) DO i = 1, SIZE(cables) IF (opts%has_motion_file) THEN pidx = find_point(points, lines(i)%nodeA) @@ -23732,12 +23774,15 @@ SUBROUTINE write_hermite_dynamic_out(out_root, channels, lines, points, opts, ca END IF END DO IF (ErrStat /= CD_DECKDRV_OK) EXIT + CALL CD_Profile_Step() + CALL CD_Profile_Enter(CD_PROF_OUTPUT) CALL write_hermite_model_row(unit, t, channels, lines, points, cables, ErrStat, ErrMsg, & motion=motion, motion_time_index=MERGE(step + 1, 0, opts%has_motion_file), & has_motion=opts%has_motion_file, ranges=ranges) IF (ErrStat == CD_DECKDRV_OK) & CALL write_dynamic_hermite_line_outputs(t, lines, cables, pos_units, ten_units, ErrStat, ErrMsg) IF (ErrStat /= CD_DECKDRV_OK) EXIT + CALL CD_Profile_Enter(CD_PROF_PROGRESS) CALL update_driver_progress(progress, step, t) END DO CLOSE (unit) @@ -24332,6 +24377,7 @@ SUBROUTINE write_finite_dynamic_out(out_root, channels, lines, points, opts, mod END IF CALL start_driver_progress(progress, nstep, opts%dtM) DO step = 1, nstep + CALL CD_Profile_Enter(CD_PROF_SOLVE) t = REAL(step, wp)*opts%dtM IF (opts%has_motion_file) THEN ! Moving-support march: the prescribed endpoint translations follow the motionFile @@ -24342,6 +24388,7 @@ SUBROUTINE write_finite_dynamic_out(out_root, channels, lines, points, opts, mod ELSE CALL step_finite_held_models(models, opts, t, opts%dtM, step_converged, stalled, n_iter, es, em) END IF + CALL CD_Profile_Enter(CD_PROF_CHECK) IF (es /= CD_DECKDRV_OK) THEN CLOSE (unit) CALL close_dynamic_line_outputs(pos_units, ten_units) @@ -24359,6 +24406,8 @@ SUBROUTINE write_finite_dynamic_out(out_root, channels, lines, points, opts, mod converged, ErrStat, ErrMsg) RETURN END IF + CALL CD_Profile_Step() + CALL CD_Profile_Enter(CD_PROF_OUTPUT) IF (opts%has_motion_file) THEN CALL write_finite_model_row(unit, t, channels, lines, points, models, output_work, ErrStat, ErrMsg, & motion, step + 1) @@ -24376,6 +24425,7 @@ SUBROUTINE write_finite_dynamic_out(out_root, channels, lines, points, opts, mod CALL close_dynamic_line_outputs(pos_units, ten_units) RETURN END IF + CALL CD_Profile_Enter(CD_PROF_PROGRESS) CALL update_driver_progress(progress, step, t) END DO CLOSE (unit) @@ -25790,6 +25840,9 @@ SUBROUTINE start_driver_progress(progress, nstep, dt) INTEGER, INTENT(IN) :: nstep REAL(wp), INTENT(IN) :: dt + ! the run so far (model build, statics, initial outputs) was the initialisation phase; the + ! march starts with the fluid update of its first step + CALL CD_Profile_Enter(MERGE(CD_PROF_FINAL, CD_PROF_FLUID, nstep <= 0)) progress%nstep = nstep progress%report_stride = MAX(1, (nstep + 19)/20) IF (nstep <= 0) RETURN @@ -25814,23 +25867,26 @@ SUBROUTINE update_driver_progress(progress, step, simulated_time) ! Every committed step: the time an abnormal end of the process reports. CALL CD_Fatal_Report_Time(simulated_time) - IF (progress%nstep <= 0 .OR. step <= 0) RETURN - IF (step < progress%nstep .AND. MOD(step, progress%report_stride) /= 0) RETURN - CALL SYSTEM_CLOCK(now) - IF (progress%count_rate > 0_int64 .AND. now >= progress%start_count) THEN - elapsed = REAL(now - progress%start_count, wp)/REAL(progress%count_rate, wp) - ELSE - elapsed = CD_ZERO - END IF - remaining = CD_ZERO - IF (step < progress%nstep .AND. elapsed > CD_ZERO) & - remaining = elapsed*REAL(progress%nstep - step, wp)/REAL(step, wp) - percent = 100.0_wp*REAL(step, wp)/REAL(progress%nstep, wp) - elapsed_text = wall_time_text(elapsed) - remaining_text = wall_time_text(remaining) - WRITE (output_unit, '(A,F6.1,A,F12.3,A,A,A,A)') ' Progress: ', percent, '% | t = ', & - simulated_time, ' s | elapsed ', TRIM(elapsed_text), ' | ETA ', TRIM(remaining_text) - FLUSH (output_unit) + IF (progress%nstep > 0 .AND. step > 0 .AND. & + (step >= progress%nstep .OR. MOD(step, progress%report_stride) == 0)) THEN + CALL SYSTEM_CLOCK(now) + IF (progress%count_rate > 0_int64 .AND. now >= progress%start_count) THEN + elapsed = REAL(now - progress%start_count, wp)/REAL(progress%count_rate, wp) + ELSE + elapsed = CD_ZERO + END IF + remaining = CD_ZERO + IF (step < progress%nstep .AND. elapsed > CD_ZERO) & + remaining = elapsed*REAL(progress%nstep - step, wp)/REAL(step, wp) + percent = 100.0_wp*REAL(step, wp)/REAL(progress%nstep, wp) + elapsed_text = wall_time_text(elapsed) + remaining_text = wall_time_text(remaining) + WRITE (output_unit, '(A,F6.1,A,F12.3,A,A,A,A)') ' Progress: ', percent, '% | t = ', & + simulated_time, ' s | elapsed ', TRIM(elapsed_text), ' | ETA ', TRIM(remaining_text) + FLUSH (output_unit) + END IF + ! the next step starts with its fluid update; after the last step the run finalises + CALL CD_Profile_Enter(MERGE(CD_PROF_FINAL, CD_PROF_FLUID, step >= progress%nstep)) END SUBROUTINE update_driver_progress PURE FUNCTION wall_time_text(seconds) RESULT(text) diff --git a/src/CableDyn_Model.f90 b/src/CableDyn_Model.f90 index c39010c..b2eb699 100644 --- a/src/CableDyn_Model.f90 +++ b/src/CableDyn_Model.f90 @@ -58,6 +58,7 @@ MODULE CableDyn_Model USE CableDyn_Mesh, ONLY: CD_Partition_Free_Dofs, CD_Validate_Connectivity USE CableDyn_Linalg, ONLY: CD_Solve_Dense_As_Banded, CD_Solve_Dense_As_Banded_Multiple, CD_Factor_Banded, & CD_Solve_Factored_Banded_Multiple + USE CableDyn_Profile, ONLY: CD_Profile_Count_Line_Step IMPLICIT NONE PRIVATE @@ -1815,6 +1816,7 @@ SUBROUTINE CD_Step_Model(model, dt, converged, stalled, n_iter, ErrStat, ErrMsg, n_iter, es, em, workspace=model%dynamic_workspace) END IF model%ve_dt = CD_ZERO + CALL CD_Profile_Count_Line_Step(n_iter) IF (es /= CD_DYN_OK) THEN ErrStat = model_status_from_dyn(es) ErrMsg = 'CableDyn_Model: step failed: '//TRIM(em) diff --git a/src/CableDyn_Profile.f90 b/src/CableDyn_Profile.f90 new file mode 100644 index 0000000..c40fcb9 --- /dev/null +++ b/src/CableDyn_Profile.f90 @@ -0,0 +1,129 @@ +! File: src/CableDyn_Profile.f90 +! SPDX-License-Identifier: Apache-2.0 +! Copyright (c) 2026 Jae Hoon Seo, SMI Lab, Inha University +MODULE CableDyn_Profile + !! Opt-in wall-clock profile of a standalone driver run, requested with the environment + !! variable CABLEDYN_PROFILE (as for the OpenFAST module). + !! + !! The driver arms it once at start, in the input phase. The run then marks where each phase + !! begins: CD_Profile_Enter(phase) adds the time since the previous mark to the phase that + !! was running and makes phase the running one, so the phases partition the run exactly and + !! a run that stops with an error has its time up to the stop in the phase it stopped in. + !! Each time march enters its fluid update, its step, its checks, its output and its + !! progress report in turn; CD_Profile_Step counts the committed steps. CD_Step_Model counts + !! the EI = 0 line steps and their Newton iterations. Unarmed, every entry point returns after + !! one test, so a run that does not ask for the profile, and a host that loads the library, + !! are not affected. The state is process-global and serves one run: the phase marks are + !! taken on the driver's thread, and the line-step counters are updated atomically because + !! lines step concurrently. + USE, INTRINSIC :: ISO_FORTRAN_ENV, ONLY: int64 + USE CableDyn_Precision, ONLY: wp + IMPLICIT NONE + PRIVATE + PUBLIC :: CD_Profile_Requested, CD_Profile_Arm, CD_Profile_Armed, CD_Profile_Enter, CD_Profile_Flush, & + CD_Profile_Step, CD_Profile_Count_Line_Step, CD_Profile_Seconds, CD_Profile_Counts + + INTEGER, PARAMETER, PUBLIC :: CD_PROF_INPUT = 1 ! deck parsing and auxiliary input files + INTEGER, PARAMETER, PUBLIC :: CD_PROF_INIT = 2 ! model build, static equilibrium, initial outputs + INTEGER, PARAMETER, PUBLIC :: CD_PROF_FLUID = 3 ! march: deck waves and current sampled by the driver + INTEGER, PARAMETER, PUBLIC :: CD_PROF_SOLVE = 4 ! march: line, cable and object steps + INTEGER, PARAMETER, PUBLIC :: CD_PROF_CHECK = 5 ! march: plausibility checks and line failures + INTEGER, PARAMETER, PUBLIC :: CD_PROF_OUTPUT = 6 ! march: output channels, line files, range graphs + INTEGER, PARAMETER, PUBLIC :: CD_PROF_PROGRESS = 7 ! march: progress report and bookkeeping + INTEGER, PARAMETER, PUBLIC :: CD_PROF_FINAL = 8 ! after the march: closing files, range files + INTEGER, PARAMETER, PUBLIC :: CD_PROF_NPHASE = 8 + + LOGICAL, SAVE :: armed = .FALSE. + INTEGER, SAVE :: current = CD_PROF_INPUT + INTEGER(int64), SAVE :: rate = 0_int64, last = 0_int64 + INTEGER(int64), SAVE :: ticks(CD_PROF_NPHASE) = 0_int64 + INTEGER(int64), SAVE :: n_march_steps = 0_int64, n_line_steps = 0_int64, n_line_iter = 0_int64 + INTEGER, SAVE :: max_line_iter = 0 + +CONTAINS + + LOGICAL FUNCTION CD_Profile_Requested() RESULT(requested) + !! TRUE when CABLEDYN_PROFILE is set to a non-empty value other than 0. + CHARACTER(32) :: value + INTEGER :: stat + value = '' + CALL GET_ENVIRONMENT_VARIABLE('CABLEDYN_PROFILE', value, STATUS=stat) + requested = stat == 0 .AND. LEN_TRIM(value) > 0 .AND. TRIM(value) /= '0' + END FUNCTION CD_Profile_Requested + + SUBROUTINE CD_Profile_Arm() + !! Zero the phases and counters and start the clock in the input phase. + ticks = 0_int64 + n_march_steps = 0_int64 + n_line_steps = 0_int64 + n_line_iter = 0_int64 + max_line_iter = 0 + current = CD_PROF_INPUT + CALL SYSTEM_CLOCK(last, rate) + armed = rate > 0_int64 + END SUBROUTINE CD_Profile_Arm + + LOGICAL FUNCTION CD_Profile_Armed() RESULT(is_armed) + is_armed = armed + END FUNCTION CD_Profile_Armed + + SUBROUTINE CD_Profile_Enter(phase) + !! Add the wall time since the previous mark to the running phase, and run phase (a + !! CD_PROF_* value) from here. + INTEGER, INTENT(IN) :: phase + IF (.NOT. armed) RETURN + IF (phase < 1 .OR. phase > CD_PROF_NPHASE) RETURN + CALL CD_Profile_Flush() + current = phase + END SUBROUTINE CD_Profile_Enter + + SUBROUTINE CD_Profile_Flush() + !! Add the wall time since the previous mark to the running phase, which keeps running. + INTEGER(int64) :: now + IF (.NOT. armed) RETURN + CALL SYSTEM_CLOCK(now) + ticks(current) = ticks(current) + (now - last) + last = now + END SUBROUTINE CD_Profile_Flush + + SUBROUTINE CD_Profile_Step() + !! Count a committed step of the march. + IF (.NOT. armed) RETURN + n_march_steps = n_march_steps + 1_int64 + END SUBROUTINE CD_Profile_Step + + SUBROUTINE CD_Profile_Count_Line_Step(n_iter) + !! Count one EI = 0 line step (a nominal step, a recovery substep or a retry) and its + !! Newton iterations. Lines of a system step in an OpenMP team, so the updates are atomic. + INTEGER, INTENT(IN) :: n_iter + INTEGER(int64) :: iterations + IF (.NOT. armed) RETURN + iterations = INT(MAX(0, n_iter), int64) + !$OMP ATOMIC UPDATE + n_line_steps = n_line_steps + 1_int64 + !$OMP ATOMIC UPDATE + n_line_iter = n_line_iter + iterations + !$OMP ATOMIC UPDATE + max_line_iter = MAX(max_line_iter, n_iter) + END SUBROUTINE CD_Profile_Count_Line_Step + + REAL(wp) FUNCTION CD_Profile_Seconds(phase) RESULT(seconds) + !! Wall time attributed to phase so far [s]; zero when the profile is not armed. + INTEGER, INTENT(IN) :: phase + seconds = 0.0_wp + IF (.NOT. armed) RETURN + IF (phase < 1 .OR. phase > CD_PROF_NPHASE) RETURN + seconds = REAL(ticks(phase), wp)/REAL(rate, wp) + END FUNCTION CD_Profile_Seconds + + SUBROUTINE CD_Profile_Counts(march_steps, line_steps, line_iterations, line_max_iterations) + !! Committed march steps, EI = 0 line steps, their Newton iterations and the most in one step. + INTEGER(int64), INTENT(OUT) :: march_steps, line_steps, line_iterations + INTEGER, INTENT(OUT) :: line_max_iterations + march_steps = n_march_steps + line_steps = n_line_steps + line_iterations = n_line_iter + line_max_iterations = max_line_iter + END SUBROUTINE CD_Profile_Counts + +END MODULE CableDyn_Profile diff --git a/tests/check_driver_profile.cmake b/tests/check_driver_profile.cmake new file mode 100644 index 0000000..56aee54 --- /dev/null +++ b/tests/check_driver_profile.cmake @@ -0,0 +1,89 @@ +# SPDX-License-Identifier: Apache-2.0 +# The run-time profile of the standalone driver (CABLEDYN_PROFILE). The same deck runs +# without the variable, with CABLEDYN_PROFILE=0 and with CABLEDYN_PROFILE=1. Only the last +# run prints the profile, before the success line, which stays the last stdout line; its +# phase rows and step counts are present; and every output file of the three runs is +# byte-identical, so the profile never changes a result. +# Optional: EXPECT (a regular expression the profiled stdout must also match). +if(NOT DEFINED DRIVER OR NOT DEFINED DECK OR NOT DEFINED OUTPUT_ROOT) + message(FATAL_ERROR "DRIVER, DECK, and OUTPUT_ROOT are required") +endif() + +function(run_driver label profile_value) + if(profile_value STREQUAL "") + unset(ENV{CABLEDYN_PROFILE}) + else() + set(ENV{CABLEDYN_PROFILE} "${profile_value}") + endif() + execute_process( + COMMAND "${DRIVER}" "${DECK}" "${OUTPUT_ROOT}_${label}" + RESULT_VARIABLE result + OUTPUT_VARIABLE out + ERROR_VARIABLE err) + if(NOT result EQUAL 0) + message(FATAL_ERROR "${label} run returned ${result}, expected 0\nstdout:\n${out}\nstderr:\n${err}") + endif() + set(stdout_${label} "${out}" PARENT_SCOPE) +endfunction() + +run_driver(unset "") +run_driver(zero "0") +run_driver(profiled "1") + +foreach(label unset zero) + if(stdout_${label} MATCHES "Run-time profile") + message(FATAL_ERROR "the ${label} run printed a profile:\n${stdout_${label}}") + endif() +endforeach() + +set(profiled "${stdout_profiled}") +foreach(row + "Run-time profile armed by CABLEDYN_PROFILE\\." + "Run-time profile \\(CABLEDYN_PROFILE\\), wall-clock time:" + "\n input parsing +[0-9]+\\.[0-9]+ s +[0-9]+\\.[0-9] %" + "\n initialisation and statics +[0-9]+\\.[0-9]+ s" + "\n dynamic march +[0-9]+\\.[0-9]+ s" + "\n fluid sampled by the driver +[0-9]+\\.[0-9]+ s" + "\n line, cable and object steps +[0-9]+\\.[0-9]+ s" + "\n checks and line failures +[0-9]+\\.[0-9]+ s" + "\n outputs +[0-9]+\\.[0-9]+ s" + "\n progress and bookkeeping +[0-9]+\\.[0-9]+ s" + "\n finalisation +[0-9]+\\.[0-9]+ s" + "\n total +[0-9]+\\.[0-9]+ s +100\\.0 %" + "\n March: [1-9][0-9]* committed step\\(s\\), [0-9]+\\.[0-9]+ ms per step\\.") + if(NOT profiled MATCHES "${row}") + message(FATAL_ERROR "the profiled stdout lacks \"${row}\":\n${profiled}") + endif() +endforeach() +if(DEFINED EXPECT AND NOT profiled MATCHES "${EXPECT}") + message(FATAL_ERROR "the profiled stdout lacks \"${EXPECT}\":\n${profiled}") +endif() +# the profile comes before the success line, which stays the last stdout line +string(STRIP "${profiled}" profiled_stripped) +if(NOT profiled_stripped MATCHES "\n total [^\n]*\n.*CableDyn_driver: converged run written to [^\n]*$") + message(FATAL_ERROR "the success line is not the last stdout line after the profile:\n${profiled}") +endif() + +# every output file of the reference run, byte-identical in the other two runs +get_filename_component(out_dir "${OUTPUT_ROOT}" DIRECTORY) +get_filename_component(out_name "${OUTPUT_ROOT}" NAME) +file(GLOB reference_files "${out_dir}/${out_name}_unset*") +list(FILTER reference_files EXCLUDE REGEX "\\.lock$") +list(LENGTH reference_files n_files) +if(n_files EQUAL 0) + message(FATAL_ERROR "the reference run wrote no output files under ${OUTPUT_ROOT}_unset") +endif() +foreach(reference IN LISTS reference_files) + file(SHA256 "${reference}" reference_hash) + foreach(label zero profiled) + string(REPLACE "${out_name}_unset" "${out_name}_${label}" other "${reference}") + if(NOT EXISTS "${other}") + message(FATAL_ERROR "the ${label} run did not write ${other}") + endif() + file(SHA256 "${other}" other_hash) + if(NOT other_hash STREQUAL reference_hash) + message(FATAL_ERROR "${other} differs from ${reference}: the profile changed a result") + endif() + endforeach() +endforeach() +message(STATUS "driver profile: ${n_files} output file(s) identical with and without the profile") diff --git a/tests/check_driver_profile_failure.cmake b/tests/check_driver_profile_failure.cmake new file mode 100644 index 0000000..ff924c4 --- /dev/null +++ b/tests/check_driver_profile_failure.cmake @@ -0,0 +1,31 @@ +# SPDX-License-Identifier: Apache-2.0 +# The run-time profile of a run that stops with an error (CABLEDYN_PROFILE): the deck's march +# fails to converge, the driver exits with code 2, and the profile it prints before the closing +# line charges the time up to the stop to the phase that was running, not to the finalisation +# the run never reached (which stays exactly zero). +if(NOT DEFINED DRIVER OR NOT DEFINED DECK OR NOT DEFINED OUTPUT_ROOT) + message(FATAL_ERROR "DRIVER, DECK, and OUTPUT_ROOT are required") +endif() + +set(ENV{CABLEDYN_PROFILE} "1") +execute_process( + COMMAND "${DRIVER}" "${DECK}" "${OUTPUT_ROOT}" + RESULT_VARIABLE result + OUTPUT_VARIABLE out + ERROR_VARIABLE err) +if(NOT result EQUAL 2) + message(FATAL_ERROR "the run returned ${result}, expected 2\nstdout:\n${out}\nstderr:\n${err}") +endif() +foreach(row + "Run-time profile \\(CABLEDYN_PROFILE\\), wall-clock time:" + "\n dynamic march +[0-9]+\\.[0-9]+ s" + "\n finalisation +0\\.000 s +0\\.0 %" + "\n total +[0-9]+\\.[0-9]+ s +100\\.0 %") + if(NOT out MATCHES "${row}") + message(FATAL_ERROR "the stdout of the failed run lacks \"${row}\":\n${out}") + endif() +endforeach() +if(NOT err MATCHES "CableDyn_driver: ended with exit code 2") + message(FATAL_ERROR "the stderr of the failed run lacks the closing line:\n${err}") +endif() +message(STATUS "driver profile of a failed run: no time charged to finalisation") diff --git a/tests/test_profile.f90 b/tests/test_profile.f90 new file mode 100644 index 0000000..ed1244a --- /dev/null +++ b/tests/test_profile.f90 @@ -0,0 +1,126 @@ +! File: tests/test_profile.f90 +! SPDX-License-Identifier: Apache-2.0 +! Copyright (c) 2026 Jae Hoon Seo, SMI Lab, Inha University +PROGRAM test_profile + !! The run-time profile of the driver (CableDyn_Profile): + !! 1. Unarmed, it records nothing. + !! 2. Armed, the phases partition the elapsed time: each mark charges the time since the + !! previous one to the phase that was running, so their sum is the time from arming to + !! the last flush. + !! 3. Time spent in a phase that never hands over (a run that stops with an error) stays + !! in that phase when the report flushes it, and a phase never entered (the + !! finalisation of such a run) stays exactly zero. + !! 4. The EI = 0 line-step counters are exact when the lines of an OpenMP team update them + !! at once. + USE CableDyn_Precision, ONLY: wp + USE CableDyn_Profile + USE CableDyn_FatalReport, ONLY: CD_Fatal_Thread_Init + USE, INTRINSIC :: ISO_FORTRAN_ENV, ONLY: int64 + IMPLICIT NONE + INTEGER :: nfail + + nfail = 0 + CALL case_unarmed() + CALL case_partition_and_failure() + CALL case_concurrent_counts() + IF (nfail > 0) THEN + WRITE (*, '(A,I0,A)') 'test_profile: ', nfail, ' failure(s)' + ERROR STOP 1 + END IF + WRITE (*, '(A)') 'test_profile: all checks passed' + +CONTAINS + + SUBROUTINE require(cond, label) + LOGICAL, INTENT(IN) :: cond + CHARACTER(*), INTENT(IN) :: label + IF (.NOT. cond) THEN + WRITE (*, '(A)') 'MISMATCH ['//label//']' + nfail = nfail + 1 + END IF + END SUBROUTINE require + + SUBROUTINE busy(seconds) + !! Spin for at least the given wall time. + REAL(wp), INTENT(IN) :: seconds + INTEGER(int64) :: c0, c, rate + CALL SYSTEM_CLOCK(c0, rate) + DO + CALL SYSTEM_CLOCK(c) + IF (REAL(c - c0, wp) >= seconds*REAL(rate, wp)) EXIT + END DO + END SUBROUTINE busy + + REAL(wp) FUNCTION total_seconds() RESULT(s) + INTEGER :: k + s = 0.0_wp + DO k = 1, CD_PROF_NPHASE + s = s + CD_Profile_Seconds(k) + END DO + END FUNCTION total_seconds + + SUBROUTINE case_unarmed() + INTEGER(int64) :: march, steps, iterations + INTEGER :: max_iterations + CALL require(.NOT. CD_Profile_Armed(), 'unarmed:not-armed-at-start') + CALL CD_Profile_Enter(CD_PROF_SOLVE) + CALL busy(0.002_wp) + CALL CD_Profile_Flush() + CALL CD_Profile_Step() + CALL CD_Profile_Count_Line_Step(4) + CALL CD_Profile_Counts(march, steps, iterations, max_iterations) + CALL require(total_seconds() <= 0.0_wp, 'unarmed:no-time') + CALL require(march == 0 .AND. steps == 0 .AND. iterations == 0 .AND. max_iterations == 0, 'unarmed:no-counts') + END SUBROUTINE case_unarmed + + SUBROUTINE case_partition_and_failure() + INTEGER(int64) :: c0, c1, rate + REAL(wp) :: elapsed + CALL SYSTEM_CLOCK(c0, rate) + CALL CD_Profile_Arm() + CALL require(CD_Profile_Armed(), 'phases:armed') + CALL busy(0.010_wp) ! input + CALL CD_Profile_Enter(CD_PROF_INIT) + CALL busy(0.020_wp) ! initialisation + CALL CD_Profile_Enter(CD_PROF_SOLVE) + CALL busy(0.030_wp) ! a step that stops with an error: no further mark + CALL CD_Profile_Flush() ! the report of the failed run + CALL SYSTEM_CLOCK(c1) + elapsed = REAL(c1 - c0, wp)/REAL(rate, wp) + CALL require(CD_Profile_Seconds(CD_PROF_INPUT) >= 0.010_wp, 'phases:input') + CALL require(CD_Profile_Seconds(CD_PROF_INIT) >= 0.020_wp, 'phases:initialisation') + CALL require(CD_Profile_Seconds(CD_PROF_SOLVE) >= 0.030_wp, 'phases:failed-step-stays-in-its-phase') + CALL require(CD_Profile_Seconds(CD_PROF_FINAL) <= 0.0_wp, 'phases:finalisation-never-entered-is-zero') + CALL require(total_seconds() >= 0.060_wp .AND. total_seconds() <= elapsed, 'phases:sum-is-the-elapsed-time') + ! a second flush adds the new time to the same running phase + CALL busy(0.005_wp) + CALL CD_Profile_Flush() + CALL require(CD_Profile_Seconds(CD_PROF_SOLVE) >= 0.035_wp .AND. CD_Profile_Seconds(CD_PROF_FINAL) <= 0.0_wp, & + 'phases:flush-keeps-the-running-phase') + ! re-arming starts a new profile + CALL CD_Profile_Arm() + CALL require(total_seconds() <= 0.0_wp, 'phases:re-armed-from-zero') + END SUBROUTINE case_partition_and_failure + + SUBROUTINE case_concurrent_counts() + INTEGER, PARAMETER :: N = 20000 + INTEGER(int64) :: march, steps, iterations + INTEGER :: max_iterations, i + CALL CD_Profile_Arm() + !$OMP PARALLEL NUM_THREADS(4) DEFAULT(SHARED) PRIVATE(i) + CALL CD_Fatal_Thread_Init() + !$OMP DO SCHEDULE(STATIC) + DO i = 1, N + CALL CD_Profile_Count_Line_Step(MOD(i, 7)) + END DO + !$OMP END DO + !$OMP END PARALLEL + CALL CD_Profile_Step() + CALL CD_Profile_Counts(march, steps, iterations, max_iterations) + CALL require(march == 1, 'counts:march-steps') + CALL require(steps == N, 'counts:line-steps-exact') + CALL require(iterations == SUM([(INT(MOD(i, 7), int64), i=1, N)]), 'counts:newton-iterations-exact') + CALL require(max_iterations == 6, 'counts:most-iterations') + END SUBROUTINE case_concurrent_counts + +END PROGRAM test_profile