From aa7b057af9f0654b167bde1a000dd5ee3903b1f0 Mon Sep 17 00:00:00 2001 From: Sam Rawlins Date: Mon, 13 Nov 2023 08:41:13 -0800 Subject: [PATCH 1/3] Add some progress bars for time-intensive tasks --- lib/src/dartdoc.dart | 10 +- lib/src/logging.dart | 189 +++++++++++++++++++++-------- lib/src/model/package_builder.dart | 15 ++- lib/src/model/package_graph.dart | 25 +++- lib/src/progress_bar.dart | 88 ++++++++++++++ pubspec.yaml | 1 - tool/src/subprocess_launcher.dart | 5 +- tool/task.dart | 68 ++++++----- 8 files changed, 304 insertions(+), 97 deletions(-) create mode 100644 lib/src/progress_bar.dart diff --git a/lib/src/dartdoc.dart b/lib/src/dartdoc.dart index 4c51dd78bc..c6f5d22b15 100644 --- a/lib/src/dartdoc.dart +++ b/lib/src/dartdoc.dart @@ -213,12 +213,8 @@ class Dartdoc { var warnings = packageGraph.packageWarningCounter.warningCount; var errors = packageGraph.packageWarningCounter.errorCount; - if (warnings == 0 && errors == 0) { - logInfo('no issues found'); - } else { - logWarning("Found $warnings ${pluralize('warning', warnings)} " - "and $errors ${pluralize('error', errors)}."); - } + logWarning("Found $warnings ${pluralize('warning', warnings)} " + "and $errors ${pluralize('error', errors)}."); var seconds = stopwatch.elapsedMilliseconds / 1000.0; libs = packageGraph.localPublicLibraries.length; @@ -288,7 +284,7 @@ class Dartdoc { exitCode = e is DartdocFailure ? 1 : 255; }, zoneSpecification: ZoneSpecification( - print: (_, __, ___, String line) => logPrint(line), + print: (_, __, ___, String line) => logInfo(line), ), ); } diff --git a/lib/src/logging.dart b/lib/src/logging.dart index f4b8abb13d..dacca78468 100644 --- a/lib/src/logging.dart +++ b/lib/src/logging.dart @@ -3,12 +3,12 @@ // BSD-style license that can be found in the LICENSE file. import 'dart:convert'; -import 'dart:io' show stderr, stdout; +import 'dart:io' as io; import 'package:analyzer/file_system/file_system.dart'; -import 'package:cli_util/cli_logging.dart' show Ansi; import 'package:dartdoc/src/dartdoc_options.dart'; import 'package:dartdoc/src/package_meta.dart'; +import 'package:dartdoc/src/progress_bar.dart'; import 'package:logging/logging.dart'; final _logger = Logger('dartdoc'); @@ -16,7 +16,7 @@ final _logger = Logger('dartdoc'); /// A custom [Level] for tracking file writes and verification. /// /// Has a value of `501` – one more than [Level.FINE]. -const Level progressLevel = Level('PROGRESS', 501); +const Level _progressLevel = Level('PROGRESS', 501); /// A custom [Level] for errant print statements. /// @@ -36,13 +36,29 @@ void logDebug(String message) { } void logProgress(String message) { - _logger.log(progressLevel, message); + _logger.log(_progressLevel, message); } void logPrint(String message) { _logger.log(printLevel, message); } +void progressBarStart(int totalTickCount) { + _DartdocLogger.instance.progressBarStart(totalTickCount); +} + +void progressBarTick() { + _DartdocLogger.instance.progressBarTick(); +} + +void progressBarUpdateTickCount(int totalTickCount) { + _DartdocLogger.instance.progressBarUpdateTickCount(totalTickCount); +} + +void progressBarComplete() { + _DartdocLogger.instance.progressBarComplete(); +} + abstract class Jsonable { /// The `String` to print when in human-readable mode String get text; @@ -54,47 +70,57 @@ abstract class Jsonable { String toString() => text; } -void startLogging(LoggingContext config) { - // By default, get all log output at `progressLevel` or greater. - // This allows us to capture progress events and print `...`. - // Change this to `Level.FINE` for debug logging. - Logger.root.level = progressLevel; - if (config.json) { - Logger.root.onRecord.listen((record) { - if (record.level == progressLevel) { - return; - } +class _DartdocLogger { + static late final _DartdocLogger instance; - var output = {'level': record.level.name}; + final bool _showProgressBar; - if (record.object is Jsonable) { - output['data'] = record.object; - } else { - output['message'] = record.message; - } + ProgressBar? _progressBar; - print(json.encode(output)); - }); - } else { + _DartdocLogger._({ + required bool isJson, + required bool isQuiet, + required bool showProgress, + }) : _showProgressBar = showProgress && !isJson && !isQuiet { + // By default, get all log output at `progressLevel` or greater. + // This allows us to capture progress events and print `...`. + // Change this to `Level.FINE` for debug logging. + Logger.root.level = _progressLevel; + if (isJson) { + Logger.root.onRecord.listen(_onJsonRecord); + return; + } + + _initialize(isQuiet: isQuiet, showProgress: showProgress); + } + + /// Initializes this as a non-JSON logger. + /// + /// This method mostly sets up callback behavior for each logged message. + void _initialize({required bool isQuiet, required bool showProgress}) { final stopwatch = Stopwatch()..start(); // Used to track if we're printing `...` to show progress. // Allows unified new-line tracking var writingProgress = false; - var ansi = Ansi(Ansi.terminalSupportsAnsi); var spinnerIndex = 0; const spinner = ['-', r'\', '|', '/']; Logger.root.onRecord.listen((record) { - if (record.level == progressLevel) { - if (!config.quiet && - config.showProgress && + if (record.level == progressBarUpdate) { + io.stdout.write(record.message); + return; + } + + if (record.level == _progressLevel) { + if (!isQuiet && + showProgress && stopwatch.elapsed.inMilliseconds > 125) { if (writingProgress = false) { - stdout.write(' '); + io.stdout.write(' '); } writingProgress = true; - stdout.write('${ansi.backspace}${spinner[spinnerIndex]}'); + io.stdout.write('$_backspace${spinner[spinnerIndex]}'); spinnerIndex = (spinnerIndex + 1) % spinner.length; stopwatch.reset(); } @@ -103,26 +129,79 @@ void startLogging(LoggingContext config) { stopwatch.reset(); if (writingProgress) { - stdout.write('${ansi.backspace} ${ansi.backspace}'); + io.stdout.write('$_backspace $_backspace'); } var message = record.message; assert(message.isNotEmpty); if (record.level < Level.WARNING) { - if (!config.quiet) { + if (!isQuiet) { print(message); } } else { if (writingProgress) { // Some console implementations, like IntelliJ, apparently need // the backspace to occur for stderr as well. - stderr.write('${ansi.backspace} ${ansi.backspace}'); + io.stderr.write('$_backspace $_backspace'); } - stderr.writeln(message); + io.stderr.writeln(message); } writingProgress = false; }); } + + void progressBarStart(int totalTickCount) { + if (!_showProgressBar) { + return; + } + _progressBar = ProgressBar(_logger, totalTickCount); + } + + void progressBarTick() { + if (!_showProgressBar) { + return; + } + _progressBar?.tick(); + } + + void progressBarUpdateTickCount(int totalTickCount) { + if (!_showProgressBar) { + return; + } + _progressBar?.totalTickCount = totalTickCount; + } + + void progressBarComplete() { + if (!_showProgressBar) { + return; + } + _progressBar?.complete(); + _progressBar = null; + } + + void _onJsonRecord(LogRecord record) { + if (record.level == _progressLevel) { + return; + } + + var output = {'level': record.level.name}; + + if (record.object is Jsonable) { + output['data'] = record.object; + } else { + output['message'] = record.message; + } + + print(json.encode(output)); + } +} + +void startLogging(LoggingContext config) { + _DartdocLogger.instance = _DartdocLogger._( + isJson: config.json, + isQuiet: config.quiet, + showProgress: config.showProgress, + ); } mixin LoggingContext on DartdocOptionContextBase { @@ -137,22 +216,34 @@ List> createLoggingOptions( PackageMetaProvider packageMetaProvider) { var resourceProvider = packageMetaProvider.resourceProvider; return [ - DartdocOptionArgOnly('json', false, resourceProvider, - help: 'Prints out progress JSON maps. One entry per line.', - negatable: true), DartdocOptionArgOnly( - 'showProgress', Ansi.terminalSupportsAnsi, resourceProvider, - help: 'Display progress indications to console stdout.', - negatable: true), - DartdocOptionArgSynth('quiet', - (DartdocSyntheticOption option, Folder dir) { - if (option.parent['generateDocs'].valueAt(dir) == false) { - return true; - } - return false; - }, resourceProvider, - abbr: 'q', - negatable: true, - help: 'Only show warnings and errors; silence all other output.'), + 'json', + false, + resourceProvider, + help: 'Prints out progress JSON maps. One entry per line.', + negatable: true, + ), + DartdocOptionArgOnly( + 'showProgress', + _terminalSupportsAnsi, + resourceProvider, + help: 'Display progress indications to console stdout.', + negatable: true, + ), + DartdocOptionArgSynth( + 'quiet', + (DartdocSyntheticOption option, Folder dir) => + option.parent['generateDocs'].valueAt(dir) == false, + resourceProvider, + abbr: 'q', + negatable: true, + help: 'Only show warnings and errors; silence all other output.', + ), ]; } + +const String _backspace = '\b'; + +bool get _terminalSupportsAnsi => + io.stdout.supportsAnsiEscapes && + io.stdioType(io.stdout) == io.StdioType.terminal; diff --git a/lib/src/model/package_builder.dart b/lib/src/model/package_builder.dart index 1a7954988c..ba02ba7935 100644 --- a/lib/src/model/package_builder.dart +++ b/lib/src/model/package_builder.dart @@ -225,9 +225,15 @@ class PubPackageBuilder implements PackageBuilder { // find all documentable files in that package, for the universal reference // scope. This variable tracks which packages we've seen so far. var knownPackages = {}; + if (!addingSpecials) { + progressBarStart(files.length); + } do { filesInLastPass = filesInCurrentPass; var newFiles = {}; + if (!addingSpecials) { + progressBarUpdateTickCount(files.length); + } // Be careful here, not to accidentally stack up multiple // [DartDocResolvedLibrary]s, as those eat our heap. var libraryFiles = files.difference(_knownParts); @@ -237,7 +243,9 @@ class PubPackageBuilder implements PackageBuilder { continue; } processedFiles.add(file); - logProgress(file); + if (!addingSpecials) { + progressBarTick(); + } var resolvedLibrary = await processLibrary(file); if (resolvedLibrary == null) { _knownParts.add(file); @@ -281,6 +289,9 @@ class PubPackageBuilder implements PackageBuilder { knownPackages.addAll(packages); } } while (!filesInLastPass.containsAll(filesInCurrentPass)); + if (!addingSpecials) { + progressBarComplete(); + } } /// Whether [libraryElement] should be included in the libraries-to-document. @@ -434,7 +445,7 @@ class PubPackageBuilder implements PackageBuilder { var files = await _getFiles(); var specialFiles = specialLibraryFiles(findSpecialsSdk); - logDebug('${DateTime.now()}: Discovering Dart libraries...'); + logInfo('Discovering libraries...'); var foundLibraries = {}; await _discoverLibraries( uninitializedPackageGraph.addLibraryToGraph, diff --git a/lib/src/model/package_graph.dart b/lib/src/model/package_graph.dart index a35af50b4b..614ec22302 100644 --- a/lib/src/model/package_graph.dart +++ b/lib/src/model/package_graph.dart @@ -155,7 +155,14 @@ class PackageGraph with CommentReferable, Nameable, ModelBuilder { var precachedElements = {}; var futures = >[]; - for (var element in _allModelElements) { + logInfo('Linking elements...'); + // This is awkward, but initializing this late final field is a sizeable + // chunk of work. Several seconds for a small package. + var allModelElements = _gatherModelElements(); + logInfo('Precaching local docs for ${allModelElements.length} elements...'); + progressBarStart(allModelElements.length); + for (var element in allModelElements) { + progressBarTick(); // Only precache elements which are canonical, have a canonical element // somewhere, or have a canonical enclosing element. Not the same as // `allCanonicalModelElements` since we need to run for any [ModelElement] @@ -168,19 +175,18 @@ class PackageGraph with CommentReferable, Nameable, ModelBuilder { if (d.needsPrecache && !precachedElements.contains(d)) { precachedElements.add(d as ModelElement); futures.add(d.precacheLocalDocs()); - logProgress(d.name); // [TopLevelVariable]s get their documentation from getters and // setters, so should be precached if either has a template. if (element is TopLevelVariable && !precachedElements.contains(element)) { precachedElements.add(element); futures.add(element.precacheLocalDocs()); - logProgress(d.name); } } } } } + progressBarComplete(); // Now wait for any of the tasks still running to complete. futures.add(config.tools.runner.wait()); return futures; @@ -306,7 +312,7 @@ class PackageGraph with CommentReferable, Nameable, ModelBuilder { final Map allLibraries = {}; /// All [ModelElement]s constructed for this package; a superset of - /// [_allModelElements]. + /// the elements gathered in [_gatherModelElements]. final Map<(Element element, Library library, Container? enclosingElement), ModelElement> allConstructedModelElements = {}; @@ -871,16 +877,22 @@ class PackageGraph with CommentReferable, Nameable, ModelBuilder { return allLibraries[e.library?.source.fullName]; } - late final Iterable _allModelElements = () { + /// Gathers all of the model elements found in all of the libraries of all + /// of the packages. + Iterable _gatherModelElements() { assert(allLibrariesAdded); var allElements = []; var completedPackages = {}; + var libraryCount = packages.fold( + 0, (previous, package) => previous + package.allLibraries.length); + progressBarStart(libraryCount); for (var package in packages) { if (completedPackages.contains(package)) { continue; } var completedLibraries = {}; for (var library in package.allLibraries) { + progressBarTick(); if (completedLibraries.contains(library)) { continue; } @@ -889,9 +901,10 @@ class PackageGraph with CommentReferable, Nameable, ModelBuilder { } completedPackages.add(package); } + progressBarComplete(); return allElements; - }(); + } late final Iterable allLocalModelElements = [ for (var library in _localLibraries) ...library.allModelElements diff --git a/lib/src/progress_bar.dart b/lib/src/progress_bar.dart new file mode 100644 index 0000000000..1849bf6cf2 --- /dev/null +++ b/lib/src/progress_bar.dart @@ -0,0 +1,88 @@ +import 'dart:io' as io; +import 'dart:math' as math; + +import 'package:logging/logging.dart'; + +const Level progressBarUpdate = Level('PROGRESS_BAR', 502); + +/// A facility for drawing a progress bar in the terminal. +/// +/// The bar is instantiated with the total number of "ticks" to be completed, +/// and progress is made by calling [tick]. The bar is drawn across one entire +/// line, like so: +/// +/// [---------- ] +/// +/// The hyphens represent completed progress, and the whitespace represents +/// remaining progress. +/// +/// If there is no terminal, the progress bar will not be drawn. +class ProgressBar { + final Logger _logger; + + /// Whether the progress bar should be drawn. + late bool _shouldDrawProgress; + + /// The width of the terminal, in terms of characters. + late int _width; + + /// The inner width of the terminal, in terms of characters. + /// + /// This represents the number of characters available for drawing progress. + late int _innerWidth; + + int totalTickCount; + + int _tickCount = 0; + + ProgressBar(this._logger, this.totalTickCount) { + if (!io.stdout.hasTerminal) { + _shouldDrawProgress = false; + } else { + _shouldDrawProgress = true; + _width = io.stdout.terminalColumns; + // Inclusion of the percent indicator assumes a terminal width of at least + // 12 (2 brackets + 1 space + 2 parenthesis characters + 3 digits + + // 1 period + 2 digits + 1 '%' character). + _innerWidth = io.stdout.terminalColumns - 12; + _logger.log(progressBarUpdate, '[${' ' * _innerWidth}]'); + } + } + + /// Clears the progress bar from the terminal, allowing other logging to be + /// printed. + void clear() { + if (!_shouldDrawProgress) { + return; + } + io.stdout.write('\r${' ' * _width}\r'); + } + + /// Draws the progress bar as complete, and print two newlines. + void complete() { + if (!_shouldDrawProgress) { + return; + } + _logger.log(progressBarUpdate, '\r[${'-' * _innerWidth}] (100.00%)\n\n'); + } + + /// Progresses the bar by one tick. + void tick() { + if (!_shouldDrawProgress) { + return; + } + _tickCount++; + final fractionComplete = + math.max(0, _tickCount * _innerWidth ~/ totalTickCount - 1); + // The inner space consists of hyphens, one spinner character, spaces, and a + // percentage (8 characters). + final hyphens = '-' * fractionComplete; + final trailingSpace = ' ' * (_innerWidth - fractionComplete - 1); + final spinner = _animationItems[_tickCount % 4]; + final pctComplete = (_tickCount * 100 / totalTickCount).toStringAsFixed(2); + _logger.log(progressBarUpdate, + '\r[$hyphens$spinner$trailingSpace] ($pctComplete%)'); + } +} + +const List _animationItems = ['/', '-', r'\', '|']; diff --git a/pubspec.yaml b/pubspec.yaml index 923504170f..0ed638f7ae 100644 --- a/pubspec.yaml +++ b/pubspec.yaml @@ -9,7 +9,6 @@ environment: dependencies: analyzer: ^6.3.0 args: ^2.4.1 - cli_util: ^0.4.0 collection: ^1.17.0 crypto: ^3.0.3 glob: ^2.1.1 diff --git a/tool/src/subprocess_launcher.dart b/tool/src/subprocess_launcher.dart index a92ca76eca..aa07b6cffb 100644 --- a/tool/src/subprocess_launcher.dart +++ b/tool/src/subprocess_launcher.dart @@ -111,7 +111,7 @@ class SubprocessLauncher { if (Platform.environment.containsKey('DRY_RUN')) return {}; if (withStats) { - (executable, arguments) = _wrapWithTime(executable, arguments); + (executable, arguments) = wrapWithTime(executable, arguments); } if (Platform.isLinux) { (executable, arguments) = _wrapWithStdbuf(executable, arguments); @@ -152,7 +152,8 @@ class SubprocessLauncher { ); /// Wraps [command] and [args] with a command to `time`. - (String, List) _wrapWithTime(String command, List args) => + static (String, List) wrapWithTime( + String command, List args) => ('/usr/bin/time', ['-l', command, ...args]); Future>> runStreamedDartCommand( diff --git a/tool/task.dart b/tool/task.dart index a4af96815f..70d46f3b94 100644 --- a/tool/task.dart +++ b/tool/task.dart @@ -391,42 +391,50 @@ Future docPackage({ var pubPackageDir = Directory.systemTemp.createTempSync(name); io_utils.copy(pubPackageDirOrig, pubPackageDir); + var executable = Platform.executable; + var arguments = [ + '--enable-asserts', + path.join(Directory.current.absolute.path, 'bin', 'dartdoc.dart'), + '--link-to-remote', + '--show-progress', + '--show-stats', + '--no-validate-links', + ]; + Map? environment; + if (pubPackageMetaProvider .fromDir(PhysicalResourceProvider.INSTANCE.getFolder(pubPackageDir.path))! .requiresFlutter) { var flutterRepo = await FlutterRepo.fromExistingFlutterRepo(await cleanFlutterRepo); - await launcher.runStreamed(flutterRepo.cacheDart, ['pub', 'get'], - environment: flutterRepo.env, - workingDirectory: pubPackageDir.absolute.path); - await launcher.runStreamed( - flutterRepo.cacheDart, - [ - '--enable-asserts', - path.join(Directory.current.absolute.path, 'bin', 'dartdoc.dart'), - '--json', - '--link-to-remote', - '--show-progress', - ], - environment: flutterRepo.env, - workingDirectory: pubPackageDir.absolute.path, - withStats: withStats, - ); - } else { - await launcher.runStreamedDartCommand(['pub', 'get'], - workingDirectory: pubPackageDir.absolute.path); - await launcher.runStreamedDartCommand( - [ - '--enable-asserts', - path.join(Directory.current.absolute.path, 'bin', 'dartdoc.dart'), - '--json', - '--link-to-remote', - '--show-progress', - ], - workingDirectory: pubPackageDir.absolute.path, - withStats: withStats, - ); + executable = flutterRepo.cacheDart; + environment = flutterRepo.env; } + await launcher.runStreamed( + executable, + ['pub', 'get'], + environment: environment, + workingDirectory: pubPackageDir.absolute.path, + ); + await launcher.runStreamed( + executable, + // Add the `--json` flag for the support in `runStreamed` to tease out + // data and messages. + [...arguments, '--json'], + workingDirectory: pubPackageDir.absolute.path, + environment: environment, + withStats: withStats, + ); + if (withStats) { + (executable, arguments) = + SubprocessLauncher.wrapWithTime(executable, arguments); + } + print('Quickly re-run doc generation with:'); + print( + ' pushd ${pubPackageDir.absolute.path} ;' + ' "$executable" ${arguments.map((a) => '"$a"').join(' ')} ;' + ' popd', + ); return path.join(pubPackageDir.absolute.path, 'doc', 'api'); } From 5ef5b17e54b8827e7932faa367cdea0e48876677 Mon Sep 17 00:00:00 2001 From: Sam Rawlins Date: Mon, 13 Nov 2023 10:15:39 -0800 Subject: [PATCH 2/3] fixe --- lib/src/logging.dart | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/lib/src/logging.dart b/lib/src/logging.dart index dacca78468..d11a157bfa 100644 --- a/lib/src/logging.dart +++ b/lib/src/logging.dart @@ -43,18 +43,26 @@ void logPrint(String message) { _logger.log(printLevel, message); } +/// Creates a new deterministic progress bar, and displays it (with zero +/// progress). void progressBarStart(int totalTickCount) { _DartdocLogger.instance.progressBarStart(totalTickCount); } +/// Increments the progress of the current progress bar. void progressBarTick() { _DartdocLogger.instance.progressBarTick(); } +/// Updates the total length of the current progress bar. void progressBarUpdateTickCount(int totalTickCount) { _DartdocLogger.instance.progressBarUpdateTickCount(totalTickCount); } +/// Completes the current progress bar. +/// +/// It is important to call this after progress is complete, in case rounding +/// errors leave the displayed progress bar at something less than 100%. void progressBarComplete() { _DartdocLogger.instance.progressBarComplete(); } @@ -71,7 +79,11 @@ abstract class Jsonable { } class _DartdocLogger { - static late final _DartdocLogger instance; + /// By default, we use a quiet logger. + /// + /// This field can be re-set, with [startLogging]. + static _DartdocLogger instance = + _DartdocLogger._(isJson: false, isQuiet: true, showProgress: false); final bool _showProgressBar; From a81bf890b770142b3aed74b1a0a4f014a26d9523 Mon Sep 17 00:00:00 2001 From: Sam Rawlins Date: Tue, 14 Nov 2023 15:30:21 -0800 Subject: [PATCH 3/3] comments --- lib/src/progress_bar.dart | 5 +++++ tool/task.dart | 5 ++++- 2 files changed, 9 insertions(+), 1 deletion(-) diff --git a/lib/src/progress_bar.dart b/lib/src/progress_bar.dart index 1849bf6cf2..6da0ec53b5 100644 --- a/lib/src/progress_bar.dart +++ b/lib/src/progress_bar.dart @@ -3,6 +3,11 @@ import 'dart:math' as math; import 'package:logging/logging.dart'; +/// The logging Level of a progress bar update. +/// +/// The number, 502, is not interesting; it is just unique, and one greater +/// than logging.dart's `_progressLevel`. That library performs different +/// actions when it sees logging messages with this Level. const Level progressBarUpdate = Level('PROGRESS_BAR', 502); /// A facility for drawing a progress bar in the terminal. diff --git a/tool/task.dart b/tool/task.dart index 70d46f3b94..a8a163fc50 100644 --- a/tool/task.dart +++ b/tool/task.dart @@ -419,7 +419,10 @@ Future docPackage({ await launcher.runStreamed( executable, // Add the `--json` flag for the support in `runStreamed` to tease out - // data and messages. + // data and messages. This flag allows the [runCompare] tasks to interpret + // data from stdout as structured data, in order to compare the dartdoc + // outputs of two commands. We add it here, but exclude it from the + // "Quickly re-run" text below, as that command is for human consumption. [...arguments, '--json'], workingDirectory: pubPackageDir.absolute.path, environment: environment,