feat: add a run-time profile to the standalone driver

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:

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

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=$<TARGET_FILE:cabledyn>
+    -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=$<TARGET_FILE:cabledyn>
+    -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=$<TARGET_FILE:cabledyn>
+    -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

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