Merge pull request #2 from xonixx/timing

Timing

Makesure.md

@@ -28,18 +28,19 @@
 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
-    - [ ] @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
  - Idea with stupid_flush (which just sends 65K spaces to shell pipe) is broken: 

Makesurefile

@@ -1,4 +1,5 @@
 
+@options timing
 
 @goal soft_folder_created
 @reached_if [[ -d "soft" ]]
@@ -31,7 +32,6 @@
 @depends_on cleaned cleaned_soft
 
 @goal debug
-  set -x
   awk --version | head -n 1
   bash --version| head -n 1
 

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'
 
@@ -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,12 +233,30 @@ 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, goal_name, loop) {
+function issue_resolved_goals_to_run(script, result,    i, goal_name, loop) {
     if (arr_len(ArgGoals) == 0)
         arr_push(ArgGoals, "default")
 
@@ -236,16 +272,17 @@ 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 = 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++)