log,allocatorimpl: log allocation messages to a separate log file

[lidorcarmel]

The allocator logs are written to the main log file, which means that
those messages sometimes spam the main log, and also, we can't increase
verbosity much. Because of that most allocation logs are now under a
vlog and therefore rarely used.

This PR moves all allocation logs to a separate channel, and file.

The next step would be to move some log messages from VEvent to be
printed always, which should help debugging.

Step 1 for #82836.

Release note: None

Release justification: low risk, should not change behavior, the main
change is having a new log file for distribution logs, the number of
log messages should not increase.

[cockroach-teamcity]

This change is 

[lidorcarmel]

cc @knz and @nvanbenschoten

[kvoli]

Reviewed 18 of 18 files at r1, all commit messages.
Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @aayushshah15)

[dhartunian]

This is reminding me that I never merged #74770 which was to offer some guidance on when to create new logging channels. I'll get on that.

I have, in the past, expressed concern about creating logging channels that are too specific. Could we perhaps justify creating a KV channel that's known to be verbose? That can at least be a magnet for more messages like this in the future.

This is change that would necessitate modification of log configuration for customers and in the cloud where we have a list of channels we persist to S3 and send to customer sinks. I'd prefer to do that rarely.

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @aayushshah15)

[knz]

No comment from me other than what David already said/requested.

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @aayushshah15)

[lidorcarmel]

thanks David for the context, this is super helpful.

offer some guidance on when to create new logging channels

• I think 3 applies here - this is the main reason for this PR, we currently don't log much because we will spam the current file quickly if we do. Allocation issues come up frequently in escalations and more verbose logging I suspect would be useful.

• 2 somewhat applies here, maybe. "KV" is distribution + transaction + replication, so with this PR we will have all distribution logs in a separate channel, looked at by the "distribution team" (there is no such team yet though).

I'm not sure I understand 1.. asked a question there.

Could we perhaps justify creating a KV channel that's known to be verbose?

That makes sense to me now, but maybe for longer term we should be more granular and have a distribution channel, we probably don't want a KV channel now and later break that to 2 or 3 channels.

That said, I'm sure others have more to say..

cc @tbg

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @aayushshah15)

[knz]

we probably don't want a KV channel now and later break that to 2 or 3 channels.

I don't know about that. What about using multiple separate structured event types, such that we can keep the option to do post-loggging filtering on event type?

[tbg]

I think some splitting up of log files is worth it. I spend a lot of time just iterating on grep -v for most incidents, and even the KV logs have lots of information that isn't always relevant.
I think of the allocator logging that is likely to be added like the pebble logs. Usually you don't want to see them, unless you suspect something is off with pebble or the allocator. So they shouldn't mix into the main file or even into a main KV file if it existed, as they would simply be too verbose.

The message related to replication changes (i.e. when the allocator actions are taken) are already fairly verbose, too. I think it makes sense to have a message about the decision in the main log (moving replica X away, or replica Y is now deleted) but not all of the intermediate steps - adding learner, sending snapshot, entering joint quorum, leaving joint quorum, etc. So maybe these messages could also go to the distribution channel together with more verbose info about the allocator.

We would then have

• DEV
• KV-DISTRIBUTION

It probably makes sense to split out KV as well (which raises questions about whether to split further into KV-SERVER and KV-CLIENT in light of these living on separate machines in multi-tenant settings which is supposed to be the new normal).

But I am a lot less sure about these things due to this affecting all customers. We can't really experiment with these splits, which is sort of sad. It would be nice if these logging channels could be "virtual" enough so that customers don't have to know about all of them. That said, I think KV-SERVER, KV-DISTRIBUTION, KV-CLIENT would be a justifiable split that would carry us for the foreseeable future. By default KV-{CLIENT,SERVER} would go into the main log file, and distribution would get its own file. Since the log channel is encoded in each message, CRL engs could use a (updated) merge-logs that lets you select the channels to watch.

(I hope my mental model of log channels is right).

[knz]

It would be nice if these logging channels could be "virtual" enough so that customers don't have to know about all of them

They are. Separate files don't get created unless you modify the default config (cli/log_flags.go) to pull individual channels out in their own separate file group. They get redirected to the same file as the DEV channel by default.

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @aayushshah15)

[lidorcarmel]

@knz in which cases would we create a channel without directing it to a separate file?

[knz]

in which cases would we create a channel without directing it to a separate file?

In the case we might want to advise a user to do this redirection during, say, a support case.

[andreimatei]

It seems reasonable to me to add an allocator channel. I don't know if I would combine it with other "kv" things, or split more of kv from DEV. I see the allocator as a pretty special subsystem in this regard, similar to Pebble (as Tobi was also saying). The allocator is a long-lived process, fairly self-contained.
If we do add a channel for it, I think we should also change the default log config to direct this channel to a dedicated file group.

@lidor, you've asked me offline if "we can start relying on your new fancy tracing for debugging the allocator". I would not let such plans stop the this PR, fwiw. Otherwise, the way I think "tracing" and "the allocator" can go together in a sentence is by tracing every time the replication queue processes a range. If any action is taken, we could trace everything that the replication queue does on behalf of that range as a single trace, and send these traces to the Obs Service. Centralizing these traces in the Obs Service could help debug, for example, decommissioning problems.

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @aayushshah15 and @lidorcarmel)

---

pkg/kv/kvserver/replicate_queue.go line 438 at r1 (raw file):

	if action == allocatorimpl.AllocatorNoop {
		log.Allocator.VInfof(ctx, 2, "no action to take")

I think you want VEventf over VInfof everywhere. The difference between VEventf and VInfof is that the former always goes to the trace, regardless of the file's verbosity level, whereas the latter only goes to the trace if it also goes to the log (i.e. if the file's verbosity is high enough). In the particular case of this queue, having these messages in the trace is important because there's that debug page that traces one particular range through a queue and gives you back the trace.
I don't know if there's ever a use for VInfof.

For some of these messages, you might want Eventf instead of VEventf, so that the message never goes to the log. For example, for this "no action to take", would this message with no context ever make sense in a log file? Maybe it does if the range id is a log tag here (which I don't know if it's the case).

[lidorcarmel]

Thanks, a few points:

We probably need channels to support Event/vEvent if we want to merge this PR.

Also, sounds like we should not introduce new channels in order to have separation of some logs messages from others, because we should move to a world where logs are consumed using tools like Splunk and not by using the files directly. But, the main reason for this PR still stands: we want to increase verbosity for allocation logs and it's hard to do that if we use the DEV channel - we might starve other important log messages.

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @aayushshah15 and @andreimatei)

---

pkg/kv/kvserver/replicate_queue.go line 438 at r1 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I think you want VEventf over VInfof everywhere. The difference between VEventf and VInfof is that the former always goes to the trace, regardless of the file's verbosity level, whereas the latter only goes to the trace if it also goes to the log (i.e. if the file's verbosity is high enough). In the particular case of this queue, having these messages in the trace is important because there's that debug page that traces one particular range through a queue and gives you back the trace.
I don't know if there's ever a use for VInfof.

For some of these messages, you might want Eventf instead of VEventf, so that the message never goes to the log. For example, for this "no action to take", would this message with no context ever make sense in a log file? Maybe it does if the range id is a log tag here (which I don't know if it's the case).

Right, the name vEvent definitely confused me initially, I guess we didn't want to call it EventAndVInfo.
But IIUC channels don't offer Event or vEvent, so if we do want a separate channel we might need to change that (or maybe I'm missing something here?).

[andreimatei]

We probably need channels to support Event/vEvent if we want to merge this PR.

log.Event does not apply to channels since it has nothing to do with logging at all. I think it should move to tracing.Event completely.
log.VEvent should definitely be supported by channels; I'm shocked that it isn't. I also think we should get rid of VInfo, in favor of VEvent everywhere.

Also, sounds like we should not introduce new channels in order to have separation of some logs messages from others, because we should move to a world where logs are consumed using tools like Splunk and not by using the files directly.

I personally am not sure I agree with this. Or, rather, have yet to see alternative logging infrastructure be available and ergonomic widely enough. A text file is a pretty good interface for consuming log messages, in my opinion, even if logs are also ingested in Splunk.

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @aayushshah15 and @andreimatei)

[knz]

FWIW: when multiple log channels are configured to route to the same file, the channel ID is still included in each event, so we can split the file afterwards.

[lidorcarmel]

@knz - clarification, the log size limit is at the file level I assume? not the channel? and I think it's 10MB per file, up to 10 files, right?

@dhartunian you had some good arguments for not adding a channel, I wonder if you now think it's ok to add?

If we're ok with a new channel, how about:

• I'll add VEvent to secondary channels
• for this PR we don't really need Event because the old code only used it 4 times and all of those can comfortably be VEvents (those make sense in a log file on their own). So we can maybe move log.Event to tracing.Event later.
• The new channel will go to a new file (this is the case in this PR).
• I'll rename Allocator to KvDistribution (channel name KV_DISTRIBUTION I guess)
• David, you mentioned that in Cloud we need to add this channel to some config, and we probably need to change the docs, is there anything else I missed? (perhaps add the list of things to do when adding a channel to your md file, to scare people off :) )

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @aayushshah15 and @andreimatei)

[lidorcarmel]

I forgot one more important thing:

• I probably need to add more logs to the new KvDistribution.. mmm.. if anyone (@tbg maybe?) have some guideline about what should go to the new channel it would be great (Allocator logs were easy, 3 files or so, KvDistribution might be more tricky).

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @aayushshah15 and @andreimatei)

[lidorcarmel]

Done, PTAL.

The only thing I did not do is to add more callers to use the log.KvDistribution - it's still just the allocation code. It's not obvious to me what else should go to this channel, this is probably a good start?

@knz if you can take a look at the log package changes it would be awesome.

Please compare to base.. looking at the recent diff will be confusing.

Reviewable status: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @andreimatei and @kvoli)

---

pkg/kv/kvserver/replicate_queue.go line 438 at r1 (raw file):

Previously, lidorcarmel (Lidor Carmel) wrote…

Right, the name vEvent definitely confused me initially, I guess we didn't want to call it EventAndVInfo.
But IIUC channels don't offer Event or vEvent, so if we do want a separate channel we might need to change that (or maybe I'm missing something here?).

Done.

[andreimatei]

Reviewable status: complete! 1 of 0 LGTMs obtained (and 1 stale) (waiting on @andreimatei, @kvoli, @lidorcarmel, and @tbg)

---

docs/generated/logging.md line 175 at r2 (raw file):

The `KV_DISTRIBUTION` channel is used to report data distribution events, such as
allocation and rebalancing.

I don't think "allocation" will mean much to a reader. Consider putting a few more words, with one of them being "ranges".

---

pkg/kv/kvserver/allocator/allocatorimpl/allocator.go line 668 at r2 (raw file):

		action = AllocatorAddVoter
		adjustedPriority = action.Priority() + float64(desiredQuorum-haveVoters)
		log.KvDistribution.VEventf(ctx, 3, "%s - missing voter need=%d, have=%d, priority=%.2f",

KVDistribution (capitalize the acronyms).

[lidorcarmel]

Reviewable status: complete! 1 of 0 LGTMs obtained (and 1 stale) (waiting on @andreimatei, @kvoli, and @tbg)

---

docs/generated/logging.md line 175 at r2 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

I don't think "allocation" will mean much to a reader. Consider putting a few more words, with one of them being "ranges".

right, done. maybe it's still too vague.. but I think this will evolve if we add more stuff to this channel.

Code quote:

channel is used to report data distribution events, such as

---

pkg/kv/kvserver/allocator/allocatorimpl/allocator.go line 668 at r2 (raw file):

Previously, andreimatei (Andrei Matei) wrote…

KVDistribution (capitalize the acronyms).

unfortunately this is generated and we cannot control this, looks like this is the relevant line:

cockroach/pkg/util/log/gen/main.go

Line 142 in 64c6b81

title := strings.ReplaceAll(cases.Title(language.English, cases.NoLower).String(

similarly we have channels such as log.SqlExec.

[tbg]

Looks good to me! I would probably move these lines as well if they haven't already:

crlMBP-VHN267714PMTY2> I220825 06:30:27.398986 3486 kv/kvserver/replica_command.go:2283 ⋮ [n1,replicate,s1,r27/1:‹/Table/2{6-7}›] 369 change replicas (add [(n3,s3):2] remove []): existing descriptor r27:‹/Table/2{6-7}› [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=1]
crlMBP-VHN267714PMTY2> I220825 06:30:26.613404 1723 kv/kvserver/store_snapshot.go:1512 ⋮ [n2,s2,r14/2:‹/Table/1{3-4}›] 151 streamed INITIAL snapshot 3304cd69 at applied index 239 to (n3,s3):3LEARNER with 46 KiB in 0.00s @ 133 MiB/s: kvs=362 rangeKVs=0, rate-limit: 32 MiB/s, queued: 0.11s
crlMBP-VHN267714PMTY2> I220825 06:30:26.869623 1690 kv/kvserver/replica_raftstorage.go:877 ⋮ [n3,s3,r27/2:{-}] 132 applying INITIAL snapshot 84bec129 from (n1,s1):1 at applied index 20
crlMBP-VHN267714PMTY2> I220825 06:30:26.234258 1601 kv/kvserver/replica_raft.go:346 ⋮ [n2,s2,r14/2:‹/Table/1{3-4}›] 150 proposing SIMPLE(l3) [(n3,s3):3LEARNER]: after=[(n1,s1):1 (n2,s2):2 (n3,s3):3LEARNER] next=4

This would significantly de-noise the main log, and putting these events in the allocator log seems reasonable since most of them are consequences of actions made by the allocator (the one exception perhaps are raft snapshots, but they are still squarely data "distribution" events in some sense, and absent a better sink still fit in there).

If this is at all controversial disregard it for now, I don't want that to hold up this PR.
Thanks for doing this!

Reviewed 16 of 20 files at r2, 1 of 1 files at r3, all commit messages.
Reviewable status: complete! 0 of 0 LGTMs obtained (and 2 stale) (waiting on @andreimatei and @kvoli)

[lidorcarmel]

Thanks! these files make sense.

@tbg , to clarify, adding these messages means (to me) replacing all log.* with log.KvDistribution.* in those 4 files, is that what you had in mind? I don't think we would normally want a single file logging to more than one channel, but maybe this is naive, not sure.

Another small thing is to replace the rare log.Events with log.KvDistribution.VEvent(.. 10..) because channels don't support Events, I think that's fine (10 or something high enough, so that even when using vmodule we would not log these because we don't today).

Reviewable status: complete! 0 of 0 LGTMs obtained (and 2 stale) (waiting on @andreimatei and @kvoli)

[tbg]

@tbg , to clarify, adding these messages means (to me) replacing all log.* with log.KvDistribution.* in those 4 files,

No, just the exact lines, since they are about data movement and are almost always consequences of allocation decisions. They have no context when they appear in the main log, if allocator decisions are elsewhere. Probably one could craft an argument about purism of the allocator logs but if it were my judgment call I'd move them over as well (though not a hill I'd die on).

is that what you had in mind? I don't think we would normally want a single file logging to more than one channel, but maybe this is naive, not sure.

I'm not sure about that either but I tend to think that sounds too rigid. We should base the channel based on what's being logged, not based on what file it is in, which often has additional constraints that can't always be sidestepped.

[lidorcarmel]

Added those 4 log messages, thanks Tobi!

Reviewable status: complete! 0 of 0 LGTMs obtained (and 2 stale) (waiting on @andreimatei, @kvoli, and @tbg)

[lidorcarmel]

thanks all!
bors r+

[craig]

Build succeeded:

• Bazel Essential CI (Cockroach)