1
2 /***************************************************************************
3 * timing.cc -- Functions related to computing scan timing (such as *
4 * keeping track of and adjusting smoothed round trip times, statistical *
5 * deviations, timeout values, etc. Various user options (such as the *
6 * timing policy (-T)) also play a role in these calculations *
7 * *
8 ***********************IMPORTANT NMAP LICENSE TERMS************************
9 * *
10 * The Nmap Security Scanner is (C) 1996-2020 Insecure.Com LLC ("The Nmap *
11 * Project"). Nmap is also a registered trademark of the Nmap Project. *
12 * *
13 * This program is distributed under the terms of the Nmap Public Source *
14 * License (NPSL). The exact license text applying to a particular Nmap *
15 * release or source code control revision is contained in the LICENSE *
16 * file distributed with that version of Nmap or source code control *
17 * revision. More Nmap copyright/legal information is available from *
18 * https://nmap.org/book/man-legal.html, and further information on the *
19 * NPSL license itself can be found at https://nmap.org/npsl. This header *
20 * summarizes some key points from the Nmap license, but is no substitute *
21 * for the actual license text. *
22 * *
23 * Nmap is generally free for end users to download and use themselves, *
24 * including commercial use. It is available from https://nmap.org. *
25 * *
26 * The Nmap license generally prohibits companies from using and *
27 * redistributing Nmap in commercial products, but we sell a special Nmap *
28 * OEM Edition with a more permissive license and special features for *
29 * this purpose. See https://nmap.org/oem *
30 * *
31 * If you have received a written Nmap license agreement or contract *
32 * stating terms other than these (such as an Nmap OEM license), you may *
33 * choose to use and redistribute Nmap under those terms instead. *
34 * *
35 * The official Nmap Windows builds include the Npcap software *
36 * (https://npcap.org) for packet capture and transmission. It is under *
37 * separate license terms which forbid redistribution without special *
38 * permission. So the official Nmap Windows builds may not be *
39 * redistributed without special permission (such as an Nmap OEM *
40 * license). *
41 * *
42 * Source is provided to this software because we believe users have a *
43 * right to know exactly what a program is going to do before they run it. *
44 * This also allows you to audit the software for security holes. *
45 * *
46 * Source code also allows you to port Nmap to new platforms, fix bugs, *
47 * and add new features. You are highly encouraged to submit your *
48 * changes as a Github PR or by email to the dev@nmap.org mailing list *
49 * for possible incorporation into the main distribution. Unless you *
50 * specify otherwise, it is understood that you are offering us very *
51 * broad rights to use your submissions as described in the Nmap Public *
52 * Source License Contributor Agreement. This is important because we *
53 * fund the project by selling licenses with various terms, and also *
54 * because the inability to relicense code has caused devastating *
55 * problems for other Free Software projects (such as KDE and NASM). *
56 * *
57 * The free version of Nmap is distributed in the hope that it will be *
58 * useful, but WITHOUT ANY WARRANTY; without even the implied warranty of *
59 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. Warranties, *
60 * indemnification and commercial support are all available through the *
61 * Npcap OEM program--see https://nmap.org/oem. *
62 * *
63 ***************************************************************************/
64
65 /* $Id: timing.cc 38078 2020-10-02 16:12:22Z dmiller $ */
66
67 #include "timing.h"
68 #include "NmapOps.h"
69 #include "utils.h"
70 #include "nmap_error.h"
71 #include "xml.h"
72
73 #include <math.h>
74 #include <limits>
75
76 extern NmapOps o;
77
78 /* Call this function on a newly allocated struct timeout_info to
79 initialize the values appropriately */
initialize_timeout_info(struct timeout_info * to)80 void initialize_timeout_info(struct timeout_info *to) {
81 to->srtt = -1;
82 to->rttvar = -1;
83 to->timeout = o.initialRttTimeout() * 1000;
84 }
85
86 /* Adjust our timeout values based on the time the latest probe took for a
87 response. We update our RTT averages, etc. */
adjust_timeouts(struct timeval sent,struct timeout_info * to)88 void adjust_timeouts(struct timeval sent, struct timeout_info *to) {
89 struct timeval received;
90 gettimeofday(&received, NULL);
91
92 adjust_timeouts2(&sent, &received, to);
93 return;
94 }
95
96 /* Same as adjust_timeouts(), except this one allows you to specify
97 the receive time too (which could be because it was received a while
98 back or it could be for efficiency because the caller already knows
99 the current time */
adjust_timeouts2(const struct timeval * sent,const struct timeval * received,struct timeout_info * to)100 void adjust_timeouts2(const struct timeval *sent,
101 const struct timeval *received,
102 struct timeout_info *to) {
103 long delta = 0;
104
105 if (o.debugging > 3) {
106 log_write(LOG_STDOUT, "Timeout vals: srtt: %d rttvar: %d to: %d ", to->srtt, to->rttvar, to->timeout);
107 }
108
109 delta = TIMEVAL_SUBTRACT(*received, *sent);
110
111 /* Argh ... pcap receive time is sometimes a little off my
112 getimeofday() results on various platforms :(. So a packet may
113 appear to be received as much as a hundredth of a second before
114 it was sent. So I will allow small negative RTT numbers */
115 if (delta < 0 && delta > -50000) {
116 if (o.debugging > 2)
117 log_write(LOG_STDOUT, "Small negative delta (probably due to libpcap time / gettimeofday() discrepancy) - adjusting from %lius to %dus\n", delta, 10000);
118 delta = 10000;
119 }
120
121
122 if (to->srtt == -1 && to->rttvar == -1) {
123 /* We need to initialize the sucker ... */
124 to->srtt = delta;
125 to->rttvar = MAX(5000, MIN(to->srtt, 2000000));
126 to->timeout = to->srtt + (to->rttvar << 2);
127 } else {
128 long rttdelta;
129
130 if (delta >= 8000000 || delta < 0) {
131 if (o.verbose)
132 error("%s: packet supposedly had rtt of %ld microseconds. Ignoring time.", __func__, delta);
133 return;
134 }
135 rttdelta = delta - to->srtt;
136 /* sanity check 2*/
137 if (rttdelta > 1500000 && rttdelta > 3 * to->srtt + 2 * to->rttvar) {
138 if (o.debugging) {
139 log_write(LOG_STDOUT, "Bogus rttdelta: %ld (srtt %d) ... ignoring\n", rttdelta, to->srtt);
140 }
141 return;
142 }
143 to->srtt += rttdelta >> 3;
144 to->rttvar += (ABS(rttdelta) - to->rttvar) >> 2;
145 to->timeout = to->srtt + (to->rttvar << 2);
146 }
147 if (to->rttvar > 2300000) {
148 error("RTTVAR has grown to over 2.3 seconds, decreasing to 2.0");
149 to->rttvar = 2000000;
150 }
151
152 /* It hurts to do this ... it really does ... but otherwise we are being
153 too risky */
154 to->timeout = box(o.minRttTimeout() * 1000, o.maxRttTimeout() * 1000,
155 to->timeout);
156
157 if (o.scan_delay)
158 to->timeout = MAX((unsigned) to->timeout, o.scan_delay * 1000);
159
160 if (o.debugging > 3) {
161 log_write(LOG_STDOUT, "delta %ld ==> srtt: %d rttvar: %d to: %d\n", delta, to->srtt, to->rttvar, to->timeout);
162 }
163
164 /* if (to->srtt < 0 || to->rttvar < 0 || to->timeout < 0 || delta < -50000000 ||
165 sent->tv_sec == 0 || received->tv_sec == 0 ) {
166 fatal("Serious time computation problem in adjust_timeout ... received = (%ld, %ld) sent=(%ld,%ld) delta = %ld srtt = %d rttvar = %d to = %d", (long) received->tv_sec, (long)received->tv_usec, (long) sent->tv_sec, (long) sent->tv_usec, delta, to->srtt, to->rttvar, to->timeout);
167 } */
168 }
169
170 /* Sleeps if necessary to ensure that it isn't called twice within less
171 time than o.send_delay. If it is passed a non-null tv, the POST-SLEEP
172 time is recorded in it */
enforce_scan_delay(struct timeval * tv)173 void enforce_scan_delay(struct timeval *tv) {
174 static int init = -1;
175 static struct timeval lastcall;
176 struct timeval now;
177 int time_diff;
178
179 if (!o.scan_delay) {
180 if (tv) gettimeofday(tv, NULL);
181 return;
182 }
183
184 if (init == -1) {
185 gettimeofday(&lastcall, NULL);
186 init = 0;
187 if (tv)
188 memcpy(tv, &lastcall, sizeof(struct timeval));
189 return;
190 }
191
192 gettimeofday(&now, NULL);
193 time_diff = TIMEVAL_MSEC_SUBTRACT(now, lastcall);
194 if (time_diff < (int) o.scan_delay) {
195 if (o.debugging > 1) {
196 log_write(LOG_PLAIN, "Sleeping for %d milliseconds in %s()\n", o.scan_delay - time_diff, __func__);
197 }
198 usleep((o.scan_delay - time_diff) * 1000);
199 gettimeofday(&lastcall, NULL);
200 } else
201 memcpy(&lastcall, &now, sizeof(struct timeval));
202 if (tv) {
203 memcpy(tv, &lastcall, sizeof(struct timeval));
204 }
205
206 return;
207 }
208
209
210 /* Returns the scaling factor to use when incrementing the congestion
211 window. */
cc_scale(const struct scan_performance_vars * perf)212 double ultra_timing_vals::cc_scale(const struct scan_performance_vars *perf) {
213 double ratio;
214
215 assert(num_replies_received > 0);
216 ratio = (double) num_replies_expected / num_replies_received;
217
218 return MIN(ratio, perf->cc_scale_max);
219 }
220
221 /* Update congestion variables for the receipt of a reply. */
ack(const struct scan_performance_vars * perf,double scale)222 void ultra_timing_vals::ack(const struct scan_performance_vars *perf, double scale) {
223 num_replies_received++;
224
225 if (cwnd < ssthresh) {
226 /* In slow start mode. "During slow start, a TCP increments cwnd by at most
227 SMSS bytes for each ACK received that acknowledges new data." */
228 cwnd += perf->slow_incr * cc_scale(perf) * scale;
229 if (cwnd > ssthresh)
230 cwnd = ssthresh;
231 } else {
232 /* Congestion avoidance mode. "During congestion avoidance, cwnd is
233 incremented by 1 full-sized segment per round-trip time (RTT). The
234 equation
235 cwnd += SMSS*SMSS/cwnd
236 provides an acceptable approximation to the underlying principle of
237 increasing cwnd by 1 full-sized segment per RTT." */
238 cwnd += perf->ca_incr / cwnd * cc_scale(perf) * scale;
239 }
240 if (cwnd > perf->max_cwnd)
241 cwnd = perf->max_cwnd;
242 }
243
244 /* Update congestion variables for a detected drop. */
drop(unsigned in_flight,const struct scan_performance_vars * perf,const struct timeval * now)245 void ultra_timing_vals::drop(unsigned in_flight,
246 const struct scan_performance_vars *perf, const struct timeval *now) {
247 /* "When a TCP sender detects segment loss using the retransmission timer, the
248 value of ssthresh MUST be set to no more than the value
249 ssthresh = max (FlightSize / 2, 2*SMSS)
250 Furthermore, upon a timeout cwnd MUST be set to no more than the loss
251 window, LW, which equals 1 full-sized segment (regardless of the value of
252 IW)." */
253 cwnd = perf->low_cwnd;
254 ssthresh = (int) MAX(in_flight / perf->host_drop_ssthresh_divisor, 2);
255 last_drop = *now;
256 }
257
258 /* Update congestion variables for a detected drop, but less aggressively for
259 group congestion control. */
drop_group(unsigned in_flight,const struct scan_performance_vars * perf,const struct timeval * now)260 void ultra_timing_vals::drop_group(unsigned in_flight,
261 const struct scan_performance_vars *perf, const struct timeval *now) {
262 cwnd = MAX(perf->low_cwnd, cwnd / perf->group_drop_cwnd_divisor);
263 ssthresh = (int) MAX(in_flight / perf->group_drop_ssthresh_divisor, 2);
264 last_drop = *now;
265 }
266
267 /* Do initialization after the global NmapOps table has been filled in. */
init()268 void scan_performance_vars::init() {
269 /* TODO: I should revisit these values for tuning. They should probably
270 at least be affected by -T. */
271 low_cwnd = o.min_parallelism ? o.min_parallelism : 1;
272 max_cwnd = MAX(low_cwnd, o.max_parallelism ? o.max_parallelism : 300);
273 group_initial_cwnd = box(low_cwnd, max_cwnd, 10);
274 host_initial_cwnd = group_initial_cwnd;
275 slow_incr = 1;
276 /* The congestion window grows faster with more aggressive timing. */
277 if (o.timing_level < 4)
278 ca_incr = 1;
279 else
280 ca_incr = 2;
281 cc_scale_max = 50;
282 initial_ssthresh = 75;
283 group_drop_cwnd_divisor = 2.0;
284 /* Change the amount that ssthresh drops based on the timing level. */
285 double ssthresh_divisor;
286 if (o.timing_level <= 3)
287 ssthresh_divisor = (3.0 / 2.0);
288 else if (o.timing_level <= 4)
289 ssthresh_divisor = (4.0 / 3.0);
290 else
291 ssthresh_divisor = (5.0 / 4.0);
292 group_drop_ssthresh_divisor = ssthresh_divisor;
293 host_drop_ssthresh_divisor = ssthresh_divisor;
294 }
295
296 /* current_rate_history defines how far back (in seconds) we look when
297 calculating the current rate. */
RateMeter(double current_rate_history)298 RateMeter::RateMeter(double current_rate_history) {
299 this->current_rate_history = current_rate_history;
300 start_tv.tv_sec = 0;
301 start_tv.tv_usec = 0;
302 stop_tv.tv_sec = 0;
303 stop_tv.tv_usec = 0;
304 last_update_tv.tv_sec = 0;
305 last_update_tv.tv_usec = 0;
306 total = 0.0;
307 current_rate = 0.0;
308 assert(!isSet(&start_tv));
309 assert(!isSet(&stop_tv));
310 }
311
start(const struct timeval * now)312 void RateMeter::start(const struct timeval *now) {
313 assert(!isSet(&start_tv));
314 assert(!isSet(&stop_tv));
315 if (now == NULL)
316 gettimeofday(&start_tv, NULL);
317 else
318 start_tv = *now;
319 }
320
stop(const struct timeval * now)321 void RateMeter::stop(const struct timeval *now) {
322 assert(isSet(&start_tv));
323 assert(!isSet(&stop_tv));
324 if (now == NULL)
325 gettimeofday(&stop_tv, NULL);
326 else
327 stop_tv = *now;
328 }
329
330 /* Update the rates to reflect the given amount added to the total at the time
331 now. If now is NULL, get the current time with gettimeofday. */
update(double amount,const struct timeval * now)332 void RateMeter::update(double amount, const struct timeval *now) {
333 struct timeval tv;
334 double diff;
335 double interval;
336 double count;
337
338 assert(isSet(&start_tv));
339 assert(!isSet(&stop_tv));
340
341 /* Update the total. */
342 total += amount;
343
344 if (now == NULL) {
345 gettimeofday(&tv, NULL);
346 now = &tv;
347 }
348 if (!isSet(&last_update_tv))
349 last_update_tv = start_tv;
350
351 /* Calculate the approximate moving average of how much was recorded in the
352 last current_rate_history seconds. This average is what is returned as the
353 "current" rate. */
354
355 /* How long since the last update? */
356 diff = TIMEVAL_SUBTRACT(*now, last_update_tv) / 1000000.0;
357
358 if (diff < -current_rate_history)
359 /* This happened farther in the past than we care about. */
360 return;
361
362 if (diff < 0.0) {
363 /* If the event happened in the past, just add it into the total and don't
364 change last_update_tv, as if it had happened at the same time as the most
365 recent event. */
366 now = &last_update_tv;
367 diff = 0.0;
368 }
369
370 /* Find out how far back in time to look. We want to look back
371 current_rate_history seconds, or to when the last update occurred,
372 whichever is longer. However, we never look past the start. */
373 struct timeval tmp;
374 /* Find the time current_rate_history seconds after the start. That's our
375 threshold for deciding how far back to look. */
376 TIMEVAL_ADD(tmp, start_tv, (time_t) (current_rate_history * 1000000.0));
377 if (TIMEVAL_AFTER(*now, tmp))
378 interval = MAX(current_rate_history, diff);
379 else
380 interval = TIMEVAL_SUBTRACT(*now, start_tv) / 1000000.0;
381 assert(diff <= interval + std::numeric_limits<double>::epsilon());
382 /* If we record an amount in the very same instant that the timer is started,
383 there's no way to calculate meaningful rates. Ignore it. */
384 if (interval == 0.0)
385 return;
386
387 /* To calculate the approximate average of the rate over the last
388 interval seconds, we assume that the rate was constant over that interval.
389 We calculate how much would have been received in that interval, ignoring
390 the first diff seconds' worth:
391 (interval - diff) * current_rate.
392 Then we add how much was received in the most recent diff seconds. Divide
393 by the width of the interval to get the average. */
394 count = (interval - diff) * current_rate + amount;
395 current_rate = count / interval;
396
397 last_update_tv = *now;
398 }
399
getOverallRate(const struct timeval * now) const400 double RateMeter::getOverallRate(const struct timeval *now) const {
401 double elapsed;
402
403 elapsed = elapsedTime(now);
404 if (elapsed <= 0.0)
405 return 0.0;
406 else
407 return total / elapsed;
408 }
409
410 /* Get the "current" rate (actually a moving average of the last
411 current_rate_history seconds). If update is true (its default value), lower
412 the rate to account for the time since the last record. */
getCurrentRate(const struct timeval * now,bool update)413 double RateMeter::getCurrentRate(const struct timeval *now, bool update) {
414 if (update)
415 this->update(0.0, now);
416
417 return current_rate;
418 }
419
getTotal(void) const420 double RateMeter::getTotal(void) const {
421 return total;
422 }
423
424 /* Get the number of seconds the meter has been running: if it has been stopped,
425 the amount of time between start and stop, or if it is still running, the
426 amount of time between start and now. */
elapsedTime(const struct timeval * now) const427 double RateMeter::elapsedTime(const struct timeval *now) const {
428 struct timeval tv;
429 const struct timeval *end_tv;
430
431 assert(isSet(&start_tv));
432
433 if (isSet(&stop_tv)) {
434 end_tv = &stop_tv;
435 } else if (now == NULL) {
436 gettimeofday(&tv, NULL);
437 end_tv = &tv;
438 } else {
439 end_tv = now;
440 }
441
442 return TIMEVAL_SUBTRACT(*end_tv, start_tv) / 1000000.0;
443 }
444
445 /* Returns true if tv has been initialized; i.e., its members are not all
446 zero. */
isSet(const struct timeval * tv)447 bool RateMeter::isSet(const struct timeval *tv) {
448 return tv->tv_sec != 0 || tv->tv_usec != 0;
449 }
450
PacketRateMeter(double current_rate_history)451 PacketRateMeter::PacketRateMeter(double current_rate_history) {
452 packet_rate_meter = RateMeter(current_rate_history);
453 byte_rate_meter = RateMeter(current_rate_history);
454 }
455
start(const struct timeval * now)456 void PacketRateMeter::start(const struct timeval *now) {
457 packet_rate_meter.start(now);
458 byte_rate_meter.start(now);
459 }
460
stop(const struct timeval * now)461 void PacketRateMeter::stop(const struct timeval *now) {
462 packet_rate_meter.stop(now);
463 byte_rate_meter.stop(now);
464 }
465
466 /* Record one packet of length len. */
update(u32 len,const struct timeval * now)467 void PacketRateMeter::update(u32 len, const struct timeval *now) {
468 packet_rate_meter.update(1, now);
469 byte_rate_meter.update(len, now);
470 }
471
getOverallPacketRate(const struct timeval * now) const472 double PacketRateMeter::getOverallPacketRate(const struct timeval *now) const {
473 return packet_rate_meter.getOverallRate(now);
474 }
475
getCurrentPacketRate(const struct timeval * now,bool update)476 double PacketRateMeter::getCurrentPacketRate(const struct timeval *now, bool update) {
477 return packet_rate_meter.getCurrentRate(now, update);
478 }
479
getOverallByteRate(const struct timeval * now) const480 double PacketRateMeter::getOverallByteRate(const struct timeval *now) const {
481 return byte_rate_meter.getOverallRate(now);
482 }
483
getCurrentByteRate(const struct timeval * now,bool update)484 double PacketRateMeter::getCurrentByteRate(const struct timeval *now, bool update) {
485 return byte_rate_meter.getCurrentRate(now, update);
486 }
487
getNumPackets(void) const488 unsigned long long PacketRateMeter::getNumPackets(void) const {
489 return (unsigned long long) packet_rate_meter.getTotal();
490 }
491
getNumBytes(void) const492 unsigned long long PacketRateMeter::getNumBytes(void) const {
493 return (unsigned long long) byte_rate_meter.getTotal();
494 }
495
ScanProgressMeter(const char * stypestr)496 ScanProgressMeter::ScanProgressMeter(const char *stypestr) {
497 scantypestr = strdup(stypestr);
498 gettimeofday(&begin, NULL);
499 last_print_test = begin;
500 memset(&last_print, 0, sizeof(last_print));
501 memset(&last_est, 0, sizeof(last_est));
502 beginOrEndTask(&begin, NULL, true);
503 }
504
~ScanProgressMeter()505 ScanProgressMeter::~ScanProgressMeter() {
506 if (scantypestr) {
507 free(scantypestr);
508 scantypestr = NULL;
509 }
510 }
511
512 /* Decides whether a timing report is likely to even be
513 printed. There are stringent limitations on how often they are
514 printed, as well as the verbosity level that must exist. So you
515 might as well check this before spending much time computing
516 progress info. now can be NULL if caller doesn't have the current
517 time handy. Just because this function returns true does not mean
518 that the next printStatsIfNecessary will always print something.
519 It depends on whether time estimates have changed, which this func
520 doesn't even know about. */
mayBePrinted(const struct timeval * now)521 bool ScanProgressMeter::mayBePrinted(const struct timeval *now) {
522 struct timeval tv;
523
524 if (!o.verbose)
525 return false;
526
527 if (!now) {
528 gettimeofday(&tv, NULL);
529 now = (const struct timeval *) &tv;
530 }
531
532 if (last_print.tv_sec == 0) {
533 /* We've never printed before -- the rules are less stringent */
534 if (difftime(now->tv_sec, begin.tv_sec) > 30)
535 return true;
536 else
537 return false;
538 }
539
540 if (difftime(now->tv_sec, last_print_test.tv_sec) < 3)
541 return false; /* No point even checking too often */
542
543 /* We'd never want to print more than once per 30 seconds */
544 if (difftime(now->tv_sec, last_print.tv_sec) < 30)
545 return false;
546
547 return true;
548 }
549
550 /* Return an estimate of the time remaining if a process was started at begin
551 and is perc_done of the way finished. Returns inf if perc_done == 0.0. */
estimate_time_left(double perc_done,const struct timeval * begin,const struct timeval * now)552 static double estimate_time_left(double perc_done,
553 const struct timeval *begin,
554 const struct timeval *now) {
555 double time_used_s;
556 double time_needed_s;
557
558 time_used_s = difftime(now->tv_sec, begin->tv_sec);
559 time_needed_s = time_used_s / perc_done;
560
561 return time_needed_s - time_used_s;
562 }
563
564 /* Prints an estimate of when this scan will complete. It only does
565 so if mayBePrinted() is true, and it seems reasonable to do so
566 because the estimate has changed significantly. Returns whether
567 or not a line was printed.*/
printStatsIfNecessary(double perc_done,const struct timeval * now)568 bool ScanProgressMeter::printStatsIfNecessary(double perc_done,
569 const struct timeval *now) {
570 struct timeval tvtmp;
571 double time_left_s;
572 bool printit = false;
573
574 if (!now) {
575 gettimeofday(&tvtmp, NULL);
576 now = (const struct timeval *) &tvtmp;
577 }
578
579 if (!mayBePrinted(now))
580 return false;
581
582 last_print_test = *now;
583
584 if (perc_done <= 0.003)
585 return false; /* Need more info first */
586
587 assert(perc_done <= 1.0);
588
589 time_left_s = estimate_time_left(perc_done, &begin, now);
590
591 if (time_left_s < 30)
592 return false; /* No point in updating when it is virtually finished. */
593
594 if (last_est.tv_sec == 0) {
595 /* We don't have an estimate yet (probably means a low completion). */
596 printit = true;
597 } else if (TIMEVAL_AFTER(*now, last_est)) {
598 /* The last estimate we printed has passed. Print a new one. */
599 printit = true;
600 } else {
601 /* If the estimate changed by more than 3 minutes, and if that change
602 represents at least 5% of the total time, print it. */
603 double prev_est_total_time_s = difftime(last_est.tv_sec, begin.tv_sec);
604 double prev_est_time_left_s = difftime(last_est.tv_sec, last_print.tv_sec);
605 double change_abs_s = ABS(prev_est_time_left_s - time_left_s);
606 if (o.debugging || (change_abs_s > 15 && change_abs_s > .05 * prev_est_total_time_s))
607 printit = true;
608 }
609
610 if (printit) {
611 return printStats(perc_done, now);
612 }
613
614 return false;
615 }
616
617 /* Prints an estimate of when this scan will complete. */
printStats(double perc_done,const struct timeval * now)618 bool ScanProgressMeter::printStats(double perc_done,
619 const struct timeval *now) {
620 struct timeval tvtmp;
621 double time_left_s;
622 time_t timet;
623 struct tm ltime;
624 int err;
625
626 if (!now) {
627 gettimeofday(&tvtmp, NULL);
628 now = (const struct timeval *) &tvtmp;
629 }
630
631 last_print = *now;
632
633 // If we're less than 1% done we probably don't have enough
634 // data for decent timing estimates. Also with perc_done == 0
635 // these elements will be nonsensical.
636 if (perc_done < 0.01) {
637 log_write(LOG_STDOUT, "%s Timing: About %.2f%% done\n",
638 scantypestr, perc_done * 100);
639 xml_open_start_tag("taskprogress");
640 xml_attribute("task", "%s", scantypestr);
641 xml_attribute("time", "%lu", (unsigned long) now->tv_sec);
642 xml_attribute("percent", "%.2f", perc_done * 100);
643 xml_close_empty_tag();
644 xml_newline();
645 log_flush(LOG_STDOUT|LOG_XML);
646 return true;
647 }
648
649 /* Add 0.5 to get the effect of rounding in integer calculations. */
650 time_left_s = estimate_time_left(perc_done, &begin, now) + 0.5;
651
652 last_est = *now;
653 last_est.tv_sec += (time_t)time_left_s;
654
655 /* Get the estimated time of day at completion */
656 timet = last_est.tv_sec;
657 err = n_localtime(&timet, <ime);
658
659 if (!err) {
660 log_write(LOG_STDOUT, "%s Timing: About %.2f%% done; ETC: %02d:%02d (%.f:%02.f:%02.f remaining)\n",
661 scantypestr, perc_done * 100, ltime.tm_hour, ltime.tm_min,
662 floor(time_left_s / 60.0 / 60.0),
663 floor(fmod(time_left_s / 60.0, 60.0)),
664 floor(fmod(time_left_s, 60.0)));
665 }
666 else {
667 log_write(LOG_STDERR, "Timing error: n_localtime(%f): %s\n", (double) timet, strerror(err));
668 log_write(LOG_STDOUT, "%s Timing: About %.2f%% done; ETC: Unknown (%.f:%02.f:%02.f remaining)\n",
669 scantypestr, perc_done * 100,
670 floor(time_left_s / 60.0 / 60.0),
671 floor(fmod(time_left_s / 60.0, 60.0)),
672 floor(fmod(time_left_s, 60.0)));
673 }
674 xml_open_start_tag("taskprogress");
675 xml_attribute("task", "%s", scantypestr);
676 xml_attribute("time", "%lu", (unsigned long) now->tv_sec);
677 xml_attribute("percent", "%.2f", perc_done * 100);
678 xml_attribute("remaining", "%.f", time_left_s);
679 xml_attribute("etc", "%lu", (unsigned long) last_est.tv_sec);
680 xml_close_empty_tag();
681 xml_newline();
682 log_flush(LOG_STDOUT|LOG_XML);
683
684 return true;
685 }
686
687 /* Indicates that the task is beginning or ending, and that a message should
688 be generated if appropriate. Returns whether a message was printed.
689 now may be NULL, if the caller doesn't have the current time handy.
690 additional_info may be NULL if no additional information is necessary. */
beginOrEndTask(const struct timeval * now,const char * additional_info,bool beginning)691 bool ScanProgressMeter::beginOrEndTask(const struct timeval *now, const char *additional_info, bool beginning) {
692 struct timeval tvtmp;
693 struct tm tm;
694 int err;
695 time_t tv_sec;
696
697 if (!o.verbose) {
698 return false;
699 }
700
701 if (!now) {
702 gettimeofday(&tvtmp, NULL);
703 now = (const struct timeval *) &tvtmp;
704 }
705
706 tv_sec = now->tv_sec;
707 err = n_localtime(&tv_sec, &tm);
708 if (err)
709 log_write(LOG_STDERR, "Timing error: n_localtime(%f): %s\n", (double) tv_sec, strerror(err));
710 if (beginning) {
711 if (!err)
712 log_write(LOG_STDOUT, "Initiating %s at %02d:%02d", scantypestr, tm.tm_hour, tm.tm_min);
713 else
714 log_write(LOG_STDOUT, "Initiating %s", scantypestr);
715 xml_open_start_tag("taskbegin");
716 xml_attribute("task", "%s", scantypestr);
717 xml_attribute("time", "%lu", (unsigned long) now->tv_sec);
718 if (additional_info) {
719 log_write(LOG_STDOUT, " (%s)", additional_info);
720 xml_attribute("extrainfo", "%s", additional_info);
721 }
722 log_write(LOG_STDOUT, "\n");
723 xml_close_empty_tag();
724 xml_newline();
725 } else {
726 if (!err)
727 log_write(LOG_STDOUT, "Completed %s at %02d:%02d, %.2fs elapsed", scantypestr, tm.tm_hour, tm.tm_min, TIMEVAL_MSEC_SUBTRACT(*now, begin) / 1000.0);
728 else
729 log_write(LOG_STDOUT, "Completed %s, %.2fs elapsed", scantypestr, TIMEVAL_MSEC_SUBTRACT(*now, begin) / 1000.0);
730 xml_open_start_tag("taskend");
731 xml_attribute("task", "%s", scantypestr);
732 xml_attribute("time", "%lu", (unsigned long) now->tv_sec);
733 if (additional_info) {
734 log_write(LOG_STDOUT, " (%s)", additional_info);
735 xml_attribute("extrainfo", "%s", additional_info);
736 }
737 log_write(LOG_STDOUT, "\n");
738 xml_close_empty_tag();
739 xml_newline();
740 }
741 log_flush(LOG_STDOUT|LOG_XML);
742 return true;
743 }
744