nushell/crates/nu-std/tests/logger_tests/test_log_custom.nu
Douglas 00709fc5bd
Improves startup time when using std-lib (#13842)
Updated summary for commit
[612e0e2](612e0e2160)
- While folks are welcome to read through the entire comments, the core
information is summarized here.

# Description

This PR drastically improves startup times of Nushell by only parsing a
single submodule of the Standard Library that provides the `banner` and
`pwd` commands. All other Standard Library commands and submodules are
parsed when imported by the user. This cuts startup times by more than
60%.

At the moment, we have stopped adding to `std-lib` because every
addition adds a small amount to the Nushell startup time.
With this change, we should once again be able to allow new
functionality to be added to the Standard Library without it impacting
`nu` startup times.

# User-Facing Changes

* Nushell now starts about 60% faster
* Breaking change: The `dirs` (Shells) aliases will return a warning
message that it will not be auto-loaded in the following release, along
with instructions on how to restore it (and disable the message)
* The `use std <submodule> *` syntax is available for convenience, but
should be avoided in scripts as it parses the entire `std` module and
all other submodules and places it in scope. The correct syntax to
*just* load a submodule is `use std/<submodule> *` (asterisk optional).
The slash is important. This will be documented.
* `use std *` can be used for convenience to load all of the library but
still incurs the full loading-time.
* `std/dirs`: Semi-breaking change. The `dirs` command replaces the
`show` command. This is more in line with the directory-stack
functionality found in other shells. Existing users will not be impacted
by this as the alias (`shells`) remains the same.

* Breaking-change: Technically a breaking change, but probably only
impacts maintainers of `std`. The virtual path for the standard library
has changed. It could previously be imported using its virtual path (and
technically, this would have been the correct way to do it):

  ```nu
  use NU_STDLIB_VIRTUAL_DIR/std
  ```

  The path is now simply `std/`:

  ```nu
  use std
  ```

  All submodules have moved accordingly.
  

# Timings

Comparisons below were made:

* In a temporary, clean config directory using `$env.XDG_CONFIG_HOME =
(mktemp -d)`.
* `nu` was run with a release build
* `nu` was run one time to generate the default `config.nu` (etc.) files
- Otherwise timings would include the user-prompt
* The shell was exited and then restarted several times to get timing
samples

(Note: Old timings based on 0.97 rather than 0.98, but in the range of
being accurate)

| Scenario | `$nu.startup-time` |
| --- | --- |
| 0.97.2
([aaaab8e](aaaab8e070))
Without this PR | 23ms - 24ms |
| This PR with deprecated commands | 9ms - <11ms |
| This PR after deprecated commands are removed in following release |
8ms - <10ms |
| Final PR (remove deprecated), using `--no-std-lib` | 6.1ms to 6.4ms |
| Final PR (remove deprecated), using `--no-config-file` | 3.1ms - 3.6ms
|
| Final PR (remove deprecated), using `--no-config-file --no-std-lib` |
1ms - 1.5ms |

*These last two timings point to the opportunity for further
optimization (see comment in thread below (will link once I write it).*

# Implementation details for future maintenance

* `use std banner` is a ridiculously deceptive call. That call parses
and imports *all* of `std` into scope. Simply replacing it with `use
std/core *` is essentially what saves ~14-15ms. This *only* imports the
submodule with the `banner` and `pwd` commands.

* From the code-comments, the reason that `NU_STDLIB_VIRTUAL_DIR` was
used as a prefix was so that there wouldn't be an issue if a user had a
`./std/mod.nu` in the current directory. This does **not** appear to be
an issue. After removing the prefix, I tested with both a relative
module as well as one in the `$env.NU_LIB_DIRS` path, and in all cases
the *internal* `std` still took precedence.

* By removing the prefix, users can now `use std` (and variants) without
requiring that it already be parsed and in scope.

* In the next release, we'll stop autoloading the `dirs` (shells)
functionality. While this only costs an additional 1-1.5ms, I think it's
better moved to the `config.nu` where the user can optionally remove it.
The main reason is its use of aliases (which have also caused issues) -
The `n`, `p`, and `g` short-commands are valuable real-estate, and users
may want to map these to something else.
  
For this release, there's an `deprecated_dirs` module that is still
autoloaded. As with the top-level commands, use of these will give a
deprecation warning with instructions on how to handle going forward.

To help with this, moved the aliases to their own submodule inside the
`dirs` module.

* Also sneaks in a small change where the top-level `dirs` command is
now the replacement for `dirs show`

* Fixed a double-import of `assert` in `dirs.nu`
* The `show_banner` step is replaced with simply `banner` rather than
re-importing it.

* A `virtual_path` may now be referenced with either a forward-slash or
a backward-slash on Windows. This allows `use std/<submodule>` to work
on all platforms.

# Performance side-notes:

* Future parsing and/or IR improvements should improve performance even
further.
* While the existing load time penalty of `std-lib` was not noticeable
on many systems, Nushell runs on a wide-variety of hardware and OS
platforms. Slower platforms will naturally see a bigger jump in
performance here. For users starting multiple Nushell sessions
frequently (e.g., `tmux`, Zellij, `screen`, et. al.) it is recommended
to keep total startup time (including user configuration) under ~250ms.

# Tests + Formatting

* All tests are green

* Updated tests:
- Removed the test that confirmed that `std` was loaded (since we
don't).
- Removed the `shells` test since it is not autoloaded. Main `dirs.nu`
functionality is tested through `stdlib-test`.
- Many tests assumed that the library was fully loaded, because it was
(even though we didn't intend for it to be). Fixed those tests.
- Tests now import only the necessary submodules (e.g., `use
std/assert`, rather than `use std assert`)
- Some tests *thought* they were loading `std/log`, but were doing so
improperly. This was masked by the now-fixed "load-everything-into-scope
bug". Local CI would pass due the `$env.NU_LOG_<...>` variables being
inherited from the calling process, but would fail in the "clean" GitHub
CI environment. These tests have also been fixed.

 * Added additional tests for the changes

# After Submitting

Will update the Standard Library doc page
2024-10-03 06:28:22 -05:00

46 lines
2.1 KiB
Plaintext

use std/assert
use commons.nu *
def run-command [
system_level: string,
message: string,
format: string,
log_level: int,
--level-prefix: string,
--ansi: string
] {
if ($level_prefix | is-empty) {
if ($ansi | is-empty) {
^$nu.current-exe --no-config-file --commands $'use std/log; NU_LOG_LEVEL=($system_level) log custom "($message)" "($format)" ($log_level)'
} else {
^$nu.current-exe --no-config-file --commands $'use std/log; NU_LOG_LEVEL=($system_level) log custom "($message)" "($format)" ($log_level) --ansi "($ansi)"'
}
} else {
^$nu.current-exe --no-config-file --commands $'use std/log; NU_LOG_LEVEL=($system_level) log custom "($message)" "($format)" ($log_level) --level-prefix "($level_prefix)" --ansi "($ansi)"'
}
| complete | get --ignore-errors stderr
}
#[test]
def errors_during_deduction [] {
assert str contains (run-command "DEBUG" "msg" "%MSG%" 25) "Cannot deduce log level prefix for given log level"
assert str contains (run-command "DEBUG" "msg" "%MSG%" 25 --ansi (ansi red)) "Cannot deduce log level prefix for given log level"
assert str contains (run-command "DEBUG" "msg" "%MSG%" 25 --level-prefix "abc") "Cannot deduce ansi for given log level"
}
#[test]
def valid_calls [] {
use std/log *
assert equal (run-command "DEBUG" "msg" "%MSG%" 25 --level-prefix "abc" --ansi (ansi default) | str trim --right) "msg"
assert equal (run-command "DEBUG" "msg" "%LEVEL% %MSG%" 20 | str trim --right) $"((log-prefix).INFO) msg"
assert equal (run-command "DEBUG" "msg" "%LEVEL% %MSG%" --level-prefix "abc" 20 | str trim --right) "abc msg"
assert equal (run-command "INFO" "msg" "%ANSI_START%%LEVEL% %MSG%%ANSI_STOP%" ((log-level).CRITICAL) | str trim --right) $"((log-ansi).CRITICAL)CRT msg(ansi reset)"
}
#[test]
def log-level_handling [] {
use std/log *
assert equal (run-command "DEBUG" "msg" "%LEVEL% %MSG%" 20 | str trim --right) $"((log-prefix).INFO) msg"
assert equal (run-command "WARNING" "msg" "%LEVEL% %MSG%" 20 | str trim --right) ""
}