Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

journalctl --all is substantially faster due to strip_tab_ansi() using fputc() #6341

Closed
vcaputo opened this issue Jul 12, 2017 · 3 comments
Closed

Comments

@vcaputo
Copy link
Member

vcaputo commented Jul 12, 2017

In valgrind profiles of journalctl -b --no-pager I tend to see fputc() prominently in the results, and simply adding --all to the commandline seems to resolve the situation with a correspondingly significant performance improvement:

# time ./journalctl -b -1 --no-pager --all > /dev/null

real    0m8.158s
user    0m7.398s
sys     0m0.756s

# time ./journalctl -b -1 --no-pager > /dev/null

real    0m11.101s
user    0m10.353s
sys     0m0.748s

There was a time long ago when the stdio character functions in libc were lightweight macros directly twiddling the buffers. I believe it was when pthreads came along these things all became functions with implicit locking probably because somebody wanted libc to magically serialize calls to putchar()/puts()/printf() from multiple threads without any special effort on the programmer's part. It's also why we have __fsetlocking() today. Ever since this stuff happened, I largely stopped using stdio in my programs for anything but the most rudimentary tasks like stderr logging or simple interactive stdio UI stuff, because the performance is generally awful.

I think it really makes sense for systemd to have its own FILE * equivalent closer in spirit to the original C implementation, and replace all the stdio stuff throughout the systemd code with it instead.

Thoughts?

@vcaputo vcaputo changed the title journalctl --all is substantially faster due to strip_tab_ansi() journalctl --all is substantially faster due to strip_tab_ansi() using fputc() Jul 12, 2017
@vcaputo
Copy link
Member Author

vcaputo commented Jul 13, 2017

There is also the option of simply switching to using the _unlocked() variants like fputc_unlocked() throughout logs-show.c and strip_tab_ansi(). My testing has shown this to substantially improve the situation with minimal effort...

Do we require the implicit locking? Since everything is largely single-threaded it shouldn't be a problem AFAICT.

@poettering
Copy link
Member

Hmm, given that strip_tab_ansi() only operates on the STREAM* object it itself allocated I think using the _unlocked() versions of those calls should be entirely safe, and a pretty low-hanging fruit...

Hmm, you said that --all speeds up things drastically, is that just about strip_tab_ansi() really? I fail to see where STDIO commands would be used systematically different if --all is specified otherwise, or am I missing something?

Changing logs-show altogether to use the unlocked version I am not sure I like too much I must say, and would prefer if we might find a different option there (for example, allocate a memstream for each entry that used the unlocked versions, then write() that with low-level syscalls to STDOUT_FILENO...). The thing is that today we never know what thread might be running in the background, and we have some these days too, and we never know if they might end up using stderr...

@vcaputo
Copy link
Member Author

vcaputo commented Jul 17, 2017

parse_fields() is another big burner of CPU time that gets eliminated by adding --all, but it's not as trivial to improve upon. It should be possible to eliminate all the granular string allocations and copies, and perhaps switching from the if-else-if parser to either a trie or hash table (though I don't believe Hashmap is well suited to this kind of task as-is; it'd be preferable to have static initialization of the field names map and a much lighter hash function).

I'll post a PR with strip_tab_ansi() unlock-ified once I have some measurements to stick in the commit message.

vcaputo added a commit to vcaputo/systemd that referenced this issue Jul 17, 2017
Trivial performance boost by explicitly bypassing the implicit
locking of stdio.

This significantly affects common cases of `journalctl` usage:

 Before:

  # time ./journalctl -b -1 > /dev/null
   real    0m26.628s
   user    0m26.495s
   sys     0m0.125s

  # time ./journalctl -b -1 > /dev/null
   real    0m27.069s
   user    0m26.936s
   sys     0m0.134s

  # time ./journalctl -b -1 > /dev/null
   real    0m26.727s
   user    0m26.607s
   sys     0m0.119s

 After:

  # time ./journalctl -b -1 > /dev/null
   real    0m23.394s
   user    0m23.244s
   sys     0m0.142s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.283s
   user    0m23.160s
   sys     0m0.121s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.274s
   user    0m23.125s
   sys     0m0.144s

Fixes systemd#6341
vcaputo added a commit to vcaputo/systemd that referenced this issue Jul 17, 2017
Trivial performance boost by explicitly bypassing the implicit
locking of stdio.

This significantly affects common cases of `journalctl` usage:

 Before:

  # time ./journalctl -b -1 > /dev/null
   real    0m26.628s
   user    0m26.495s
   sys     0m0.125s

  # time ./journalctl -b -1 > /dev/null
   real    0m27.069s
   user    0m26.936s
   sys     0m0.134s

  # time ./journalctl -b -1 > /dev/null
   real    0m26.727s
   user    0m26.607s
   sys     0m0.119s

 After:

  # time ./journalctl -b -1 > /dev/null
   real    0m23.394s
   user    0m23.244s
   sys     0m0.142s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.283s
   user    0m23.160s
   sys     0m0.121s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.274s
   user    0m23.125s
   sys     0m0.144s

Fixes systemd#6341
vcaputo added a commit to vcaputo/systemd that referenced this issue Jul 17, 2017
Trivial performance boost by explicitly bypassing the implicit
locking of stdio.

This significantly affects common cases of `journalctl` usage:

 Before:

  # time ./journalctl -b -1 > /dev/null
   real    0m26.628s
   user    0m26.495s
   sys     0m0.125s

  # time ./journalctl -b -1 > /dev/null
   real    0m27.069s
   user    0m26.936s
   sys     0m0.134s

  # time ./journalctl -b -1 > /dev/null
   real    0m26.727s
   user    0m26.607s
   sys     0m0.119s

 After:

  # time ./journalctl -b -1 > /dev/null
   real    0m23.394s
   user    0m23.244s
   sys     0m0.142s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.283s
   user    0m23.160s
   sys     0m0.121s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.274s
   user    0m23.125s
   sys     0m0.144s

Fixes systemd#6341
poettering pushed a commit that referenced this issue Jul 17, 2017
Trivial performance boost by explicitly bypassing the implicit
locking of stdio.

This significantly affects common cases of `journalctl` usage:

 Before:

  # time ./journalctl -b -1 > /dev/null
   real    0m26.628s
   user    0m26.495s
   sys     0m0.125s

  # time ./journalctl -b -1 > /dev/null
   real    0m27.069s
   user    0m26.936s
   sys     0m0.134s

  # time ./journalctl -b -1 > /dev/null
   real    0m26.727s
   user    0m26.607s
   sys     0m0.119s

 After:

  # time ./journalctl -b -1 > /dev/null
   real    0m23.394s
   user    0m23.244s
   sys     0m0.142s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.283s
   user    0m23.160s
   sys     0m0.121s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.274s
   user    0m23.125s
   sys     0m0.144s

Fixes #6341
andir pushed a commit to andir/systemd that referenced this issue Sep 7, 2017
Trivial performance boost by explicitly bypassing the implicit
locking of stdio.

This significantly affects common cases of `journalctl` usage:

 Before:

  # time ./journalctl -b -1 > /dev/null
   real    0m26.628s
   user    0m26.495s
   sys     0m0.125s

  # time ./journalctl -b -1 > /dev/null
   real    0m27.069s
   user    0m26.936s
   sys     0m0.134s

  # time ./journalctl -b -1 > /dev/null
   real    0m26.727s
   user    0m26.607s
   sys     0m0.119s

 After:

  # time ./journalctl -b -1 > /dev/null
   real    0m23.394s
   user    0m23.244s
   sys     0m0.142s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.283s
   user    0m23.160s
   sys     0m0.121s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.274s
   user    0m23.125s
   sys     0m0.144s

Fixes systemd#6341
andir pushed a commit to andir/systemd that referenced this issue Sep 22, 2017
Trivial performance boost by explicitly bypassing the implicit
locking of stdio.

This significantly affects common cases of `journalctl` usage:

 Before:

  # time ./journalctl -b -1 > /dev/null
   real    0m26.628s
   user    0m26.495s
   sys     0m0.125s

  # time ./journalctl -b -1 > /dev/null
   real    0m27.069s
   user    0m26.936s
   sys     0m0.134s

  # time ./journalctl -b -1 > /dev/null
   real    0m26.727s
   user    0m26.607s
   sys     0m0.119s

 After:

  # time ./journalctl -b -1 > /dev/null
   real    0m23.394s
   user    0m23.244s
   sys     0m0.142s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.283s
   user    0m23.160s
   sys     0m0.121s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.274s
   user    0m23.125s
   sys     0m0.144s

Fixes systemd#6341
tblume pushed a commit to tblume/systemd-testsuite-suse that referenced this issue Aug 6, 2018
Trivial performance boost by explicitly bypassing the implicit
locking of stdio.

This significantly affects common cases of `journalctl` usage:

 Before:

  # time ./journalctl -b -1 > /dev/null
   real    0m26.628s
   user    0m26.495s
   sys     0m0.125s

  # time ./journalctl -b -1 > /dev/null
   real    0m27.069s
   user    0m26.936s
   sys     0m0.134s

  # time ./journalctl -b -1 > /dev/null
   real    0m26.727s
   user    0m26.607s
   sys     0m0.119s

 After:

  # time ./journalctl -b -1 > /dev/null
   real    0m23.394s
   user    0m23.244s
   sys     0m0.142s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.283s
   user    0m23.160s
   sys     0m0.121s

  # time ./journalctl -b -1 > /dev/null
   real    0m23.274s
   user    0m23.125s
   sys     0m0.144s

Fixes systemd/systemd#6341
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Development

No branches or pull requests

2 participants