| 62 | } |
| 63 | |
| 64 | pub fn observe_e2e_optimization_time(&self, object_type: &str, duration: Duration) { |
| 65 | self.e2e_optimization_time_seconds |
| 66 | .with_label_values(&[object_type]) |
| 67 | .observe(duration.as_secs_f64()); |
| 68 | // Also log it when it's big. |
| 69 | let debug_threshold = cfg!(debug_assertions); |
| 70 | let threshold = if debug_threshold { |
| 71 | // Debug builds are much slower to optimize (despite mz-transform being built |
| 72 | // with `opt-level = 3` even in debug builds), so we have a larger threshold. |
| 73 | // (A big part of the slowness comes from not optimizing mz-expr, but turning on |
| 74 | // optimizations for that in debug builds would slow down the build |
| 75 | // considerably.) |
| 76 | self.e2e_optimization_time_seconds_log_threshold * 6 |
| 77 | } else { |
| 78 | self.e2e_optimization_time_seconds_log_threshold |
| 79 | }; |
| 80 | if duration > threshold { |
| 81 | let transform_times = self |
| 82 | .transform_time_seconds |
| 83 | .iter() |
| 84 | .map(|(k, v)| { |
| 85 | ( |
| 86 | k, |
| 87 | v.into_iter() |
| 88 | .map(|duration| duration.as_micros()) |
| 89 | .collect::<Vec<_>>(), |
| 90 | ) |
| 91 | }) |
| 92 | .collect::<Vec<_>>(); |
| 93 | let threshold_string = if debug_threshold { |
| 94 | format!("{}ms (debug)", threshold.as_millis()) |
| 95 | } else { |
| 96 | format!("{}ms", threshold.as_millis()) |
| 97 | }; |
| 98 | tracing::warn!( |
| 99 | duration = format!("{}ms", duration.as_millis()), |
| 100 | threshold = threshold_string, |
| 101 | object_type = object_type, |
| 102 | transform_times_μs = serde_json::to_string(&transform_times) |
| 103 | .unwrap_or_else(|_| format!("{:?}", transform_times)), |
| 104 | "slow optimization", |
| 105 | ); |
| 106 | } |
| 107 | } |
| 108 | |
| 109 | pub fn inc_outer_join_lowering(&self, case: &str) { |
| 110 | self.outer_join_lowering_cases |