Repository: sharkdp/fd (language: rust)

Issue:
--color=always ~10x slower
**Describe the bug you encountered:**

I understand that outputting the escape sequences for colors is more text, but I didn't expect it to be 10x slower. Is this expected behavior?

**Describe what you expected to happen:**

Expected `color=always` to not be 10x slower, although maybe I'm simply misguided.

![image](https://user-images.githubusercontent.com/25516241/105956489-c0898e80-602c-11eb-97f2-96a9569650ec.png)

**What version of `fd` are you using?**
`fd 8.2.1` (`fd-8.2.1-1` on the AUR)

**Which operating system / distribution are you on?**

```
Linux 5.10.10-arch1-1 x86_64
```

and `lsb_release` but I don't think it's very helpful :)
```
LSB Version:	1.4
Distributor ID:	Arch
Description:	Arch Linux
Release:	rolling
Codename:	n/a
```
Ryzen 3900x (24 threads) but it seemed during the bench mark only ~80% cpu was being used.


Discussion / hints:
`--color` can be much more expensive because it needs to `stat()` more often, since colors depend on things like permissions and link counts that aren't known from just reading directories.  However, the sheer number of `stat()` calls seems like a bug:

```
$ strace -cf fd --color=always -HI -j1 >/dev/null
strace: Process 51592 attached
strace: Process 51594 attached
strace: Process 51593 attached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ------------------
 64.09    3.465955        6211       558         4 futex
 25.69    1.389121           2    500392         1 statx
  4.53    0.244950           2    115031           write
  2.64    0.142739           8     16900           getdents64
  1.08    0.058637           6      8455           openat
  0.98    0.052769           6      8454           fstat
  0.97    0.052676           6      8457           close
...
$ strace -cf fd -HI -j1 >/dev/null
strace: Process 51606 attached
strace: Process 51607 attached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ------------------
 57.20    1.086218        1792       606        29 futex
 23.77    0.451380           3    115031           write
  9.00    0.170929          10     16900           getdents64
  4.33    0.082204           9      8455           openat
  3.10    0.058842           6      8457           close
  2.59    0.049160           5      8454           fstat
...
```

500392 calls to `statx()` is much more than necessary for only 115031 total files.  (Also, 1 `write()` per file is suboptimal too.)  It looks like `fd` is calling `statx()` for every path component, which results in lots of repeated calls that could be cached:

```
$ mkdir -p 1/2/3/4/5/6/7/8/9
$ strace -f -e statx fd -HI -j1 . 1
...
[pid 57576] statx(AT_FDCWD, "1", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0750, stx_size=2, ...}) = 0
[pid 57576] statx(AT_FDCWD, "1/2", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0750, stx_size=2, ...}) = 0
1/2
[pid 57576] statx(AT_FDCWD, "1", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0750, stx_size=2, ...}) = 0
[pid 57576] statx(AT_FDCWD, "1/2", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0750, stx_size=2, ...}) = 0
[pid 57576] statx(AT_FDCWD, "1/2/3", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0750, stx_size=2, ...}) = 0
1/2/3
[pid 57576] statx(AT_FDCWD, "1", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0750, stx_size=2, ...}) = 0
[pid 57576] statx(AT_FDCWD, "1/2", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0750, stx_size=2, ...}) = 0
[pid 57576] statx(AT_FDCWD, "1/2/3", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0750, stx_size=2, ...}) = 0
[pid 57576] statx(AT_FDCWD, "1/2/3/4", AT_STATX_SYNC_AS_STAT|AT_SYMLINK_NOFOLLOW, STATX_ALL, {stx_mask=STATX_ALL|STATX_MNT_ID, stx_attributes=0, stx_mode=S_IFDIR|0750, stx_size=2, ...}) = 0
1/2/3/4
...
```

This happens because `fd` colors each path component separately.  In `bfs` I just color the whole thing up to the basename as a directory (even though some components might be links).  The extra precision of `fd` here is costly without any caching.
The extra `write()` calls are because [*Rust's Stdout is always line-buffered, even if stdout is not a tty*](https://github.com/rust-lang/rust/blob/a3ed564c130ec3f19e933a9ea31faca5a717ce91/library/std/src/io/stdio.rs#L491-L494) :O

https://github.com/rust-lang/rust/issues/60673
Thank you for reporting this. I was aware of this performance problem but never got around to fixing it. Note that the "10x slower" is only true if there are LOTS of search results.

Related:

- https://github.com/sharkdp/fd/issues/36#issuecomment-330303308
- https://github.com/sharkdp/fd/issues/304#issuecomment-397738773
- this code comment :smile:
  https://github.com/sharkdp/fd/blob/b8089f8d5842dff6b4a42bf5dfdeb24c02b71d76/src/output.rs#L42-L43

>  It looks like `fd` is calling `statx()` for every path component, which results in lots of repeated calls that could be cached:

True.

> This happens because `fd` colors each path component separately. In `bfs` I just color the whole thing up to the basename as a directory (even though some components might be links). The extra precision of `fd` here is costly without any caching.

Thank you for the information. Colorizing everything up to the basename also sounds like a reasonable alternative. We won't be able to do this anymore:
![image](https://user-images.githubusercontent.com/4209276/107862266-e9db5480-6e4b-11eb-9ec6-96d198a63135.png)
But I guess that's okay. A cache might still be of value if there are multiple results in the same folder. This is definitely something that we should address.

> Also, 1 `write()` per file is suboptimal too.

Could you go into more detail here? You mean we could buffer results if not writing to a TTY? (if we write to a TTY, we want results to be visible immediately).
> Could you go into more detail here? You mean we could buffer results if not writing to a TTY? (if we write to a TTY, we want results to be visible immediately).

Yeah, I expect stdout to be line buffered when going to a TTY and fully buffered otherwise.  That's how it is in C anyway.  I thought Rust would do the same thing but it's just always line buffered.

Fix patch:
diff --git a/CHANGELOG.md b/CHANGELOG.md
index bb6f8e0e9..ffb2fb100 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -5,6 +5,8 @@
 - File metadata is now cached between the different filters that require it (e.g. `--owner`,
   `--size`), reducing the number of `stat` syscalls when multiple filters are used; see #863
 
+- Colorized output is now significantly faster, see #720 and #853 (@tavianator)
+
 ## Features
 - Don't buffer command output from `--exec` when using a single thread. See #522
 
diff --git a/src/output.rs b/src/output.rs
index 536626d1a..828d99504 100644
--- a/src/output.rs
+++ b/src/output.rs
@@ -1,10 +1,11 @@
+use std::borrow::Cow;
 use std::io::{self, StdoutLock, Write};
 use std::path::Path;
 use std::process;
 use std::sync::atomic::{AtomicBool, Ordering};
 use std::sync::Arc;
 
-use lscolors::{LsColors, Style};
+use lscolors::{Indicator, LsColors, Style};
 
 use crate::config::Config;
 use crate::error::print_error;
@@ -53,32 +54,51 @@ fn print_entry_colorized(
     ls_colors: &LsColors,
     wants_to_quit: &Arc<AtomicBool>,
 ) -> io::Result<()> {
-    let default_style = ansi_term::Style::default();
-
-    // Traverse the path and colorize each component
-    for (component, style) in ls_colors.style_for_path_components(path) {
-        let style = style
-            .map(Style::to_ansi_term_style)
-            .unwrap_or(default_style);
+    // Split the path between the parent and the last component
+    let mut offset = 0;
+    let path_str = path.to_string_lossy();
+
+    if let Some(parent) = path.parent() {
+        offset = parent.to_string_lossy().len();
+        for c in path_str[offset..].chars() {
+            if std::path::is_separator(c) {
+                offset += c.len_utf8();
+            } else {
+                break;
+            }
+        }
+    }
 
-        let mut path_string = component.to_string_lossy();
+    if offset > 0 {
+        let mut parent_str = Cow::from(&path_str[..offset]);
         if let Some(ref separator) = config.path_separator {
-            *path_string.to_mut() = replace_path_separator(&path_string, separator);
+            *parent_str.to_mut() = replace_path_separator(&parent_str, separator);
         }
-        write!(stdout, "{}", style.paint(path_string))?;
 
-        // TODO: can we move this out of the if-statement? Why do we call it that often?
-        if wants_to_quit.load(Ordering::Relaxed) {
-            writeln!(stdout)?;
-            process::exit(ExitCode::KilledBySigint.into());
-        }
+        let style = ls_colors
+            .style_for_indicator(Indicator::Directory)
+            .map(Style::to_ansi_term_style)
+            .unwrap_or_default();
+        write!(stdout, "{}", style.paint(parent_str))?;
     }
 
+    let style = ls_colors
+        .style_for_path(path)
+        .map(Style::to_ansi_term_style)
+        .unwrap_or_default();
+    write!(stdout, "{}", style.paint(&path_str[offset..]))?;
+
     if config.null_separator {
-        write!(stdout, "\0")
+        write!(stdout, "\0")?;
     } else {
-        writeln!(stdout)
+        writeln!(stdout)?;
     }
+
+    if wants_to_quit.load(Ordering::Relaxed) {
+        process::exit(ExitCode::KilledBySigint.into());
+    }
+
+    Ok(())
 }
 
 // TODO: this function is performance critical and can probably be optimized


Test patch: