dsi_progress_logger/lib.rs
1/*
2 * SPDX-FileCopyrightText: 2023 Inria
3 * SPDX-FileCopyrightText: 2023 Sebastiano Vigna
4 * SPDX-FileCopyrightText: 2024 Fondation Inria
5 *
6 * SPDX-License-Identifier: Apache-2.0 OR MIT
7 */
8
9#![doc = include_str!("../README.md")]
10
11use log::{Level, debug, error, info, log, trace, warn};
12use num_format::{Locale, ToFormattedString};
13use pluralizer::pluralize;
14use std::fmt::{Arguments, Display, Formatter, Result};
15use std::sync::{Arc, Mutex};
16use std::time::{Duration, Instant};
17use sysinfo::{MemoryRefreshKind, Pid, ProcessRefreshKind, ProcessesToUpdate, RefreshKind, System};
18mod utils;
19pub use utils::*;
20
21/// Logging trait.
22///
23/// To log the progress of an activity, you call [`start`](ProgressLog::start).
24/// Then, each time you want to mark progress, you call
25/// [`update`](ProgressLog::update), which increases the item counter, and will
26/// log progress information if enough time has passed since the last log.
27/// [`light_update`](ProgressLog::light_update) will perform a time check only
28/// on a subset of updates (e.g., for [`ProgressLogger`], multiples of
29/// [`LIGHT_UPDATE_MASK`](ProgressLogger::LIGHT_UPDATE_MASK) + 1); it should be
30/// used when the activity has an extremely low cost that is comparable to that
31/// of the time check (a call to [`Instant::now()`]) itself.
32///
33/// A few setters can be called at any time to customize the logger (e.g.,
34/// [`item_name`](ProgressLog::item_name),
35/// [`log_interval`](ProgressLog::log_interval),
36/// [`expected_updates`](ProgressLog::expected_updates), etc.). The setters take
37/// and return a mutable reference to the logger, so you must first assign the
38/// logger to a variable, and then you can chain-call the setters on the
39/// variable in fluent style. The disadvantage of this approach is that you must
40/// assign the logger to a variable, but the advantage is that you can call any
41/// setter without having to reassign the variable holding the logger.
42///
43/// It is also possible to log used and free memory at each log interval by
44/// calling [`display_memory`](ProgressLog::display_memory). Memory is read from
45/// system data by the [`sysinfo`] crate, and will be updated at each log
46/// interval (note that this will slightly slow down the logging process).
47/// However, never use this feature in a
48/// [`rayon`](https://crates.io/crates/rayon) environment if another crate in
49/// your compilation unit depends on
50/// [`sysinfo`](https://crates.io/crates/sysinfo)'s (default) `multithread`
51/// feature, as [this can lead to a
52/// deadlock](https://github.com/rayon-rs/rayon/issues/592).
53///
54///
55/// At any time, displaying the progress logger will give you time information
56/// up to the present. However, since it is impossible to update the memory
57/// information from the [`Display::fmt`] implementation, you should call
58/// [`refresh`](ProgressLog::refresh) before displaying the logger on your own.
59///
60/// When the activity is over, you call [`stop`](ProgressLog::stop), which fixes
61/// the final time, and possibly display again the logger.
62/// [`done`](ProgressLog::done) will stop the logger, print `Completed.`, and
63/// display the final stats.
64///
65/// After you finish a run of the progress logger, you can call
66/// [`start`](ProgressLog::start) again to measure another activity.
67///
68/// As explained in the [crate documentation](crate), we suggest using `&mut
69/// impl ProgressLog` to pass a logger as an argument, to be able to use
70/// optional logging.
71///
72/// # Examples
73///
74/// See the [`ProgressLogger`] documentation.
75pub trait ProgressLog {
76 /// The type returned by [`concurrent`](ProgressLog::concurrent).
77 type Concurrent: ConcurrentProgressLog;
78
79 /// Forces a log of `self` assuming `now` is the current time.
80 ///
81 /// This is a low-level method that should not be called directly.
82 fn log(&mut self, now: Instant);
83
84 /// Logs `self` if it is time to log.
85 ///
86 /// This is a low-level method that should not be called directly.
87 fn log_if(&mut self, now: Instant);
88
89 /// Sets the display of memory information.
90 ///
91 /// Memory information includes:
92 /// - the [resident-set size](sysinfo::Process::memory) of the process that
93 /// created the logger;
94 /// - the [virtual-memory size](sysinfo::Process::virtual_memory) of the
95 /// process that created the logger;
96 /// - the [available memory](sysinfo::System::available_memory);
97 /// - the [free memory](sysinfo::System::free_memory);
98 /// - the [total amount](sysinfo::System::total_memory) of memory.
99 ///
100 /// Never use this feature in a [`rayon`](https://crates.io/crates/rayon)
101 /// environment if another crate in your compilation unit depends on
102 /// [`sysinfo`](https://crates.io/crates/sysinfo)'s (default) `multithread`
103 /// feature, as [this can lead to a
104 /// deadlock](https://github.com/rayon-rs/rayon/issues/592).
105 fn display_memory(&mut self, display_memory: bool) -> &mut Self;
106
107 /// Sets the name of an item.
108 fn item_name(&mut self, item_name: impl AsRef<str>) -> &mut Self;
109
110 /// Sets the log interval.
111 fn log_interval(&mut self, log_interval: Duration) -> &mut Self;
112
113 /// Sets the expected number of updates.
114 ///
115 /// If not [`None`], the logger will display the percentage of completion
116 /// and an estimate of the time to completion.
117 ///
118 /// Note that there is no need to use a [`Some`]
119 /// wrapper around the argument, as the method will automatically convert it
120 /// to an [`Option`] type.
121 fn expected_updates(&mut self, expected_updates: impl Into<Option<usize>>) -> &mut Self;
122
123 /// Sets the time unit to use for speed.
124 ///
125 /// If not [`None`], the logger will always display the speed in this unit
126 /// instead of making a choice of readable unit based on the elapsed time.
127 /// Moreover, large numbers will not be thousands separated. This behavior
128 /// is useful when the output of the logger must be parsed.
129 ///
130 /// Note that there is no need to use a [`Some`]
131 /// wrapper around the argument, as the method will automatically convert it
132 /// to an [`Option`] type.
133 fn time_unit(&mut self, time_unit: impl Into<Option<TimeUnit>>) -> &mut Self;
134
135 /// Sets whether to display additionally the speed achieved during the last
136 /// log interval.
137 fn local_speed(&mut self, local_speed: bool) -> &mut Self;
138
139 /// Sets the [`mod@log`] target.
140 ///
141 /// This should often be the path of the module logging progress, which is
142 /// obtained with [`std::module_path!`].
143 ///
144 /// Note that the macro [`progress_logger!`] sets this field automatically
145 /// to [`std::module_path!`].
146 ///
147 /// Calling this method clears any suffixes previously pushed with
148 /// [`push_log_target`](ProgressLog::push_log_target).
149 ///
150 /// # Examples
151 ///
152 /// ```rust
153 /// # fn main() -> Result<(), Box<dyn std::error::Error>> {
154 /// # use dsi_progress_logger::prelude::*;
155 /// env_logger::builder().filter_level(log::LevelFilter::Info).try_init()?;
156 ///
157 /// let mut pl = ProgressLogger::default();
158 /// pl.item_name("pumpkin");
159 /// pl.log_target(std::module_path!());
160 /// pl.start("Smashing pumpkins from a module...");
161 /// for _ in 0..100 {
162 /// // do something on each pumpkin
163 /// pl.update();
164 /// }
165 /// pl.done();
166 /// # Ok(())
167 /// # }
168 /// ```
169 fn log_target(&mut self, target: impl AsRef<str>) -> &mut Self;
170
171 /// Pushes a suffix to the [`mod@log`] target.
172 ///
173 /// The suffix is appended to the current log target as-is, with no
174 /// separator. The caller controls the format (e.g., `" > subtask"` or
175 /// `"::phase2"`).
176 ///
177 /// Each push records the current length of the log target so that
178 /// [`pop_log_target`](ProgressLog::pop_log_target) can restore it.
179 ///
180 /// # Examples
181 ///
182 /// ```rust
183 /// # fn main() -> Result<(), Box<dyn std::error::Error>> {
184 /// # use dsi_progress_logger::prelude::*;
185 /// env_logger::builder().filter_level(log::LevelFilter::Info).try_init()?;
186 ///
187 /// let mut pl = ProgressLogger::default();
188 /// pl.item_name("pumpkin");
189 /// pl.log_target(std::module_path!());
190 /// pl.start("Smashing pumpkins from a module...");
191 /// for _ in 0..100 {
192 /// // do something on each pumpkin
193 /// pl.update();
194 /// }
195 /// pl.done();
196 ///
197 /// // Entering subtask
198 /// pl.push_log_target(" > smoothing");
199 /// pl.start("Smashing pumpkins...");
200 /// for _ in 0..100 {
201 /// // do something on each pumpkin
202 /// pl.update();
203 /// }
204 /// pl.done();
205 /// pl.pop_log_target();
206 /// # Ok(())
207 /// # }
208 /// ```
209 fn push_log_target(&mut self, suffix: impl AsRef<str>) -> &mut Self;
210
211 /// Pops the last suffix pushed with
212 /// [`push_log_target`](ProgressLog::push_log_target).
213 ///
214 /// If no suffix has been pushed, this method is a no-op.
215 fn pop_log_target(&mut self) -> &mut Self;
216
217 /// Sets the [`mod@log`] level used for progress messages.
218 ///
219 /// By default, progress messages are logged at the
220 /// [`Info`](`log::Level::Info`) level.
221 fn log_level(&mut self, log_level: Level) -> &mut Self;
222
223 /// Adds a value to the counter.
224 ///
225 /// This method is mainly useful for wrappers or to implement a custom
226 /// update strategy.
227 fn add_to_count(&mut self, count: usize);
228
229 /// Starts the logger, displaying the given message.
230 ///
231 /// An empty string can be passed to display nothing.
232 fn start(&mut self, msg: impl AsRef<str>);
233
234 /// Increases the count and checks whether it is time to log.
235 fn update(&mut self);
236
237 /// Sets the count and checks whether it is time to log.
238 fn update_with_count(&mut self, count: usize) {
239 self.update_with_count_and_time(count, Instant::now());
240 }
241
242 /// Sets the count and checks whether it is time to log, given the current
243 /// time.
244 ///
245 /// This method is mainly useful for wrappers that want to avoid unnecessary
246 /// calls to [`Instant::now`].
247 fn update_with_count_and_time(&mut self, count: usize, now: Instant);
248
249 /// Increases the count but checks whether it is time to log only after an
250 /// implementation-defined number of calls.
251 ///
252 /// Useful for very short activities with respect to which checking the
253 /// time is expensive.
254 fn light_update(&mut self);
255
256 /// Increases the count and forces a log.
257 fn update_and_display(&mut self);
258
259 /// Stops the logger, fixing the final time.
260 fn stop(&mut self);
261
262 /// Stops the logger, prints `Completed.`, and displays the final stats.
263 /// The number of expected updates will be cleared.
264 fn done(&mut self);
265
266 /// Stops the logger, sets the count, prints `Completed.`, and displays the
267 /// final stats. The number of expected updates will be cleared.
268 ///
269 /// This method is particularly useful in two circumstances:
270 /// * the logger has been updated with some approximate values (e.g., in a
271 /// multicore computation) but before printing the final stats the
272 /// internal counter should contain an exact value;
273 /// * the logger has been used as a handy timer, calling just
274 /// [`start`](ProgressLog::start) and this method.
275 fn done_with_count(&mut self, count: usize);
276
277 /// Returns the elapsed time since the logger was started, or `None` if the
278 /// logger has not been started.
279 fn elapsed(&self) -> Option<Duration>;
280
281 /// Returns the last count the logger has been set to.
282 ///
283 /// Note that this method can be called even after the logger has been
284 /// [stopped](ProgressLog::stop).
285 fn count(&self) -> usize;
286
287 /// Refreshes memory information, if previously requested with
288 /// [`display_memory`](ProgressLog::display_memory). There is no need to
289 /// call this method unless the logger is displayed manually.
290 fn refresh(&mut self);
291
292 /// Outputs the given message at the [trace](`log::Level::Trace`) level.
293 ///
294 /// See [`info`](ProgressLog::info) for an example.
295 fn trace(&self, args: Arguments<'_>);
296
297 /// Outputs the given message at the [debug](`log::Level::Debug`) level.
298 ///
299 /// See [`info`](ProgressLog::info) for an example.
300 fn debug(&self, args: Arguments<'_>);
301
302 /// Outputs the given message at the [info](`log::Level::Info`) level.
303 ///
304 /// For maximum flexibility, this method takes as argument the result of a
305 /// [`std::format_args!`] macro. Note that there will be no output if the
306 /// logger is [`None`].
307 ///
308 /// # Examples
309 ///
310 /// ```rust
311 /// # fn main() -> Result<(), Box<dyn std::error::Error>> {
312 /// # use dsi_progress_logger::*;
313 /// env_logger::builder().filter_level(log::LevelFilter::Info).try_init()?;
314 ///
315 /// let logger_name = "my_logger";
316 /// let mut pl = progress_logger![];
317 /// pl.info(format_args!("My logger named {}", logger_name));
318 /// # Ok(())
319 /// # }
320 /// ```
321 fn info(&self, args: Arguments<'_>);
322
323 /// Outputs the given message at the [warn](`log::Level::Warn`) level.
324 ///
325 /// See [`info`](ProgressLog::info) for an example.
326 fn warn(&self, args: Arguments<'_>);
327
328 /// Outputs the given message at the [error](`log::Level::Error`) level.
329 ///
330 /// See [`info`](ProgressLog::info) for an example.
331 fn error(&self, args: Arguments<'_>);
332
333 /// Returns a concurrent copy of the logger.
334 ///
335 /// Some methods require both sequential and concurrent logging. To keep
336 /// optional logging efficient, it is suggested to use `&mut impl
337 /// ProgressLog` to pass a logger as an argument, and then create a
338 /// concurrent copy of the logger with this method. If the original logger
339 /// is `None`, the concurrent copy will be `None` as well.
340 ///
341 /// Note that the result of the method is a copy—it will not share the state
342 /// of the original logger.
343 ///
344 /// Concurrent logger implementations can just return a duplicate of
345 /// themselves via [`dup`](ConcurrentProgressLog::dup).
346 fn concurrent(&self) -> Self::Concurrent;
347}
348
349/// Concurrent logging trait.
350///
351/// This trait extends [`ProgressLog`] by adding a
352/// [`dup`](ConcurrentProgressLog::dup) method that duplicates the logger and
353/// adding the [`Clone`], [`Sync`], and [`Send`] traits.
354///
355/// By contract, [`Clone`] implementations must return a new logger updating the
356/// same internal state, so you can easily use a [`ConcurrentProgressLog`] in
357/// methods like
358/// [`rayon::ParallelIterator::for_each_with`](https://docs.rs/rayon/latest/rayon/iter/trait.ParallelIterator.html#method.for_each_with),
359/// [`rayon::ParallelIterator::map_with`](https://docs.rs/rayon/latest/rayon/iter/trait.ParallelIterator.html#method.map_with),
360/// and so on. In a [`rayon`](https://docs.rs/rayon) environment, however, you
361/// cannot use [`display_memory`](ProgressLog::display_memory) if another crate
362/// in your compilation unit depends on
363/// [`sysinfo`](https://crates.io/crates/sysinfo)'s (default) `multithread`
364/// feature, as [this can lead to a
365/// deadlock](https://github.com/rayon-rs/rayon/issues/592).
366///
367/// Note that [`ProgressLogger`]'s [`Clone`
368/// implementation](ProgressLogger#impl-Clone-for-ProgressLogger) has a
369/// completely different semantics.
370///
371/// As explained in the [crate documentation](crate), we suggest using `&mut
372/// Self::Concurrent` to pass a concurrent logger as an argument, to be able to
373/// use optional logging.
374///
375/// # Examples
376///
377/// See the [`ConcurrentWrapper`] documentation.
378pub trait ConcurrentProgressLog: ProgressLog + Sync + Send + Clone {
379 /// The type returned by [`dup`](ConcurrentProgressLog::dup).
380 type Duplicated: ConcurrentProgressLog;
381
382 /// Duplicates the concurrent progress logger, obtaining a new one.
383 ///
384 /// Note that this method has the same semantics of [`ProgressLogger`'s
385 /// `Clone` implementation](ProgressLogger#impl-Clone-for-ProgressLogger),
386 /// but in a [`ConcurrentProgressLog`] by contract [cloning must generate
387 /// copies with the same underlying logger](ConcurrentProgressLog).
388 fn dup(&self) -> Self::Duplicated;
389}
390
391impl<P: ProgressLog> ProgressLog for &mut P {
392 type Concurrent = P::Concurrent;
393
394 fn log(&mut self, now: Instant) {
395 (**self).log(now);
396 }
397
398 fn log_if(&mut self, now: Instant) {
399 (**self).log_if(now);
400 }
401
402 fn add_to_count(&mut self, count: usize) {
403 (**self).add_to_count(count);
404 }
405
406 fn display_memory(&mut self, display_memory: bool) -> &mut Self {
407 (**self).display_memory(display_memory);
408 self
409 }
410
411 fn item_name(&mut self, item_name: impl AsRef<str>) -> &mut Self {
412 (**self).item_name(item_name);
413 self
414 }
415
416 fn log_interval(&mut self, log_interval: Duration) -> &mut Self {
417 (**self).log_interval(log_interval);
418 self
419 }
420
421 fn expected_updates(&mut self, expected_updates: impl Into<Option<usize>>) -> &mut Self {
422 (**self).expected_updates(expected_updates.into());
423 self
424 }
425
426 fn time_unit(&mut self, time_unit: impl Into<Option<TimeUnit>>) -> &mut Self {
427 (**self).time_unit(time_unit.into());
428 self
429 }
430
431 fn local_speed(&mut self, local_speed: bool) -> &mut Self {
432 (**self).local_speed(local_speed);
433 self
434 }
435
436 fn log_target(&mut self, target: impl AsRef<str>) -> &mut Self {
437 (**self).log_target(target);
438 self
439 }
440
441 fn push_log_target(&mut self, suffix: impl AsRef<str>) -> &mut Self {
442 (**self).push_log_target(suffix);
443 self
444 }
445
446 fn pop_log_target(&mut self) -> &mut Self {
447 (**self).pop_log_target();
448 self
449 }
450
451 fn log_level(&mut self, log_level: Level) -> &mut Self {
452 (**self).log_level(log_level);
453 self
454 }
455
456 fn start(&mut self, msg: impl AsRef<str>) {
457 (**self).start(msg);
458 }
459
460 fn update(&mut self) {
461 (**self).update();
462 }
463
464 fn update_with_count(&mut self, count: usize) {
465 (**self).update_with_count(count);
466 }
467
468 fn update_with_count_and_time(&mut self, count: usize, now: Instant) {
469 (**self).update_with_count_and_time(count, now);
470 }
471
472 fn light_update(&mut self) {
473 (**self).light_update();
474 }
475
476 fn update_and_display(&mut self) {
477 (**self).update_and_display();
478 }
479
480 fn stop(&mut self) {
481 (**self).stop();
482 }
483
484 fn done(&mut self) {
485 (**self).done();
486 }
487
488 fn done_with_count(&mut self, count: usize) {
489 (**self).done_with_count(count);
490 }
491
492 fn elapsed(&self) -> Option<Duration> {
493 (**self).elapsed()
494 }
495
496 fn count(&self) -> usize {
497 (**self).count()
498 }
499
500 fn refresh(&mut self) {
501 (**self).refresh();
502 }
503
504 fn trace(&self, args: Arguments<'_>) {
505 (**self).trace(args);
506 }
507
508 fn debug(&self, args: Arguments<'_>) {
509 (**self).debug(args);
510 }
511
512 fn info(&self, args: Arguments<'_>) {
513 (**self).info(args);
514 }
515
516 fn warn(&self, args: Arguments<'_>) {
517 (**self).warn(args);
518 }
519
520 fn error(&self, args: Arguments<'_>) {
521 (**self).error(args);
522 }
523
524 fn concurrent(&self) -> Self::Concurrent {
525 (**self).concurrent()
526 }
527}
528
529impl<P: ProgressLog> ProgressLog for Option<P> {
530 type Concurrent = Option<P::Concurrent>;
531
532 fn log(&mut self, now: Instant) {
533 if let Some(pl) = self {
534 pl.log(now);
535 }
536 }
537
538 fn log_if(&mut self, now: Instant) {
539 if let Some(pl) = self {
540 pl.log_if(now);
541 }
542 }
543
544 fn add_to_count(&mut self, count: usize) {
545 if let Some(pl) = self {
546 pl.add_to_count(count);
547 }
548 }
549
550 fn display_memory(&mut self, display_memory: bool) -> &mut Self {
551 if let Some(pl) = self {
552 pl.display_memory(display_memory);
553 }
554 self
555 }
556
557 fn item_name(&mut self, item_name: impl AsRef<str>) -> &mut Self {
558 if let Some(pl) = self {
559 pl.item_name(item_name);
560 }
561 self
562 }
563
564 fn log_interval(&mut self, log_interval: Duration) -> &mut Self {
565 if let Some(pl) = self {
566 pl.log_interval(log_interval);
567 }
568 self
569 }
570
571 fn expected_updates(&mut self, expected_updates: impl Into<Option<usize>>) -> &mut Self {
572 if let Some(pl) = self {
573 pl.expected_updates(expected_updates.into());
574 }
575 self
576 }
577
578 fn time_unit(&mut self, time_unit: impl Into<Option<TimeUnit>>) -> &mut Self {
579 if let Some(pl) = self {
580 pl.time_unit(time_unit.into());
581 }
582 self
583 }
584
585 fn local_speed(&mut self, local_speed: bool) -> &mut Self {
586 if let Some(pl) = self {
587 pl.local_speed(local_speed);
588 }
589 self
590 }
591
592 fn log_target(&mut self, target: impl AsRef<str>) -> &mut Self {
593 if let Some(pl) = self {
594 pl.log_target(target);
595 }
596 self
597 }
598
599 fn push_log_target(&mut self, suffix: impl AsRef<str>) -> &mut Self {
600 if let Some(pl) = self {
601 pl.push_log_target(suffix);
602 }
603 self
604 }
605
606 fn pop_log_target(&mut self) -> &mut Self {
607 if let Some(pl) = self {
608 pl.pop_log_target();
609 }
610 self
611 }
612
613 fn log_level(&mut self, log_level: Level) -> &mut Self {
614 if let Some(pl) = self {
615 pl.log_level(log_level);
616 }
617 self
618 }
619
620 fn start(&mut self, msg: impl AsRef<str>) {
621 if let Some(pl) = self {
622 pl.start(msg);
623 }
624 }
625
626 fn update(&mut self) {
627 if let Some(pl) = self {
628 pl.update();
629 }
630 }
631
632 fn update_with_count(&mut self, count: usize) {
633 if let Some(pl) = self {
634 pl.update_with_count(count);
635 }
636 }
637
638 fn update_with_count_and_time(&mut self, count: usize, now: Instant) {
639 if let Some(pl) = self {
640 pl.update_with_count_and_time(count, now);
641 }
642 }
643
644 fn light_update(&mut self) {
645 if let Some(pl) = self {
646 pl.light_update();
647 }
648 }
649
650 fn update_and_display(&mut self) {
651 if let Some(pl) = self {
652 pl.update_and_display();
653 }
654 }
655
656 fn stop(&mut self) {
657 if let Some(pl) = self {
658 pl.stop();
659 }
660 }
661
662 fn done(&mut self) {
663 if let Some(pl) = self {
664 pl.done();
665 }
666 }
667
668 fn done_with_count(&mut self, count: usize) {
669 if let Some(pl) = self {
670 pl.done_with_count(count);
671 }
672 }
673
674 fn elapsed(&self) -> Option<Duration> {
675 self.as_ref().and_then(|pl| pl.elapsed())
676 }
677
678 fn count(&self) -> usize {
679 self.as_ref().map(|pl| pl.count()).unwrap_or(0)
680 }
681
682 fn refresh(&mut self) {
683 if let Some(pl) = self {
684 pl.refresh();
685 }
686 }
687
688 fn trace(&self, args: Arguments<'_>) {
689 if let Some(pl) = self {
690 pl.trace(args);
691 }
692 }
693
694 fn debug(&self, args: Arguments<'_>) {
695 if let Some(pl) = self {
696 pl.debug(args);
697 }
698 }
699
700 fn info(&self, args: Arguments<'_>) {
701 if let Some(pl) = self {
702 pl.info(args);
703 }
704 }
705
706 fn warn(&self, args: Arguments<'_>) {
707 if let Some(pl) = self {
708 pl.warn(args);
709 }
710 }
711
712 fn error(&self, args: Arguments<'_>) {
713 if let Some(pl) = self {
714 pl.error(args);
715 }
716 }
717
718 fn concurrent(&self) -> Self::Concurrent {
719 self.as_ref().map(|pl| pl.concurrent())
720 }
721}
722
723impl<P: ConcurrentProgressLog> ConcurrentProgressLog for Option<P> {
724 type Duplicated = Option<P::Duplicated>;
725
726 fn dup(&self) -> Self::Duplicated {
727 self.as_ref().map(|pl| pl.dup())
728 }
729}
730
731/// An implementation of [`ProgressLog`] with output generated using the
732/// [`log`](https://docs.rs/log) crate at a configurable level (default:
733/// `info`).
734///
735/// Instances can be created by using fluent setters, or by using the
736/// [`progress_logger`] macro.
737///
738/// You can [clone](#impl-Clone-for-ProgressLogger) a logger to create a new one
739/// with the same setup but with all the counters reset and the expected number
740/// of updates cleared. This behavior is useful when you want to configure a
741/// logger and then use its configuration for other loggers.
742///
743/// # Examples
744///
745/// A typical call sequence to a progress logger is as follows:
746///
747/// ```rust
748/// # fn main() -> Result<(), Box<dyn std::error::Error>> {
749/// # use dsi_progress_logger::prelude::*;
750/// env_logger::builder().filter_level(log::LevelFilter::Info).try_init()?;
751///
752/// let mut pl = ProgressLogger::default();
753/// pl.item_name("pumpkin");
754/// pl.start("Smashing pumpkins...");
755/// for _ in 0..100 {
756/// // do something on each pumpkin
757/// pl.update();
758/// }
759/// pl.done();
760/// # Ok(())
761/// # }
762/// ```
763///
764/// The [`progress_logger`] macro will create the progress logger for you and
765/// set its [`log_target`](ProgressLog::log_target) to [`std::module_path!()`],
766/// which is usually what you want. You can also call any setter with a
767/// key-value syntax:
768///
769/// ```rust
770/// # fn main() -> Result<(), Box<dyn std::error::Error>> {
771/// # use dsi_progress_logger::prelude::*;
772/// env_logger::builder().filter_level(log::LevelFilter::Info).try_init()?;
773///
774/// let mut pl = progress_logger![item_name="pumpkin"];
775/// pl.start("Smashing pumpkins...");
776/// for _ in 0..100 {
777/// // do something on each pumpkin
778/// pl.update();
779/// }
780/// pl.done();
781/// # Ok(())
782/// # }
783/// ```
784///
785/// A progress logger can also be used as a handy timer:
786///
787/// ```rust
788/// # fn main() -> Result<(), Box<dyn std::error::Error>> {
789/// # use dsi_progress_logger::prelude::*;
790/// env_logger::builder().filter_level(log::LevelFilter::Info).try_init()?;
791///
792/// let mut pl = progress_logger![item_name="pumpkin"];
793/// pl.start("Smashing pumpkins...");
794/// for _ in 0..100 {
795/// // do something on each pumpkin
796/// }
797/// pl.done_with_count(100);
798/// # Ok(())
799/// # }
800/// ```
801///
802/// This progress logger will display information about memory usage:
803///
804/// ```rust
805/// # fn main() -> Result<(), Box<dyn std::error::Error>> {
806/// # use dsi_progress_logger::prelude::*;
807/// env_logger::builder().filter_level(log::LevelFilter::Info).try_init()?;
808///
809/// let mut pl = progress_logger![display_memory=true];
810/// # Ok(())
811/// # }
812/// ```
813pub struct ProgressLogger {
814 /// The name of an item. Defaults to `item`.
815 item_name: String,
816 /// The pluralized name of an item. Defaults to `items`. It is quite
817 /// expensive to compute with [`pluralize`], hence the caching.
818 items_name: String,
819 /// The log interval. Defaults to 10 seconds.
820 log_interval: Duration,
821 /// The expected number of updates. If set, the logger will display the percentage of completion and
822 /// an estimate of the time to completion.
823 expected_updates: Option<usize>,
824 /// The time unit to use for speed. If set, the logger will always display the speed in this unit
825 /// instead of making a choice of readable unit based on the elapsed time. Moreover, large numbers
826 /// will not be thousands separated. This is useful when the output of the logger must be parsed.
827 time_unit: Option<TimeUnit>,
828 /// Display additionally the speed achieved during the last log interval.
829 local_speed: bool,
830 /// [`mod@log`] target
831 ///
832 /// This is often the path of the module logging progress.
833 log_target: String,
834 /// Stack of cut positions for [`push_log_target`](ProgressLog::push_log_target)/[`pop_log_target`](ProgressLog::pop_log_target).
835 log_target_cut_positions: Vec<usize>,
836 /// [`mod@log`] level for progress messages. Defaults to [`Level::Info`].
837 log_level: Level,
838 /// When the logger was started.
839 start_time: Option<Instant>,
840 /// The last time we logged the activity (to compute speed).
841 last_log_time: Instant,
842 /// The next time we will log the activity.
843 next_log_time: Instant,
844 /// When the logger was stopped.
845 stop_time: Option<Instant>,
846 /// The number of items.
847 count: usize,
848 /// The number of items at the last log (to compute speed).
849 last_count: usize,
850 /// Display additionally the amount of used and free memory using this [`sysinfo::System`]
851 system: Option<System>,
852 /// The pid of the current process
853 pid: Pid,
854}
855
856impl Default for ProgressLogger {
857 /// Creates a default [`ProgressLogger`] with a log interval of 10 seconds and
858 /// item name set to “item”.
859 fn default() -> Self {
860 Self {
861 item_name: "item".into(),
862 items_name: "items".into(),
863 log_interval: Duration::from_secs(10),
864 expected_updates: None,
865 time_unit: None,
866 local_speed: false,
867 log_target: std::env::current_exe()
868 .ok()
869 .and_then(|path| {
870 path.file_name()
871 .and_then(|s| s.to_owned().into_string().ok())
872 })
873 .unwrap_or_else(|| "main".to_string()),
874 log_target_cut_positions: Vec::new(),
875 log_level: Level::Info,
876 start_time: None,
877 last_log_time: Instant::now(),
878 next_log_time: Instant::now(),
879 stop_time: None,
880 count: 0,
881 last_count: 0,
882 system: None,
883 pid: Pid::from(std::process::id() as usize),
884 }
885 }
886}
887
888impl Clone for ProgressLogger {
889 /// Clones the logger, returning a logger with the same setup but with all
890 /// the counters reset and the expected number of updates cleared.
891 ///
892 /// The expected number of updates is cleared, as in
893 /// [`stop`](ProgressLog::stop), because it rarely carries over to another
894 /// activity; if needed, it can be set again with
895 /// [`expected_updates`](ProgressLog::expected_updates). Note that this
896 /// behavior extends to [`ProgressLog::concurrent`] and
897 /// [`ConcurrentProgressLog::dup`], which clone the underlying logger.
898 #[allow(clippy::manual_map)]
899 fn clone(&self) -> Self {
900 Self {
901 item_name: self.item_name.clone(),
902 items_name: self.items_name.clone(),
903 log_interval: self.log_interval,
904 time_unit: self.time_unit,
905 local_speed: self.local_speed,
906 log_level: self.log_level,
907 log_target: self.log_target.clone(),
908 log_target_cut_positions: self.log_target_cut_positions.clone(),
909 system: match self.system {
910 Some(_) => Some(System::new_with_specifics(
911 RefreshKind::nothing().with_memory(MemoryRefreshKind::nothing().with_ram()),
912 )),
913 None => None,
914 },
915 ..ProgressLogger::default()
916 }
917 }
918}
919
920/// Macro to create a [`ProgressLogger`] with default log target set to
921/// [`std::module_path!`], and key-value pairs instead of setters.
922///
923/// # Examples
924///
925/// ```rust
926/// # use dsi_progress_logger::prelude::*;
927/// let mut pl = progress_logger![item_name = "pumpkin", display_memory = true];
928/// ```
929#[macro_export]
930macro_rules! progress_logger {
931 ($($method:ident = $arg:expr),* $(,)?) => {
932 {
933 let mut pl = $crate::ProgressLogger::default();
934 $crate::ProgressLog::log_target(&mut pl, ::std::module_path!());
935 $(
936 $crate::ProgressLog::$method(&mut pl, $arg);
937 )*
938 pl
939 }
940 }
941}
942
943impl ProgressLogger {
944 /// Calls to [light_update](ProgressLog::light_update) will cause a call to
945 /// [`Instant::now`] only if the current count is a multiple of this mask
946 /// plus one.
947 pub const LIGHT_UPDATE_MASK: usize = (1 << 20) - 1;
948
949 fn fmt_timing_speed(&self, f: &mut Formatter<'_>, seconds_per_item: f64) -> Result {
950 let items_per_second = 1.0 / seconds_per_item;
951
952 let time_unit_timing = self
953 .time_unit
954 .unwrap_or_else(|| TimeUnit::nice_time_unit(seconds_per_item));
955
956 let time_unit_speed = self
957 .time_unit
958 .unwrap_or_else(|| TimeUnit::nice_speed_unit(seconds_per_item));
959
960 f.write_fmt(format_args!(
961 "{:.2} {}/{}, {:.2} {}/{}",
962 items_per_second * time_unit_speed.as_seconds(),
963 self.items_name,
964 time_unit_speed.label(),
965 seconds_per_item / time_unit_timing.as_seconds(),
966 time_unit_timing.label(),
967 self.item_name
968 ))?;
969
970 Ok(())
971 }
972}
973
974impl ProgressLog for ProgressLogger {
975 type Concurrent = ConcurrentWrapper<Self>;
976
977 fn log(&mut self, now: Instant) {
978 self.refresh();
979 log!(target: &self.log_target, self.log_level, "{}", self);
980 self.last_count = self.count;
981 self.last_log_time = now;
982 self.next_log_time = now + self.log_interval;
983 }
984
985 fn log_if(&mut self, now: Instant) {
986 if self.next_log_time <= now {
987 self.log(now);
988 }
989 }
990
991 fn add_to_count(&mut self, count: usize) {
992 self.count += count;
993 }
994
995 fn display_memory(&mut self, display_memory: bool) -> &mut Self {
996 match (display_memory, &self.system) {
997 (true, None) => {
998 self.system = Some(System::new_with_specifics(
999 RefreshKind::nothing().with_memory(MemoryRefreshKind::nothing().with_ram()),
1000 ));
1001 }
1002 (false, Some(_)) => {
1003 self.system = None;
1004 }
1005 _ => (),
1006 }
1007 self
1008 }
1009
1010 fn item_name(&mut self, item_name: impl AsRef<str>) -> &mut Self {
1011 self.item_name = item_name.as_ref().into();
1012 self.items_name = pluralize(item_name.as_ref(), 2, false);
1013 self
1014 }
1015
1016 fn log_interval(&mut self, log_interval: Duration) -> &mut Self {
1017 self.log_interval = log_interval;
1018 self
1019 }
1020
1021 fn expected_updates(&mut self, expected_updates: impl Into<Option<usize>>) -> &mut Self {
1022 self.expected_updates = expected_updates.into();
1023 self
1024 }
1025
1026 fn time_unit(&mut self, time_unit: impl Into<Option<TimeUnit>>) -> &mut Self {
1027 self.time_unit = time_unit.into();
1028 self
1029 }
1030
1031 fn local_speed(&mut self, local_speed: bool) -> &mut Self {
1032 self.local_speed = local_speed;
1033 self
1034 }
1035
1036 fn log_target(&mut self, target: impl AsRef<str>) -> &mut Self {
1037 self.log_target = target.as_ref().into();
1038 self.log_target_cut_positions.clear();
1039 self
1040 }
1041
1042 fn push_log_target(&mut self, suffix: impl AsRef<str>) -> &mut Self {
1043 self.log_target_cut_positions.push(self.log_target.len());
1044 self.log_target.push_str(suffix.as_ref());
1045 self
1046 }
1047
1048 fn pop_log_target(&mut self) -> &mut Self {
1049 if let Some(pos) = self.log_target_cut_positions.pop() {
1050 self.log_target.truncate(pos);
1051 }
1052 self
1053 }
1054
1055 fn log_level(&mut self, log_level: Level) -> &mut Self {
1056 self.log_level = log_level;
1057 self
1058 }
1059
1060 fn start(&mut self, msg: impl AsRef<str>) {
1061 let now = Instant::now();
1062 self.start_time = Some(now);
1063 self.stop_time = None;
1064 self.count = 0;
1065 self.last_count = 0;
1066 self.last_log_time = now;
1067 self.next_log_time = now + self.log_interval;
1068 if !msg.as_ref().is_empty() {
1069 log!(target: &self.log_target, self.log_level, "{}", msg.as_ref());
1070 }
1071 }
1072
1073 fn refresh(&mut self) {
1074 if let Some(system) = &mut self.system {
1075 system.refresh_memory_specifics(MemoryRefreshKind::nothing().with_ram());
1076 system.refresh_processes_specifics(
1077 ProcessesToUpdate::Some(&[self.pid]),
1078 false,
1079 ProcessRefreshKind::nothing().with_memory(),
1080 );
1081 }
1082 }
1083
1084 fn update(&mut self) {
1085 self.count += 1;
1086 self.log_if(Instant::now());
1087 }
1088
1089 fn update_with_count_and_time(&mut self, count: usize, now: Instant) {
1090 self.count += count;
1091 self.log_if(now);
1092 }
1093
1094 /// Increases the count and, once every
1095 /// [`LIGHT_UPDATE_MASK`](ProgressLogger::LIGHT_UPDATE_MASK) + 1 calls,
1096 /// checks whether it is time to log.
1097 #[inline(always)]
1098 fn light_update(&mut self) {
1099 self.count += 1;
1100 if (self.count & Self::LIGHT_UPDATE_MASK) == 0 {
1101 self.log_if(Instant::now());
1102 }
1103 }
1104
1105 fn update_and_display(&mut self) {
1106 self.count += 1;
1107 self.log(Instant::now());
1108 }
1109
1110 fn stop(&mut self) {
1111 self.stop_time = Some(Instant::now());
1112 // just to avoid wrong reuses
1113 self.expected_updates = None;
1114 }
1115
1116 fn done(&mut self) {
1117 self.stop();
1118 log!(target: &self.log_target, self.log_level, "Completed.");
1119 self.refresh();
1120 log!(target: &self.log_target, self.log_level, "{}", self);
1121 }
1122
1123 fn done_with_count(&mut self, count: usize) {
1124 self.count = count;
1125 self.done();
1126 }
1127
1128 fn elapsed(&self) -> Option<Duration> {
1129 let start_time = self.start_time?;
1130 Some(self.stop_time.unwrap_or_else(Instant::now) - start_time)
1131 }
1132
1133 fn count(&self) -> usize {
1134 self.count
1135 }
1136
1137 fn trace(&self, args: Arguments<'_>) {
1138 trace!(target: &self.log_target, "{}", std::fmt::format(args));
1139 }
1140
1141 fn debug(&self, args: Arguments<'_>) {
1142 debug!(target: &self.log_target, "{}", std::fmt::format(args));
1143 }
1144
1145 fn info(&self, args: Arguments<'_>) {
1146 info!(target: &self.log_target, "{}", std::fmt::format(args));
1147 }
1148
1149 fn warn(&self, args: Arguments<'_>) {
1150 warn!(target: &self.log_target, "{}", std::fmt::format(args));
1151 }
1152
1153 fn error(&self, args: Arguments<'_>) {
1154 error!(target: &self.log_target, "{}", std::fmt::format(args));
1155 }
1156
1157 fn concurrent(&self) -> Self::Concurrent {
1158 ConcurrentWrapper::wrap(self.clone())
1159 }
1160}
1161
1162impl Display for ProgressLogger {
1163 fn fmt(&self, f: &mut Formatter<'_>) -> Result {
1164 if let Some(start_time) = self.start_time {
1165 let count_fmtd = if self.time_unit.is_none() {
1166 self.count.to_formatted_string(&Locale::en)
1167 } else {
1168 self.count.to_string()
1169 };
1170
1171 if let Some(stop_time) = self.stop_time {
1172 let elapsed = stop_time - start_time;
1173 let seconds_per_item = elapsed.as_secs_f64() / self.count as f64;
1174
1175 f.write_fmt(format_args!(
1176 "Elapsed: {}",
1177 TimeUnit::pretty_print(elapsed.as_millis())
1178 ))?;
1179
1180 if self.count != 0 {
1181 f.write_fmt(format_args!(
1182 " [{} {}, ",
1183 count_fmtd,
1184 if self.count == 1 {
1185 &self.item_name
1186 } else {
1187 &self.items_name
1188 }
1189 ))?;
1190 self.fmt_timing_speed(f, seconds_per_item)?;
1191 f.write_fmt(format_args!("]"))?
1192 }
1193 } else {
1194 let now = Instant::now();
1195
1196 let elapsed = now - start_time;
1197
1198 f.write_fmt(format_args!(
1199 "{} {}, {}",
1200 count_fmtd,
1201 if self.count == 1 {
1202 &self.item_name
1203 } else {
1204 &self.items_name
1205 },
1206 TimeUnit::pretty_print(elapsed.as_millis()),
1207 ))?;
1208
1209 if self.count != 0 {
1210 let seconds_per_item = elapsed.as_secs_f64() / self.count as f64;
1211 f.write_fmt(format_args!(", "))?;
1212 self.fmt_timing_speed(f, seconds_per_item)?;
1213
1214 if let Some(expected_updates) = self.expected_updates {
1215 let millis_to_end: u128 = (expected_updates.saturating_sub(self.count)
1216 as u128
1217 * elapsed.as_millis())
1218 / (self.count as u128 + 1);
1219 f.write_fmt(format_args!(
1220 "; {:.2}% done, {} to end",
1221 100.0 * self.count as f64 / expected_updates as f64,
1222 TimeUnit::pretty_print(millis_to_end)
1223 ))?;
1224 }
1225
1226 if self.local_speed && self.stop_time.is_none() && self.count != self.last_count
1227 {
1228 f.write_fmt(format_args!(" ["))?;
1229
1230 let elapsed = now - self.last_log_time;
1231 let seconds_per_item =
1232 elapsed.as_secs_f64() / (self.count - self.last_count) as f64;
1233 self.fmt_timing_speed(f, seconds_per_item)?;
1234
1235 f.write_fmt(format_args!("]"))?;
1236 }
1237 }
1238 }
1239
1240 // It would be ideal to refresh self.system here, but this operation
1241 // would require an &mut self reference.
1242 if let Some(system) = &self.system {
1243 f.write_fmt(format_args!(
1244 "; res/vir/avail/free/total mem {}/{}/{}B/{}B/{}B",
1245 system
1246 .process(self.pid)
1247 .map(|process| humanize(process.memory() as _) + "B")
1248 .unwrap_or("N/A".to_string()),
1249 system
1250 .process(self.pid)
1251 .map(|process| humanize(process.virtual_memory() as _) + "B")
1252 .unwrap_or("N/A".to_string()),
1253 humanize(system.available_memory() as _),
1254 humanize(system.free_memory() as _),
1255 humanize(system.total_memory() as _)
1256 ))?;
1257 }
1258
1259 Ok(())
1260 } else {
1261 write!(f, "ProgressLogger not started")
1262 }
1263 }
1264}
1265
1266/// A [`ConcurrentProgressLog`] implementation that wraps a [`ProgressLog`] in
1267/// an [`Arc`]/[`Mutex`].
1268///
1269/// The methods [`update`](ProgressLog::update) and
1270/// [`update_with_count`](ProgressLog::update_with_count) buffer the increment
1271/// and add it to the underlying logger only when the buffer reaches a
1272/// threshold; this prevents locking the underlying logger too often. The
1273/// threshold is set at creation using the methods
1274/// [`with_threshold`](Self::with_threshold) and
1275/// [`wrap_with_threshold`](Self::wrap_with_threshold), or by calling the method
1276/// [`threshold`](Self::threshold); it is always clamped to
1277/// [`MAX_THRESHOLD`](Self::MAX_THRESHOLD).
1278///
1279/// The method [`light_update`](ProgressLog::light_update), as in the case of
1280/// [`ProgressLogger`], further delays updates using an even faster check.
1281///
1282/// # Examples
1283///
1284/// In this example, we manually spawn processes:
1285///
1286/// ```rust
1287/// # use dsi_progress_logger::prelude::*;
1288/// # use std::thread;
1289/// let mut cpl = concurrent_progress_logger![item_name = "pumpkin"];
1290/// cpl.start("Smashing pumpkins (using many threads)...");
1291///
1292/// std::thread::scope(|s| {
1293/// for i in 0..100 {
1294/// let mut pl = cpl.clone();
1295/// s.spawn(move || {
1296/// for _ in 0..100000 {
1297/// // do something on each pumpkin
1298/// pl.update();
1299/// }
1300/// });
1301/// }
1302/// });
1303///
1304/// cpl.done();
1305/// ```
1306///
1307/// You can obtain the same behavior with
1308/// [`rayon`](https://crates.io/crates/rayon) using methods such as
1309/// [`for_each_with`](https://docs.rs/rayon/latest/rayon/iter/trait.ParallelIterator.html#method.for_each_with)
1310/// and
1311/// [`map_with`](https://docs.rs/rayon/latest/rayon/iter/trait.ParallelIterator.html#method.map_with):
1312///
1313/// ```rust
1314/// # use dsi_progress_logger::prelude::*;
1315/// # use rayon::prelude::*;
1316/// let mut cpl = concurrent_progress_logger![item_name = "pumpkin"];
1317/// cpl.start("Smashing pumpkins (using many threads)...");
1318///
1319/// (0..1000000).into_par_iter().
1320/// with_min_len(1000). // optional, might reduce the amount of cloning
1321/// for_each_with(cpl.clone(), |pl, i| {
1322/// // do something on each pumpkin
1323/// pl.update();
1324/// }
1325/// );
1326///
1327/// cpl.done();
1328/// ```
1329///
1330/// Note that you have to pass `cpl.clone()` to avoid a move that would make the
1331/// call to [`done`](ProgressLog::done) impossible. Also, since
1332/// [`for_each_with`](https://docs.rs/rayon/latest/rayon/iter/trait.ParallelIterator.html#method.for_each_with)
1333/// might perform excessive cloning if jobs are too short, you can use
1334/// [`with_min_len`](https://docs.rs/rayon/latest/rayon/iter/trait.ParallelIterator.html#method.with_min_len)
1335/// to reduce the amount of cloning.
1336pub struct ConcurrentWrapper<P: ProgressLog = ProgressLogger> {
1337 /// Underlying logger
1338 inner: Arc<Mutex<P>>,
1339 /// The number of items processed by the current thread.
1340 local_count: u32,
1341 /// The threshold for updating the underlying logger.
1342 threshold: u32,
1343}
1344
1345impl Default for ConcurrentWrapper {
1346 /// Creates a new [`ConcurrentWrapper`] based on a default
1347 /// [`ProgressLogger`], with a threshold of
1348 /// [`DEFAULT_THRESHOLD`](Self::DEFAULT_THRESHOLD).
1349 fn default() -> Self {
1350 Self {
1351 inner: Arc::new(Mutex::new(ProgressLogger::default())),
1352 local_count: 0,
1353 threshold: Self::DEFAULT_THRESHOLD,
1354 }
1355 }
1356}
1357
1358impl<P: ProgressLog + Clone> Clone for ConcurrentWrapper<P> {
1359 /// Clones the concurrent wrapper, obtaining a new one with the same
1360 /// threshold, with a local count of zero, and with the same inner
1361 /// [`ProgressLog`].
1362 fn clone(&self) -> Self {
1363 Self {
1364 inner: self.inner.clone(),
1365 local_count: 0,
1366 threshold: self.threshold,
1367 }
1368 }
1369}
1370
1371/// Macro to create a [`ConcurrentWrapper`] based on a
1372/// [`ProgressLogger`], with default log target set to [`std::module_path!`],
1373/// and key-value pairs instead of setters.
1374///
1375/// # Examples
1376///
1377/// ```rust
1378/// # use dsi_progress_logger::prelude::*;
1379/// let mut pl = concurrent_progress_logger![item_name = "pumpkin", display_memory = true];
1380/// ```
1381#[macro_export]
1382macro_rules! concurrent_progress_logger {
1383 ($($method:ident = $arg:expr),* $(,)?) => {
1384 {
1385 let mut cpl = $crate::ConcurrentWrapper::default();
1386 $crate::ProgressLog::log_target(&mut cpl, ::std::module_path!());
1387 $(
1388 $crate::ProgressLog::$method(&mut cpl, $arg);
1389 )*
1390 cpl
1391 }
1392 }
1393}
1394
1395impl ConcurrentWrapper {
1396 /// Creates a new [`ConcurrentWrapper`] based on a default
1397 /// [`ProgressLogger`], using the [default
1398 /// threshold](Self::DEFAULT_THRESHOLD).
1399 pub fn new() -> Self {
1400 Self::with_threshold(Self::DEFAULT_THRESHOLD)
1401 }
1402
1403 /// Creates a new [`ConcurrentWrapper`] wrapping a default
1404 /// [`ProgressLogger`], using the given threshold.
1405 ///
1406 /// The threshold is clamped to [`MAX_THRESHOLD`](Self::MAX_THRESHOLD).
1407 pub fn with_threshold(threshold: u32) -> Self {
1408 Self {
1409 inner: Arc::new(Mutex::new(ProgressLogger::default())),
1410 local_count: 0,
1411 threshold: threshold.min(Self::MAX_THRESHOLD),
1412 }
1413 }
1414}
1415
1416impl<P: ProgressLog> ConcurrentWrapper<P> {
1417 /// The default threshold for updating the underlying logger.
1418 pub const DEFAULT_THRESHOLD: u32 = 1 << 15;
1419
1420 /// Calls to [`light_update`](ProgressLog::light_update) will cause a call
1421 /// to [`update_with_count`](ProgressLog::update_with_count) only if the
1422 /// current local count is a multiple of this mask plus one and at least
1423 /// equal to the threshold.
1424 ///
1425 /// Note that this constant is significantly smaller than the one used in
1426 /// [`ProgressLogger`], as updates will be further delayed by the threshold
1427 /// mechanism.
1428 pub const LIGHT_UPDATE_MASK: u32 = (1 << 10) - 1;
1429
1430 /// The maximum possible threshold for updating the underlying logger.
1431 ///
1432 /// Thresholds passed to [`with_threshold`](ConcurrentWrapper::with_threshold),
1433 /// [`wrap_with_threshold`](Self::wrap_with_threshold), and
1434 /// [`threshold`](Self::threshold) are clamped to this value, which
1435 /// guarantees that the internal counter used by
1436 /// [`light_update`](ProgressLog::light_update) cannot overflow.
1437 pub const MAX_THRESHOLD: u32 = !Self::LIGHT_UPDATE_MASK;
1438
1439 /// Sets the threshold for updating the underlying logger.
1440 ///
1441 /// The threshold is clamped to [`MAX_THRESHOLD`](Self::MAX_THRESHOLD).
1442 ///
1443 /// Note that concurrent loggers with the same underlying logger
1444 /// have independent thresholds.
1445 pub fn threshold(&mut self, threshold: u32) -> &mut Self {
1446 self.threshold = threshold.min(Self::MAX_THRESHOLD);
1447 self
1448 }
1449
1450 /// Wraps a given [`ProgressLog`] in a [`ConcurrentWrapper`]
1451 /// using the [default threshold](Self::DEFAULT_THRESHOLD).
1452 pub fn wrap(inner: P) -> Self {
1453 Self {
1454 inner: Arc::new(Mutex::new(inner)),
1455 local_count: 0,
1456 threshold: Self::DEFAULT_THRESHOLD,
1457 }
1458 }
1459
1460 /// Wraps a given [`ProgressLog`] in a [`ConcurrentWrapper`] using a
1461 /// given threshold.
1462 ///
1463 /// The threshold is clamped to [`MAX_THRESHOLD`](Self::MAX_THRESHOLD).
1464 pub fn wrap_with_threshold(inner: P, threshold: u32) -> Self {
1465 Self {
1466 inner: Arc::new(Mutex::new(inner)),
1467 local_count: 0,
1468 threshold: threshold.min(Self::MAX_THRESHOLD),
1469 }
1470 }
1471
1472 /// Buffers `count`, flushing the local count to the underlying logger if
1473 /// the threshold has been reached; `now` is invoked only if a flush
1474 /// actually happens.
1475 fn buffer_or_flush(&mut self, count: usize, now: impl FnOnce() -> Instant) {
1476 match (self.local_count as usize).checked_add(count) {
1477 None => {
1478 // Sum overflows, update in two steps
1479 {
1480 let now = now();
1481 let mut inner = self.inner.lock().unwrap();
1482 inner.update_with_count_and_time(self.local_count as _, now);
1483 inner.update_with_count_and_time(count, now);
1484 }
1485 self.local_count = 0;
1486 }
1487 Some(total_count) => {
1488 if total_count >= self.threshold as usize {
1489 self.local_count = 0;
1490 // Threshold reached, time to flush to the inner ProgressLog
1491 self.inner
1492 .lock()
1493 .unwrap()
1494 .update_with_count_and_time(total_count, now());
1495 } else {
1496 // total_count is lower than self.threshold, which is a u32;
1497 // so total_count fits in u32.
1498 self.local_count = total_count as u32;
1499 }
1500 }
1501 }
1502 }
1503
1504 /// Forces an update of the underlying logger with the current local count,
1505 /// if nonzero.
1506 ///
1507 /// If the local count is zero, this method has no effect; in particular,
1508 /// dropping a wrapper after [`stop`](ProgressLog::stop) or
1509 /// [`done`](ProgressLog::done) will not log spuriously. If the mutex
1510 /// guarding the underlying logger has been poisoned by a panic in another
1511 /// thread, the local count is discarded.
1512 pub fn flush(&mut self) {
1513 if self.local_count != 0 {
1514 if let Ok(mut inner) = self.inner.lock() {
1515 inner.update_with_count(self.local_count as _);
1516 }
1517 self.local_count = 0;
1518 }
1519 }
1520}
1521
1522impl<P: ProgressLog + Clone> ConcurrentWrapper<P> {
1523 /// Duplicates the concurrent wrapper, obtaining a new one with the same
1524 /// threshold, with a local count of zero, and with an inner
1525 /// [`ProgressLog`] that is a clone of the original one.
1526 pub fn dup(&self) -> Self {
1527 Self {
1528 inner: Arc::new(Mutex::new(self.inner.lock().unwrap().clone())),
1529 local_count: 0,
1530 threshold: self.threshold,
1531 }
1532 }
1533}
1534
1535impl<P: ProgressLog + Clone + Send> ConcurrentProgressLog for ConcurrentWrapper<P> {
1536 type Duplicated = ConcurrentWrapper<P>;
1537 fn dup(&self) -> Self {
1538 ConcurrentWrapper::dup(self)
1539 }
1540}
1541
1542impl<P: ProgressLog + Clone + Send> ProgressLog for ConcurrentWrapper<P> {
1543 type Concurrent = Self;
1544
1545 fn log(&mut self, now: Instant) {
1546 self.inner.lock().unwrap().log(now);
1547 }
1548
1549 fn log_if(&mut self, now: Instant) {
1550 self.inner.lock().unwrap().log_if(now);
1551 }
1552
1553 fn add_to_count(&mut self, count: usize) {
1554 self.inner.lock().unwrap().add_to_count(count);
1555 }
1556
1557 fn display_memory(&mut self, display_memory: bool) -> &mut Self {
1558 self.inner.lock().unwrap().display_memory(display_memory);
1559 self
1560 }
1561
1562 fn item_name(&mut self, item_name: impl AsRef<str>) -> &mut Self {
1563 self.inner.lock().unwrap().item_name(item_name);
1564 self
1565 }
1566
1567 fn log_interval(&mut self, log_interval: Duration) -> &mut Self {
1568 self.inner.lock().unwrap().log_interval(log_interval);
1569 self
1570 }
1571
1572 fn expected_updates(&mut self, expected_updates: impl Into<Option<usize>>) -> &mut Self {
1573 self.inner
1574 .lock()
1575 .unwrap()
1576 .expected_updates(expected_updates.into());
1577 self
1578 }
1579
1580 fn time_unit(&mut self, time_unit: impl Into<Option<TimeUnit>>) -> &mut Self {
1581 self.inner.lock().unwrap().time_unit(time_unit.into());
1582 self
1583 }
1584
1585 fn local_speed(&mut self, local_speed: bool) -> &mut Self {
1586 self.inner.lock().unwrap().local_speed(local_speed);
1587 self
1588 }
1589
1590 fn log_target(&mut self, target: impl AsRef<str>) -> &mut Self {
1591 self.inner.lock().unwrap().log_target(target);
1592 self
1593 }
1594
1595 fn push_log_target(&mut self, suffix: impl AsRef<str>) -> &mut Self {
1596 self.inner.lock().unwrap().push_log_target(suffix);
1597 self
1598 }
1599
1600 fn pop_log_target(&mut self) -> &mut Self {
1601 self.inner.lock().unwrap().pop_log_target();
1602 self
1603 }
1604
1605 fn log_level(&mut self, log_level: Level) -> &mut Self {
1606 self.inner.lock().unwrap().log_level(log_level);
1607 self
1608 }
1609
1610 fn start(&mut self, msg: impl AsRef<str>) {
1611 self.inner.lock().unwrap().start(msg);
1612 self.local_count = 0;
1613 }
1614
1615 #[inline]
1616 fn update(&mut self) {
1617 self.update_with_count(1)
1618 }
1619
1620 #[inline]
1621 fn update_with_count_and_time(&mut self, count: usize, now: Instant) {
1622 self.buffer_or_flush(count, || now);
1623 }
1624
1625 #[inline]
1626 fn update_with_count(&mut self, count: usize) {
1627 self.buffer_or_flush(count, Instant::now);
1628 }
1629
1630 #[inline]
1631 fn light_update(&mut self) {
1632 self.local_count += 1;
1633 if (self.local_count & Self::LIGHT_UPDATE_MASK) == 0 && self.local_count >= self.threshold {
1634 // Threshold reached, time to flush to the inner ProgressLog
1635 let local_count = self.local_count as usize;
1636 self.local_count = 0;
1637 let now = Instant::now();
1638 self.inner
1639 .lock()
1640 .unwrap()
1641 .update_with_count_and_time(local_count, now);
1642 }
1643 }
1644
1645 fn update_and_display(&mut self) {
1646 {
1647 let mut inner = self.inner.lock().unwrap();
1648 inner.add_to_count(self.local_count as _);
1649 inner.update_and_display();
1650 }
1651 self.local_count = 0;
1652 }
1653
1654 fn stop(&mut self) {
1655 self.flush();
1656 self.inner.lock().unwrap().stop();
1657 }
1658
1659 fn done(&mut self) {
1660 self.flush();
1661 self.inner.lock().unwrap().done();
1662 }
1663
1664 fn done_with_count(&mut self, count: usize) {
1665 self.flush();
1666 self.inner.lock().unwrap().done_with_count(count);
1667 }
1668
1669 fn elapsed(&self) -> Option<Duration> {
1670 self.inner.lock().unwrap().elapsed()
1671 }
1672
1673 fn count(&self) -> usize {
1674 self.inner.lock().unwrap().count()
1675 }
1676
1677 fn refresh(&mut self) {
1678 self.inner.lock().unwrap().refresh();
1679 }
1680
1681 fn trace(&self, args: Arguments<'_>) {
1682 self.inner.lock().unwrap().trace(args);
1683 }
1684
1685 fn debug(&self, args: Arguments<'_>) {
1686 self.inner.lock().unwrap().debug(args);
1687 }
1688
1689 fn info(&self, args: Arguments<'_>) {
1690 self.inner.lock().unwrap().info(args);
1691 }
1692
1693 fn warn(&self, args: Arguments<'_>) {
1694 self.inner.lock().unwrap().warn(args);
1695 }
1696
1697 fn error(&self, args: Arguments<'_>) {
1698 self.inner.lock().unwrap().error(args);
1699 }
1700
1701 fn concurrent(&self) -> Self::Concurrent {
1702 self.dup()
1703 }
1704}
1705
1706/// This implementation just calls [`flush`](ConcurrentWrapper::flush),
1707/// to guarantee that all updates are correctly passed to the underlying logger.
1708impl<P: ProgressLog> Drop for ConcurrentWrapper<P> {
1709 fn drop(&mut self) {
1710 self.flush();
1711 }
1712}
1713
1714impl<P: ProgressLog + Display> Display for ConcurrentWrapper<P> {
1715 fn fmt(&self, f: &mut Formatter<'_>) -> Result {
1716 self.inner.lock().unwrap().fmt(f)
1717 }
1718}
1719
1720/// Convenience macro specifying that no (concurrent) logging should be
1721/// performed.
1722#[macro_export]
1723macro_rules! no_logging {
1724 () => {
1725 &mut Option::<$crate::ConcurrentWrapper<$crate::ProgressLogger>>::None
1726 };
1727}
1728
1729pub mod prelude {
1730 pub use log::Level;
1731
1732 pub use super::{
1733 ConcurrentProgressLog, ConcurrentWrapper, ProgressLog, ProgressLogger, TimeUnit,
1734 concurrent_progress_logger, no_logging, progress_logger,
1735 };
1736}
1737
1738#[cfg(test)]
1739mod tests {
1740 use super::*;
1741 use std::sync::atomic::{AtomicUsize, Ordering};
1742
1743 /// A [`ProgressLog`] implementation that records counts and calls in
1744 /// shared atomics, so that state remains observable through clones and
1745 /// after drops.
1746 #[derive(Clone, Default)]
1747 struct MockLog {
1748 count: Arc<AtomicUsize>,
1749 update_calls: Arc<AtomicUsize>,
1750 }
1751
1752 impl ProgressLog for MockLog {
1753 type Concurrent = ConcurrentWrapper<MockLog>;
1754
1755 fn log(&mut self, _now: Instant) {}
1756
1757 fn log_if(&mut self, _now: Instant) {}
1758
1759 fn add_to_count(&mut self, count: usize) {
1760 self.count.fetch_add(count, Ordering::Relaxed);
1761 }
1762
1763 fn display_memory(&mut self, _display_memory: bool) -> &mut Self {
1764 self
1765 }
1766
1767 fn item_name(&mut self, _item_name: impl AsRef<str>) -> &mut Self {
1768 self
1769 }
1770
1771 fn log_interval(&mut self, _log_interval: Duration) -> &mut Self {
1772 self
1773 }
1774
1775 fn expected_updates(&mut self, _expected_updates: impl Into<Option<usize>>) -> &mut Self {
1776 self
1777 }
1778
1779 fn time_unit(&mut self, _time_unit: impl Into<Option<TimeUnit>>) -> &mut Self {
1780 self
1781 }
1782
1783 fn local_speed(&mut self, _local_speed: bool) -> &mut Self {
1784 self
1785 }
1786
1787 fn log_target(&mut self, _target: impl AsRef<str>) -> &mut Self {
1788 self
1789 }
1790
1791 fn push_log_target(&mut self, _suffix: impl AsRef<str>) -> &mut Self {
1792 self
1793 }
1794
1795 fn pop_log_target(&mut self) -> &mut Self {
1796 self
1797 }
1798
1799 fn log_level(&mut self, _log_level: Level) -> &mut Self {
1800 self
1801 }
1802
1803 fn start(&mut self, _msg: impl AsRef<str>) {
1804 self.count.store(0, Ordering::Relaxed);
1805 }
1806
1807 fn update(&mut self) {
1808 self.update_with_count_and_time(1, Instant::now());
1809 }
1810
1811 fn update_with_count_and_time(&mut self, count: usize, _now: Instant) {
1812 self.count.fetch_add(count, Ordering::Relaxed);
1813 self.update_calls.fetch_add(1, Ordering::Relaxed);
1814 }
1815
1816 fn light_update(&mut self) {
1817 self.update();
1818 }
1819
1820 fn update_and_display(&mut self) {
1821 self.update();
1822 }
1823
1824 fn stop(&mut self) {}
1825
1826 fn done(&mut self) {}
1827
1828 fn done_with_count(&mut self, count: usize) {
1829 self.count.store(count, Ordering::Relaxed);
1830 }
1831
1832 fn elapsed(&self) -> Option<Duration> {
1833 None
1834 }
1835
1836 fn count(&self) -> usize {
1837 self.count.load(Ordering::Relaxed)
1838 }
1839
1840 fn refresh(&mut self) {}
1841
1842 fn trace(&self, _args: Arguments<'_>) {}
1843
1844 fn debug(&self, _args: Arguments<'_>) {}
1845
1846 fn info(&self, _args: Arguments<'_>) {}
1847
1848 fn warn(&self, _args: Arguments<'_>) {}
1849
1850 fn error(&self, _args: Arguments<'_>) {}
1851
1852 fn concurrent(&self) -> Self::Concurrent {
1853 ConcurrentWrapper::wrap(self.clone())
1854 }
1855 }
1856
1857 #[test]
1858 fn test_progress_logger_counting() {
1859 let mut pl = ProgressLogger::default();
1860 pl.start("");
1861 pl.update();
1862 pl.update_with_count(3);
1863 pl.add_to_count(2);
1864 pl.light_update();
1865 assert_eq!(pl.count(), 7);
1866 pl.stop();
1867 assert!(pl.elapsed().is_some());
1868 }
1869
1870 #[test]
1871 fn test_start_resets_count() {
1872 let mut pl = ProgressLogger::default();
1873 pl.start("");
1874 pl.update_with_count(10);
1875 pl.stop();
1876 pl.start("");
1877 assert_eq!(pl.count(), 0);
1878 }
1879
1880 #[test]
1881 fn test_clone_resets_counters_and_expected_updates() {
1882 let mut pl = ProgressLogger::default();
1883 pl.item_name("pumpkin");
1884 pl.log_target("target");
1885 pl.expected_updates(100);
1886 pl.start("");
1887 pl.update_with_count(10);
1888 let clone = pl.clone();
1889 assert_eq!(clone.count(), 0);
1890 assert!(clone.start_time.is_none());
1891 assert_eq!(clone.item_name, "pumpkin");
1892 assert_eq!(clone.items_name, "pumpkins");
1893 assert_eq!(clone.log_target, "target");
1894 // Documented behavior: expected updates are cleared on clone.
1895 assert_eq!(clone.expected_updates, None);
1896 }
1897
1898 #[test]
1899 fn test_push_pop_log_target() {
1900 let mut pl = ProgressLogger::default();
1901 pl.log_target("main");
1902 pl.push_log_target("::sub");
1903 assert_eq!(pl.log_target, "main::sub");
1904 pl.push_log_target("::subsub");
1905 assert_eq!(pl.log_target, "main::sub::subsub");
1906 pl.pop_log_target();
1907 assert_eq!(pl.log_target, "main::sub");
1908 pl.pop_log_target();
1909 assert_eq!(pl.log_target, "main");
1910 // Popping with no pushes is a no-op
1911 pl.pop_log_target();
1912 assert_eq!(pl.log_target, "main");
1913 // Setting the log target clears pending suffixes
1914 pl.push_log_target("::sub");
1915 pl.log_target("other");
1916 pl.pop_log_target();
1917 assert_eq!(pl.log_target, "other");
1918 }
1919
1920 #[test]
1921 fn test_concurrent_threshold_buffering() {
1922 let mock = MockLog::default();
1923 let mut cpl = ConcurrentWrapper::wrap_with_threshold(mock.clone(), 4);
1924 cpl.update();
1925 cpl.update();
1926 cpl.update();
1927 assert_eq!(mock.count(), 0);
1928 cpl.update();
1929 assert_eq!(mock.count(), 4);
1930 }
1931
1932 #[test]
1933 fn test_concurrent_flush_on_drop() {
1934 let mock = MockLog::default();
1935 let mut cpl = ConcurrentWrapper::wrap_with_threshold(mock.clone(), 100);
1936 {
1937 let mut clone = cpl.clone();
1938 clone.update();
1939 clone.update();
1940 }
1941 assert_eq!(mock.count(), 2);
1942 cpl.update();
1943 drop(cpl);
1944 assert_eq!(mock.count(), 3);
1945 }
1946
1947 #[test]
1948 fn test_flush_with_empty_buffer_is_noop() {
1949 let mock = MockLog::default();
1950 let mut cpl = ConcurrentWrapper::wrap_with_threshold(mock.clone(), 100);
1951 cpl.update();
1952 cpl.update();
1953 cpl.done();
1954 let update_calls = mock.update_calls.load(Ordering::Relaxed);
1955 drop(cpl);
1956 // Dropping after done() must not touch the inner logger again
1957 assert_eq!(mock.update_calls.load(Ordering::Relaxed), update_calls);
1958 assert_eq!(mock.count(), 2);
1959 }
1960
1961 #[test]
1962 fn test_light_update_flushes_at_threshold() {
1963 let mock = MockLog::default();
1964 let mut cpl = ConcurrentWrapper::wrap_with_threshold(mock.clone(), 1 << 10);
1965 for _ in 0..(1 << 10) - 1 {
1966 cpl.light_update();
1967 }
1968 assert_eq!(mock.count(), 0);
1969 cpl.light_update();
1970 assert_eq!(mock.count(), 1 << 10);
1971 }
1972
1973 #[test]
1974 fn test_threshold_clamping() {
1975 let cpl = ConcurrentWrapper::with_threshold(u32::MAX);
1976 assert_eq!(
1977 cpl.threshold,
1978 ConcurrentWrapper::<ProgressLogger>::MAX_THRESHOLD
1979 );
1980 let mut cpl = ConcurrentWrapper::wrap_with_threshold(MockLog::default(), u32::MAX);
1981 assert_eq!(cpl.threshold, ConcurrentWrapper::<MockLog>::MAX_THRESHOLD);
1982 cpl.threshold(u32::MAX - 5);
1983 assert_eq!(cpl.threshold, ConcurrentWrapper::<MockLog>::MAX_THRESHOLD);
1984 }
1985
1986 #[test]
1987 fn test_clone_shares_dup_is_independent() {
1988 let mut cpl = ConcurrentWrapper::wrap_with_threshold(ProgressLogger::default(), 1);
1989 cpl.start("");
1990 cpl.update();
1991 assert_eq!(cpl.count(), 1);
1992 // dup() wraps a clone of the inner logger, with counters reset
1993 let mut dup = cpl.dup();
1994 assert_eq!(dup.count(), 0);
1995 dup.start("");
1996 dup.update();
1997 assert_eq!(dup.count(), 1);
1998 assert_eq!(cpl.count(), 1);
1999 // clone() shares the inner logger
2000 let mut clone = cpl.clone();
2001 clone.update();
2002 assert_eq!(cpl.count(), 2);
2003 }
2004
2005 #[test]
2006 fn test_option_none_is_noop() {
2007 let pl = no_logging![];
2008 pl.update();
2009 pl.update_with_count(10);
2010 pl.light_update();
2011 assert_eq!(pl.count(), 0);
2012 assert!(pl.elapsed().is_none());
2013 }
2014}