Merge pull request #2034 from fbeqv/add_effective_fuzzing_time_tracker

Adds stats tracking for time spend actually mutating & running test i…

4 files changed, 100 insertions, 65 deletions

diff --git a/include/afl-fuzz.h b/include/afl-fuzz.h
index be86910e..91eb6887 100644
--- a/include/afl-fuzz.h
+++ b/include/afl-fuzz.h
@@ -648,7 +648,10 @@ typedef struct afl_state {
       longest_find_time,                /* Longest time taken for a find    */
       exit_on_time,                     /* Delay to exit if no new paths    */
       sync_time,                        /* Sync time (ms)                   */
-      switch_fuzz_mode;                 /* auto or fixed fuzz mode          */
+      switch_fuzz_mode,                 /* auto or fixed fuzz mode          */
+      calibration_time_us,              /* Time spend on calibration        */
+      sync_time_us,                     /* Time spend on sync               */
+      trim_time_us;                     /* Time spend on trimming           */
 
   u32 slowest_exec_ms,                  /* Slowest testcase non hang in ms  */
       subseq_tmouts;                    /* Number of timeouts in a row      */
@@ -1215,6 +1218,10 @@ void show_stats_normal(afl_state_t *);
 void show_stats_pizza(afl_state_t *);
 void show_init_stats(afl_state_t *);
 
+void update_calibration_time(afl_state_t *afl, u64* time);
+void update_trim_time(afl_state_t *afl, u64* time);
+void update_sync_time(afl_state_t *afl, u64* time);
+
 /* StatsD */
 
 void statsd_setup_format(afl_state_t *afl);
@@ -1402,4 +1409,3 @@ void queue_testcase_store_mem(afl_state_t *afl, struct queue_entry *q, u8 *mem);
 #endif
 
 #endif
-
diff --git a/src/afl-fuzz-run.c b/src/afl-fuzz-run.c
index d764952c..82cdeb81 100644
--- a/src/afl-fuzz-run.c
+++ b/src/afl-fuzz-run.c
@@ -409,6 +409,7 @@ u8 calibrate_case(afl_state_t *afl, struct queue_entry *q, u8 *use_mem,
   u32 use_tmout = afl->fsrv.exec_tmout;
   u8 *old_sn = afl->stage_name;
 
+  u64 calibration_start_us = get_cur_time_us();
   if (unlikely(afl->shm.cmplog_mode)) { q->exec_cksum = 0; }
 
   /* Be a bit more generous about timeouts when resuming sessions, or when
@@ -504,6 +505,9 @@ u8 calibrate_case(afl_state_t *afl, struct queue_entry *q, u8 *use_mem,
 
     fault = fuzz_run_target(afl, &afl->fsrv, use_tmout);
 
+    // update the time spend in calibration after each execution, as those may be slow
+    update_calibration_time(afl, &calibration_start_us);
+
     /* afl->stop_soon is set by the handler for Ctrl+C. When it's pressed,
        we want to bail out quickly. */
 
@@ -650,6 +654,7 @@ abort_calibration:
 
   if (!first_run) { show_stats(afl); }
 
+  update_calibration_time(afl, &calibration_start_us);
   return fault;
 
 }
@@ -669,11 +674,15 @@ void sync_fuzzers(afl_state_t *afl) {
   afl->stage_max = afl->stage_cur = 0;
   afl->cur_depth = 0;
 
+  u64 sync_start_us = get_cur_time_us();
   /* Look at the entries created for every other fuzzer in the sync directory.
    */
 
   while ((sd_ent = readdir(sd))) {
 
+    // since sync can take substantial amounts of time, update time spend every iteration
+    update_sync_time(afl, &sync_start_us);
+
     u8  qd_synced_path[PATH_MAX], qd_path[PATH_MAX];
     u32 min_accept = 0, next_min_accept = 0;
 
@@ -861,6 +870,9 @@ void sync_fuzzers(afl_state_t *afl) {
 
   if (afl->foreign_sync_cnt) read_foreign_testcases(afl, 0);
 
+  //add time in sync one last time
+  update_sync_time(afl, &sync_start_us);
+
   afl->last_sync_time = get_cur_time();
   afl->last_sync_cycle = afl->queue_cycle;
 
@@ -872,8 +884,9 @@ void sync_fuzzers(afl_state_t *afl) {
 
 u8 trim_case(afl_state_t *afl, struct queue_entry *q, u8 *in_buf) {
 
+  u8  needs_write = 0, fault = 0;
   u32 orig_len = q->len;
-
+  u64 trim_start_us = get_cur_time_us();
   /* Custom mutator trimmer */
   if (afl->custom_mutators_count) {
 
@@ -897,11 +910,10 @@ u8 trim_case(afl_state_t *afl, struct queue_entry *q, u8 *in_buf) {
 
     }
 
-    if (custom_trimmed) return trimmed_case;
+    if (custom_trimmed) { fault = trimmed_case; goto abort_trimming; }
 
   }
 
-  u8  needs_write = 0, fault = 0;
   u32 trim_exec = 0;
   u32 remove_len;
   u32 len_p2;
@@ -912,7 +924,7 @@ u8 trim_case(afl_state_t *afl, struct queue_entry *q, u8 *in_buf) {
      detected, it will still work to some extent, so we don't check for
      this. */
 
-  if (unlikely(q->len < 5)) { return 0; }
+  if (unlikely(q->len < 5)) { fault = 0; goto abort_trimming; }
 
   afl->stage_name = afl->stage_name_buf;
   afl->bytes_trim_in += q->len;
@@ -946,6 +958,8 @@ u8 trim_case(afl_state_t *afl, struct queue_entry *q, u8 *in_buf) {
 
       fault = fuzz_run_target(afl, &afl->fsrv, afl->fsrv.exec_tmout);
 
+      update_trim_time(afl, &trim_start_us);
+
       if (afl->stop_soon || fault == FSRV_RUN_ERROR) { goto abort_trimming; }
 
       /* Note that we don't keep track of crashes or hangs here; maybe TODO?
@@ -1039,8 +1053,9 @@ u8 trim_case(afl_state_t *afl, struct queue_entry *q, u8 *in_buf) {
   }
 
 abort_trimming:
-
   afl->bytes_trim_out += q->len;
+  update_trim_time(afl, &trim_start_us);
+
   return fault;
 
 }
@@ -1104,4 +1119,3 @@ common_fuzz_stuff(afl_state_t *afl, u8 *out_buf, u32 len) {
   return 0;
 
 }
-
diff --git a/src/afl-fuzz-stats.c b/src/afl-fuzz-stats.c
index 4f398863..b39c8299 100644
--- a/src/afl-fuzz-stats.c
+++ b/src/afl-fuzz-stats.c
@@ -133,6 +133,10 @@ void write_setup_file(afl_state_t *afl, u32 argc, char **argv) {
 
 }
 
+static bool starts_with(char* key, char* line) {
+  return strncmp(key, line, strlen(key)) == 0;
+}
+
 /* load some of the existing stats file when resuming.*/
 void load_stats_file(afl_state_t *afl) {
 
@@ -175,65 +179,54 @@ void load_stats_file(afl_state_t *afl) {
       strcpy(keystring, lstartptr);
       lptr++;
       char *nptr;
-      switch (lineno) {
-
-        case 3:
-          if (!strcmp(keystring, "run_time          "))
-            afl->prev_run_time = 1000 * strtoull(lptr, &nptr, 10);
-          break;
-        case 5:
-          if (!strcmp(keystring, "cycles_done       "))
-            afl->queue_cycle =
-                strtoull(lptr, &nptr, 10) ? strtoull(lptr, &nptr, 10) + 1 : 0;
-          break;
-        case 7:
-          if (!strcmp(keystring, "execs_done        "))
-            afl->fsrv.total_execs = strtoull(lptr, &nptr, 10);
-          break;
-        case 10:
-          if (!strcmp(keystring, "corpus_count      ")) {
-
-            u32 corpus_count = strtoul(lptr, &nptr, 10);
-            if (corpus_count != afl->queued_items) {
-
-              WARNF(
-                  "queue/ has been modified -- things might not work, you're "
-                  "on your own!");
-
-            }
-
-          }
-
-          break;
-        case 12:
-          if (!strcmp(keystring, "corpus_found      "))
-            afl->queued_discovered = strtoul(lptr, &nptr, 10);
-          break;
-        case 13:
-          if (!strcmp(keystring, "corpus_imported   "))
-            afl->queued_imported = strtoul(lptr, &nptr, 10);
-          break;
-        case 14:
-          if (!strcmp(keystring, "max_depth         "))
-            afl->max_depth = strtoul(lptr, &nptr, 10);
-          break;
-        case 21:
-          if (!strcmp(keystring, "saved_crashes    "))
-            afl->saved_crashes = strtoull(lptr, &nptr, 10);
-          break;
-        case 22:
-          if (!strcmp(keystring, "saved_hangs      "))
-            afl->saved_hangs = strtoull(lptr, &nptr, 10);
-          break;
-        default:
-          break;
-
+      if (starts_with("run_time", keystring)){
+        afl->prev_run_time = 1000 * strtoull(lptr, &nptr, 10);
+      }
+      if (starts_with("cycles_done", keystring)){
+        afl->queue_cycle =
+            strtoull(lptr, &nptr, 10) ? strtoull(lptr, &nptr, 10) + 1 : 0;
+      }
+      if (starts_with("calibration_time", keystring)){
+        afl->calibration_time_us = strtoull(lptr, &nptr, 10) * 1000000;
+      }
+      if (starts_with("sync_time", keystring)){
+        afl->sync_time_us = strtoull(lptr, &nptr, 10) * 1000000;
+      }
+      if (starts_with("trim_time", keystring)){
+        afl->trim_time_us = strtoull(lptr, &nptr, 10) * 1000000;
       }
+      if (starts_with("execs_done", keystring)){
+        afl->fsrv.total_execs = strtoull(lptr, &nptr, 10);
+      }
+      if (starts_with("corpus_count", keystring)) {
 
-    }
+        u32 corpus_count = strtoul(lptr, &nptr, 10);
+        if (corpus_count != afl->queued_items) {
 
-  }
+          WARNF(
+              "queue/ has been modified -- things might not work, you're "
+              "on your own!");
 
+        }
+
+      }
+      if (starts_with("corpus_found", keystring)){
+        afl->queued_discovered = strtoul(lptr, &nptr, 10);
+      }
+      if (starts_with("corpus_imported", keystring)){
+        afl->queued_imported = strtoul(lptr, &nptr, 10);
+      }
+      if (starts_with("max_depth", keystring)) {
+        afl->max_depth = strtoul(lptr, &nptr, 10);
+      }
+      if (starts_with("saved_crashes", keystring)) {
+        afl->saved_crashes = strtoull(lptr, &nptr, 10);
+      }
+      if (starts_with("saved_hangs", keystring)) {
+        afl->saved_hangs = strtoull(lptr, &nptr, 10);
+      }
+    }
+  }
   if (afl->saved_crashes) { write_crash_readme(afl); }
 
   return;
@@ -300,6 +293,10 @@ void write_stats_file(afl_state_t *afl, u32 t_bytes, double bitmap_cvg,
       "cycles_done       : %llu\n"
       "cycles_wo_finds   : %llu\n"
       "time_wo_finds     : %llu\n"
+      "fuzz_time         : %llu\n"
+      "calibration_time  : %llu\n"
+      "sync_time         : %llu\n"
+      "trim_time         : %llu\n"
       "execs_done        : %llu\n"
       "execs_per_sec     : %0.02f\n"
       "execs_ps_last_min : %0.02f\n"
@@ -345,6 +342,10 @@ void write_stats_file(afl_state_t *afl, u32 t_bytes, double bitmap_cvg,
           : ((afl->start_time == 0 || afl->last_find_time == 0)
                  ? 0
                  : (cur_time - afl->last_find_time) / 1000),
+      (runtime - (afl->calibration_time_us + afl->sync_time_us + afl->trim_time_us) / 1000) / 1000,
+      afl->calibration_time_us / 1000000,
+      afl->sync_time_us / 1000000,
+      afl->trim_time_us / 1000000,
       afl->fsrv.total_execs, afl->fsrv.total_execs / ((double)(runtime) / 1000),
       afl->last_avg_execs_saved, afl->queued_items, afl->queued_favored,
       afl->queued_discovered, afl->queued_imported, afl->queued_variable,
@@ -414,7 +415,6 @@ void write_stats_file(afl_state_t *afl, u32 t_bytes, double bitmap_cvg,
 
   fclose(f);
   rename(fn_tmp, fn_final);
-
 }
 
 #ifdef INTROSPECTION
@@ -2438,4 +2438,20 @@ void show_init_stats(afl_state_t *afl) {
 #undef IB
 
 }
+void update_calibration_time(afl_state_t *afl, u64* time){
+  u64 cur =  get_cur_time_us();
+  afl->calibration_time_us += cur-*time;
+  *time = cur;
+}
+
+void update_trim_time(afl_state_t *afl, u64* time){
+  u64 cur =  get_cur_time_us();
+  afl->trim_time_us += cur-*time;
+  *time = cur;
+}
 
+void update_sync_time(afl_state_t *afl, u64* time){
+  u64 cur =  get_cur_time_us();
+  afl->sync_time_us += cur-*time;
+  *time = cur;
+}
diff --git a/src/afl-fuzz.c b/src/afl-fuzz.c
index 99491628..102809cd 100644
--- a/src/afl-fuzz.c
+++ b/src/afl-fuzz.c
@@ -3099,4 +3099,3 @@ stop_fuzzing:
 }
 
 #endif                                                          /* !AFL_LIB */
-