-
Notifications
You must be signed in to change notification settings - Fork 37
Performance notes
Robin Sommer edited this page Mar 30, 2021
·
1 revision
Here's some information from compile times with the TLS analyzer, as of Spicy 1.0-rc1
= spicyz tls.spicy tls.evt zeek_tls.spicy
real 1m57.861s
user 3m3.817s
= spicyz tls.spicy
real 1m39.337s
user 1m44.557s
= spicyz -d tls.spicy tls.evt zeek_tls.spicy
real 0m57.926s
user 1m39.835s
= spicyz -d tls.spicy
real 0m40.592s
user 0m46.740s
The above were (I believe ...) all with precompiled headers. For comparison:
= spicyz -d tls.spicy tls.evt zeek_tls.spicy, wo/ precompiled headers
real 1m7.164s
user 1m54.752s
= spicyz -d tls.spicy tls.evt zeek_tls.spicy, w/ precompiled headers
real 0m56.838s
user 1m34.831s
Timing break-down (-R):
= spicyz -d tls.spicy tls.evt zeek_tls.spicy, w/ precompiled headers
=== Execution Time Summary ===
66.40% 37.55s hilti/jit (#1)
64.37% 36.40s hilti/jit/compile (#1)
11.73% 6.64s hilti/compiler/codegen (#30)
6.17% 3.49s hilti/compiler/operator-resolver (#110)
3.21% 1.81s hilti/compiler/id-resolver (#110)
2.33% 1.32s hilti/compiler/scope-builder (#19)
1.64% 0.93s hilti/compiler/apply-coercions (#110)
1.60% 0.91s hilti/jit/link (#1)
1.07% 0.60s spicy/compiler/id-resolver (#110)
0.97% 0.55s spicy/compiler/codegen (#110)
0.70% 0.40s hilti/compiler/parser (#7)
0.68% 0.39s hilti/compiler/importer (#110)
0.68% 0.39s spicy/compiler/validator (#170)
0.54% 0.31s spicy/compiler/scope-builder (#19)
0.47% 0.27s spicy/compiler/apply-coercions (#110)
0.04% 0.02s hilti/linker (#1)
0.02% 0.01s hilti/printer (#3634)
0.00% 0.00s spicy/printer (#7888)
Total time: 56.56s
ClangBuildAnalyzer:
= spicyz -d tls.spicy tls.evt zeek_tls.spicy, w/ precompiled headers
Analyzing build trace from 'prof'...
**** Time summary:
Compilation (12 times):
Parsing (frontend): 61.4 s
Codegen & opts (backend): 13.2 s
**** Files that took longest to parse (compiler frontend):
18561 ms: dbg.TLS.cc.o
10614 ms: dbg.spicy_hooks_TLS.cc.o
10556 ms: dbg.Zeek_TLS.cc.o
9451 ms: dbg.spicy_hooks_Zeek_TLS.cc.o
5087 ms: dbg.TLS.cc.o
3021 ms: dbg.spicy_init.cc.o
1846 ms: dbg.__linker__.cc.o
1163 ms: dbg.spicy_hooks_TLS.cc.o
704 ms: dbg.Zeek_TLS.cc.o
391 ms: dbg.spicy_hooks_Zeek_TLS.cc.o
**** Files that took longest to codegen (compiler backend):
9461 ms: dbg.TLS.cc.o
1978 ms: dbg.spicy_hooks_TLS.cc.o
942 ms: dbg.Zeek_TLS.cc.o
719 ms: dbg.spicy_hooks_Zeek_TLS.cc.o
45 ms: dbg.__linker__.cc.o
35 ms: dbg.spicy_init.cc.o
**** Templates that took longest to instantiate:
2111 ms: std::__1::__optional_move_assign_base<hilti::rt::ValueReference<__hl... (4 times, avg 527 ms)
2111 ms: std::__1::__optional_storage_base<hilti::rt::ValueReference<__hlt::T... (4 times, avg 527 ms)
2093 ms: hilti::rt::ValueReference<__hlt::TLS::ClientHello>::operator= (5 times, avg 418 ms)
1900 ms: hilti::rt::Vector<hilti::rt::ValueReference<__hlt::TLS::Extension>, ... (8 times, avg 237 ms)
1899 ms: std::__1::vector<hilti::rt::ValueReference<__hlt::TLS::Extension>, s... (8 times, avg 237 ms)
1898 ms: std::__1::__optional_copy_assign_base<hilti::rt::Vector<hilti::rt::V... (4 times, avg 474 ms)
1898 ms: std::__1::__optional_storage_base<hilti::rt::Vector<hilti::rt::Value... (4 times, avg 474 ms)
1892 ms: std::__1::vector<hilti::rt::ValueReference<__hlt::TLS::Extension>, s... (4 times, avg 473 ms)
1716 ms: hilti::rt::ValueReference<__hlt::TLS::Extension>::operator= (5 times, avg 343 ms)
1711 ms: std::__1::copy<hilti::rt::ValueReference<__hlt::TLS::Extension> *, h... (4 times, avg 427 ms)
1709 ms: std::__1::__copy_constexpr<hilti::rt::ValueReference<__hlt::TLS::Ext... (4 times, avg 427 ms)
1222 ms: std::__1::__optional_move_assign_base<hilti::rt::ValueReference<__hl... (4 times, avg 305 ms)
1222 ms: std::__1::__optional_storage_base<hilti::rt::ValueReference<__hlt::T... (4 times, avg 305 ms)
1203 ms: hilti::rt::ValueReference<__hlt::TLS::PreSharedKey>::operator= (5 times, avg 240 ms)
1022 ms: std::__1::__optional_copy_assign_base<hilti::rt::ValueReference<__hl... (4 times, avg 255 ms)
1022 ms: std::__1::__optional_storage_base<hilti::rt::ValueReference<__hlt::T... (4 times, avg 255 ms)
986 ms: std::__1::__optional_move_assign_base<hilti::rt::ValueReference<__hl... (4 times, avg 246 ms)
985 ms: std::__1::__optional_storage_base<hilti::rt::ValueReference<__hlt::T... (4 times, avg 246 ms)
964 ms: hilti::rt::ValueReference<__hlt::TLS::ServerKeyExchange>::operator= (5 times, avg 192 ms)
883 ms: hilti::rt::ValueReference<__hlt::TLS::OfferedPsks>::operator= (9 times, avg 98 ms)
881 ms: std::__1::__optional_move_assign_base<hilti::rt::ValueReference<__hl... (4 times, avg 220 ms)
881 ms: std::__1::__optional_storage_base<hilti::rt::ValueReference<__hlt::T... (4 times, avg 220 ms)
858 ms: hilti::rt::ValueReference<__hlt::TLS::KeyShare>::operator= (5 times, avg 171 ms)
677 ms: std::__1::make_tuple<(lambda at /Users/robin/spicy/install/1.0/inclu... (56 times, avg 12 ms)
486 ms: std::__1::__optional_move_assign_base<hilti::rt::ValueReference<__hl... (4 times, avg 121 ms)
485 ms: std::__1::__optional_storage_base<hilti::rt::ValueReference<__hlt::T... (4 times, avg 121 ms)
467 ms: std::__1::__optional_copy_assign_base<hilti::rt::ValueReference<__hl... (4 times, avg 116 ms)
467 ms: std::__1::__optional_storage_base<hilti::rt::ValueReference<__hlt::T... (4 times, avg 116 ms)
463 ms: hilti::rt::ValueReference<__hlt::TLS::ClientKeyExchange>::operator= (5 times, avg 92 ms)
456 ms: std::__1::__optional_move_assign_base<hilti::rt::ValueReference<__hl... (4 times, avg 114 ms)
**** Template sets that took longest to instantiate:
11980 ms: std::__1::make_shared<$> (431 times, avg 27 ms)
10322 ms: std::__1::__optional_storage_base<$>::__assign_from<$> (250 times, avg 41 ms)
9091 ms: hilti::rt::ValueReference<$>::ValueReference (538 times, avg 16 ms)
8254 ms: std::__1::__shared_ptr_emplace<$>::__shared_ptr_emplace<$> (367 times, avg 22 ms)
7514 ms: std::__1::__optional_storage_base<$>::__construct<$> (414 times, avg 18 ms)
6312 ms: std::__1::forward_as_tuple<$> (773 times, avg 8 ms)
6017 ms: std::__1::optional<$> (710 times, avg 8 ms)
3629 ms: std::__1::tuple<$> (945 times, avg 3 ms)
3363 ms: std::__1::vector<$>::assign<$> (48 times, avg 70 ms)
2524 ms: std::__1::__compressed_pair<$>::__compressed_pair<$> (1167 times, avg 2 ms)
2508 ms: std::__1::variant<$> (281 times, avg 8 ms)
2354 ms: hilti::rt::type_info::Vector::accessor<$> (56 times, avg 42 ms)
2333 ms: hilti::rt::ValueReference<$> (250 times, avg 9 ms)
2111 ms: std::__1::__optional_move_assign_base<hilti::rt::ValueReference<__hl... (4 times, avg 527 ms)
2093 ms: hilti::rt::ValueReference<__hlt::TLS::ClientHello>::operator= (5 times, avg 418 ms)
1941 ms: std::__1::allocator_traits<$>::construct<$> (148 times, avg 13 ms)
1900 ms: hilti::rt::Vector<hilti::rt::ValueReference<__hlt::TLS::Extension>, ... (8 times, avg 237 ms)
1899 ms: std::__1::vector<hilti::rt::ValueReference<__hlt::TLS::Extension>, s... (8 times, avg 237 ms)
1898 ms: std::__1::__optional_copy_assign_base<hilti::rt::Vector<hilti::rt::V... (4 times, avg 474 ms)
1864 ms: std::__1::allocator_traits<$>::__construct<$> (75 times, avg 24 ms)
1857 ms: std::__1::allocator<$>::construct<$> (74 times, avg 25 ms)
1838 ms: std::__1::copy<$> (47 times, avg 39 ms)
1813 ms: std::__1::__copy_constexpr<$> (35 times, avg 51 ms)
1784 ms: hilti::rt::ValueReference<$>::self (224 times, avg 7 ms)
1752 ms: std::__1::unique_ptr<$> (581 times, avg 3 ms)
1716 ms: hilti::rt::ValueReference<__hlt::TLS::Extension>::operator= (5 times, avg 343 ms)
1641 ms: hilti::rt::Vector<$>::Vector (87 times, avg 18 ms)
1591 ms: std::__1::allocator_traits<$> (1417 times, avg 1 ms)
1485 ms: std::__1::tuple<$>::_CheckArgsConstructor<$>::__enable_implicit<$> (1277 times, avg 1 ms)
1477 ms: std::__1::vector<$>::__construct_at_end<$> (84 times, avg 17 ms)
**** Functions that took longest to compile:
54 ms: __hlt::TLS::ClientHello::__parse_stage1(hilti::rt::ValueReference<hi... (dbg.TLS.cc)
48 ms: __hlt::TLS::SignedCertificateTimestamp::__parse_stage1(hilti::rt::Va... (dbg.TLS.cc)
48 ms: __cxx_global_var_init.410 (dbg.TLS.cc)
45 ms: __hlt::TLS::ServerHello::__parse_stage1(hilti::rt::ValueReference<hi... (dbg.TLS.cc)
42 ms: __hlt::TLS::DhAnonServerKeyExchange::__parse_stage1(hilti::rt::Value... (dbg.TLS.cc)
34 ms: __hlt::TLS::DheServerKeyExchange::__parse_stage1(hilti::rt::ValueRef... (dbg.TLS.cc)
31 ms: __hlt::TLS::Extension::__parse_switch_43_stage1(hilti::rt::ValueRefe... (dbg.TLS.cc)
20 ms: __hlt::TLS::Handshake_message::__parse_switch_16_stage1(hilti::rt::V... (dbg.TLS.cc)
19 ms: __hlt::TLS::StatusRequest::__parse_switch_55_case_1_stage1(hilti::rt... (dbg.TLS.cc)
19 ms: std::__1::enable_if<__is_cpp17_forward_iterator<SafeInt<unsigned sho... (dbg.spicy_hooks_TLS.cc)
17 ms: __hlt::TLS::Heartbeat::__parse_stage1(hilti::rt::ValueReference<hilt... (dbg.TLS.cc)
17 ms: __hlt::TLS::CertificateStatus::__parse_stage1(hilti::rt::ValueRefere... (dbg.TLS.cc)
17 ms: __hlt::TLS::NewSessionTicket::__parse_stage1(hilti::rt::ValueReferen... (dbg.TLS.cc)
16 ms: __hlt::TLS::SingleCertificate::__parse_stage1(hilti::rt::ValueRefere... (dbg.TLS.cc)
16 ms: __hlt::TLS::KeyShareEntry::__parse_stage1(hilti::rt::ValueReference<... (dbg.TLS.cc)
16 ms: __hlt::TLS::RecordFragment::__parse_stage1(hilti::rt::ValueReference... (dbg.TLS.cc)
15 ms: __hlt::TLS::PSKIdentity::__parse_stage1(hilti::rt::ValueReference<hi... (dbg.TLS.cc)
15 ms: __hlt::TLS::ServerECDHParamsAndSignature::__parse_stage1(hilti::rt::... (dbg.TLS.cc)
14 ms: __hlt::spicy_hooks_TLS::__hook_ServerHello___on_0x25_done_af86(hilti... (dbg.spicy_hooks_TLS.cc)
13 ms: __hlt::TLS::ServerKeyExchangeSignature::__parse_stage1(hilti::rt::Va... (dbg.TLS.cc)
13 ms: __hlt::TLS::Handshake_message::__parse_stage1(hilti::rt::ValueRefere... (dbg.TLS.cc)
12 ms: __hlt::TLS::Alert_message::__parse_stage1(hilti::rt::ValueReference<... (dbg.TLS.cc)
12 ms: __hlt::TLS::Certificate::__parse_stage1(hilti::rt::ValueReference<hi... (dbg.TLS.cc)
12 ms: __hlt::TLS::PSKBindersList::__parse_stage1(hilti::rt::ValueReference... (dbg.TLS.cc)
11 ms: __hlt::TLS::ServerKeyExchange::__parse_switch_58_stage1(hilti::rt::V... (dbg.TLS.cc)
11 ms: __hlt::TLS::PSKBinder::__parse_stage1(hilti::rt::ValueReference<hilt... (dbg.TLS.cc)
11 ms: __hlt::spicy_hooks_TLS::__hook_ClientHello___on_0x25_done_e4a6(hilti... (dbg.spicy_hooks_TLS.cc)
11 ms: __hlt::TLS::Extension::__parse_stage1(hilti::rt::ValueReference<hilt... (dbg.TLS.cc)
11 ms: __hlt::TLS::ProtocolName::__parse_stage1(hilti::rt::ValueReference<h... (dbg.TLS.cc)
11 ms: __hlt::TLS::Random::__parse_stage1(hilti::rt::ValueReference<hilti::... (dbg.TLS.cc)
**** Function sets that took longest to compile / optimize:
66 ms: hilti::rt::ValueReference<$>::asSharedPtr() const (58 times, avg 1 ms)
54 ms: __hlt::TLS::ClientHello::__parse_stage1(hilti::rt::ValueReference<$>... (1 times, avg 54 ms)
48 ms: __hlt::TLS::SignedCertificateTimestamp::__parse_stage1(hilti::rt::Va... (1 times, avg 48 ms)
45 ms: __hlt::TLS::ServerHello::__parse_stage1(hilti::rt::ValueReference<$>... (1 times, avg 45 ms)
44 ms: hilti::rt::ValueReference<$>::_safeGet() (63 times, avg 0 ms)
42 ms: __hlt::TLS::DhAnonServerKeyExchange::__parse_stage1(hilti::rt::Value... (1 times, avg 42 ms)
34 ms: __hlt::TLS::DheServerKeyExchange::__parse_stage1(hilti::rt::ValueRef... (1 times, avg 34 ms)
33 ms: std::__1::enable_if<$>::type std::__1::make_shared<$>() (52 times, avg 0 ms)
33 ms: std::__1::enable_if<$>::type std::__1::make_shared<$>(std::__1::tupl... (58 times, avg 0 ms)
32 ms: std::__1::__tuple_impl<$>::__tuple_impl<$>(std::__1::__tuple_indices... (51 times, avg 0 ms)
31 ms: std::__1::enable_if<$>::type std::__1::make_shared<$>(hilti::rt::Vec... (32 times, avg 0 ms)
31 ms: __hlt::TLS::Extension::__parse_switch_43_stage1(hilti::rt::ValueRefe... (1 times, avg 31 ms)
30 ms: hilti::rt::vector::ConstIterator<$>::_container() const (44 times, avg 0 ms)
27 ms: auto& hilti::rt::optional::value<$>(std::__1::optional<$>&, char con... (41 times, avg 0 ms)
26 ms: void tinyformat::detail::formatTruncated<$>(std::__1::basic_ostream<... (42 times, avg 0 ms)
24 ms: hilti::rt::ValueReference<$>::_safeGet() const (41 times, avg 0 ms)
24 ms: void spicy::rt::ParsedUnit::initialize<$>(spicy::rt::ParsedUnit&, hi... (34 times, avg 0 ms)
20 ms: __hlt::TLS::Handshake_message::__parse_switch_16_stage1(hilti::rt::V... (1 times, avg 20 ms)
19 ms: __hlt::TLS::StatusRequest::__parse_switch_55_case_1_stage1(hilti::rt... (1 times, avg 19 ms)
19 ms: std::__1::enable_if<$>::type std::__1::vector<$>::__construct_at_end... (1 times, avg 19 ms)
17 ms: __hlt::TLS::Heartbeat::__parse_stage1(hilti::rt::ValueReference<$>&,... (1 times, avg 17 ms)
17 ms: __hlt::TLS::CertificateStatus::__parse_stage1(hilti::rt::ValueRefere... (1 times, avg 17 ms)
17 ms: __hlt::TLS::NewSessionTicket::__parse_stage1(hilti::rt::ValueReferen... (1 times, avg 17 ms)
16 ms: __hlt::TLS::SingleCertificate::__parse_stage1(hilti::rt::ValueRefere... (1 times, avg 16 ms)
16 ms: __hlt::TLS::KeyShareEntry::__parse_stage1(hilti::rt::ValueReference<... (1 times, avg 16 ms)
16 ms: __hlt::TLS::RecordFragment::__parse_stage1(hilti::rt::ValueReference... (1 times, avg 16 ms)
15 ms: auto* std::__1::__generic_get_if<$>(std::__1::variant<$>*) (25 times, avg 0 ms)
15 ms: __hlt::TLS::PSKIdentity::__parse_stage1(hilti::rt::ValueReference<$>... (1 times, avg 15 ms)
15 ms: __hlt::TLS::ServerECDHParamsAndSignature::__parse_stage1(hilti::rt::... (1 times, avg 15 ms)
14 ms: void tinyformat::detail::formatTruncated<$>(std::__1::basic_ostream<... (19 times, avg 0 ms)
*** Expensive headers:
9005 ms: /Users/robin/spicy/install/1.0/include/hilti/rt/libhilti.h (included 6 times, avg 1500 ms), included via:
dbg.spicy_hooks_TLS.cc.o (1789 ms)
dbg.spicy_hooks_Zeek_TLS.cc.o (1782 ms)
dbg.Zeek_TLS.cc.o (1496 ms)
dbg.__linker__.cc.o (1363 ms)
dbg.TLS.cc.o (1331 ms)
dbg.spicy_init.cc.o (1242 ms)
...
3732 ms: /Users/robin/work/spicy/master/zeek/spicy-plugin/plugin/include/zeek-spicy/runtime-support.h (included 4 times, avg 933 ms), included via:
dbg.Zeek_TLS.cc.o (1023 ms)
dbg.spicy_hooks_TLS.cc.o (1020 ms)
dbg.spicy_hooks_Zeek_TLS.cc.o (931 ms)
dbg.spicy_init.cc.o (757 ms)
841 ms: /Users/robin/spicy/install/1.0/include/spicy/rt/libspicy.h (included 5 times, avg 168 ms), included via:
dbg.spicy_hooks_TLS.cc.o (186 ms)
dbg.Zeek_TLS.cc.o (181 ms)
dbg.spicy_hooks_Zeek_TLS.cc.o (179 ms)
dbg.TLS.cc.o (147 ms)
dbg.spicy_init.cc.o (146 ms)
done in 0.2s.