FixedWindowRoller: rotate log files in a separate thread

[yakov-bakhmatov]

Compression of large files during log rotation may take several seconds. At this time, all threads writing logs are blocked, which can lead to undesirable delays.
The problem is resolved when the rotation is executed in a separate thread. Library users can enable new behavior using feature async_rotation.

[estk]

Hi @yakov-bakhmatov thanks for opening this PR! I'm just catching up from the holiday season but I should have some time to review this soon. One question I had: is there a benchmark that you have that demonstrated the delays?

Also, would you rebase on master?

[yakov-bakhmatov]

Hello, @estk

Thanks for a great library.

Benchmark code: https://github.com/yakov-bakhmatov/log4rs-benchmark

My results:

Office desktop, Windows, 4 cores, SSD

$ cargo --version
cargo 1.40.0 (bc8e4c8be 2019-11-22)

$ cargo run --release -- 2

2020-01-31 09:28:17.261 +05:00 INFO [log4rs_benchmark - thread #1] delay 359.995534ms
2020-01-31 09:28:17.261 +05:00 INFO [log4rs_benchmark - thread #0] delay 362.839576ms
2020-01-31 09:28:27.393 +05:00 INFO [log4rs_benchmark - thread #1] delay 330.208742ms
2020-01-31 09:28:27.393 +05:00 INFO [log4rs_benchmark - thread #0] delay 335.971146ms
2020-01-31 09:28:37.497 +05:00 INFO [log4rs_benchmark - thread #0] delay 330.390086ms
2020-01-31 09:28:37.497 +05:00 INFO [log4rs_benchmark - thread #1] delay 340.064121ms
2020-01-31 09:28:47.583 +05:00 INFO [log4rs_benchmark - thread #0] delay 333.97305ms
2020-01-31 09:28:47.583 +05:00 INFO [log4rs_benchmark - thread #1] delay 343.171097ms
2020-01-31 09:28:57.748 +05:00 INFO [log4rs_benchmark - thread #1] delay 336.176604ms
2020-01-31 09:28:57.748 +05:00 INFO [log4rs_benchmark - thread #0] delay 338.38181ms
^C

$ ls -l --full-time logs
total 16804
-rwxrwxr-x+ 1 bakhmatov Domain Users   366842 2020-01-31 09:28:57.748686000 +0500 log.0.gz
-rwxrwxr-x+ 1 bakhmatov Domain Users   367379 2020-01-31 09:28:47.568354700 +0500 log.1.gz
-rwxrwxr-x+ 1 bakhmatov Domain Users   367182 2020-01-31 09:28:37.481624600 +0500 log.2.gz
-rwxrwxr-x+ 1 bakhmatov Domain Users   366822 2020-01-31 09:28:27.378294200 +0500 log.3.gz
-rwxrwxr-x+ 1 bakhmatov Domain Users   366421 2020-01-31 09:28:17.230762100 +0500 log.4.gz
-rwxrwxr-x+ 1 bakhmatov Domain Users 15363887 2020-01-31 09:28:59.184904500 +0500 log.log

$ rm logs/*

$ cargo run --release --features=async_rotation -- 2
^C

$ ls -l --full-time logs
total 73116
-rwxrwxr-x+ 1 bakhmatov Domain Users   363331 2020-01-31 09:30:39.077278000 +0500 log.0.gz
-rwxrwxr-x+ 1 bakhmatov Domain Users   363693 2020-01-31 09:30:28.550742000 +0500 log.1.gz
-rwxrwxr-x+ 1 bakhmatov Domain Users   363973 2020-01-31 09:30:18.121807600 +0500 log.2.gz
-rwxrwxr-x+ 1 bakhmatov Domain Users   364699 2020-01-31 09:30:07.650671700 +0500 log.3.gz
-rwxrwxr-x+ 1 bakhmatov Domain Users 73407411 2020-01-31 09:30:45.932766500 +0500 log.log

Linux server, 12 cores, SSD

$ cargo --version
cargo 1.39.0 (1c6ec66d5 2019-09-30)

$ uptime
 05:41:43 up 55 days, 21:00,  5 users,  load average: 1.37, 2.45, 2.30

$ cargo run --release -- 2
    Finished release [optimized] target(s) in 0.02s
     Running `target/release/log4rs-benchmark 2`
2020-01-31 05:41:53.069 +01:00 INFO [log4rs_benchmark - thread #1] delay 241.853587ms
2020-01-31 05:41:53.069 +01:00 INFO [log4rs_benchmark - thread #0] delay 243.969526ms
2020-01-31 05:41:59.117 +01:00 INFO [log4rs_benchmark - thread #1] delay 245.190303ms
2020-01-31 05:41:59.117 +01:00 INFO [log4rs_benchmark - thread #0] delay 247.404703ms
2020-01-31 05:42:05.178 +01:00 INFO [log4rs_benchmark - thread #0] delay 249.418877ms
2020-01-31 05:42:05.178 +01:00 INFO [log4rs_benchmark - thread #1] delay 252.435502ms
2020-01-31 05:42:11.709 +01:00 INFO [log4rs_benchmark - thread #0] delay 264.485327ms
2020-01-31 05:42:11.709 +01:00 INFO [log4rs_benchmark - thread #1] delay 265.403713ms
2020-01-31 05:42:17.817 +01:00 INFO [log4rs_benchmark - thread #1] delay 243.694014ms
2020-01-31 05:42:17.817 +01:00 INFO [log4rs_benchmark - thread #0] delay 255.612344ms
^C

$ ls -l --full-time logs
total 44420
-rw-rw-r-- 1 bakhmatov bakhmatov   373764 2020-01-31 05:42:17.801880746 +0100 log.0.gz
-rw-rw-r-- 1 bakhmatov bakhmatov   375939 2020-01-31 05:42:11.693913648 +0100 log.1.gz
-rw-rw-r-- 1 bakhmatov bakhmatov   375796 2020-01-31 05:42:05.165948651 +0100 log.2.gz
-rw-rw-r-- 1 bakhmatov bakhmatov   377581 2020-01-31 05:41:59.101981014 +0100 log.3.gz
-rw-rw-r-- 1 bakhmatov bakhmatov   371157 2020-01-31 05:41:53.054013145 +0100 log.4.gz
-rw-rw-r-- 1 bakhmatov bakhmatov 43601504 2020-01-31 05:42:19.821869833 +0100 log.log

$ uptime
 05:43:02 up 55 days, 21:02,  5 users,  load average: 1.83, 2.35, 2.27

$ rm logs/*
$ cargo run --release --features=async_rotation -- 2
    Finished release [optimized] target(s) in 0.02s
     Running `target/release/log4rs-benchmark 2`
^C

$ ls -l --full-time logs
total 15072
-rw-rw-r-- 1 bakhmatov bakhmatov   376143 2020-01-31 05:44:30.205134792 +0100 log.0.gz
-rw-rw-r-- 1 bakhmatov bakhmatov   371912 2020-01-31 05:44:24.561167761 +0100 log.1.gz
-rw-rw-r-- 1 bakhmatov bakhmatov   371120 2020-01-31 05:44:19.313198330 +0100 log.2.gz
-rw-rw-r-- 1 bakhmatov bakhmatov   376316 2020-01-31 05:44:14.625225569 +0100 log.3.gz
-rw-rw-r-- 1 bakhmatov bakhmatov   373472 2020-01-31 05:44:08.893258779 +0100 log.4.gz
-rw-rw-r-- 1 bakhmatov bakhmatov 13554372 2020-01-31 05:44:30.605132453 +0100 log.log

$ uptime
 05:44:40 up 55 days, 21:03,  5 users,  load average: 3.71, 2.93, 2.49

Ancient laptop, Linux, 2 cores, HDD 5400 rpm

$ cargo --version
cargo 1.40.0 (bc8e4c8be 2019-11-22)


$ cargo run --release -- 2

2020-01-30 23:52:31.815 +05:00 INFO [log4rs_benchmark - thread #0] delay 2.056480279s
2020-01-30 23:52:31.816 +05:00 INFO [log4rs_benchmark - thread #1] delay 2.046231827s
2020-01-30 23:52:53.315 +05:00 INFO [log4rs_benchmark - thread #0] delay 989.154971ms
2020-01-30 23:52:53.315 +05:00 INFO [log4rs_benchmark - thread #1] delay 983.107738ms
2020-01-30 23:53:14.263 +05:00 INFO [log4rs_benchmark - thread #1] delay 969.487183ms
2020-01-30 23:53:14.270 +05:00 INFO [log4rs_benchmark - thread #0] delay 981.659052ms
2020-01-30 23:53:35.568 +05:00 INFO [log4rs_benchmark - thread #0] delay 978.220795ms
2020-01-30 23:53:35.577 +05:00 INFO [log4rs_benchmark - thread #1] delay 990.864697ms
2020-01-30 23:53:47.669 +05:00 INFO [log4rs_benchmark - thread #1] delay 371.398899ms
2020-01-30 23:53:47.673 +05:00 INFO [log4rs_benchmark - thread #0] delay 375.466999ms
2020-01-30 23:53:57.759 +05:00 INFO [log4rs_benchmark - thread #1] delay 994.33366ms
2020-01-30 23:53:57.760 +05:00 INFO [log4rs_benchmark - thread #0] delay 991.529774ms
2020-01-30 23:54:19.228 +05:00 INFO [log4rs_benchmark - thread #1] delay 986.578621ms
2020-01-30 23:54:19.228 +05:00 INFO [log4rs_benchmark - thread #0] delay 986.649779ms
^C

$ ls -l --full-time logs
-rw-rw-r-- 1 yakov yakov   405581 2020-01-30 23:54:19.188987110 +0500 log.0.gz
-rw-rw-r-- 1 yakov yakov   406745 2020-01-30 23:53:57.725869767 +0500 log.1.gz
-rw-rw-r-- 1 yakov yakov   403866 2020-01-30 23:53:35.526602361 +0500 log.2.gz
-rw-rw-r-- 1 yakov yakov   403805 2020-01-30 23:53:14.223101090 +0500 log.3.gz
-rw-rw-r-- 1 yakov yakov   406033 2020-01-30 23:52:53.275360546 +0500 log.4.gz
-rw-rw-r-- 1 yakov yakov 20771104 2020-01-30 23:54:23.400796160 +0500 log.log

$ rm logs/*

$ cargo run --release --features=async_rotation -- 2

2020-01-31 00:28:42.233 +05:00 INFO [log4rs_benchmark - thread #1] delay 64.000435ms
2020-01-31 00:29:43.472 +05:00 INFO [log4rs_benchmark - thread #1] delay 285.146841ms
2020-01-31 00:29:43.474 +05:00 INFO [log4rs_benchmark - thread #0] delay 287.06181ms
2020-01-31 00:30:09.645 +05:00 INFO [log4rs_benchmark - thread #1] delay 56.021344ms
2020-01-31 00:30:37.458 +05:00 INFO [log4rs_benchmark - thread #0] delay 576.936086ms
2020-01-31 00:30:37.466 +05:00 INFO [log4rs_benchmark - thread #1] delay 595.695804ms
^C

$ ls -l --full-time logs
-rw-rw-r-- 1 yakov yakov   425858 2020-01-31 00:30:40.207438919 +0500 log.0.gz
-rw-rw-r-- 1 yakov yakov   426752 2020-01-31 00:30:11.968207939 +0500 log.1.gz
-rw-rw-r-- 1 yakov yakov   425545 2020-01-31 00:29:45.372906697 +0500 log.2.gz
-rw-rw-r-- 1 yakov yakov   426246 2020-01-31 00:29:17.829601349 +0500 log.3.gz
-rw-rw-r-- 1 yakov yakov   425475 2020-01-31 00:28:50.970247145 +0500 log.4.gz
-rw-rw-r-- 1 yakov yakov 89302356 2020-01-31 00:30:59.554897439 +0500 log.log


$ cargo run --release --features=async_rotation -- 1
^C

works without delays

[yakov-bakhmatov]

The benchmark is configured for a maximum log file size of 100 MB.
On production, we use 1GB logs with a rotation of 100 files. This causes delays of 2 to 5 seconds or more during rotation.

[estk]

First thing, would you rebase again? Sorry, somehow I didnt have CI set up correctly and it didnt run.

So I started peeking around and this is awesome!
I instrumented the roll method and my results are below. What is really incredible to me is that logging is not buffered. I need to do some more reading, but this has the potential to seriously increase the performance of a LOT of applications. Thanks for raising this!

removal elapsed 84ns
temp file elapsed 276.17µs
create parent elapsed 299.736µs
parent varies elapsed 303.752µs
move all elapsed 1.239617ms
compress elapsed 266.951174ms
2020-01-31 12:05:47.549 -08:00 INFO [log4rs_benchmark - thread #1] delay 267.616614ms
2020-01-31 12:05:47.550 -08:00 INFO [log4rs_benchmark - thread #0] delay 281.076589ms

[yakov-bakhmatov]

Sorry for the delay in answering.
I rebased the branch.

[estk]

@yakov-bakhmatov Thanks!

[estk]

@yakov-bakhmatov also, if you're interested, I'd love to add that code that showed the issue as a bench test. Would you be interested in submitting another pr? Or do you mind if I lift that code?