Skip to content

util/mon: Downgrade "bytes usage increases" log message#34806

Merged
craig[bot] merged 1 commit intocockroachdb:masterfrom
bdarnell:mem-mon-logs
Feb 25, 2019
Merged

util/mon: Downgrade "bytes usage increases" log message#34806
craig[bot] merged 1 commit intocockroachdb:masterfrom
bdarnell:mem-mon-logs

Conversation

@bdarnell
Copy link
Copy Markdown
Contributor

This message can be logged frequently in certain workloads, and its
appearance in the info log is not actionable since there is no way to
tie it back to the query that caused it. I see no reason to have
these messages enabled by default.

Release note: None

@bdarnell bdarnell requested a review from knz February 11, 2019 22:51
@cockroach-teamcity
Copy link
Copy Markdown
Member

This change is Reviewable

@knz
Copy link
Copy Markdown
Contributor

knz commented Feb 11, 2019

Yeah no that won't do, last time we tried that specific change the log.V called started popping up in profiles quite bad (it's an expensive function).

I think the actionable next step here is to bump the noteworthy usage limit? or something like that. @jordanlewis was looking into alleviating this previously, do you remember what your recommendation was last time?

@bdarnell
Copy link
Copy Markdown
Contributor Author

There's another call to log.V just below this, so if this is a place that's too frequent for log.V we should do something about the other one too.

Is anyone actually using this message? Can we just get rid of it? It seems like this is the kind of message that should go into a trace or something like that but stay out of the main logs. Or conversely, if this is something worth logging, can we add more context to the message to tie it back to the memory-using query?

@knz
Copy link
Copy Markdown
Contributor

knz commented Feb 11, 2019

I hadn't seen the log.V call below, so please disregard my previous comment. Yours is fine.

The existence of this message is motivated by a need to signal the user when their queries are behaving unreasonably wrt memory usage. Without any message at all, there won't be smoking guns in log files when ram usage starts to balloon because of SQL.

However we may get away with increasing the noteworthy limit?

@bdarnell
Copy link
Copy Markdown
Contributor Author

The existence of this message is motivated by a need to signal the user when their queries are behaving unreasonably wrt memory usage. Without any message at all, there won't be smoking guns in log files when ram usage starts to balloon because of SQL.

It's not doing a good job of that. It just looks like this; what can I do with it? (if I even think to look in the log files which are rarely intelligible to users). Should users strive to ensure that these messages never appear in their logs? How?

I190208 18:20:26.931012 3872 util/mon/bytes_usage.go:607  distsql: bytes usage increases to 1.0 MiB (+10240)
I190208 18:20:26.931022 3872 util/mon/bytes_usage.go:607  flow: bytes usage increases to 1.0 MiB (+10240)
I190208 18:20:27.106544 3872 util/mon/bytes_usage.go:607  distsql: bytes usage increases to 1.0 MiB (+20480)
I190208 18:20:27.106552 3872 util/mon/bytes_usage.go:607  flow: bytes usage increases to 1.0 MiB (+20480)
I190208 18:20:27.143992 3872 util/mon/bytes_usage.go:607  distsql: bytes usage increases to 1.0 MiB (+20480)
I190208 18:20:27.406353 3872 util/mon/bytes_usage.go:607  distsql: bytes usage increases to 1.0 MiB (+20480)
I190208 18:20:27.406363 3872 util/mon/bytes_usage.go:607  flow: bytes usage increases to 1.0 MiB (+20480)
I190208 18:20:27.525779 3872 util/mon/bytes_usage.go:607  distsql: bytes usage increases to 1.0 MiB (+20480)
I190208 18:20:27.525789 3872 util/mon/bytes_usage.go:607  flow: bytes usage increases to 1.0 MiB (+20480)
I190208 18:20:27.832207 3872 util/mon/bytes_usage.go:607  distsql: bytes usage increases to 1.0 MiB (+20480)
I190208 18:20:27.832217 3872 util/mon/bytes_usage.go:607  flow: bytes usage increases to 1.0 MiB (+20480)
I190208 18:20:27.999953 3872 util/mon/bytes_usage.go:607  distsql: bytes usage increases to 1.0 MiB (+20480)
I190208 18:20:28.000244 3872 util/mon/bytes_usage.go:607  flow: bytes usage increases to 1.0 MiB (+10240)
I190208 18:20:28.200866 3872 util/mon/bytes_usage.go:607  distsql: bytes usage increases to 1.0 MiB (+10240)

This report is for monitored allocations, so it's not going to alert the user to memory usage that may lead to crashes. I think we should ensure that this information gets into the traces (if enabled) and the statements page, but it's not helpful in the logs.

@jordanlewis
Copy link
Copy Markdown
Member

I agree that this message is unactionable. It might make sense in the context of a database that is running a well-known, single query at a time workload, where an operator is watching the logs as queries are getting sent. But in a production database, someone will only look at the logs later - and see a flood of messages like this that are not linkable back to the original query. What would an operator do at that point?

I would vote for removing this line, but keeping one that indicates when queries were terminated due to lack of available memory resources.

@knz
Copy link
Copy Markdown
Contributor

knz commented Feb 12, 2019

I'll trust your collective judgment here. My past experience in that area is hardly a good standard for the future.

@bdarnell
Copy link
Copy Markdown
Contributor Author

Can I get an LGTM? @jordanlewis @knz

This message can be logged frequently in certain workloads, and its
appearance in the info log is not actionable since there is no way to
tie it back to the query that caused it. I see no reason to have
these messages enabled by default.

Release note: None
@bdarnell
Copy link
Copy Markdown
Contributor Author

bors r=knz

craig bot pushed a commit that referenced this pull request Feb 25, 2019
34806: util/mon: Downgrade "bytes usage increases" log message r=knz a=bdarnell

This message can be logged frequently in certain workloads, and its
appearance in the info log is not actionable since there is no way to
tie it back to the query that caused it. I see no reason to have
these messages enabled by default.

Release note: None

34886: storage/engine,libroach: 1x write amplification on ingest sst r=dt a=dt

This uses the new flag added in facebook/rocksdb#4172 to avoid needing to make global_seq_no-related edits to SSTs, and thus avoid the SST copying those edits forced us to do to preserve the raft log immutability when hard-linking directly to side load SSTs.

This is gated on a cluster version that is defined well after the upgrade to rocks 5.17, since using the flag requires that no older versions of RocksDB (<5.16),
will ever be used to read these SSTs, as they will lack the seq_no that the older versions need for correctness.

Release note (performance improvement): reduce write-amplification during bulk-loading (IMPORT and RESTORE)

34902: sql: ensure spans get anonymized in plan collection r=knz a=knz

Fixes #34889.

Release note (bug fix): The logical plans collected for display in the
web UI now also hide the details of which key ranges are scanned in
table lookups.

Co-authored-by: Ben Darnell <ben@bendarnell.com>
Co-authored-by: David Taylor <tinystatemachine@gmail.com>
Co-authored-by: Raphael 'kena' Poss <knz@cockroachlabs.com>
@craig
Copy link
Copy Markdown
Contributor

craig bot commented Feb 25, 2019

Build succeeded

@craig craig bot merged commit 6f59230 into cockroachdb:master Feb 25, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants