::run
2.67% bro libc-2.17.so [.] \_\_GI\_\_\_libc\_nanosleep
1.98% bro libtcmalloc.so.4.4.5 [.] operator new[]
1.79% bro libc-2.17.so [.] \_\_sleep
1.68% bro libtcmalloc.so.4.4.5 [.] tc\_deletearray\_nothrow
1.47% bro libc-2.17.so [.] \_\_libc\_disable\_asynccancel
1.28% bro libstdc++.so.6.0.19 [.] std::this\_thread::\_\_sleep\_for
1.10% bro libc-2.17.so [.] usleep
1.05% bro bro [.] ones\_complement\_checksum
I haven't noticed a huge difference on a real multi process cluster, at least not a 30x change, so this is odd that pcap processing is so much slower.
Especially since broker should be completely disabled when pcap files are being read and caf shouldn't even be doing anything.
---
### Author:  [@Jon\_Siwek](https://community.zeek.org/u/Jon_Siwek)
#### Post date: [June 6, 2018, 9:50pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/3 "2018-06-06T21:50:40Z")
> Is the Bro development team still optimizing the Broker/Actor framework?
Yes, in the sense that optimizations will be done according to
feedback. No, in the sense that there was no one actively looking
into it at the moment you asked.
> It might be helpful to have a way to disable Broker for those of us who haven’t migrated to it yet.
That's unlikely at this point as scripts have been completely ported
to Broker now and usages of the old communication system completely
removed from them. No simple switch to it back, so your feedback is
especially important/helpful.
> # ~1GB file time (old)
>
> $ time /hostname/bro-devel/bin/bro -r 20180606-1049-prodfilers-truncated\_00000\_20180606104904.pcap master.bro
>
> real 0m2.294s
>
> user 0m1.862s
>
> sys 0m0.385s
>
> # ~1GB file time (new)
>
> $ time /hostname/bro-devel/bin/bro -r 20180606-1049-prodfilers-truncated\_00000\_20180606104904.pcap master.bro
>
> real 1m11.458s
>
> user 0m58.933s
>
> sys 1m34.074s
Try pulling in the change I just did at [1], which was a big part of
the problem in my own test:
# 2.5.3
$ time bro -r 2009-M57-day11-18.trace
real 0m16.187s
user 0m16.312s
sys 0m1.865s
# master before [1]
$ time bro -r ../testing/external/bro-testing/Traces/2009-M57-day11-18.trace
real 1m31.434s
user 1m44.925s
sys 1m4.947s
# master after [1]
$ time bro -r 2009-M57-day11-18.trace
real 0m24.595s
user 0m25.574s
sys 0m5.816s
- Jon
[1] [Improve Broker performance · bro/bro@9822fc2 · GitHub](https://github.com/bro/bro/commit/9822fc252d5e92208704df4a388ea31989869499)
---
### Author:  [@Jon\_Siwek](https://community.zeek.org/u/Jon_Siwek)
#### Post date: [June 6, 2018, 10:05pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/4 "2018-06-06T22:05:57Z")
It's not that simple.
You could think of broker being enabled in this case of simply reading
a pcap because it was querying the library for whether there were any
peers (and that was actually a at least part of the perf. problem).
Beyond that, you can still think of broker being enabled when you're
reading a pcap and you are also using data stores (which the Known\*
scripts in Bro now do by default). Communication with a local master
data store is still asynchronous communication (with local
threads/actors) that ends up going through CAF messaging. There's
also essentially a per-packet synchronization being done between Bro
and Broker/CAF now to ensure that this type of asynchronous workload
ends up producing the same results between any given Bro run. So
there's now also that bit of extra overhead in pcap processing.
- Jon
---
### Author:  [@robin](https://community.zeek.org/u/robin)
#### Post date: [June 7, 2018, 5:21pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/5 "2018-06-07T17:21:54Z")
Hmm, I'm still seeing much larger runtimes on that M57 trace using our
test configuration, even with yesterday's change:
; Master, pre-Broker
# zcat 2009-M57-day11-18.trace.gz | time bro -r - tests/m57-long.bro
73.72user 7.90system 1:06.53elapsed 122%CPU (0avgtext+0avgdata 199092maxresident)
; Current master
# zcat 2009-M57-day11-18.trace.gz | time bro -r - tests/m57-long.bro
2191.59user 1606.69system 12:39.92elapsed 499%CPU (0avgtext+0avgdata 228400maxresident)
Bro must still be blocking somewhere when reading from trace files.
Robin
---
### Author:  [@Jon\_Siwek](https://community.zeek.org/u/Jon_Siwek)
#### Post date: [June 7, 2018, 10:05pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/6 "2018-06-07T22:05:33Z")
Thanks, if you pull master changes [1] again there's likely some improvement.
You can also try comparing the timing of:
# zcat 2009-M57-day11-18.trace.gz | time bro -r - tests/m57-long.bro
Known::use\_host\_store=F Known::use\_service\_store=F
Known::use\_cert\_store=F
With that, I get the same timings as from before pre-Broker. At least
a good chunk of the difference when using data stores is that, for
every query, Bro will immediately block until getting a response back
from the data store thread/actor. Not doing this type of synchronous
data store access when reading pcaps leads to the possibility of
results differing between runs (and I recall such differences being
likely from experience in running the unit test suite).
- Jon
[1] [https://github.com/bro/broker/commit/9b56fea4999d4e11a5cd2caaafd934759015fab5](https://github.com/bro/broker/commit/9b56fea4999d4e11a5cd2caaafd934759015fab5)
---
### Author:  [@robin](https://community.zeek.org/u/robin)
#### Post date: [June 8, 2018, 3:23pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/7 "2018-06-08T15:23:47Z")
> Thanks, if you pull master changes [1] again there's likely some improvement.
Yeah, a little bit, not much though.
> # zcat 2009-M57-day11-18.trace.gz | time bro -r - tests/m57-long.bro
> Known::use\_host\_store=F Known::use\_service\_store=F
> Known::use\_cert\_store=F
That indeed gets it way down, though still not back to the same level
on my box:
170.49user 58.14system 1:55.94elapsed 197%CPU
(pre-master: 73.72user 7.90system 1:06.53elapsed 122%CPU)
Are there more places where Bro's waiting for Broker in pcap mode?
> With that, I get the same timings as from before pre-Broker. At least
> a good chunk of the difference when using data stores is that, for
> every query, Bro will immediately block until getting a response back
> from the data store thread/actor.
Yeah, I remember that discussion. It's the trade-off between
performance and consistency. Where's the code that's doing this
blocking? Would it be possible to not block right away, but sync up
with Broker when events are flushed the next time? (Like we had
discussed before as a general mechanism for making async operations
consistent)
Robin
---
### Author:  [@Jon\_Siwek](https://community.zeek.org/u/Jon_Siwek)
#### Post date: [June 8, 2018, 5:16pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/8 "2018-06-08T17:16:41Z")
> \> # zcat 2009-M57-day11-18.trace.gz | time bro -r - tests/m57-long.bro
> \> Known::use\_host\_store=F Known::use\_service\_store=F
> \> Known::use\_cert\_store=F
>
> That indeed gets it way down, though still not back to the same level
> on my box:
>
> 170.49user 58.14system 1:55.94elapsed 197%CPU
>
> (pre-master: 73.72user 7.90system 1:06.53elapsed 122%CPU)
Just double-checking: same configure/build flags were used between the two?
Here's the more precise results I got from running on a macOS and Linux system:
# Linux master (b51e6f3) --build-type=debug
$ export BROPATH=$BROPATH:../testing/external/scripts; time bro -r
2009-M57-day11-18.trace test-all-policy testing-setup
real 0m32.572s
user 0m40.926s
sys 0m7.873s
# Linux master (b51e6f3) --build-type=debug
$ export BROPATH=$BROPATH:../testing/external/scripts; time bro -r
2009-M57-day11-18.trace test-all-policy testing-setup
Known::use\_host\_store=F Known::use\_cert\_store=F
Known::use\_service\_store=F
real 0m25.603s
user 0m23.311s
sys 0m7.952s
# Linux pre-broker (7a6f502) --build-type=debug
$ export BROPATH=$BROPATH:../testing/external/scripts; time bro -r
2009-M57-day11-18.trace test-all-policy testing-setup
real 0m24.785s
user 0m21.230s
sys 0m8.341s
# macOS master (b51e6f3) --build-type=debug
$ export BROPATH=$BROPATH:../testing/external/scripts; time bro -r
2009-M57-day11-18.trace test-all-policy testing-setup.bro
real 0m38.775s
user 0m42.365s
sys 0m8.950s
# macOS master (b51e6f3) --build-type=debug
$ export BROPATH=$BROPATH:../testing/external/scripts; time bro -r
2009-M57-day11-18.trace test-all-policy testing-setup.bro
Known::use\_host\_store=F Known::use\_cert\_store=F
Known::use\_service\_store=F
real 0m32.975s
user 0m33.774s
sys 0m4.409s
# macOS pre-broker (7a6f502) --build-type=debug
$ export BROPATH=$BROPATH:../testing/external/scripts; time bro -r
2009-M57-day11-18.trace test-all-policy testing-setup.bro
real 0m30.785s
user 0m31.840s
sys 0m3.788s
> Are there more places where Bro's waiting for Broker in pcap mode?
Not that I can think of.
> Yeah, I remember that discussion. It's the trade-off between
> performance and consistency. Where's the code that's doing this
> blocking?
I just know that Manager::AdvanceTime() and also
Manager::TrackStoreQuery() -\> FlushPendingQueries() can block/spin
waiting on actor/threading in pcap mode.
> Would it be possible to not block right away, but sync up
> with Broker when events are flushed the next time? (Like we had
> discussed before as a general mechanism for making async operations
> consistent)
I think the way to make an async operation most consistent is to model
it as a synchronous operation? That's what I'm doing now at least,
and if I try moving FlushPendingQueries() to later (before the
AdvanceTime() call) in an attempt to possibly have more queries in the
queue/buffer, I get the external test suites failing. At least on my
own test systems, I don't have much performance to recover by going
this route anyway, so maybe we need to dig more into why your results
are different. Only thing I'm thinking is that your test system maybe
does a poorer job of scheduling the right thread to run in order for
the FlushPendingQueries() spin-loop to actually finish.
- Jon
---
### Author:  [@Jon\_Siwek](https://community.zeek.org/u/Jon_Siwek)
#### Post date: [June 8, 2018, 5:40pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/9 "2018-06-08T17:40:52Z")
Actually, realized you still had bad timing with data stores off, so
it would more likely be a problem with the AdvanceTime() code path.
There's some mutex locking going on there, but w/o data stores
involved there shouldn't be anyone competing for them.
- Jon
---
### Author:  [@robin](https://community.zeek.org/u/robin)
#### Post date: [June 8, 2018, 5:47pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/10 "2018-06-08T17:47:11Z")
Ok, I'll dig around a bit more and also double-check that I didn't
change any settings in the meantime.
Robin
---
### Author:  [@McMullan\_Tim](https://community.zeek.org/u/McMullan_Tim)
#### Post date: [June 8, 2018, 7:18pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/11 "2018-06-08T19:18:47Z")
Hi Jon,
Thanks for looking into this! I tried this again after pulling from master and at least for our case it is looking good!
### old
# /hostname/bro/bin/bro --version
/hostname/bro/bin/bro version 2.5-519
# time /hostname/bro/bin/bro -r 20180606-1242-prodfilers.pcap master.bro
real 0m32.772s
user 0m28.821s
sys 0m3.873s
### new
# /hostname/bro-devel/bin/bro --version
/hostname/bro-devel/bin/bro version 2.5-658
# time /hostname/bro-devel/bin/bro -r 20180606-1242-prodfilers.pcap master.bro
real 0m34.684s
user 0m31.502s
sys 0m4.266s
Thanks again!
--Tim
---
### Author:  [@robin](https://community.zeek.org/u/robin)
#### Post date: [June 11, 2018, 11:30pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/12 "2018-06-11T23:30:07Z")
Confirmed that I'm still seeing that difference even when using the
options to turn the stores. Tried it on two different Fedora 28
systems, with similar results.
I haven't been able to nail down what's going on though. The
AdvanceTime() method does seem to do a lot of locking in pcap mode,
independent of whether there's actually any data store operations.
However, I tried a quick hack to get that down and that didn't change
anything.
I then ran it through oprofile. Output is attached. There's indeed
some locking showing up high in there, but I can't tell if that's just
expected idling in CAF. I am bit surprised to see a number of
std::chrono() methods showing rather prominently that I would expect
to be cheap.
Robin
[report](https://community.zeek.org/uploads/short-url/slqqasYJscuKPd0inEqYoNMt1rE) (107 KB)
---
### Author:  [@Jon\_Siwek](https://community.zeek.org/u/Jon_Siwek)
#### Post date: [June 12, 2018, 7:16pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/13 "2018-06-12T19:16:22Z")
I had previously tried on a Fedora 28 VM w/ 4 CPUs and didn't
reproduce it, but trying again on a system with 32 CPUs, I can
reproduce your results. This has lead to the fix/workaround at [1],
now in master, which should bring things back to baseline when not
using data stores and more sane timings when using them.
General changes/improvements in CAF itself may be warranted here
because I can recreate the same performance overhead if I artificially
remove all broker functionality from Bro, but then simply create and
never use a caf::actor\_system via the default configuration.
- Jon
[1] [https://github.com/bro/bro/commit/c9fe9a943c4d78b18ffbae13c562b93349a5f951](https://github.com/bro/bro/commit/c9fe9a943c4d78b18ffbae13c562b93349a5f951)
---
### Author:  [@robin](https://community.zeek.org/u/robin)
#### Post date: [June 12, 2018, 9:26pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/14 "2018-06-12T21:26:19Z")
> This has lead to the fix/workaround at [1], now in master, which
Cool, that indeed solved it! It also helps significantly when data
stores \*are\* being used; that still takes about 2x the time, but
that's much less than before. Now I'm wondering if we can get that
back down to normal, too ...
One question about Broker's endpoint::advance\_time(): that's locking
on each call when in pcap mode, i.e., once per packet. Could we limit
that to cases where something actually needs to be done? Quick idea:
use an atomic\<\> for current\_time plus another atomic\<\> counter
tracking if there are any pending message. And go into the locked case
only if the latter is non-zero?
> General changes/improvements in CAF itself may be warranted here
Yeah, sounds like it.
Robin
---
### Author:  [@Jon\_Siwek](https://community.zeek.org/u/Jon_Siwek)
#### Post date: [June 13, 2018, 7:50pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/15 "2018-06-13T19:50:08Z")
> One question about Broker's endpoint::advance\_time(): that's locking
> on each call when in pcap mode, i.e., once per packet. Could we limit
> that to cases where something actually needs to be done? Quick idea:
> use an atomic\<\> for current\_time plus another atomic\<\> counter
> tracking if there are any pending message. And go into the locked case
> only if the latter is non-zero?
Yes, I've done that in master, but didn't measure a notable difference.
> \> General changes/improvements in CAF itself may be warranted here
Made an issue for that here:
>
>
> On a 32-core Linux system (\`std::thread::hardware\_concurrency()\` is 32) and defa…ult build of caf/master (cdfe2c223) using the following test benchmark:
>
> \`\`\`c++
> \#include "caf/actor\_system.hpp"
> \#include "caf/actor\_system\_config.hpp"
> \#include \
> using namespace caf;
>
> int main()
> {
> actor\_system\_config cfg;
> actor\_system system{cfg};
>
> uint64\_t total = 0u;
> uint64\_t limit = 10000000000u;
>
> for ( uint64\_t i = 0u; i \< limit; ++i )
> total += i;
>
> return 0;
> }
> \`\`\`
>
> I get this timing (built w/ \`-O0\`):
>
> \`\`\`
> $ time ./a.out
>
> real 1m6.162s
> user 1m12.252s
> sys 0m27.054s
> \`\`\`
>
> Then recompile without creating an \`actor\_system\`:
>
>
> \`\`\`c++
> \#include "caf/actor\_system.hpp"
> \#include "caf/actor\_system\_config.hpp"
> \#include \
> using namespace caf;
>
> int main()
> {
> //actor\_system\_config cfg;
> //actor\_system system{cfg};
>
> uint64\_t total = 0u;
> uint64\_t limit = 10000000000u;
>
> for ( uint64\_t i = 0u; i \< limit; ++i )
> total += i;
>
> return 0;
> }
> \`\`\`
>
> And I get this timing:
>
> \`\`\`
> $ time ./a.out
>
> real 0m45.918s
> user 0m45.751s
> sys 0m0.002s
> \`\`\`
>
> I can also get closer to the better timing by artificially limiting the number of threads via \`cfg.scheduler\_max\_threads = 4;\`. Running the benchmarks on a lower-core system with default configuration would also not see as much of a problem.
>
> Does this generally indicate some scaling issues on high-core-count systems? Or is there any room to improve CAF so that the default configuration of an actor system on a high-core-count machine doesn't have as much overhead?
- Jon
---
### Author:  [@system](https://community.zeek.org/u/system)
#### Post date: [May 6, 2022, 3:45pm UTC](https://community.zeek.org/t/performance-issues-after-the-fe7e1ee-commit/5340/16 "2022-05-06T15:45:51Z")