Use command groups for $trace_file writes to reduce syscalls and impr…

…ove robustness 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]>
nextflow-io · Oct 11, 2024 · 379299b · 379299b
1 parent 8eb0c39
commit 379299b
Show file tree

Hide file tree

Showing 2 changed files with 66 additions and 56 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,30 @@ 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
+    {
+        echo "%mem=${nxf_stat_ret[1]}"
+        echo "vmem=${nxf_stat_ret[2]}"
+        echo "rss=${nxf_stat_ret[3]}"
+        echo "peak_vmem=${nxf_stat_ret[4]}"
+        echo "peak_rss=${nxf_stat_ret[5]}"
+        echo "vol_ctxt=${nxf_stat_ret[6]}"
+        echo "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
+    {
+        echo "nextflow.trace/v2"
+        echo "realtime=$wall_time"
+        echo "%cpu=$ucpu"
+        echo "cpu_model=$cpu_model"
+        echo "rchar=${io_stat1[0]}"
+        echo "wchar=${io_stat1[1]}"
+        echo "syscr=${io_stat1[2]}"
+        echo "syscw=${io_stat1[3]}"
+        echo "read_bytes=${io_stat1[4]}"
+        echo "write_bytes=${io_stat1[5]}"
+    } > $trace_file || >&2 echo "Error: Failed to write to file: $trace_file"
 }
 
 nxf_trace_mac() {
@@ -172,7 +176,6 @@ nxf_trace_linux() {
     local start_millis=$(nxf_date)
     ## capture error and kill mem watcher
     trap 'kill $mem_proc' ERR
-
     ## run task script
     {{trace_cmd}} &
     local task=$!
@@ -199,16 +202,18 @@ 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
+    {
+        echo "nextflow.trace/v2"
+        echo "realtime=$wall_time"
+        echo "%cpu=$ucpu"
+        echo "cpu_model=$cpu_model"
+        echo "rchar=${io_stat1[0]}"
+        echo "wchar=${io_stat1[1]}"
+        echo "syscr=${io_stat1[2]}"
+        echo "syscw=${io_stat1[3]}"
+        echo "read_bytes=${io_stat1[4]}"
+        echo "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,30 @@ 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
+    {
+        echo "%mem=${nxf_stat_ret[1]}"
+        echo "vmem=${nxf_stat_ret[2]}"
+        echo "rss=${nxf_stat_ret[3]}"
+        echo "peak_vmem=${nxf_stat_ret[4]}"
+        echo "peak_rss=${nxf_stat_ret[5]}"
+        echo "vol_ctxt=${nxf_stat_ret[6]}"
+        echo "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
+    {
+        echo "nextflow.trace/v2"
+        echo "realtime=$wall_time"
+        echo "%cpu=$ucpu"
+        echo "cpu_model=$cpu_model"
+        echo "rchar=${io_stat1[0]}"
+        echo "wchar=${io_stat1[1]}"
+        echo "syscr=${io_stat1[2]}"
+        echo "syscw=${io_stat1[3]}"
+        echo "read_bytes=${io_stat1[4]}"
+        echo "write_bytes=${io_stat1[5]}"
+    } > $trace_file || >&2 echo "Error: Failed to write to file: $trace_file"
 }
 
 nxf_trace_mac() {
@@ -149,7 +153,6 @@ nxf_trace_linux() {
     local io_stat0=($(2> /dev/null < /proc/$pid/io sed 's/^.*:\s*//' | head -n 6 | tr '\n' ' ' || echo -n '0 0 0 0 0 0'))
     local start_millis=$(nxf_date)
     trap 'kill $mem_proc' ERR
-
     /bin/bash -ue {{folder}}/.command.sh &
     local task=$!
 
@@ -173,16 +176,18 @@ 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
+    {
+        echo "nextflow.trace/v2"
+        echo "realtime=$wall_time"
+        echo "%cpu=$ucpu"
+        echo "cpu_model=$cpu_model"
+        echo "rchar=${io_stat1[0]}"
+        echo "wchar=${io_stat1[1]}"
+        echo "syscr=${io_stat1[2]}"
+        echo "syscw=${io_stat1[3]}"
+        echo "read_bytes=${io_stat1[4]}"
+        echo "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