PHOENIX-6388 Add sampled logging for read repairs #1146
Conversation
|
💔 -1 overall
This message was automatically generated. |
| if (shouldLog()) { | ||
| LOG.info("Index row repair on region " | ||
| + env.getRegionInfo().getRegionNameAsString() + " took " | ||
| + repairTime + "ms"); |
There was a problem hiding this comment.
nit: use {} substitution for parameters ?
yanxinyi
force-pushed
the
PHOENIX-6388-4.X
branch
from
33ca9be
to
33fefeb
Compare
|
💔 -1 overall
This message was automatically generated. |
| @@ -101,6 +102,9 @@ | |||
| */ | |||
| public class GlobalIndexChecker extends BaseScannerRegionObserver { | |||
| private static final Logger LOG = LoggerFactory.getLogger(GlobalIndexChecker.class); | |||
| private static final String REPAIR_LOGGING_PERCENT_ATTRIB = "phoenix.index.repair.logging.percent"; | |||
| private static final double DEFAULT_REPAIR_LOGGING_PERCENT = 0.01; | |||
There was a problem hiding this comment.
As per random.nextDouble() <= (loggingPercent / 100.0d), we will compare random.nextDouble() with 0.01/100 = 0.0001 which seems way less. If we can keep default value as 1 here, even 1/100 is going to be very less as far as random distribution between 0 and 1 is concerned. Unless we never want to log with default config value, i think we should change this to 1 (at least some better probability of logging read repairs than 0.01 as default value, which is almost never going to log)
| if (shouldLog()) { | ||
| LOG.info(String.format("Index row repair on region %s took %d ms.", | ||
| env.getRegionInfo().getRegionNameAsString(), repairTime)); | ||
| } |
There was a problem hiding this comment.
This is good one, however regardless of shouldLog(), we might want to consider logging at TRACE level always:
if (shouldLog()) {
LOG.info("Index row repair on region {} took {} ms.",
env.getRegionInfo().getRegionNameAsString(), repairTime);
}
if (LOG.isTraceEnabled()) {
LOG.trace("Index row repair on region {} took {} ms.",
env.getRegionInfo().getRegionNameAsString(), repairTime);
}
There was a problem hiding this comment.
nit: String.format() is not required, we can use slf4j log placeholder {}
LOG.info("Index row repair on region {} took {} ms.",
env.getRegionInfo().getRegionNameAsString(), repairTime);
There was a problem hiding this comment.
Agree on the placeholder, but I don't think addig the unconditional trace log is a good idea.
We should not use one set of conditions for INFO, and another for TRACE, and should not double log, as both conflicts with the usual/expected logging semantics.
There was a problem hiding this comment.
I was just thinking if a user enables TRACE logging, this is a good log candidate for all read repairs (it might be overwhelming too but that's why unconditional TRACE might be more suitable) and whereas % based logs at INFO level won't make it overwhelming which is the purpose of this PR anyways. Thoughts?
There was a problem hiding this comment.
On one hand, logging every event with trace would make sense from an operational standpoint, as it can theoretically be enabled without restarting the RS (I THINK that LOG4j will pick logging config file changes during runtime)
On the other hand I feel that having a statistic logging at INFO level, but also logging everything at TRACE level would go against the 'do not surprise/confuse the user' principle. AFAIK we have other statistic logging events, which cover similar cases, but we don't override the percentage setting like this.
IMO REPAIR_LOGGING_PERCENT_ATTRIB sets the probability for logging the event at INFO, but we're logging every event at TRACE anyway is not intuitive behaviour, nor is logging the same event twice at different logging levels.
Unfiltered trace logging in production systems in unsustainable, and if someone wants to do targeted log index rebuilds, he can just use the percentage setting (which is easier to get right than logging config, even if it does require an RS restart to take effect)
There was a problem hiding this comment.
nor is logging the same event twice at different logging levels.
Yeah got your point, sure I think it's fine, we don't need TRACE level logging, anyways we have some useful metrics available too e.g unverifiedIndexRowAge, indexRepairTime etc
| if (shouldLog()) { | ||
| LOG.warn(String.format("Index row repair failure on region %s took %d ms.", | ||
| env.getRegionInfo().getRegionNameAsString(), repairTime)); | ||
| } |
yanxinyi
force-pushed
the
PHOENIX-6388-4.X
branch
from
33fefeb
to
e67204d
Compare
|
💔 -1 overall
This message was automatically generated. |
yanxinyi
force-pushed
the
PHOENIX-6388-4.X
branch
from
e67204d
to
2591235
Compare
|
💔 -1 overall
This message was automatically generated. |
No description provided.