SpriteOvO / spdlog-rs

Fast, highly configurable Rust logging crate
https://crates.io/crates/spdlog-rs
Apache License 2.0
109 stars 12 forks source link

Flush `AsyncPoolSink` on the current thread if tearing down #66

Closed SpriteOvO closed 7 months ago

SpriteOvO commented 7 months ago

Fixes #64.

I've figured out what happened with this bug. There are 2 things went wrong:

  1. crossbeam uses thread-local internally, which is not supported in atexit callback. This is the reason of panic use of std::thread::current() is not possible after the thread's local data has been destroyed.

    Fixed it by directly flushing the sinks on the current thread if the program is tearing down.

  2. The default logger just gets flushed in atexit callback, but not dropped. This results in the program not waiting for the asynchronous thread to finish but simply exiting after the task has been sent.

    ~Fixed it by changing the global variable with Option<T>, so that we could explicitly drop the default logger in atexit callback.~ Reverted, paragraph 3 addresses the problem.

  3. UPDATE: Destroying the thread pool before the final flush is required as well, otherwise pending log tasks may be lost.

    Fixing this by ~adding a RwLock to ThreadPool~ and explicitly destroy the thread pool before the final flush, but needs to be benchmarked to see if the performance change is acceptable.

    UPDATE: Changed to ArcSwapOption for a better performance.


Related discussion #63 #65, CC @MrCoco5921 @Bestfast

SpriteOvO commented 7 months ago

Benchmark results

On ArchLinux, commit e1f9a068b1c28dcd223ba121df7853f9dc263e65

Before

[info] --------------------------------------------
[info] Messages     : 1000000
[info] Threads      : 10
[info] Queue        : 8192 slots
[info] Queue memory : 8192 x 120 = 960 KB
[info] Total iters  : 3
[info] --------------------------------------------
[info] 
[info] ********************************************
[info] Queue Overflow Policy: Block
[info] ********************************************
[info] Elapsed: 0.355563435 secs         2812437/sec
[info] Elapsed: 0.392709661 secs         2546410/sec
[info] Elapsed: 0.350509562 secs         2852989/sec
[info] 
[info] ********************************************
[info] Queue Overflow Policy: DropIncoming
[info] ********************************************
[info] Elapsed: 0.080866536 secs         12366054/sec
[info] Elapsed: 0.077687493 secs         12872084/sec
[info] Elapsed: 0.075060614 secs         13322566/sec

After

[info] --------------------------------------------
[info] Messages     : 1000000
[info] Threads      : 10
[info] Queue        : 8192 slots
[info] Queue memory : 8192 x 120 = 960 KB
[info] Total iters  : 3
[info] --------------------------------------------
[info] 
[info] ********************************************
[info] Queue Overflow Policy: Block
[info] ********************************************
[info] Elapsed: 0.417248511 secs         2396653/sec
[info] Elapsed: 0.434975067 secs         2298982/sec
[info] Elapsed: 0.406287435 secs         2461311/sec
[info] 
[info] ********************************************
[info] Queue Overflow Policy: DropIncoming
[info] ********************************************
[info] Elapsed: 0.123620255 secs         8089289/sec
[info] Elapsed: 0.104598975 secs         9560323/sec
[info] Elapsed: 0.107852031 secs         9271962/sec

Guess the main reason for the worse is the new RwLock added to ThreadPool, I will try to see if there is a solution with better performance.

SpriteOvO commented 7 months ago

If we use ArcSwapOption instead of RwLock, we could get a nice performance - almost no impact.

[info] --------------------------------------------
[info] Messages     : 1000000
[info] Threads      : 10
[info] Queue        : 8192 slots
[info] Queue memory : 8192 x 120 = 960 KB
[info] Total iters  : 3
[info] --------------------------------------------
[info] 
[info] ********************************************
[info] Queue Overflow Policy: Block
[info] ********************************************
[info] Elapsed: 0.339878523 secs         2942227/sec
[info] Elapsed: 0.388267234 secs         2575545/sec
[info] Elapsed: 0.357158248 secs         2799879/sec
[info] 
[info] ********************************************
[info] Queue Overflow Policy: DropIncoming
[info] ********************************************
[info] Elapsed: 0.071169735 secs         14050916/sec
[info] Elapsed: 0.075486378 secs         13247423/sec
[info] Elapsed: 0.074043964 secs         13505489/sec
SpriteOvO commented 7 months ago

Reverted commit Drop the default logger in atexit callback. We have explicitly destroyed the thread pool, so no longer need the drop function to wait for tasks to complete. Let's minimize the changes, keep the rule in Rust that global variables don't get dropped.