Logging continuously tries to delete logs

[zwoop]

I noticed the CPU on the Docs machine was constantly running at ~15% CPU, which is not normal. Looking at perf top, it seems we're stuck trying to delete logs, which is an area where we have made lots of changes for 9.0.0, and recently as well.

Overhead  Shared Object          Symbol
   5.29%  traffic_server         [.] std::unique_ptr<LogDeleteCandidate, std::default_delete<LogDeleteCandidate> >::get
   5.29%  traffic_server         [.] std::unique_ptr<LogDeleteCandidate, std::default_delete<LogDeleteCandidate> >::operator->
   4.91%  traffic_server         [.] std::__uniq_ptr_impl<LogDeleteCandidate, std::default_delete<LogDeleteCandidate> >::_M_ptr
   4.07%  traffic_server         [.] std::__get_helper<0ul, LogDeleteCandidate*, std::default_delete<LogDeleteCandidate> >
   3.87%  traffic_server         [.] std::get<0ul, LogDeleteCandidate*, std::default_delete<LogDeleteCandidate> >
   3.46%  traffic_server         [.] std::_Tuple_impl<0ul, LogDeleteCandidate*, std::default_delete<LogDeleteCandidate> >::_M_head
   3.07%  traffic_server         [.] RolledLogDeleter::consider_for_candidacy(std::basic_string_view<char, std::char_traits<char> >, long, l
   2.58%  traffic_server         [.] std::_Head_base<0ul, LogDeleteCandidate*, false>::_M_head
   2.32%  traffic_server         [.] __gnu_cxx::__normal_iterator<std::unique_ptr<LogDeleteCandidate, std::default_delete<LogDeleteCandidate
   2.16%  traffic_server         [.] __gnu_cxx::__normal_iterator<std::unique_ptr<LogDeleteCandidate, std::default_delete<LogDeleteCandidate
   2.01%  traffic_server         [.] std::__uniq_ptr_impl<LogDeleteCandidate, std::default_delete<LogDeleteCandidate> >::_M_ptr
   2.00%  traffic_server         [.] std::_Tuple_impl<0ul, LogDeleteCandidate*, std::default_delete<LogDeleteCandidate> >::_M_head
   1.97%  traffic_server         [.] __gnu_cxx::__normal_iterator<std::unique_ptr<LogDeleteCandidate, std::default_delete<LogDeleteCandidate
   1.94%  traffic_server         [.] std::get<0ul, LogDeleteCandidate*, std::default_delete<LogDeleteCandidate> >
   1.79%  traffic_server         [.] std::unique_ptr<LogDeleteCandidate, std::default_delete<LogDeleteCandidate> >::release
   1.78%  traffic_server         [.] std::__uniq_ptr_impl<LogDeleteCandidate, std::default_delete<LogDeleteCandidate> >::_M_deleter
   1.71%  traffic_server         [.] std::unique_ptr<LogDeleteCandidate, std::default_delete<LogDeleteCandidate> >::get_deleter
   1.67%  traffic_server         [.] __gnu_cxx::__ops::_Iter_comp_iter<RolledLogDeleter::consider_for_candidacy(std::basic_string_view<char,
   1.60%  traffic_server         [.] std::__get_helper<0ul, LogDeleteCandidate*, std::default_delete<LogDeleteCandidate> >
   1.53%  traffic_server         [.] std::__adjust_heap<__gnu_cxx::__normal_iterator<std::unique_ptr<LogDeleteCandidate, std::default_delete
   1.49%  traffic_server         [.] std::unique_ptr<LogDeleteCandidate, std::default_delete<LogDeleteCandidate> >::operator=
   1.44%  traffic_server         [.] std::_Tuple_impl<1ul, std::default_delete<LogDeleteCandidate> >::_M_head
   1.43%  traffic_server         [.] std::_Head_base<0ul, LogDeleteCandidate*, false>::_M_head
   1.43%  traffic_server         [.] std::__get_helper<1ul, std::default_delete<LogDeleteCandidate>>
   1.35%  traffic_server         [.] std::forward<std::default_delete<LogDeleteCandidate> >
   1.27%  traffic_server         [.] std::get<1ul, LogDeleteCandidate*, std::default_delete<LogDeleteCandidate> >
   1.23%  libtscore.so.9.0.0     [.] freelist_free
   1.17%  traffic_server         [.] std::swap<LogDeleteCandidate*>
   1.07%  traffic_server         [.] std::_Head_base<1ul, std::default_delete<LogDeleteCandidate>, true>::_M_head

[bneradt]

I've reproduced this in our prod sim by creating 10,000 files in the log directory that look like delete candidates. They are empty, so not much space is actually used, but they are inspected on each iteration. When the check is made on each iteration, I see a CPU spike.

The candidates are stored as unique_ptr's here:
https://github.com/apache/trafficserver/blob/master/proxy/logging/RolledLogDeleter.h#L71

I'll see whether I can decrease the spike of CPU by implementing these candidates on the stack instead of via unique_ptr's.

[bneradt]

This actually isn't due to the unique_ptrs or these objects being created on the heap. This is due to sort being called for each candidate (1000 files in the Doc tests case):

trafficserver/proxy/logging/RolledLogDeleter.cc

Line 90 in c23c5a4

std::sort(

That should only be called once if we decide to remove candidates. I'll get a PR up shortly.