refactor(pgwire): unify query logs and slow query logs #13924

BugenZhao · 2023-12-11T13:16:54Z

I hereby agree to the terms of the RisingWave Labs, Inc. Contributor License Agreement.

What's changed and what's your intention?

Provide the common info like mode, session, sql with a tracing span in the entrance function do_process, which...

avoid code duplication on different message types
is reused with feat: distributed tracing for frontend and meta client #10660
unify the path for query logs and slow query logs

The slow query log was introduced in #6624 a long time ago. However, it has recently been discovered (in #13287 (comment) and also by @liurenjie1024) that it fails to take into account the time required to consume the data stream. This PR also fixes that by handling all these stuff in pgwire.

Tested locally:

query.log

2023-12-12T16:43:36.017757+08:00 risingwave-main ThreadId(10) handle_query{mode="simple query" session_id=0 sql=select fu;}: status="err" time=68.853375ms
2023-12-12T16:45:20.525747+08:00 risingwave-main ThreadId(06) handle_query{mode="simple query" session_id=0 sql=select pg_sleep(65);}: status="ok" time=65.020061167s

slow_query.log

2023-12-12T16:45:15.508607+08:00 risingwave-main ThreadId(07) handle_query{mode="simple query" session_id=0 sql=select pg_sleep(65);}: slow query elapsed=60s

Checklist

I have written necessary rustdoc comments
I have added necessary unit tests and integration tests
All checks passed in ./risedev check (or alias, ./risedev c)

Documentation

My PR needs documentation updates. (Please use the Release note section below to summarize the impact on users)

Release note

If this PR includes changes that directly affect users or other significant modifications relevant to the community, kindly draft a release note to provide a concise summary of these changes. Please prioritize highlighting the impact these changes will have on users.

Signed-off-by: Bugen Zhao <[email protected]>

liurenjie1024

LGTM, thanks!

src/common/src/util/query_log.rs

Signed-off-by: Bugen Zhao <[email protected]>

codecov · 2023-12-12T09:30:32Z

Codecov Report

Attention: 68 lines in your changes are missing coverage. Please review.

Comparison is base (942a826) 68.00% compared to head (0f92b6b) 68.07%.
Report is 1 commits behind head on main.

Files	Patch %	Lines
src/utils/runtime/src/logger.rs	0.00%	42 Missing ⚠️
src/utils/pgwire/src/pg_protocol.rs	81.81%	18 Missing ⚠️
src/frontend/src/session.rs	27.27%	8 Missing ⚠️

Additional details and impacted files

@@            Coverage Diff             @@
##             main   #13924      +/-   ##
==========================================
+ Coverage   68.00%   68.07%   +0.06%     
==========================================
  Files        1542     1543       +1     
  Lines      266905   266920      +15     
==========================================
+ Hits       181520   181714     +194     
+ Misses      85385    85206     -179

Flag	Coverage Δ
rust	`68.07% <57.23%> (+0.06%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

chenzl25

LGTM. Good Catch

xxchan · 2023-12-13T03:23:57Z

src/utils/runtime/src/logger.rs

+        /// Newtype wrapper for `DefaultFields`.
+        ///
+        /// `fmt::Layer` will share the same `FormattedFields` extension for spans across
+        /// different layers, as long as the type of `N: FormatFields` is the same. This
+        /// will cause several problems:
+        ///
+        /// - `with_ansi(false)` does not take effect and it will follow the settings of
+        ///   the primary fmt layer installed above.
+        /// - `Span::record` will update the same `FormattedFields` multiple times,
+        ///   leading to duplicated fields.
+        ///
+        /// As a workaround, we use a newtype wrapper here to get a different type id.
+        /// The const generic parameter `SLOW` is further used to distinguish between the
+        /// query log and the slow query log.


Specifically, what part of the following log is controlled by this? (What does it look like without this?)

2023-12-12T16:43:36.017757+08:00 risingwave-main ThreadId(10) handle_query{mode="simple query" session_id=0 sql=select fu;}: status="err" time=68.853375ms

- handle_query + <some control character for ANSI color>handle_query - {mode="simple query" session_id=0 sql=select fu;}: + {mode="simple query" session_id=0 sql=select fu; sql=select fu; sql=select fu;}: status="err" time=68.853375ms

Why it's colorful: https://docs.rs/tracing-subscriber/0.3.18/src/tracing_subscriber/fmt/fmt_layer.rs.html#815-823

Why sql is recorded multiple times: https://docs.rs/tracing-subscriber/0.3.18/src/tracing_subscriber/fmt/fmt_layer.rs.html#851-854

Notice the type parameter N here.

xxchan · 2023-12-13T03:29:52Z

src/utils/pgwire/src/pg_protocol.rs

+    /// The span is only effective if there's a current session and the message is
+    /// query-related. Otherwise, `Span::none()` is returned.
+    fn root_span_for_msg(&self, msg: &FeMessage) -> tracing::Span {
+        let Some(session_id) = self.session.as_ref().map(|s| s.id().0) else {
+            return tracing::Span::none();
+        };


When is there no session? 👀

I guess when the Startup message is not handled?

xxchan · 2023-12-13T03:57:19Z

src/utils/pgwire/src/pg_protocol.rs

@@ -460,26 +554,12 @@ where
    async fn process_query_msg(&mut self, query_string: io::Result<&str>) -> PsqlResult<()> {
        let sql: Arc<str> =
            Arc::from(query_string.map_err(|err| PsqlError::SimpleQueryError(Box::new(err)))?);
-        let start = Instant::now();
+        record_sql_in_span(&sql);


a little confused. Does this duplicate with the layer in do_process?

the layer in do_process?

What do you mean by this? 😳

Oh, do_process emits the log line, but process_query_msg adds the sql field. I see.

fuyufjh · 2023-12-13T05:43:26Z

src/utils/runtime/src/logger.rs

+        /// The const generic parameter `SLOW` is further used to distinguish between the
+        /// query log and the slow query log.
+        #[derive(Default)]
+        struct FmtFields<const SLOW: bool>(DefaultFields);


Where is the SLOW used?

risingwave/src/utils/runtime/src/logger.rs

Lines 303 to 306 in 9dcad74

let layer = match is_slow {

true => layer.fmt_fields(FmtFields::<true>::default()).boxed(),

false => layer.fmt_fields(FmtFields::<false>::default()).boxed(),

};

There's no actual use for this flag. It just makes the compiler to treat them as different types and then assign them with different type_ids, which is used for RTTI.

chenzl25 · 2023-12-13T05:56:28Z

src/utils/pgwire/src/pg_protocol.rs

+                tracing::info!(
+                    target: PGWIRE_QUERY_LOG,
+                    status = if result.is_ok() { "ok" } else { "err" },
+                    time = ?elapsed,


BTW, shall we print the elapsed in a fixed width and fixed unit format?

Can you elaborate more? I'm afraid it's hard to do this for the duration from 50 µs = 0.05 ms to 5 min = 300 000 ms. 🥺

I think ms is enough for batch query. How about using .as_millis()? With the same time unit could let us easy to grep these lines.

fuyufjh

Overall, I feel that "unifying query logs and slow query logs" doesn't seem to reduce the complexity but somehow make it more complicated to me... Tend to keep the original implementation, which was simple and straight-forward.

fuyufjh · 2023-12-13T06:15:15Z

src/utils/pgwire/src/pg_protocol.rs

@@ -160,6 +158,17 @@ pub fn cstr_to_str(b: &Bytes) -> Result<&str, Utf8Error> {
    std::str::from_utf8(without_null)
 }

+/// Record `sql` in the current tracing span.
+fn record_sql_in_span(sql: &str) {


What's the relationship between this and the run_stmt in #10660?

I assume you're talking about the span created here:

risingwave/src/utils/pgwire/src/pg_protocol.rs

Lines 230 to 236 in 9dcad74

tracing::info_span!(

target: PGWIRE_ROOT_SPAN_TARGET,

"handle_query",

mode,

session_id,

sql = tracing::field::Empty, // record SQL later in each `process` call

)

This replaces the old one, which was renamed to process_query_msg_one_stmt after that PR. Pros:

It's defined in the unified path for handling Query Parse and Execute, while the old one only handled (simple) Query.

It's now not only used by traces, but also used to provide common info for the query logs later, including the slow ones.

risingwave/src/utils/pgwire/src/pg_protocol.rs

Lines 312 to 316 in 9dcad74

tracing::info!(

target: PGWIRE_QUERY_LOG,

status = if result.is_ok() { "ok" } else { "err" },

time = ?elapsed,

);

risingwave/src/utils/pgwire/src/pg_protocol.rs

Lines 288 to 292 in 9dcad74

tracing::info!(

target: PGWIRE_SLOW_QUERY_LOG,

?elapsed,

"slow query"

);

As for recording the SQL field after creating the span: I just don't want to duplicate the code for extracting the SQL from the messages. This also reduces allocations.

xxchan · 2023-12-13T07:10:27Z

src/utils/pgwire/src/pg_protocol.rs

+        // Query log.
+        let fut = async move {


Do the consecutive async move layers have performance implications? 🤔

I guess not intuitively. 🤣 This is just like the adaptors for iterators or futures.

BugenZhao · 2023-12-13T08:15:00Z

Overall, I feel that "unifying query logs and slow query logs" doesn't seem to reduce the complexity but somehow make it more complicated to me... Tend to keep the original implementation, which was simple and straight-forward.

To be honest, this PR is more like a fix and a feature than a refactor.

Frontend tracing now works in extended mode as well.
The slow query log now correctly records the time by moving it to pgwire.

If the refactor were not done, then the code for providing the common fields like sql or session_id has to be repeated 3 (log, slow log, trace span) x 3(query, parse, execute) = 9 times, also including the code for truncating and possibly redacting (#12673). I believe DRY is necessary here. 😕

New code introduced in this PR is scalable. For example, it requires minimal changes to

add or transform a field
support a new query type

Signed-off-by: Bugen Zhao <[email protected]>

refactor(pgwire): unify query logs and slow query logs

7936970

Signed-off-by: Bugen Zhao <[email protected]>

github-actions bot added the type/refactor label Dec 11, 2023

liurenjie1024 approved these changes Dec 12, 2023

View reviewed changes

src/common/src/util/query_log.rs Show resolved Hide resolved

BugenZhao added 2 commits December 12, 2023 17:03

record sql later

e363223

Signed-off-by: Bugen Zhao <[email protected]>

fix clippy

9dcad74

Signed-off-by: Bugen Zhao <[email protected]>

BugenZhao requested review from chenzl25 and xxchan December 12, 2023 09:11

chenzl25 reviewed Dec 12, 2023

View reviewed changes

xxchan mentioned this pull request Dec 13, 2023

feat: configure query log path/period in system config #13961

Closed

xxchan reviewed Dec 13, 2023

View reviewed changes

fuyufjh reviewed Dec 13, 2023

View reviewed changes

chenzl25 reviewed Dec 13, 2023

View reviewed changes

fuyufjh reviewed Dec 13, 2023

View reviewed changes

xxchan reviewed Dec 13, 2023

View reviewed changes

BugenZhao added this pull request to the merge queue Dec 18, 2023

github-merge-queue bot removed this pull request from the merge queue due to failed status checks Dec 18, 2023

BugenZhao added 2 commits December 18, 2023 15:19

always use millis

0856ec9

Signed-off-by: Bugen Zhao <[email protected]>

Merge remote-tracking branch 'origin/main' into bz/unified-query-log

0f92b6b

BugenZhao enabled auto-merge December 18, 2023 07:19

BugenZhao added this pull request to the merge queue Dec 18, 2023

Merged via the queue into main with commit d1128cb Dec 18, 2023
26 of 27 checks passed

BugenZhao deleted the bz/unified-query-log branch December 18, 2023 08:16

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

refactor(pgwire): unify query logs and slow query logs #13924

refactor(pgwire): unify query logs and slow query logs #13924

BugenZhao commented Dec 11, 2023 •

edited

Loading

liurenjie1024 left a comment

codecov bot commented Dec 12, 2023 •

edited

Loading

chenzl25 left a comment

xxchan Dec 13, 2023 •

edited

Loading

BugenZhao Dec 13, 2023

BugenZhao Dec 13, 2023

xxchan Dec 13, 2023

BugenZhao Dec 13, 2023

xxchan Dec 13, 2023

BugenZhao Dec 13, 2023

xxchan Dec 13, 2023

fuyufjh Dec 13, 2023

BugenZhao Dec 13, 2023 •

edited

Loading

chenzl25 Dec 13, 2023

BugenZhao Dec 13, 2023

chenzl25 Dec 13, 2023

fuyufjh left a comment

fuyufjh Dec 13, 2023

BugenZhao Dec 13, 2023

xxchan Dec 13, 2023

BugenZhao Dec 13, 2023

BugenZhao commented Dec 13, 2023 •

edited

Loading

	let layer = match is_slow {
	true => layer.fmt_fields(FmtFields::<true>::default()).boxed(),
	false => layer.fmt_fields(FmtFields::<false>::default()).boxed(),
	};

	tracing::info_span!(
	target: PGWIRE_ROOT_SPAN_TARGET,
	"handle_query",
	mode,
	session_id,
	sql = tracing::field::Empty, // record SQL later in each `process` call
	)

	tracing::info!(
	target: PGWIRE_QUERY_LOG,
	status = if result.is_ok() { "ok" } else { "err" },
	time = ?elapsed,
	);

	tracing::info!(
	target: PGWIRE_SLOW_QUERY_LOG,
	?elapsed,
	"slow query"
	);

refactor(pgwire): unify query logs and slow query logs #13924

refactor(pgwire): unify query logs and slow query logs #13924

Conversation

BugenZhao commented Dec 11, 2023 • edited Loading

What's changed and what's your intention?

Checklist

Documentation

Release note

liurenjie1024 left a comment

Choose a reason for hiding this comment

codecov bot commented Dec 12, 2023 • edited Loading

Codecov Report

chenzl25 left a comment

Choose a reason for hiding this comment

xxchan Dec 13, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BugenZhao Dec 13, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

fuyufjh left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BugenZhao commented Dec 13, 2023 • edited Loading

BugenZhao commented Dec 11, 2023 •

edited

Loading

codecov bot commented Dec 12, 2023 •

edited

Loading

xxchan Dec 13, 2023 •

edited

Loading

BugenZhao Dec 13, 2023 •

edited

Loading

BugenZhao commented Dec 13, 2023 •

edited

Loading