Use exponential moving average for timing estimates

Time remaining estimates are now based on a moving average work unit
completion rate instead of percent completion of the entire task. This
better fits tasks that may increase the number of work units as time
goes on (such as increasing the number of retries for any given probe)

libnetutil/massdns.h

@@ -265,8 +265,11 @@ struct Stats
   void reset() {
     servers = names = actual = ok = nx = sf = trans = dropped = system = 0;
   }
+  int statDone() const {
+    return ok + nx + sf + dropped;
+  }
   double getCompletion() const {
-    return (double) (ok + nx + sf + dropped) / actual;
+    return (double) statDone() / actual;
   }
 };
 

nmap_dns.cc

@@ -84,7 +84,7 @@ void nmap_massdns_status(const DNS::Stats *stat)
 {
   if (keyWasPressed()) {
     assert(SPM != NULL);
-    SPM->printStats(stat->getCompletion(), NULL);
+    SPM->printStats(stat->statDone(), stat->actual, NULL);
     /* Because this can change with runtime interaction */
     nmap_adjust_loglevel(o.packetTrace());
   }

nmap_ftp.cc

@@ -341,11 +341,9 @@ void bounce_scan(Target *target, u16 *portarray, int numports,
       }
     }
     nextport:
-    if (SPM->mayBePrinted(NULL)) {
-      SPM->printStatsIfNecessary((double) i / numports, NULL);
-    }
-    else if (keyWasPressed()) {
-      SPM->printStats((double) i / numports, NULL);
+    if (!SPM->printStatsIfNecessary(i, numports, NULL)
+        && keyWasPressed()) {
+      SPM->printStats(i, numports, NULL);
       log_flush(LOG_STDOUT);
     }
   }

nse_main.cc

@@ -161,10 +161,10 @@ static int scp (lua_State *L)
   switch (luaL_checkoption(L, 1, NULL, ops))
   {
     case 0: /* printStats */
-      progress->printStats((double) luaL_checknumber(L, 2), NULL);
+      progress->printStats(luaL_checkinteger(L, 2), luaL_checkinteger(L, 3), NULL);
       break;
     case 1:
-      progress->printStatsIfNecessary((double) luaL_checknumber(L, 2), NULL);
+      progress->printStatsIfNecessary(luaL_checkinteger(L, 2), luaL_checkinteger(L, 3), NULL);
       break;
     case 2: /*mayBePrinted */
       lua_pushboolean(L, progress->mayBePrinted(NULL));

nse_main.lua

@@ -994,7 +994,7 @@ local function run (threads_iter)
     if total > 0 and cnse.key_was_pressed() then
       print_verbose(1, "Active NSE Script Threads: %d (%d waiting)",
           nr+nw, nw);
-      progress("printStats", 1-(nr+nw)/total);
+      progress("printStats", total - (nr+nw), total);
       if debugging() >= 2 then
         for co, thread in pairs(running) do
           thread:d("Running: %THREAD_AGAINST\n\t%s",
@@ -1042,9 +1042,9 @@ local function run (threads_iter)
       end
     elseif total > 0 and progress "mayBePrinted" then
       if verbosity() > 1 or debugging() > 0 then
-        progress("printStats", 1-(nr+nw)/total);
+        progress("printStats", total - (nr+nw), total);
       else
-        progress("printStatsIfNecessary", 1-(nr+nw)/total);
+        progress("printStatsIfNecessary", total - (nr+nw), total);
       end
     end
 

scan_engine.cc

@@ -778,27 +778,24 @@ HostScanStats *UltraScanInfo::nextIncompleteHost() {
 /* Return a number between 0.0 and 1.0 inclusive indicating how much of the scan
    is done. */
 double UltraScanInfo::getCompletionFraction() const {
+  size_t denominator = 0;
+  size_t numerator = this->getCompletionFraction(&denominator);
+  return (double) numerator / denominator;
+}
+size_t UltraScanInfo::getCompletionFraction(size_t *denominator) const {
   std::multiset<HostScanStats *, HssPredicate>::const_iterator hostI;
-  double total;
+  size_t done = send_rate_meter.getNumPackets();
+  size_t total = done;
 
-  /* Add 1 for each completed host. */
-  total = gstats->numtargets - numIncompleteHosts();
   /* Get the completion fraction for each incomplete host. */
   for (hostI = incompleteHosts.begin(); hostI != incompleteHosts.end(); hostI++) {
     const HostScanStats *host = *hostI;
-    int maxtries = host->allowedTryno(NULL, NULL) + 1;
-    double thishostpercdone;
+    int maxtries = host->allowedTryno(NULL, NULL);
 
-    // This is inexact (maxtries - 1) because numprobes_sent includes
-    // at least one try of ports_finished.
-    thishostpercdone = host->ports_finished * (maxtries - 1) + host->numprobes_sent;
-    thishostpercdone /= maxtries * gstats->numprobes;
-    if (thishostpercdone >= 0.9999)
-      thishostpercdone = 0.9999;
-    total += thishostpercdone;
+    total += maxtries * (gstats->numprobes - host->ports_finished);
   }
-
-  return total / gstats->numtargets;
+  *denominator = total;
+  return done;
 }
 
 /* Initialize the state for ports that don't receive a response in all the
@@ -2536,7 +2533,11 @@ static void printAnyStats(UltraScanInfo *USI) {
   }
 
   if (USI->SPM->mayBePrinted(&USI->now))
-    USI->SPM->printStatsIfNecessary(USI->getCompletionFraction(), &USI->now);
+  {
+    size_t total = 0;
+    size_t done = USI->getCompletionFraction(&total);
+    USI->SPM->printStatsIfNecessary(done, total, &USI->now);
+  }
 }
 
 static void waitForResponses(UltraScanInfo *USI) {
@@ -2800,7 +2801,9 @@ void ultra_scan(std::vector<Target *> &Targets, const struct scan_lists *ports,
     if (keyWasPressed()) {
       // This prints something like
       // SYN Stealth Scan Timing: About 1.14% done; ETC: 15:01 (0:43:23 remaining);
-      USI.SPM->printStats(USI.getCompletionFraction(), NULL);
+      size_t total = 0;
+      size_t done = USI.getCompletionFraction(&total);
+      USI.SPM->printStats(done, total, NULL);
       if (o.debugging) {
         /* Don't update when getting the current rates, otherwise we can get
            anomalies (rates are too low) from having just done a potentially

scan_engine.h

@@ -594,6 +594,7 @@ public:
   HostScanStats *findHost(const struct sockaddr_storage *ss) const;
 
   double getCompletionFraction() const;
+  size_t getCompletionFraction(size_t *denominator) const;
 
   unsigned int numIncompleteHosts() const {
     return incompleteHosts.size();

service_scan.cc

@@ -217,6 +217,7 @@ public:
   std::list<ServiceNFO *> services_finished; // Services finished (discovered or not)
   std::list<ServiceNFO *> services_in_progress; // Services currently being probed
   std::list<ServiceNFO *> services_remaining; // Probes not started yet
+  size_t total_services;
   unsigned int ideal_parallelism; // Max (and desired) number of probes out at once.
   ScanProgressMeter *SPM;
   int num_hosts_timedout; // # of hosts timed out during (or before) scan
@@ -1992,6 +1993,7 @@ ServiceGroup::ServiceGroup(std::vector<Target *> &Targets, AllProbes *AP) {
       svc->proto = nxtport->proto;
       services_remaining.push_back(svc);
     }
+    total_services = services_remaining.size();
 
     /* Check if any early responses can help */
     for (std::vector<EarlySvcResponse *>::iterator it = target->earlySvcResponses.begin();
@@ -2232,17 +2234,13 @@ static void considerPrintingStats(ServiceGroup *SG) {
    /* Check for status requests */
    if (keyWasPressed()) {
       nmap_adjust_loglevel(o.versionTrace());
-      SG->SPM->printStats(SG->services_finished.size() /
-                          ((double)SG->services_remaining.size() + SG->services_in_progress.size() +
-                           SG->services_finished.size()), nsock_gettimeofday());
+      SG->SPM->printStats(SG->services_finished.size(), SG->total_services, nsock_gettimeofday());
+   }
+   else {
+      /* Perhaps this should be made more complex, but I suppose it should be
+         good enough for now. */
+      SG->SPM->printStatsIfNecessary(SG->services_finished.size(), SG->total_services, nsock_gettimeofday());
    }
-
-
-  /* Perhaps this should be made more complex, but I suppose it should be
-     good enough for now. */
-  if (SG->SPM->mayBePrinted(nsock_gettimeofday())) {
-    SG->SPM->printStatsIfNecessary(SG->services_finished.size() / ((double)SG->services_remaining.size() + SG->services_in_progress.size() + SG->services_finished.size()), nsock_gettimeofday());
-  }
 }
 
 /* Check if target is done (no more probes remaining for it in service group),
@@ -2441,9 +2439,7 @@ static void servicescan_write_handler(nsock_pool nsp, nsock_event nse, void *myd
 
   // Check if a status message was requested
   if (keyWasPressed()) {
-     SG->SPM->printStats(SG->services_finished.size() /
-                         ((double)SG->services_remaining.size() + SG->services_in_progress.size() +
-                          SG->services_finished.size()), nsock_gettimeofday());
+     SG->SPM->printStats(SG->services_finished.size(), SG->total_services, nsock_gettimeofday());
   }
 
 

timing.cc

@@ -494,10 +494,12 @@ unsigned long long PacketRateMeter::getNumBytes(void) const {
   return (unsigned long long) byte_rate_meter.getTotal();
 }
 
-ScanProgressMeter::ScanProgressMeter(const char *stypestr) {
+ScanProgressMeter::ScanProgressMeter(const char *stypestr)
+  : prev_done(0), prev_rate(0.0), last_time_left(0) {
   scantypestr = strdup(stypestr);
   gettimeofday(&begin, NULL);
   last_print_test = begin;
+  prev_time = begin;
   memset(&last_print, 0, sizeof(last_print));
   memset(&last_est, 0, sizeof(last_est));
   beginOrEndTask(&begin, NULL, true);
@@ -532,44 +534,84 @@ bool ScanProgressMeter::mayBePrinted(const struct timeval *now) {
 
   if (last_print.tv_sec == 0) {
     /* We've never printed before -- the rules are less stringent */
-    if (difftime(now->tv_sec, begin.tv_sec) > 30)
+    if (TIMEVAL_SEC_SUBTRACT(*now, begin) > 30)
       return true;
     else
       return false;
   }
 
-  if (difftime(now->tv_sec, last_print_test.tv_sec) < 3)
+  if (TIMEVAL_SEC_SUBTRACT(*now, last_print_test) < 3)
     return false;  /* No point even checking too often */
 
   /* We'd never want to print more than once per 30 seconds */
-  if (difftime(now->tv_sec, last_print.tv_sec) < 30)
+  if (TIMEVAL_SEC_SUBTRACT(*now, last_print) < 30)
     return false;
 
   return true;
 }
 
-/* Return an estimate of the time remaining if a process was started at begin
-   and is perc_done of the way finished. Returns inf if perc_done == 0.0. */
-static double estimate_time_left(double perc_done,
-                                 const struct timeval *begin,
+// Cap ETA at 10 days. Beyond that is useless.
+static const unsigned int MAX_ETA_SECONDS = 864000;
+
+/* Return the estimated seconds remaining */
+unsigned int ScanProgressMeter::estimate_time_left(size_t num_done, size_t num_total,
                                  const struct timeval *now) {
-  double time_used_s;
-  double time_needed_s;
+  if (num_done >= num_total)
+    return 0;
+  if (num_done < prev_done)
+    prev_done = num_done;
+  size_t completed = num_done - prev_done;
+  // Check for unrecovered stall
+  if (completed == 0 && prev_rate == 0.0)
+    return MAX_ETA_SECONDS;
 
-  time_used_s = difftime(now->tv_sec, begin->tv_sec);
-  time_needed_s = time_used_s / perc_done;
+  double time_since_prev = TIMEVAL_FSEC_SUBTRACT(*now, prev_time);
+  if (time_since_prev < 5.0 // Don't recalculate more often than every 5 seconds
+    && last_time_left > time_since_prev) // unless we've passed the last estimate
+  {
+    return last_time_left - time_since_prev;
+  }
 
-  return time_needed_s - time_used_s;
+  double rate = completed / time_since_prev;
+
+  if (prev_rate == 0.0) {
+    // Either we're just starting out or we're coming back from a stall.
+    // In both cases, fall back to the old average time estimate.
+    double time_since_start = TIMEVAL_FSEC_SUBTRACT(*now, begin);
+    assert(time_since_start > 0.0);
+    if (time_since_start > 0.0)
+      prev_rate = num_done / time_since_start;
+    else
+      prev_rate = 1.0; // Bogus, but ought to be unreachable
+  }
+
+  // Average the previous rate with the current rate
+  rate = 0.25 * rate + 0.75 * prev_rate;
+  assert(rate > 0.0);
+
+  double remaining = (num_total - num_done) / rate;
+  if (remaining > (double) MAX_ETA_SECONDS) {
+    // Effectively stalled, signal with rate/prev_rate = 0.0
+    rate = 0.0;
+    last_time_left = MAX_ETA_SECONDS;
+  }
+  else
+    last_time_left = remaining;
+
+  prev_time = *now;
+  prev_done = num_done;
+  prev_rate = rate;
+
+  return last_time_left;
 }
 
 /* Prints an estimate of when this scan will complete.  It only does
    so if mayBePrinted() is true, and it seems reasonable to do so
    because the estimate has changed significantly.  Returns whether
    or not a line was printed.*/
-bool ScanProgressMeter::printStatsIfNecessary(double perc_done,
+bool ScanProgressMeter::printStatsIfNecessary(size_t num_done, size_t num_total,
                                                const struct timeval *now) {
   struct timeval tvtmp;
-  double time_left_s;
   bool printit = false;
 
   if (!now) {
@@ -582,12 +624,11 @@ bool ScanProgressMeter::printStatsIfNecessary(double perc_done,
 
   last_print_test = *now;
 
+  double perc_done = (double) num_done / num_total;
   if (perc_done <= 0.003)
     return false; /* Need more info first */
 
-  assert(perc_done <= 1.0);
-
-  time_left_s = estimate_time_left(perc_done, &begin, now);
+  unsigned int time_left_s = estimate_time_left(num_done, num_total, now);
 
   if (time_left_s < 30)
     return false; /* No point in updating when it is virtually finished. */
@@ -609,32 +650,29 @@ bool ScanProgressMeter::printStatsIfNecessary(double perc_done,
   }
 
   if (printit) {
-     return printStats(perc_done, now);
+     return printStats_common(time_left_s, perc_done, now);
   }
 
   return false;
 }
 
 /* Prints an estimate of when this scan will complete.  */
-bool ScanProgressMeter::printStats(double perc_done,
+bool ScanProgressMeter::printStats(size_t num_done, size_t num_total,
                                    const struct timeval *now) {
   struct timeval tvtmp;
-  double time_left_s;
-  time_t timet;
-  struct tm ltime;
-  int err;
 
   if (!now) {
     gettimeofday(&tvtmp, NULL);
     now = (const struct timeval *) &tvtmp;
   }
 
-  last_print = *now;
+  double perc_done = (double) num_done / num_total;
 
   // If we're less than 1% done we probably don't have enough
   // data for decent timing estimates. Also with perc_done == 0
   // these elements will be nonsensical.
   if (perc_done < 0.01) {
+    last_print = *now;
     log_write(LOG_STDOUT, "%s Timing: About %.2f%% done\n",
         scantypestr, perc_done * 100);
     xml_open_start_tag("taskprogress");
@@ -647,37 +685,51 @@ bool ScanProgressMeter::printStats(double perc_done,
     return true;
   }
 
-  /* Add 0.5 to get the effect of rounding in integer calculations. */
-  time_left_s = estimate_time_left(perc_done, &begin, now) + 0.5;
+  unsigned int time_left_s = estimate_time_left(num_done, num_total, now);
 
-  last_est = *now;
-  last_est.tv_sec += (time_t)time_left_s;
+  return printStats_common(time_left_s, perc_done, now);
+}
 
-  /* Get the estimated time of day at completion */
-  timet = last_est.tv_sec;
-  err = n_localtime(&timet, &ltime);
+bool ScanProgressMeter::printStats_common(unsigned int time_left_s, double perc_done, const struct timeval *now)
+{
+  // Avoid saying something is 100.00% done when it's clearly not.
+  if (perc_done > 0.9999)
+    perc_done = 0.9999;
 
-  if (!err) {
-    log_write(LOG_STDOUT, "%s Timing: About %.2f%% done; ETC: %02d:%02d (%.f:%02.f:%02.f remaining)\n",
-        scantypestr, perc_done * 100, ltime.tm_hour, ltime.tm_min,
-        floor(time_left_s / 60.0 / 60.0),
-        floor(fmod(time_left_s / 60.0, 60.0)),
-        floor(fmod(time_left_s, 60.0)));
-  }
-  else {
-    log_write(LOG_STDERR, "Timing error: n_localtime(%f): %s\n", (double) timet, strerror(err));
-    log_write(LOG_STDOUT, "%s Timing: About %.2f%% done; ETC: Unknown (%.f:%02.f:%02.f remaining)\n",
-        scantypestr, perc_done * 100,
-        floor(time_left_s / 60.0 / 60.0),
-        floor(fmod(time_left_s / 60.0, 60.0)),
-        floor(fmod(time_left_s, 60.0)));
-  }
   xml_open_start_tag("taskprogress");
   xml_attribute("task", "%s", scantypestr);
   xml_attribute("time", "%lu", (unsigned long) now->tv_sec);
   xml_attribute("percent", "%.2f", perc_done * 100);
-  xml_attribute("remaining", "%.f", time_left_s);
-  xml_attribute("etc", "%lu", (unsigned long) last_est.tv_sec);
+  xml_attribute("remaining", "%u", time_left_s);
+
+  if (time_left_s == MAX_ETA_SECONDS) {
+    log_write(LOG_STDOUT, "%s Timing: About %.2f%% done; ETC: Unknown (>10 days remaining)\n",
+        scantypestr, perc_done * 100);
+  }
+  else {
+    char etc_str[] = "Unknown";
+    last_est = *now;
+    last_est.tv_sec += (time_t)time_left_s;
+
+    /* Get the estimated time of day at completion */
+    struct tm ltime;
+    time_t timet = last_est.tv_sec;
+    int err = n_localtime(&timet, &ltime);
+
+    last_print = *now;
+    if (!err) {
+      Snprintf(etc_str, sizeof(etc_str), "%02d:%02d", ltime.tm_hour, ltime.tm_min);
+    }
+    else {
+      log_write(LOG_STDERR, "Timing error: n_localtime(%f): %s\n", (double) timet, strerror(err));
+    }
+    log_write(LOG_STDOUT, "%s Timing: About %.2f%% done; ETC: %s (%.f:%02.f:%02.f remaining)\n",
+        scantypestr, perc_done * 100, etc_str,
+        floor(time_left_s / 60.0 / 60.0),
+        floor(fmod(time_left_s / 60.0, 60.0)),
+        floor(fmod(time_left_s, 60.0)));
+    xml_attribute("etc", "%lu", (unsigned long) last_est.tv_sec);
+  }
   xml_close_empty_tag();
   xml_newline();
   log_flush(LOG_STDOUT|LOG_XML);

timing.h

@@ -232,10 +232,10 @@ class ScanProgressMeter {
    so if mayBePrinted() is true, and it seems reasonable to do so
    because the estimate has changed significantly.  Returns whether
    or not a line was printed.*/
-  bool printStatsIfNecessary(double perc_done, const struct timeval *now);
+  bool printStatsIfNecessary(size_t num_done, size_t num_total, const struct timeval *now);
 
   /* Prints an estimate of when this scan will complete. */
-  bool printStats(double perc_done, const struct timeval *now);
+  bool printStats(size_t num_done, size_t num_total, const struct timeval *now);
 
   /* Prints that this task is complete. */
   bool endTask(const struct timeval *now, const char *additional_info) { return beginOrEndTask(now, additional_info, false); }
@@ -246,8 +246,14 @@ class ScanProgressMeter {
   struct timeval last_print; /* The most recent time the ETC was printed */
   char *scantypestr;
   struct timeval last_est; /* The latest PRINTED estimate */
+  struct timeval prev_time;
+  size_t prev_done;
+  double prev_rate;
+  unsigned int last_time_left;
 
   bool beginOrEndTask(const struct timeval *now, const char *additional_info, bool beginning);
+  unsigned int estimate_time_left(size_t num_done, size_t num_total, const struct timeval *now);
+  bool printStats_common(unsigned int time_left_s, double perc_done, const struct timeval *now);
 };
 
 #endif /* NMAP_TIMING_H */

traceroute.cc

@@ -237,7 +237,7 @@ public:
   int cancel_probes_above(u8 ttl);
   Hop *insert_hop(u8 ttl, const struct sockaddr_storage *addr, float rtt);
   void link_to(Hop *hop);
-  double completion_fraction() const;
+  unsigned int completion() const;
 
 private:
   void child_parent_ttl(u8 ttl, Hop **child, Hop **parent) const;
@@ -289,7 +289,7 @@ public:
   void resolve_hops();
   void transfer_hops();
 
-  double completion_fraction() const;
+  unsigned int completion(unsigned int *total) const;
 
 private:
   netutil_eth_t *ethsd;
@@ -491,11 +491,11 @@ void HostState::link_to(Hop *hop) {
     prev->parent = hop;
 }
 
-double HostState::completion_fraction() const {
+unsigned int HostState::completion() const {
   unsigned int i, n;
 
   if (this->is_finished())
-    return 1.0;
+    return sent_ttls.size();
 
   n = 0;
   for (i = 0; i < sent_ttls.size(); i++) {
@@ -503,7 +503,7 @@ double HostState::completion_fraction() const {
       n++;
   }
 
-  return (double) n / sent_ttls.size();
+  return n;
 }
 
 void HostState::child_parent_ttl(u8 ttl, Hop **child, Hop **parent) const {
@@ -1414,14 +1414,18 @@ Probe *TracerouteState::lookup_probe(
   return NULL;
 }
 
-double TracerouteState::completion_fraction() const {
+unsigned int TracerouteState::completion(unsigned int *total) const {
   std::vector<HostState *>::const_iterator it;
-  double sum;
+  unsigned int complete = 0;
+  unsigned int sum = 0;
 
-  sum = 0.0;
   for (it = hosts.begin(); it != hosts.end(); it++)
-    sum += (*it)->completion_fraction();
-  return sum / hosts.size();
+  {
+    complete += (*it)->completion();
+    sum += (*it)->sent_ttls.size();
+  }
+  *total = sum;
+  return complete;
 }
 
 /* This is a special case of traceroute when all the targets are directly
@@ -1479,8 +1483,11 @@ static int traceroute_remote(std::vector<Target *> targets) {
     global_state.cull_timeouts();
     global_state.remove_finished_hosts();
 
-    if (keyWasPressed())
-      SPM.printStats(global_state.completion_fraction(), NULL);
+    if (keyWasPressed()) {
+      unsigned int complete, total;
+      complete = global_state.completion(&total);
+      SPM.printStats(complete, total, NULL);
+    }
   }
 
   SPM.endTask(NULL, NULL);