From a01e0b10011239f8e25188338cd3567c1e22c8f7 Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Wed, 23 Dec 2020 00:52:45 +0200
Subject: [PATCH 01/17] @options timing

---
 makesure | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/makesure b/makesure
index 3d0f5ba..ea34f1d 100755
--- a/makesure
+++ b/makesure
@@ -12,6 +12,7 @@ BEGIN {
     SupportedOptions["silent"]
     SupportedOptions["timing"]
     prepare_args()
+    print current_time_millis()
 }
 
 NR==1 && /^#!/      { next }
@@ -342,6 +343,13 @@ function topological_sort_perform(node, result, loop,    i, s) {
     arr_push(result, node)
 }
 
+function current_time_millis(    script, res) {
+  script = "date +%s%3N"
+  script | getline res
+  close(script)
+  sub(/%3N/, "000", res) # if date doesn't support %N (macos?) just use second-precision
+  return res + 0
+}
 function join(arr, start_incl, end_excl, sep,    result, i) {
     result = arr[start_incl]
     for (i = start_incl + 1; i < end_excl; i++)

From 4d0a7752707f2cc763daacdc825bb88b890fcf6d Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Wed, 23 Dec 2020 01:12:57 +0200
Subject: [PATCH 02/17] @options timing : render_duration ported from Java

---
 makesure | 56 +++++++++++++++++++++++++++++++++++++++++++++++++++++++-
 1 file changed, 55 insertions(+), 1 deletion(-)

diff --git a/makesure b/makesure
index ea34f1d..19547f5 100755
--- a/makesure
+++ b/makesure
@@ -12,7 +12,19 @@ BEGIN {
     SupportedOptions["silent"]
     SupportedOptions["timing"]
     prepare_args()
-    print current_time_millis()
+    print render_duration(0)
+    print render_duration(100)
+    print render_duration(1000)
+    print render_duration(1001)
+    print render_duration(10000)
+    print render_duration(10001)
+    print render_duration(60000)
+    print render_duration(60001)
+    print render_duration(120000)
+    print render_duration(120001)
+    print render_duration(10000000)
+    print render_duration(50000000)
+    print render_duration(100000000)
 }
 
 NR==1 && /^#!/      { next }
@@ -350,6 +362,48 @@ function current_time_millis(    script, res) {
   sub(/%3N/, "000", res) # if date doesn't support %N (macos?) just use second-precision
   return res + 0
 }
+function render_duration(deltaMillis,
+#
+deltaSec, deltaMin,deltaHr,deltaDay,
+dayS,hrS,minS,secS,secSI,
+res) {
+  deltaSec = deltaMillis / 1000
+  deltaMin = 0
+  deltaHr = 0
+  deltaDay = 0
+
+  if (deltaSec >= 60) {
+    deltaMin = int(deltaSec / 60)
+    deltaSec = deltaSec - deltaMin * 60
+  }
+
+  if (deltaMin >= 60) {
+    deltaHr = int(deltaMin / 60)
+    deltaMin = deltaMin - deltaHr * 60
+  }
+
+  if (deltaHr >= 24) {
+    deltaDay = int(deltaHr / 24)
+    deltaHr = deltaHr - deltaDay * 24
+  }
+
+  dayS = deltaDay > 0 ? deltaDay " d" : ""
+  hrS = deltaHr > 0 ? deltaHr " h" : ""
+  minS = deltaMin > 0 ? deltaMin " m" : ""
+  secS = deltaSec > 0 ? deltaSec " s" : ""
+  secSI = deltaSec > 0 ? int(deltaSec) " s" : ""
+
+  if (dayS != "")
+    res = dayS " " (hrS == "" ? "0 h" : hrS)
+  else if (deltaHr > 0)
+    res = hrS " " (minS == "" ? "0 m" : minS)
+  else if (deltaMin > 0)
+    res = minS " " (secSI == "" ? "0 s" : secSI)
+  else
+    res = deltaSec > 0 ? secS : "0 s"
+
+  return res
+}
 function join(arr, start_incl, end_excl, sep,    result, i) {
     result = arr[start_incl]
     for (i = start_incl + 1; i < end_excl; i++)

From 7c1b6421fa384e2b885b8de76ff55c19ad8211ac Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Wed, 23 Dec 2020 01:41:00 +0200
Subject: [PATCH 03/17] @options timing

---
 Makesurefile |  1 -
 makesure     | 45 ++++++++++++++++++---------------------------
 2 files changed, 18 insertions(+), 28 deletions(-)

diff --git a/Makesurefile b/Makesurefile
index 94e84f8..10098fe 100644
--- a/Makesurefile
+++ b/Makesurefile
@@ -31,7 +31,6 @@
 @depends_on cleaned cleaned_soft
 
 @goal debug
-  set -x
   awk --version | head -n 1
   bash --version| head -n 1
 
diff --git a/makesure b/makesure
index 19547f5..2e1f3ba 100755
--- a/makesure
+++ b/makesure
@@ -12,19 +12,6 @@ BEGIN {
     SupportedOptions["silent"]
     SupportedOptions["timing"]
     prepare_args()
-    print render_duration(0)
-    print render_duration(100)
-    print render_duration(1000)
-    print render_duration(1001)
-    print render_duration(10000)
-    print render_duration(10001)
-    print render_duration(60000)
-    print render_duration(60001)
-    print render_duration(120000)
-    print render_duration(120001)
-    print render_duration(10000000)
-    print render_duration(50000000)
-    print render_duration(100000000)
 }
 
 NR==1 && /^#!/      { next }
@@ -42,7 +29,7 @@ END { if (!Died) do_work() }
 function prepare_args(    i,arg) {
     for (i = 0; i < ARGC; i++) {
         arg = ARGV[i]
-        #print i " " arg;
+        #print i " " arg
         if (i > 1) {
             if (substr(arg,1,1) == "-") {
                 if (arg == "-f" || arg == "--file") {
@@ -144,7 +131,7 @@ function handle_reached_if(    goal_name) {
     ReachedIf[goal_name] = trim($0)
 }
 
-function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,body,prelude_body,resolved_goals,cmd) {
+function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,body,prelude_body,goal_body,resolved_goals,cmd) {
     if ("tracing" in Options)
         issue_script_line("set -x")
 
@@ -187,26 +174,27 @@ function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,body,prelude
 
         issue_script_line("\n" Shell " -e <<'EOF'")
 
+        goal_body = ""
         if (!("silent" in Options)) {
-            issue_script_line("  printf \"  goal '" goal_name "' \"")
+            goal_body = issue_script_line_ret(goal_body, "  printf \"  goal '" goal_name "' \"")
         }
-        issue_script_line("  if " (reached_if_condition ? reached_if_condition : "false") "; then")
+        goal_body = issue_script_line_ret(goal_body, "  if " (reached_if_condition ? reached_if_condition : "false") "; then")
         if (!("silent" in Options)) {
-            issue_script_line("    echo \"[already satisfied].\"")
+            goal_body = issue_script_line_ret(goal_body, "    echo \"[already satisfied].\"")
         }
-        issue_script_line("    exit 0")
+        goal_body = issue_script_line_ret(goal_body, "    exit 0")
         if (!("silent" in Options)) {
-            issue_script_line("  else")
-            issue_script_line("    echo \"" (body == ":" ? "[empty]." : "...") "\"")
+            goal_body = issue_script_line_ret(goal_body, "  else")
+            goal_body = issue_script_line_ret(goal_body, "    echo \"" (body == ":" ? "[empty]." : "...") "\"")
         }
-        issue_script_line("  fi")
+        goal_body = issue_script_line_ret(goal_body, "  fi")
 
         if ("tracing" in Options)
-            issue_script_line("set -x")
+            goal_body = issue_script_line_ret(goal_body, "set -x")
 
-        issue_script_line("  " body)
+        goal_body = issue_script_line_ret(goal_body, "  " body)
 
-        issue_script_line("EOF\n")
+        issue_script_line(goal_body "EOF\n")
         issue_script_line("}")
     }
 
@@ -258,7 +246,10 @@ function issue_resolved_goals_to_run(result,    i, goal_name, loop) {
 }
 
 function issue_script_line(line) {
-    Script = Script line "\n";
+    Script = issue_script_line_ret(Script, line)
+}
+function issue_script_line_ret(script, line) {
+    return script line "\n"
 }
 
 function is_prelude() {
@@ -364,7 +355,7 @@ function current_time_millis(    script, res) {
 }
 function render_duration(deltaMillis,
 #
-deltaSec, deltaMin,deltaHr,deltaDay,
+deltaSec,deltaMin,deltaHr,deltaDay,
 dayS,hrS,minS,secS,secSI,
 res) {
   deltaSec = deltaMillis / 1000

From 6ec8c98b41fb4c0bdd6d69c2ecf351d865e0237d Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Wed, 23 Dec 2020 01:54:30 +0200
Subject: [PATCH 04/17] @options timing : rfct

---
 makesure | 62 ++++++++++++++++++++++++++++----------------------------
 1 file changed, 31 insertions(+), 31 deletions(-)

diff --git a/makesure b/makesure
index 2e1f3ba..0f414f8 100755
--- a/makesure
+++ b/makesure
@@ -131,25 +131,27 @@ function handle_reached_if(    goal_name) {
     ReachedIf[goal_name] = trim($0)
 }
 
-function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,body,prelude_body,goal_body,resolved_goals,cmd) {
+function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,body,prelude_body,goal_body,resolved_goals,cmd) {
+    script = ""
+    
     if ("tracing" in Options)
-        issue_script_line("set -x")
+        script = issue_line(script, "set -x")
 
-    issue_script_line("MYDIR='" get_my_dir() "'")
-    issue_script_line("export MYDIR")
-    issue_script_line("cd \"$MYDIR\"")
+    script = issue_line(script, "MYDIR='" get_my_dir() "'")
+    script = issue_line(script, "export MYDIR")
+    script = issue_line(script, "cd \"$MYDIR\"")
 
     # prelude
     body = trim(code[""])
     prelude_body = body
-    issue_script_line(body)
+    script = issue_line(script, body)
 
     for (i = 0; i < arr_len(GoalNames); i++) {
         goal_name = GoalNames[i]
 
         body = trim(code[goal_name])
 
-        issue_script_line("\n" goal_name "() {")
+        script = issue_line(script, "\n" goal_name "() {")
 
         reached_if_condition = ReachedIf[goal_name]
 
@@ -172,33 +174,33 @@ function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,body,prelude
             body = ":"
         }
 
-        issue_script_line("\n" Shell " -e <<'EOF'")
+        script = issue_line(script, "\n" Shell " -e <<'EOF'")
 
         goal_body = ""
         if (!("silent" in Options)) {
-            goal_body = issue_script_line_ret(goal_body, "  printf \"  goal '" goal_name "' \"")
+            goal_body = issue_line( goal_body, "  printf \"  goal '" goal_name "' \"")
         }
-        goal_body = issue_script_line_ret(goal_body, "  if " (reached_if_condition ? reached_if_condition : "false") "; then")
+        goal_body = issue_line( goal_body, "  if " (reached_if_condition ? reached_if_condition : "false") "; then")
         if (!("silent" in Options)) {
-            goal_body = issue_script_line_ret(goal_body, "    echo \"[already satisfied].\"")
+            goal_body = issue_line( goal_body, "    echo \"[already satisfied].\"")
         }
-        goal_body = issue_script_line_ret(goal_body, "    exit 0")
+        goal_body = issue_line( goal_body, "    exit 0")
         if (!("silent" in Options)) {
-            goal_body = issue_script_line_ret(goal_body, "  else")
-            goal_body = issue_script_line_ret(goal_body, "    echo \"" (body == ":" ? "[empty]." : "...") "\"")
+            goal_body = issue_line( goal_body, "  else")
+            goal_body = issue_line( goal_body, "    echo \"" (body == ":" ? "[empty]." : "...") "\"")
         }
-        goal_body = issue_script_line_ret(goal_body, "  fi")
+        goal_body = issue_line( goal_body, "  fi")
 
         if ("tracing" in Options)
-            goal_body = issue_script_line_ret(goal_body, "set -x")
+            goal_body = issue_line( goal_body, "set -x")
 
-        goal_body = issue_script_line_ret(goal_body, "  " body)
+        goal_body = issue_line( goal_body, "  " body)
 
-        issue_script_line(goal_body "EOF\n")
-        issue_script_line("}")
+        script = issue_line(script, goal_body "EOF\n")
+        script = issue_line(script, "}")
     }
 
-    issue_resolved_goals_to_run(resolved_goals)
+    script = issue_resolved_goals_to_run(script, resolved_goals)
 
     if ("-d" in Args || "--resolved" in Args) {
         printf("Resolved goals to reach for '%s':\n", join(ArgGoals, 0, arr_len(ArgGoals), " "))
@@ -216,12 +218,12 @@ function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,body,prelude
             }
         }
     } else if ("-p" in Args || "--print" in Args) {
-        print Script
+        print script
     } else
-        exit shell_exec(Script, "EOF_OUTER")
+        exit shell_exec(script, "EOF_OUTER")
 }
 
-function issue_resolved_goals_to_run(result,    i, goal_name, loop) {
+function issue_resolved_goals_to_run(script, result,    i, goal_name, loop) {
     if (arr_len(ArgGoals) == 0)
         arr_push(ArgGoals, "default")
 
@@ -237,18 +239,16 @@ function issue_resolved_goals_to_run(result,    i, goal_name, loop) {
         die_msg("There is a loop in goal dependencies via " loop[1] " -> " loop[2])
     }
 
-    issue_script_line("__resolved_goals() {")
+    script = issue_line(script, "__resolved_goals() {")
     for (i = 0; i < arr_len(result); i++) {
-       issue_script_line("  " result[i])
+       script = issue_line(script, "  " result[i])
     }
-    issue_script_line("}")
-    issue_script_line("__resolved_goals")
+    script = issue_line(script, "}")
+    script = issue_line(script, "__resolved_goals")
+    return script
 }
 
-function issue_script_line(line) {
-    Script = issue_script_line_ret(Script, line)
-}
-function issue_script_line_ret(script, line) {
+function issue_line(script, line) {
     return script line "\n"
 }
 

From bf19b707d17dbd44d0fcf4e81f64307ec183a63e Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Wed, 23 Dec 2020 02:11:26 +0200
Subject: [PATCH 05/17] @options timing

---
 makesure | 33 +++++++++++++++++++++------------
 1 file changed, 21 insertions(+), 12 deletions(-)

diff --git a/makesure b/makesure
index 0f414f8..af684c4 100755
--- a/makesure
+++ b/makesure
@@ -131,7 +131,7 @@ function handle_reached_if(    goal_name) {
     ReachedIf[goal_name] = trim($0)
 }
 
-function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,body,prelude_body,goal_body,resolved_goals,cmd) {
+function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,body,prelude_body,goal_body,goal_bodies,resolved_goals,cmd,exit_code) {
     script = ""
     
     if ("tracing" in Options)
@@ -178,23 +178,24 @@ function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,body,
 
         goal_body = ""
         if (!("silent" in Options)) {
-            goal_body = issue_line( goal_body, "  printf \"  goal '" goal_name "' \"")
+            goal_body = issue_line(goal_body, "  printf \"  goal '" goal_name "' \"")
         }
-        goal_body = issue_line( goal_body, "  if " (reached_if_condition ? reached_if_condition : "false") "; then")
+        goal_body = issue_line(goal_body, "  if " (reached_if_condition ? reached_if_condition : "false") "; then")
         if (!("silent" in Options)) {
-            goal_body = issue_line( goal_body, "    echo \"[already satisfied].\"")
+            goal_body = issue_line(goal_body, "    echo \"[already satisfied].\"")
         }
-        goal_body = issue_line( goal_body, "    exit 0")
+        goal_body = issue_line(goal_body, "    exit 0")
         if (!("silent" in Options)) {
-            goal_body = issue_line( goal_body, "  else")
-            goal_body = issue_line( goal_body, "    echo \"" (body == ":" ? "[empty]." : "...") "\"")
+            goal_body = issue_line(goal_body, "  else")
+            goal_body = issue_line(goal_body, "    echo \"" (body == ":" ? "[empty]." : "...") "\"")
         }
-        goal_body = issue_line( goal_body, "  fi")
+        goal_body = issue_line(goal_body, "  fi")
 
         if ("tracing" in Options)
-            goal_body = issue_line( goal_body, "set -x")
+            goal_body = issue_line(goal_body, "set -x")
 
-        goal_body = issue_line( goal_body, "  " body)
+        goal_body = issue_line(goal_body, "  " body)
+        goal_bodies[goal_name] = goal_body
 
         script = issue_line(script, goal_body "EOF\n")
         script = issue_line(script, "}")
@@ -219,8 +220,16 @@ function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,body,
         }
     } else if ("-p" in Args || "--print" in Args) {
         print script
-    } else
-        exit shell_exec(script, "EOF_OUTER")
+    } else {
+        # exit shell_exec(script, "EOF_OUTER")
+        for (i = 0; i < arr_len(resolved_goals); i++) {
+          goal_name = resolved_goals[i]
+          goal_body = goal_bodies[goal_name]
+          exit_code = shell_exec(prelude_body "\n" goal_body)
+          if (exit_code != 0)
+            exit exit_code
+        }
+    }
 }
 
 function issue_resolved_goals_to_run(script, result,    i, goal_name, loop) {

From 44b777dd6d9c5366d1f00441872af01958263a9e Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Wed, 23 Dec 2020 02:23:30 +0200
Subject: [PATCH 06/17] @options timing

---
 makesure | 13 +++++++------
 1 file changed, 7 insertions(+), 6 deletions(-)

diff --git a/makesure b/makesure
index af684c4..dc021bc 100755
--- a/makesure
+++ b/makesure
@@ -131,20 +131,21 @@ function handle_reached_if(    goal_name) {
     ReachedIf[goal_name] = trim($0)
 }
 
-function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,body,prelude_body,goal_body,goal_bodies,resolved_goals,cmd,exit_code) {
+function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,my_dir,body,prelude_body,goal_body,goal_bodies,resolved_goals,cmd,exit_code) {
     script = ""
     
     if ("tracing" in Options)
         script = issue_line(script, "set -x")
 
-    script = issue_line(script, "MYDIR='" get_my_dir() "'")
-    script = issue_line(script, "export MYDIR")
-    script = issue_line(script, "cd \"$MYDIR\"")
+    my_dir = ""
+    my_dir = issue_line(my_dir, "MYDIR='" get_my_dir() "'")
+    my_dir = issue_line(my_dir, "export MYDIR")
+    my_dir = issue_line(my_dir, "cd \"$MYDIR\"")
 
     # prelude
     body = trim(code[""])
     prelude_body = body
-    script = issue_line(script, body)
+    script = issue_line(script, my_dir prelude_body)
 
     for (i = 0; i < arr_len(GoalNames); i++) {
         goal_name = GoalNames[i]
@@ -225,7 +226,7 @@ function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,body,
         for (i = 0; i < arr_len(resolved_goals); i++) {
           goal_name = resolved_goals[i]
           goal_body = goal_bodies[goal_name]
-          exit_code = shell_exec(prelude_body "\n" goal_body)
+          exit_code = shell_exec(my_dir prelude_body "\n" goal_body)
           if (exit_code != 0)
             exit exit_code
         }

From 6651325f52fdf5aff0a35a347a372bd29e86cc50 Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Wed, 23 Dec 2020 02:30:19 +0200
Subject: [PATCH 07/17] @options timing

---
 tests/4_trace.tush   | 16 ----------------
 tests/7_options.tush |  6 ------
 2 files changed, 22 deletions(-)

diff --git a/tests/4_trace.tush b/tests/4_trace.tush
index f667c5f..1ce6b96 100644
--- a/tests/4_trace.tush
+++ b/tests/4_trace.tush
@@ -6,26 +6,10 @@ $ cd "$MYDIR"; ./makesure -f tests/4_trace.sh
 $ cd "$MYDIR"; bash -c "./makesure -f tests/4_trace.sh -x 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
 |   goal 'default' ...
 | A=aaa
-@ + MYDIR=tests
-@ + export MYDIR
-@ + cd tests
-@ + export A=aaa
-@ + A=aaa
-@ + __resolved_goals
-@ + default
-@ + bash -e
 @ + echo A=aaa
 
 $ cd "$MYDIR"; bash -c "./makesure -f tests/4_trace.sh --tracing 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
 |   goal 'default' ...
 | A=aaa
-@ + MYDIR=tests
-@ + export MYDIR
-@ + cd tests
-@ + export A=aaa
-@ + A=aaa
-@ + __resolved_goals
-@ + default
-@ + bash -e
 @ + echo A=aaa
 
diff --git a/tests/7_options.tush b/tests/7_options.tush
index b5a409d..d044d56 100644
--- a/tests/7_options.tush
+++ b/tests/7_options.tush
@@ -12,11 +12,5 @@ $ cd "$MYDIR"; ./makesure -f tests/7_options_invalid.sh
 $ cd "$MYDIR"; bash -c "./makesure -f tests/7_options_tracing.sh -x 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
 |   goal 'default' ...
 | test
-@ + MYDIR=tests
-@ + export MYDIR
-@ + cd tests
-@ + __resolved_goals
-@ + default
-@ + bash -e
 @ + echo test
 

From 8063e5091840f5ca09320932fd2d82292c7cae01 Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Wed, 23 Dec 2020 02:58:05 +0200
Subject: [PATCH 08/17] @options timing

---
 Makesure.md        | 1 +
 makesure           | 4 ++--
 tests/4_trace.tush | 5 +++++
 3 files changed, 8 insertions(+), 2 deletions(-)

diff --git a/Makesure.md b/Makesure.md
index 354ff44..b553603 100644
--- a/Makesure.md
+++ b/Makesure.md
@@ -40,6 +40,7 @@
     - [x] @options tracing
     - [x] @options silent
     - [ ] @options timing
+30. [ ] find a way to enable tracing for the prelude - this correlates with "prelude runs exactly 1 time"
 
 ## Ideas proved not to work
  - Idea with stupid_flush (which just sends 65K spaces to shell pipe) is broken: 
diff --git a/makesure b/makesure
index dc021bc..b876f8e 100755
--- a/makesure
+++ b/makesure
@@ -134,8 +134,8 @@ function handle_reached_if(    goal_name) {
 function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,my_dir,body,prelude_body,goal_body,goal_bodies,resolved_goals,cmd,exit_code) {
     script = ""
     
-    if ("tracing" in Options)
-        script = issue_line(script, "set -x")
+#    if ("tracing" in Options)
+#        script = issue_line(script, "set -x")
 
     my_dir = ""
     my_dir = issue_line(my_dir, "MYDIR='" get_my_dir() "'")
diff --git a/tests/4_trace.tush b/tests/4_trace.tush
index 1ce6b96..56ac31e 100644
--- a/tests/4_trace.tush
+++ b/tests/4_trace.tush
@@ -8,6 +8,11 @@ $ cd "$MYDIR"; bash -c "./makesure -f tests/4_trace.sh -x 2> >(sed 's#\/.*\/test
 | A=aaa
 @ + echo A=aaa
 
+$ cd "$MYDIR"; bash -c "./makesure -f tests/4_trace.sh -x -p | bash 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
+|   goal 'default' ...
+| A=aaa
+@ + echo A=aaa
+
 $ cd "$MYDIR"; bash -c "./makesure -f tests/4_trace.sh --tracing 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
 |   goal 'default' ...
 | A=aaa

From 4b46b9e751843b177cfc4e54ef78dfa49d0db582 Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Wed, 23 Dec 2020 03:07:53 +0200
Subject: [PATCH 09/17] @options timing

---
 Makesurefile |  1 +
 makesure     | 13 ++++++++++++-
 2 files changed, 13 insertions(+), 1 deletion(-)

diff --git a/Makesurefile b/Makesurefile
index 10098fe..5d61511 100644
--- a/Makesurefile
+++ b/Makesurefile
@@ -1,4 +1,5 @@
 
+@options timing
 
 @goal soft_folder_created
 @reached_if [[ -d "soft" ]]
diff --git a/makesure b/makesure
index b876f8e..bcf4ca1 100755
--- a/makesure
+++ b/makesure
@@ -131,7 +131,10 @@ function handle_reached_if(    goal_name) {
     ReachedIf[goal_name] = trim($0)
 }
 
-function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,my_dir,body,prelude_body,goal_body,goal_bodies,resolved_goals,cmd,exit_code) {
+function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,my_dir,
+body,prelude_body,goal_body,goal_bodies,
+resolved_goals,cmd,exit_code,
+t0,t1,t2) {
     script = ""
     
 #    if ("tracing" in Options)
@@ -223,10 +226,18 @@ function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,my_di
         print script
     } else {
         # exit shell_exec(script, "EOF_OUTER")
+        if ("timing" in Options)
+          t0 = current_time_millis()
         for (i = 0; i < arr_len(resolved_goals); i++) {
+          if ("timing" in Options)
+            t1 = current_time_millis()
           goal_name = resolved_goals[i]
           goal_body = goal_bodies[goal_name]
           exit_code = shell_exec(my_dir prelude_body "\n" goal_body)
+          if ("timing" in Options) {
+            t2 = current_time_millis()
+            print "  goal '" goal_name "' took " render_duration(t2 - t1)
+          }
           if (exit_code != 0)
             exit exit_code
         }

From 77644e2f7233538b32715cec57f2dd369c099f51 Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Thu, 24 Dec 2020 15:57:44 +0200
Subject: [PATCH 10/17] @options timing

---
 Makesure.md        |  2 +-
 makesure           | 18 +++++++++++-------
 tests/0_basic.tush |  4 ++--
 3 files changed, 14 insertions(+), 10 deletions(-)

diff --git a/Makesure.md b/Makesure.md
index b553603..7e3a3ce 100644
--- a/Makesure.md
+++ b/Makesure.md
@@ -39,7 +39,7 @@
 29. [ ] support @options directive
     - [x] @options tracing
     - [x] @options silent
-    - [ ] @options timing
+    - [x] @options timing
 30. [ ] find a way to enable tracing for the prelude - this correlates with "prelude runs exactly 1 time"
 
 ## Ideas proved not to work
diff --git a/makesure b/makesure
index bcf4ca1..99d6069 100755
--- a/makesure
+++ b/makesure
@@ -1,6 +1,6 @@
 #!/usr/bin/env sh
 
-VERSION="0.9.3"
+VERSION="0.9.4"
 
 exec awk -v "Version=$VERSION" -f - Makesurefile "$@" <<'MAKESURE'
 
@@ -132,13 +132,15 @@ function handle_reached_if(    goal_name) {
 }
 
 function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,my_dir,
-body,prelude_body,goal_body,goal_bodies,
-resolved_goals,cmd,exit_code,
-t0,t1,t2) {
+  body,prelude_body,goal_body,goal_bodies,
+  resolved_goals,cmd,exit_code,
+  t0,t1,t2) {
     script = ""
     
 #    if ("tracing" in Options)
 #        script = issue_line(script, "set -x")
+    if ("timing" in Options)
+      t0 = current_time_millis()
 
     my_dir = ""
     my_dir = issue_line(my_dir, "MYDIR='" get_my_dir() "'")
@@ -226,8 +228,6 @@ t0,t1,t2) {
         print script
     } else {
         # exit shell_exec(script, "EOF_OUTER")
-        if ("timing" in Options)
-          t0 = current_time_millis()
         for (i = 0; i < arr_len(resolved_goals); i++) {
           if ("timing" in Options)
             t1 = current_time_millis()
@@ -239,8 +239,12 @@ t0,t1,t2) {
             print "  goal '" goal_name "' took " render_duration(t2 - t1)
           }
           if (exit_code != 0)
-            exit exit_code
+            break
         }
+        if ("timing" in Options)
+          print "  total time " render_duration(t2 - t0)
+        if (exit_code != 0)
+          exit exit_code
     }
 }
 
diff --git a/tests/0_basic.tush b/tests/0_basic.tush
index de3694a..6edc0fa 100644
--- a/tests/0_basic.tush
+++ b/tests/0_basic.tush
@@ -1,7 +1,7 @@
 
 $ cd "$MYDIR"; ./makesure -v; ./makesure --version
-| 0.9.3
-| 0.9.3
+| 0.9.4
+| 0.9.4
 
 $ cd "$MYDIR"; ./makesure -f non-existent-file
 @ makesure file not found: non-existent-file

From 865de66c5b9194306054517b3fd16e6ff24e812e Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Thu, 24 Dec 2020 16:14:58 +0200
Subject: [PATCH 11/17] @options timing

---
 tests/7_options.tush      | 7 +++++++
 tests/7_options_timing.sh | 5 +++++
 2 files changed, 12 insertions(+)
 create mode 100644 tests/7_options_timing.sh

diff --git a/tests/7_options.tush b/tests/7_options.tush
index d044d56..8f9a9c5 100644
--- a/tests/7_options.tush
+++ b/tests/7_options.tush
@@ -9,6 +9,13 @@ $ cd "$MYDIR"; ./makesure -f tests/7_options_invalid.sh
 @ tests/7_options_invalid.sh:2: @options invalid
 ? 1
 
+$ cd "$MYDIR"; ./makesure -f tests/7_options_timing.sh | sed -r 's#took .+$#took X#g ; s#total time .+$#total time X#g'
+|   goal 'default' ...
+| test
+|   goal 'default' took X
+|   total time X
+
+
 $ cd "$MYDIR"; bash -c "./makesure -f tests/7_options_tracing.sh -x 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
 |   goal 'default' ...
 | test
diff --git a/tests/7_options_timing.sh b/tests/7_options_timing.sh
new file mode 100644
index 0000000..fd3247e
--- /dev/null
+++ b/tests/7_options_timing.sh
@@ -0,0 +1,5 @@
+
+@options timing
+
+@goal default
+  echo test

From 262d446199edbfb8b15326335fa5505e7c185e3e Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Thu, 24 Dec 2020 16:28:34 +0200
Subject: [PATCH 12/17] @options timing

---
 makesure                         | 8 ++++++++
 tests/7_options.tush             | 2 ++
 tests/7_options_timing_silent.sh | 5 +++++
 3 files changed, 15 insertions(+)
 create mode 100644 tests/7_options_timing_silent.sh

diff --git a/makesure b/makesure
index 99d6069..cdff6b5 100755
--- a/makesure
+++ b/makesure
@@ -87,7 +87,15 @@ function handle_shell() {
       die("Shell '" Shell "' is not supported")
 }
 
+function adjust_options() {
+  if ("silent" in Options)
+    delete Options["timing"]
+}
+
 function handle_goal(    goal_name) {
+    if (is_prelude()) # 1st goal
+      adjust_options()
+
     goal_name = trim($2)
     if (length(goal_name) == 0) {
         die("Goal must have a name")
diff --git a/tests/7_options.tush b/tests/7_options.tush
index 8f9a9c5..f7c546e 100644
--- a/tests/7_options.tush
+++ b/tests/7_options.tush
@@ -15,6 +15,8 @@ $ cd "$MYDIR"; ./makesure -f tests/7_options_timing.sh | sed -r 's#took .+$#took
 |   goal 'default' took X
 |   total time X
 
+$ cd "$MYDIR"; ./makesure -f tests/7_options_timing_silent.sh
+| test
 
 $ cd "$MYDIR"; bash -c "./makesure -f tests/7_options_tracing.sh -x 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
 |   goal 'default' ...
diff --git a/tests/7_options_timing_silent.sh b/tests/7_options_timing_silent.sh
new file mode 100644
index 0000000..293a1d4
--- /dev/null
+++ b/tests/7_options_timing_silent.sh
@@ -0,0 +1,5 @@
+
+@options timing silent
+
+@goal default
+  echo test

From 9b05d220e1238a85335db2135d20874c0ad0f323 Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Thu, 24 Dec 2020 16:35:09 +0200
Subject: [PATCH 13/17] @options timing

---
 Makesure.md                                    |  8 ++++----
 tests/7_options.tush                           |  9 ---------
 ...7_options_timing.sh => 8_options_timing.sh} |  0
 ...ng_silent.sh => 8_options_timing_silent.sh} |  0
 tests/8_timing.sh                              |  3 +++
 tests/8_timing.tush                            | 18 ++++++++++++++++++
 6 files changed, 25 insertions(+), 13 deletions(-)
 rename tests/{7_options_timing.sh => 8_options_timing.sh} (100%)
 rename tests/{7_options_timing_silent.sh => 8_options_timing_silent.sh} (100%)
 create mode 100644 tests/8_timing.sh
 create mode 100644 tests/8_timing.tush

diff --git a/Makesure.md b/Makesure.md
index 7e3a3ce..2feb5da 100644
--- a/Makesure.md
+++ b/Makesure.md
@@ -28,15 +28,15 @@
 20. [x] `-v` flag to show version 
 21. [x] `-d` flag to show resolved dependencies
 22. [x] introduce test suite via tush
-23. [ ] `-t` flag for timing for goals execution
-    - [ ] is it possible to ms precision?
-    - [ ] measure each goal
+23. [x] `-t` flag for timing for goals execution
+    - [x] is it possible to ms precision?
+    - [x] measure each goal
 24. [ ] `-h` flag for help
 25. [ ] (?) `-F` to force build despite the reached_if
 26. [x] `-x` to enable tracing in bash
 27. [x] support `@options silent` mode and flag `-s`
 28. [ ] allow override @define-s
-29. [ ] support @options directive
+29. [x] support @options directive
     - [x] @options tracing
     - [x] @options silent
     - [x] @options timing
diff --git a/tests/7_options.tush b/tests/7_options.tush
index f7c546e..d044d56 100644
--- a/tests/7_options.tush
+++ b/tests/7_options.tush
@@ -9,15 +9,6 @@ $ cd "$MYDIR"; ./makesure -f tests/7_options_invalid.sh
 @ tests/7_options_invalid.sh:2: @options invalid
 ? 1
 
-$ cd "$MYDIR"; ./makesure -f tests/7_options_timing.sh | sed -r 's#took .+$#took X#g ; s#total time .+$#total time X#g'
-|   goal 'default' ...
-| test
-|   goal 'default' took X
-|   total time X
-
-$ cd "$MYDIR"; ./makesure -f tests/7_options_timing_silent.sh
-| test
-
 $ cd "$MYDIR"; bash -c "./makesure -f tests/7_options_tracing.sh -x 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
 |   goal 'default' ...
 | test
diff --git a/tests/7_options_timing.sh b/tests/8_options_timing.sh
similarity index 100%
rename from tests/7_options_timing.sh
rename to tests/8_options_timing.sh
diff --git a/tests/7_options_timing_silent.sh b/tests/8_options_timing_silent.sh
similarity index 100%
rename from tests/7_options_timing_silent.sh
rename to tests/8_options_timing_silent.sh
diff --git a/tests/8_timing.sh b/tests/8_timing.sh
new file mode 100644
index 0000000..4c94ba8
--- /dev/null
+++ b/tests/8_timing.sh
@@ -0,0 +1,3 @@
+
+@goal default
+  echo test
diff --git a/tests/8_timing.tush b/tests/8_timing.tush
new file mode 100644
index 0000000..99964f9
--- /dev/null
+++ b/tests/8_timing.tush
@@ -0,0 +1,18 @@
+
+$ cd "$MYDIR"; ./makesure -f tests/8_options_timing.sh | sed -r 's#took .+$#took X#g ; s#total time .+$#total time X#g'
+|   goal 'default' ...
+| test
+|   goal 'default' took X
+|   total time X
+
+$ cd "$MYDIR"; ./makesure -f tests/8_options_timing_silent.sh
+| test
+
+$ cd "$MYDIR"; ./makesure -t -f tests/8_timing.sh | sed -r 's#took .+$#took X#g ; s#total time .+$#total time X#g'
+|   goal 'default' ...
+| test
+|   goal 'default' took X
+|   total time X
+
+$ cd "$MYDIR"; ./makesure -t -s -f tests/8_timing.sh
+| test

From 3bbe410287f0f51ff0d3a82f9bc4b757f99aa2f6 Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Thu, 24 Dec 2020 16:39:45 +0200
Subject: [PATCH 14/17] @options timing

---
 tests/8_timing.tush | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/8_timing.tush b/tests/8_timing.tush
index 99964f9..ac74637 100644
--- a/tests/8_timing.tush
+++ b/tests/8_timing.tush
@@ -8,7 +8,7 @@ $ cd "$MYDIR"; ./makesure -f tests/8_options_timing.sh | sed -r 's#took .+$#took
 $ cd "$MYDIR"; ./makesure -f tests/8_options_timing_silent.sh
 | test
 
-$ cd "$MYDIR"; ./makesure -t -f tests/8_timing.sh | sed -r 's#took .+$#took X#g ; s#total time .+$#total time X#g'
+$ cd "$MYDIR"; ./makesure -t -f tests/8_timing.sh | sed 's#took .*$#took X#g ; s#total time .*$#total time X#g'
 |   goal 'default' ...
 | test
 |   goal 'default' took X

From 88aa519f8b6c70d701d06d9e277f016166063eb6 Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Thu, 24 Dec 2020 16:45:00 +0200
Subject: [PATCH 15/17] fix

---
 tests/4_trace.tush | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/tests/4_trace.tush b/tests/4_trace.tush
index 56ac31e..0dec92b 100644
--- a/tests/4_trace.tush
+++ b/tests/4_trace.tush
@@ -3,17 +3,17 @@ $ cd "$MYDIR"; ./makesure -f tests/4_trace.sh
 |   goal 'default' ...
 | A=aaa
 
-$ cd "$MYDIR"; bash -c "./makesure -f tests/4_trace.sh -x 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
+$ cd "$MYDIR"; ./makesure -f tests/4_trace.sh -x
 |   goal 'default' ...
 | A=aaa
 @ + echo A=aaa
 
-$ cd "$MYDIR"; bash -c "./makesure -f tests/4_trace.sh -x -p | bash 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
+$ cd "$MYDIR"; ./makesure -f tests/4_trace.sh -x -p | bash
 |   goal 'default' ...
 | A=aaa
 @ + echo A=aaa
 
-$ cd "$MYDIR"; bash -c "./makesure -f tests/4_trace.sh --tracing 2> >(sed 's#\/.*\/tests#tests#g' >&2)"
+$ cd "$MYDIR"; ./makesure -f tests/4_trace.sh --tracing
 |   goal 'default' ...
 | A=aaa
 @ + echo A=aaa

From 21eda0e6f7c79f991d01e2ae1f508bf4e75bf0a0 Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Thu, 24 Dec 2020 16:47:35 +0200
Subject: [PATCH 16/17] fix

---
 tests/8_timing.tush | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tests/8_timing.tush b/tests/8_timing.tush
index ac74637..396587c 100644
--- a/tests/8_timing.tush
+++ b/tests/8_timing.tush
@@ -1,5 +1,5 @@
 
-$ cd "$MYDIR"; ./makesure -f tests/8_options_timing.sh | sed -r 's#took .+$#took X#g ; s#total time .+$#total time X#g'
+$ cd "$MYDIR"; ./makesure -f tests/8_options_timing.sh | sed 's#took .*$#took X#g ; s#total time .*$#total time X#g'
 |   goal 'default' ...
 | test
 |   goal 'default' took X

From 704e8919acd2adfcdf5bb1618e0fd914a9bc86f6 Mon Sep 17 00:00:00 2001
From: xonix <xonixx@gmail.com>
Date: Thu, 24 Dec 2020 16:51:16 +0200
Subject: [PATCH 17/17] makesure_stable

---
 makesure_stable | 162 ++++++++++++++++++++++++++++++++++++------------
 1 file changed, 124 insertions(+), 38 deletions(-)

diff --git a/makesure_stable b/makesure_stable
index 1fed403..cdff6b5 100755
--- a/makesure_stable
+++ b/makesure_stable
@@ -1,6 +1,6 @@
 #!/usr/bin/env sh
 
-VERSION="0.9.3"
+VERSION="0.9.4"
 
 exec awk -v "Version=$VERSION" -f - Makesurefile "$@" <<'MAKESURE'
 
@@ -29,7 +29,7 @@ END { if (!Died) do_work() }
 function prepare_args(    i,arg) {
     for (i = 0; i < ARGC; i++) {
         arg = ARGV[i]
-        #print i " " arg;
+        #print i " " arg
         if (i > 1) {
             if (substr(arg,1,1) == "-") {
                 if (arg == "-f" || arg == "--file") {
@@ -87,7 +87,15 @@ function handle_shell() {
       die("Shell '" Shell "' is not supported")
 }
 
+function adjust_options() {
+  if ("silent" in Options)
+    delete Options["timing"]
+}
+
 function handle_goal(    goal_name) {
+    if (is_prelude()) # 1st goal
+      adjust_options()
+
     goal_name = trim($2)
     if (length(goal_name) == 0) {
         die("Goal must have a name")
@@ -131,25 +139,33 @@ function handle_reached_if(    goal_name) {
     ReachedIf[goal_name] = trim($0)
 }
 
-function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,body,prelude_body,resolved_goals,cmd) {
-    if ("tracing" in Options)
-        issue_script_line("set -x")
-
-    issue_script_line("MYDIR='" get_my_dir() "'")
-    issue_script_line("export MYDIR")
-    issue_script_line("cd \"$MYDIR\"")
+function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,script,my_dir,
+  body,prelude_body,goal_body,goal_bodies,
+  resolved_goals,cmd,exit_code,
+  t0,t1,t2) {
+    script = ""
+    
+#    if ("tracing" in Options)
+#        script = issue_line(script, "set -x")
+    if ("timing" in Options)
+      t0 = current_time_millis()
+
+    my_dir = ""
+    my_dir = issue_line(my_dir, "MYDIR='" get_my_dir() "'")
+    my_dir = issue_line(my_dir, "export MYDIR")
+    my_dir = issue_line(my_dir, "cd \"$MYDIR\"")
 
     # prelude
     body = trim(code[""])
     prelude_body = body
-    issue_script_line(body)
+    script = issue_line(script, my_dir prelude_body)
 
     for (i = 0; i < arr_len(GoalNames); i++) {
         goal_name = GoalNames[i]
 
         body = trim(code[goal_name])
 
-        issue_script_line("\n" goal_name "() {")
+        script = issue_line(script, "\n" goal_name "() {")
 
         reached_if_condition = ReachedIf[goal_name]
 
@@ -172,32 +188,34 @@ function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,body,prelude
             body = ":"
         }
 
-        issue_script_line("\n" Shell " -e <<'EOF'")
+        script = issue_line(script, "\n" Shell " -e <<'EOF'")
 
+        goal_body = ""
         if (!("silent" in Options)) {
-            issue_script_line("  printf \"  goal '" goal_name "' \"")
+            goal_body = issue_line(goal_body, "  printf \"  goal '" goal_name "' \"")
         }
-        issue_script_line("  if " (reached_if_condition ? reached_if_condition : "false") "; then")
+        goal_body = issue_line(goal_body, "  if " (reached_if_condition ? reached_if_condition : "false") "; then")
         if (!("silent" in Options)) {
-            issue_script_line("    echo \"[already satisfied].\"")
+            goal_body = issue_line(goal_body, "    echo \"[already satisfied].\"")
         }
-        issue_script_line("    exit 0")
+        goal_body = issue_line(goal_body, "    exit 0")
         if (!("silent" in Options)) {
-            issue_script_line("  else")
-            issue_script_line("    echo \"" (body == ":" ? "[empty]." : "...") "\"")
+            goal_body = issue_line(goal_body, "  else")
+            goal_body = issue_line(goal_body, "    echo \"" (body == ":" ? "[empty]." : "...") "\"")
         }
-        issue_script_line("  fi")
+        goal_body = issue_line(goal_body, "  fi")
 
         if ("tracing" in Options)
-            issue_script_line("set -x")
+            goal_body = issue_line(goal_body, "set -x")
 
-        issue_script_line("  " body)
+        goal_body = issue_line(goal_body, "  " body)
+        goal_bodies[goal_name] = goal_body
 
-        issue_script_line("EOF\n")
-        issue_script_line("}")
+        script = issue_line(script, goal_body "EOF\n")
+        script = issue_line(script, "}")
     }
 
-    issue_resolved_goals_to_run(resolved_goals)
+    script = issue_resolved_goals_to_run(script, resolved_goals)
 
     if ("-d" in Args || "--resolved" in Args) {
         printf("Resolved goals to reach for '%s':\n", join(ArgGoals, 0, arr_len(ArgGoals), " "))
@@ -215,37 +233,56 @@ function do_work(    i,j,goal_name,dep_cnt,dep,reached_if_condition,body,prelude
             }
         }
     } else if ("-p" in Args || "--print" in Args) {
-        print Script
-    } else
-        exit shell_exec(Script, "EOF_OUTER")
+        print script
+    } else {
+        # exit shell_exec(script, "EOF_OUTER")
+        for (i = 0; i < arr_len(resolved_goals); i++) {
+          if ("timing" in Options)
+            t1 = current_time_millis()
+          goal_name = resolved_goals[i]
+          goal_body = goal_bodies[goal_name]
+          exit_code = shell_exec(my_dir prelude_body "\n" goal_body)
+          if ("timing" in Options) {
+            t2 = current_time_millis()
+            print "  goal '" goal_name "' took " render_duration(t2 - t1)
+          }
+          if (exit_code != 0)
+            break
+        }
+        if ("timing" in Options)
+          print "  total time " render_duration(t2 - t0)
+        if (exit_code != 0)
+          exit exit_code
+    }
 }
 
-function issue_resolved_goals_to_run(result,    i, g, loop) {
+function issue_resolved_goals_to_run(script, result,    i, goal_name, loop) {
     if (arr_len(ArgGoals) == 0)
         arr_push(ArgGoals, "default")
 
     for (i = 0; i < arr_len(ArgGoals); i++) {
-        g = ArgGoals[i]
-        if (!(g in GoalsByName)) {
-            die_msg("Goal not found: " g) # TODO can we show line number here?
+        goal_name = ArgGoals[i]
+        if (!(goal_name in GoalsByName)) {
+            die_msg("Goal not found: " goal_name) # TODO can we show line number here?
         }
-        topological_sort_perform(g, result, loop)
+        topological_sort_perform(goal_name, result, loop)
     }
 
     if (loop[0] == 1) {
         die_msg("There is a loop in goal dependencies via " loop[1] " -> " loop[2])
     }
 
-    issue_script_line("__resolved_goals() {")
+    script = issue_line(script, "__resolved_goals() {")
     for (i = 0; i < arr_len(result); i++) {
-       issue_script_line("  " result[i])
+       script = issue_line(script, "  " result[i])
     }
-    issue_script_line("}")
-    issue_script_line("__resolved_goals")
+    script = issue_line(script, "}")
+    script = issue_line(script, "__resolved_goals")
+    return script
 }
 
-function issue_script_line(line) {
-    Script = Script line "\n";
+function issue_line(script, line) {
+    return script line "\n"
 }
 
 function is_prelude() {
@@ -342,6 +379,55 @@ function topological_sort_perform(node, result, loop,    i, s) {
     arr_push(result, node)
 }
 
+function current_time_millis(    script, res) {
+  script = "date +%s%3N"
+  script | getline res
+  close(script)
+  sub(/%3N/, "000", res) # if date doesn't support %N (macos?) just use second-precision
+  return res + 0
+}
+function render_duration(deltaMillis,
+#
+deltaSec,deltaMin,deltaHr,deltaDay,
+dayS,hrS,minS,secS,secSI,
+res) {
+  deltaSec = deltaMillis / 1000
+  deltaMin = 0
+  deltaHr = 0
+  deltaDay = 0
+
+  if (deltaSec >= 60) {
+    deltaMin = int(deltaSec / 60)
+    deltaSec = deltaSec - deltaMin * 60
+  }
+
+  if (deltaMin >= 60) {
+    deltaHr = int(deltaMin / 60)
+    deltaMin = deltaMin - deltaHr * 60
+  }
+
+  if (deltaHr >= 24) {
+    deltaDay = int(deltaHr / 24)
+    deltaHr = deltaHr - deltaDay * 24
+  }
+
+  dayS = deltaDay > 0 ? deltaDay " d" : ""
+  hrS = deltaHr > 0 ? deltaHr " h" : ""
+  minS = deltaMin > 0 ? deltaMin " m" : ""
+  secS = deltaSec > 0 ? deltaSec " s" : ""
+  secSI = deltaSec > 0 ? int(deltaSec) " s" : ""
+
+  if (dayS != "")
+    res = dayS " " (hrS == "" ? "0 h" : hrS)
+  else if (deltaHr > 0)
+    res = hrS " " (minS == "" ? "0 m" : minS)
+  else if (deltaMin > 0)
+    res = minS " " (secSI == "" ? "0 s" : secSI)
+  else
+    res = deltaSec > 0 ? secS : "0 s"
+
+  return res
+}
 function join(arr, start_incl, end_excl, sep,    result, i) {
     result = arr[start_incl]
     for (i = start_incl + 1; i < end_excl; i++)