From 48a862c503483f64db713fd6a0392148b5584ca4 Mon Sep 17 00:00:00 2001 From: Cornelius Aschermann Date: Wed, 13 Mar 2024 11:43:58 -0700 Subject: :Adds stats tracking time spend in calibration/trim/sync This currently does not affect statsd nor the UI. Only the fuzzer_stats file is updated --- include/afl-fuzz.h | 10 +++- src/afl-fuzz-run.c | 26 ++++++++--- src/afl-fuzz-stats.c | 128 +++++++++++++++++++++++++++++---------------------- src/afl-fuzz.c | 1 - 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 */ - -- cgit v1.2.3