Use printf instead of echo to write trace file (#5397)

Echo commands were combined into a single block to write to $trace_file more efficiently, reducing the number of system calls. Added error handling to prevent tracing from causing workflow failures. Signed-off-by: Nico Holguin <[email protected]> Signed-off-by: Paolo Di Tommaso <[email protected]> Co-authored-by: nholguin <[email protected]> Co-authored-by: Paolo Di Tommaso <[email protected]>
nextflow-io · Dec 9, 2024 · c6434d4 · c6434d4
1 parent 18f7de1
commit c6434d4
Show file tree

Hide file tree

Showing 2 changed files with 60 additions and 54 deletions.
diff --git a/modules/nextflow/src/main/resources/nextflow/executor/command-trace.txt b/modules/nextflow/src/main/resources/nextflow/executor/command-trace.txt
@@ -114,26 +114,28 @@ nxf_mem_watch() {
     done
 
     ## result struct: pid %mem vmem rss peak_vmem peak_rss
-    echo "%mem=${nxf_stat_ret[1]}"      >> $trace_file
-    echo "vmem=${nxf_stat_ret[2]}"      >> $trace_file
-    echo "rss=${nxf_stat_ret[3]}"       >> $trace_file
-    echo "peak_vmem=${nxf_stat_ret[4]}" >> $trace_file
-    echo "peak_rss=${nxf_stat_ret[5]}"  >> $trace_file
-    echo "vol_ctxt=${nxf_stat_ret[6]}"  >> $trace_file
-    echo "inv_ctxt=${nxf_stat_ret[7]}"  >> $trace_file
+    printf "%s\n" \
+        "%mem=${nxf_stat_ret[1]}" \
+        "vmem=${nxf_stat_ret[2]}" \
+        "rss=${nxf_stat_ret[3]}" \
+        "peak_vmem=${nxf_stat_ret[4]}" \
+        "peak_rss=${nxf_stat_ret[5]}" \
+        "vol_ctxt=${nxf_stat_ret[6]}" \
+        "inv_ctxt=${nxf_stat_ret[7]}" >> "$trace_file" || >&2 echo "Error: Failed to append to file: $trace_file"
 }
 
 nxf_write_trace() {
-    echo "nextflow.trace/v2"           > $trace_file
-    echo "realtime=$wall_time"         >> $trace_file
-    echo "%cpu=$ucpu"                  >> $trace_file
-    echo "cpu_model=$cpu_model"        >> $trace_file
-    echo "rchar=${io_stat1[0]}"        >> $trace_file
-    echo "wchar=${io_stat1[1]}"        >> $trace_file
-    echo "syscr=${io_stat1[2]}"        >> $trace_file
-    echo "syscw=${io_stat1[3]}"        >> $trace_file
-    echo "read_bytes=${io_stat1[4]}"   >> $trace_file
-    echo "write_bytes=${io_stat1[5]}"  >> $trace_file
+    printf "%s\n" \
+        "nextflow.trace/v2" \
+        "realtime=$wall_time" \
+        "%cpu=$ucpu" \
+        "cpu_model=$cpu_model" \
+        "rchar=${io_stat1[0]}" \
+        "wchar=${io_stat1[1]}" \
+        "syscr=${io_stat1[2]}" \
+        "syscw=${io_stat1[3]}" \
+        "read_bytes=${io_stat1[4]}" \
+        "write_bytes=${io_stat1[5]}" > "$trace_file" || >&2 echo "Error: Failed to write to file: $trace_file"
 }
 
 nxf_trace_mac() {
@@ -199,16 +201,17 @@ nxf_trace_linux() {
     local wall_time=$((end_millis-start_millis))
     [ $NXF_DEBUG = 1 ] && echo "+++ STATS %CPU=$ucpu TIME=$wall_time I/O=${io_stat1[*]}"
 
-    echo "nextflow.trace/v2"           > $trace_file
-    echo "realtime=$wall_time"         >> $trace_file
-    echo "%cpu=$ucpu"                  >> $trace_file
-    echo "cpu_model=$cpu_model"        >> $trace_file
-    echo "rchar=${io_stat1[0]}"        >> $trace_file
-    echo "wchar=${io_stat1[1]}"        >> $trace_file
-    echo "syscr=${io_stat1[2]}"        >> $trace_file
-    echo "syscw=${io_stat1[3]}"        >> $trace_file
-    echo "read_bytes=${io_stat1[4]}"   >> $trace_file
-    echo "write_bytes=${io_stat1[5]}"  >> $trace_file
+    printf "%s\n" \
+        "nextflow.trace/v2" \
+        "realtime=$wall_time" \
+        "%cpu=$ucpu" \
+        "cpu_model=$cpu_model" \
+        "rchar=${io_stat1[0]}" \
+        "wchar=${io_stat1[1]}" \
+        "syscr=${io_stat1[2]}" \
+        "syscw=${io_stat1[3]}" \
+        "read_bytes=${io_stat1[4]}" \
+        "write_bytes=${io_stat1[5]}" > "$trace_file" || >&2 echo "Error: Failed to write to file: $trace_file"
 
     ## join nxf_mem_watch
     [ -e /proc/$mem_proc ] && eval "echo 'DONE' >&$mem_fd" || true

diff --git a/modules/nextflow/src/test/resources/nextflow/executor/test-bash-wrapper-with-trace.txt b/modules/nextflow/src/test/resources/nextflow/executor/test-bash-wrapper-with-trace.txt
@@ -98,26 +98,28 @@ nxf_mem_watch() {
         count=$((count+1))
     done
 
-    echo "%mem=${nxf_stat_ret[1]}"      >> $trace_file
-    echo "vmem=${nxf_stat_ret[2]}"      >> $trace_file
-    echo "rss=${nxf_stat_ret[3]}"       >> $trace_file
-    echo "peak_vmem=${nxf_stat_ret[4]}" >> $trace_file
-    echo "peak_rss=${nxf_stat_ret[5]}"  >> $trace_file
-    echo "vol_ctxt=${nxf_stat_ret[6]}"  >> $trace_file
-    echo "inv_ctxt=${nxf_stat_ret[7]}"  >> $trace_file
+    printf "%s\n" \
+        "%mem=${nxf_stat_ret[1]}" \
+        "vmem=${nxf_stat_ret[2]}" \
+        "rss=${nxf_stat_ret[3]}" \
+        "peak_vmem=${nxf_stat_ret[4]}" \
+        "peak_rss=${nxf_stat_ret[5]}" \
+        "vol_ctxt=${nxf_stat_ret[6]}" \
+        "inv_ctxt=${nxf_stat_ret[7]}" >> "$trace_file" || >&2 echo "Error: Failed to append to file: $trace_file"
 }
 
 nxf_write_trace() {
-    echo "nextflow.trace/v2"           > $trace_file
-    echo "realtime=$wall_time"         >> $trace_file
-    echo "%cpu=$ucpu"                  >> $trace_file
-    echo "cpu_model=$cpu_model"        >> $trace_file
-    echo "rchar=${io_stat1[0]}"        >> $trace_file
-    echo "wchar=${io_stat1[1]}"        >> $trace_file
-    echo "syscr=${io_stat1[2]}"        >> $trace_file
-    echo "syscw=${io_stat1[3]}"        >> $trace_file
-    echo "read_bytes=${io_stat1[4]}"   >> $trace_file
-    echo "write_bytes=${io_stat1[5]}"  >> $trace_file
+    printf "%s\n" \
+        "nextflow.trace/v2" \
+        "realtime=$wall_time" \
+        "%cpu=$ucpu" \
+        "cpu_model=$cpu_model" \
+        "rchar=${io_stat1[0]}" \
+        "wchar=${io_stat1[1]}" \
+        "syscr=${io_stat1[2]}" \
+        "syscw=${io_stat1[3]}" \
+        "read_bytes=${io_stat1[4]}" \
+        "write_bytes=${io_stat1[5]}" > "$trace_file" || >&2 echo "Error: Failed to write to file: $trace_file"
 }
 
 nxf_trace_mac() {
@@ -173,16 +175,17 @@ nxf_trace_linux() {
     local wall_time=$((end_millis-start_millis))
     [ $NXF_DEBUG = 1 ] && echo "+++ STATS %CPU=$ucpu TIME=$wall_time I/O=${io_stat1[*]}"
 
-    echo "nextflow.trace/v2"           > $trace_file
-    echo "realtime=$wall_time"         >> $trace_file
-    echo "%cpu=$ucpu"                  >> $trace_file
-    echo "cpu_model=$cpu_model"        >> $trace_file
-    echo "rchar=${io_stat1[0]}"        >> $trace_file
-    echo "wchar=${io_stat1[1]}"        >> $trace_file
-    echo "syscr=${io_stat1[2]}"        >> $trace_file
-    echo "syscw=${io_stat1[3]}"        >> $trace_file
-    echo "read_bytes=${io_stat1[4]}"   >> $trace_file
-    echo "write_bytes=${io_stat1[5]}"  >> $trace_file
+    printf "%s\n" \
+        "nextflow.trace/v2" \
+        "realtime=$wall_time" \
+        "%cpu=$ucpu" \
+        "cpu_model=$cpu_model" \
+        "rchar=${io_stat1[0]}" \
+        "wchar=${io_stat1[1]}" \
+        "syscr=${io_stat1[2]}" \
+        "syscw=${io_stat1[3]}" \
+        "read_bytes=${io_stat1[4]}" \
+        "write_bytes=${io_stat1[5]}" > "$trace_file" || >&2 echo "Error: Failed to write to file: $trace_file"
 
     [ -e /proc/$mem_proc ] && eval "echo 'DONE' >&$mem_fd" || true
     wait $mem_proc 2>/dev/null || true