From 379299bbdfffedce9de6daee6048d12c06bebdc4 Mon Sep 17 00:00:00 2001 From: nholguin Date: Wed, 9 Oct 2024 16:40:52 -0700 Subject: [PATCH] Use command groups for $trace_file writes to reduce syscalls and improve 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 --- .../nextflow/executor/command-trace.txt | 61 ++++++++++--------- .../executor/test-bash-wrapper-with-trace.txt | 61 ++++++++++--------- 2 files changed, 66 insertions(+), 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 index 8b5b2195f6..84ee8f10e3 100644 --- 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 index ef1380e7cf..befdaad80d 100644 --- 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