Log duration of major IPA steps #686
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
akoshelev
commented
Jun 7, 2023
| @@ -77,7 +77,7 @@ pub fn execute( | |||
| input: ByteArrStream, | |||
| ) -> JoinHandle<QueryResult> { | |||
| match (config.query_type, config.field_type) { | |||
| #[cfg(any(test, feature = "cli", feature = "test-fixture"))] | |||
| #[cfg(any(test, feature = "weak-field"))] | |||
There was a problem hiding this comment.
this is an unrelated change, but the previous commit broke our helper CLI
|
Most probably a dumb qn but does close report overall time taken for the span? If so, Do we need to log "new" |
yes it does. there is a little bit of math required because close event indicates two times: busy (when future was actively polled) and idle (when it was waiting for inner futures to complete) so in this case IPA execution took 33.61 seconds to finish |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Using
span_eventsto log the durationsThis is how malicious IPA run looks like
2023-06-07T22:17:12.017603Z INFO ipa::cli::verbosity: Logging setup at level info 2023-06-07T22:17:12.022709Z INFO ipa::net::server: server listening on http://0.0.0.0:3000 2023-06-07T22:17:53.390055Z INFO ipa_query: ipa::query::runner::ipa: new 2023-06-07T22:17:54.384306Z INFO ipa_query:modulus_conversion{bits=40 parallel=3 step=protocol/malicious_protocol/mod_conv_match_key}: ipa::protocol::modulus_conversion::convert_shares: new 2023-06-07T22:17:56.001739Z INFO ipa_query:modulus_conversion{bits=40 parallel=3 step=protocol/malicious_protocol/mod_conv_match_key}: ipa::protocol::modulus_conversion::convert_shares: close time.busy=117ms time.idle=1.50s 2023-06-07T22:17:56.001846Z INFO ipa_query:validate{step=protocol/validate}: ipa::protocol::context::validator: new 2023-06-07T22:17:56.189931Z INFO ipa_query:validate{step=protocol/validate}: ipa::protocol::context::validator: close time.busy=1.21ms time.idle=187ms 2023-06-07T22:17:56.190003Z INFO ipa_query:sort_permutation: ipa::protocol::sort::generate_permutation: new 2023-06-07T22:17:56.489640Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/validate}: ipa::protocol::context::validator: new 2023-06-07T22:17:56.595265Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/validate}: ipa::protocol::context::validator: close time.busy=1.35ms time.idle=104ms 2023-06-07T22:17:57.220475Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort0/validate}: ipa::protocol::context::validator: new 2023-06-07T22:17:57.356592Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort0/validate}: ipa::protocol::context::validator: close time.busy=1.09ms time.idle=135ms 2023-06-07T22:17:57.956533Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort1/validate}: ipa::protocol::context::validator: new 2023-06-07T22:17:58.065649Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort1/validate}: ipa::protocol::context::validator: close time.busy=1.26ms time.idle=108ms 2023-06-07T22:17:58.703780Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort2/validate}: ipa::protocol::context::validator: new 2023-06-07T22:17:58.801083Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort2/validate}: ipa::protocol::context::validator: close time.busy=1.36ms time.idle=95.9ms 2023-06-07T22:17:59.459303Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort3/validate}: ipa::protocol::context::validator: new 2023-06-07T22:17:59.567692Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort3/validate}: ipa::protocol::context::validator: close time.busy=1.10ms time.idle=107ms 2023-06-07T22:18:00.211501Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort4/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:00.343464Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort4/validate}: ipa::protocol::context::validator: close time.busy=1.22ms time.idle=131ms 2023-06-07T22:18:01.035821Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort5/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:01.206953Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort5/validate}: ipa::protocol::context::validator: close time.busy=1.50ms time.idle=170ms 2023-06-07T22:18:01.867801Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort6/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:01.983031Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort6/validate}: ipa::protocol::context::validator: close time.busy=1.34ms time.idle=114ms 2023-06-07T22:18:02.597539Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort7/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:02.721038Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort7/validate}: ipa::protocol::context::validator: close time.busy=1.10ms time.idle=122ms 2023-06-07T22:18:03.385075Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort8/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:03.516495Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort8/validate}: ipa::protocol::context::validator: close time.busy=1.15ms time.idle=130ms 2023-06-07T22:18:04.176438Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort9/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:04.283417Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort9/validate}: ipa::protocol::context::validator: close time.busy=1.47ms time.idle=106ms 2023-06-07T22:18:04.884976Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort10/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:05.007320Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort10/validate}: ipa::protocol::context::validator: close time.busy=1.16ms time.idle=121ms 2023-06-07T22:18:05.654546Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort11/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:05.789431Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort11/validate}: ipa::protocol::context::validator: close time.busy=1.22ms time.idle=134ms 2023-06-07T22:18:06.091295Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort12/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:06.190212Z INFO ipa_query:sort_permutation:validate{step=protocol/gen_sort_permutation_from_match_keys/sort_keys/sort12/validate}: ipa::protocol::context::validator: close time.busy=1.23ms time.idle=97.7ms 2023-06-07T22:18:06.190253Z INFO ipa_query:sort_permutation: ipa::protocol::sort::generate_permutation: close time.busy=387ms time.idle=9.61s 2023-06-07T22:18:07.096205Z INFO ipa_query:modulus_conversion{bits=8 parallel=8 step=protocol/after_convert_all_bits/malicious_protocol/mod_conv_breakdown_key}: ipa::protocol::modulus_conversion::convert_shares: new 2023-06-07T22:18:07.454668Z INFO ipa_query:modulus_conversion{bits=8 parallel=8 step=protocol/after_convert_all_bits/malicious_protocol/mod_conv_breakdown_key}: ipa::protocol::modulus_conversion::convert_shares: close time.busy=21.9ms time.idle=337ms 2023-06-07T22:18:07.671220Z INFO ipa_query:apply_sort{step=protocol/after_convert_all_bits/malicious_protocol/apply_sort_permutation}: ipa::protocol::sort::apply_sort: new 2023-06-07T22:18:08.441951Z INFO ipa_query:apply_sort{step=protocol/after_convert_all_bits/malicious_protocol/apply_sort_permutation}: ipa::protocol::sort::apply_sort: close time.busy=44.3ms time.idle=726ms 2023-06-07T22:18:08.442002Z INFO ipa_query:apply_sort{step=protocol/binary_validator/malicious_protocol/apply_sort_permutation}: ipa::protocol::sort::apply_sort: new 2023-06-07T22:18:11.163628Z INFO ipa_query:apply_sort{step=protocol/binary_validator/malicious_protocol/apply_sort_permutation}: ipa::protocol::sort::apply_sort: close time.busy=288ms time.idle=2.43s 2023-06-07T22:18:11.163706Z INFO ipa_query:attribute{step=protocol}: ipa::protocol::attribution: new 2023-06-07T22:18:12.631348Z INFO ipa_query:attribute{step=protocol}:validate{step=protocol/binary_validator/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:12.697520Z INFO ipa_query:attribute{step=protocol}:validate{step=protocol/binary_validator/validate}: ipa::protocol::context::validator: close time.busy=844µs time.idle=65.3ms 2023-06-07T22:18:12.802385Z INFO ipa_query:attribute:apply_window: ipa::protocol::attribution::apply_attribution_window: new 2023-06-07T22:18:12.802429Z INFO ipa_query:attribute:apply_window: ipa::protocol::attribution::apply_attribution_window: close time.busy=12.9µs time.idle=37.4µs 2023-06-07T22:18:12.802459Z INFO ipa_query:attribute:accumulate_credit: ipa::protocol::attribution::accumulate_credit: new 2023-06-07T22:18:13.070621Z INFO ipa_query:attribute:accumulate_credit: ipa::protocol::attribution::accumulate_credit: close time.busy=7.03ms time.idle=261ms 2023-06-07T22:18:13.070701Z INFO ipa_query:attribute:user_capping: ipa::protocol::attribution::credit_capping: new 2023-06-07T22:18:26.580261Z INFO ipa_query:attribute:user_capping: ipa::protocol::attribution::credit_capping: close time.busy=676ms time.idle=12.8s 2023-06-07T22:18:26.580342Z INFO ipa_query:attribute:aggregate_credit: ipa::protocol::attribution::aggregate_credit: new 2023-06-07T22:18:26.891659Z INFO ipa_query:attribute:aggregate_credit: ipa::protocol::attribution::aggregate_credit: close time.busy=15.0ms time.idle=296ms 2023-06-07T22:18:26.891723Z INFO ipa_query:attribute:validate{step=protocol/after_convert_all_bits/validate}: ipa::protocol::context::validator: new 2023-06-07T22:18:27.022074Z INFO ipa_query:attribute{step=protocol}:validate{step=protocol/after_convert_all_bits/validate}: ipa::protocol::context::validator: close time.busy=1.36ms time.idle=129ms 2023-06-07T22:18:27.023138Z INFO ipa_query:attribute: ipa::protocol::attribution: close time.busy=837ms time.idle=15.0s 2023-06-07T22:18:27.023219Z INFO ipa_query: ipa::query::runner::ipa: close time.busy=1.91s time.idle=31.7shope that it will help me with #685