Removing SegmentProfiler?

[awelzel]

Running zeek -r against a pcap with 128 connections and ~29k orig and ~22k resp packetes and 20k raised events per connection for a simple and fast BinPac analyzer shows the SegmentProfiler constructor as the 4th hottest function.

I wonder if SegmentProfiler these days has basically been replaced by "perf" or "instruments" or other tools and maybe we could just drop it? Also, if we need custom profiling within Zeek, maybe it would be nice to look into USDT - Userland Statically-Defined Tracing and add some at crucial points [1,2].

If we don't want to ditch it, maybe we can switch it to something more efficient similar to how Spicy's profiling does it, I suspect it's actually the 144bytes rusage initialized to 0 that are so expensive.

[1] https://www.brendangregg.com/blog/2015-06-28/linux-ftrace-uprobe.html
[2] https://lwn.net/Articles/753601/
Link to pcap: https://github.com/awelzel/pcaps/blob/master/bench-traffic-128-10000.pcap.zst

[awelzel]

I suspect it's actually the 144bytes rusage initialized to 0 that are so expensive.

Indeed, looking at EventMgr::Drain, 43% of self-time is spent on initializing 144 bytes to 0 via rep stos (8*0x12(rcx)).

$ perf annotate zeek::EventMgr::Drain
    5.66 :   ced2a9: mov    $0x12,%ecx                                                                                                                                                         
    0.00 :   ced2ae: mov    %rax,-0xd0(%rbp)                                                                                                                                                   
    0.00 :   ced2b5: xor    %eax,%eax                                                    
         : 53     std::__shared_ptr<zeek::detail::SegmentStatsReporter, (__gnu_cxx::_Lock_policy)2>::__shared_ptr(std::__shared_ptr<zeek::detail::SegmentStatsReporter, (__gnu_cxx::_Lock_policy)2>&&):                                                                                                                                                                                       
         : 1162   { }                                                                          
         :                                                                                     
         : 1164   __shared_ptr(__shared_ptr&& __r) noexcept                                    
         : 1165   : _M_ptr(__r._M_ptr), _M_refcount()                                                                                                                                          
    0.00 :   ced2b7: mov    %rdx,-0xe0(%rbp)                                                                                                                                                   
         : 1167   zeek::detail::SegmentProfiler::SegmentProfiler(std::shared_ptr<zeek::detail::SegmentStatsReporter>, char const*):                                                            
    0.00 :   ced2be: movq   $0x0,-0xc8(%rbp)                                        
   43.43 :   ced2c9: rep stos %rax,%es:(%rdi) 

After patching SegmentProfiler to not initialize initial_rusage, runtime for above pcap improves quite a bit:

Command	Mean [s]	Min [s]	Max [s]	Relative
taskset -c 0 /opt/zeek-dev-prod/bin/zeek -D -C -b protocols/bench -r issues/bench-traffic/bench-traffic-128-10000.pcap Bench::t=binpac	9.972 ± 0.077	9.881	10.115	1.06 ± 0.01
taskset -c 0 /home/awelzel/corelight-oss/zeek/prod-build/src/zeek -D -C -b protocols/bench -r issues/bench-traffic/bench-traffic-128-10000.pcap Bench::t=binpac	9.387 ± 0.047	9.300	9.451	1.00

I'll add that to #3483.

Whether or not to keep SegmentProfiler at all would still be good to discuss.

[JustinAzoff]

+1 for removing it. I have no idea how to use SegmentProfiler and not sure if it's been used in decades.

[timwoj]

https://lwn.net/Articles/753601/

@0xxon Didn't you have a prototype at one point of adding dtrace/bpftrace points to the code?

[ckreibich]

Looks like this is indeed quite dated, @rsmmr and Jon originally worked on it around 2010. It's controlled by the script layer — try running with misc/profiling segment_profiling=T and look at the resulting prof.log. You'll see stuff like

1071580904.891921 segment-dispatching-packet dt=0.000237 dmem=0
1071580904.891921 segment-Broker::__flush_logs dt=0.000001 dmem=0
1071580904.891921 segment-/home/christian/inst/opt/zeek/share/zeek/base/frameworks/broker/./main.zeek:587 dt=0.000011 dmem=0
1071580904.891921 segment-/home/christian/inst/opt/zeek/share/zeek/base/frameworks/broker/./main.zeek:455 dt=0.000021 dmem=0
1071580904.891921 segment-get_net_stats dt=0.000002 dmem=0
1071580904.891921 segment-/home/christian/inst/opt/zeek/share/zeek/base/misc/find-checksum-offloading.zeek:24 dt=0.000034 dmem=0
1071580904.891921 segment-/home/christian/inst/opt/zeek/share/zeek/base/frameworks/telemetry/./main.zeek:303 dt=0.000000 dmem=0
1071580904.891921 segment-/home/christian/inst/opt/zeek/share/zeek/base/frameworks/telemetry/./main.zeek:577 dt=0.000009 dmem=0
1071580904.891921 segment-/home/christian/inst/opt/zeek/share/zeek/base/frameworks/packet-filter/./main.zeek:158 dt=0.000004 dmem=0
1071580904.891921 segment-/home/christian/inst/opt/zeek/share/zeek/base/bif/event.bif.zeek:117 dt=0.000005 dmem=0
1071580904.891921 segment-draining-events dt=0.000134 dmem=0
1071580904.891921 segment-draining-events dt=0.000001 dmem=0
1071580905.035577 segment-expiring-timers dt=0.000138 dmem=0
1071580905.035577 segment-dispatching-packet dt=0.000056 dmem=0
1071580905.035577 segment-/home/christian/inst/opt/zeek/share/zeek/base/bif/plugins/./Zeek_TCP.events.bif.zeek:53 dt=0.000019 dmem=0
1071580905.035577 segment-draining-events dt=0.000038 dmem=0

It's only very lightly used. I thought I spotted a recent instance in the packet analyzer framework but it looks like it just ended up there as part of migrating code. It doesn't seem as valuable as the other perf content. The ability to place the profiler into specific scopes is nice since it keeps potential workflows within Zeek as opposed to, say, perf. But I see no test cases for any of this, and it'd need modernizing. It's also little code overall, and there's virtually nothing in NEWS/CHANGES.

Without any objections I'll vote to remove it all outright. But first:

@vpax I know that profiling is of great interest to you — this isn't what you're working with, is it?

@rsmmr — any history lessons for this one? :-)

[vpax]

@ckreibich no, this isn't part of the profiling stuff of interest for me - thanks for checking!

[ckreibich]

Robin also confirms he doesn't use it, so it looks safe to discard.

[awelzel]

It's been removed.