Skip to content

Commit 1ae057b

Browse files
rmdmattinglyrmdmattingly
authored
HBASE-27536: Include more request information in slowlog for Scans (#5166)
Signed-off-by: Viraj Jasani <vjasani@apache.org> Signed-off-by: Bryan Beaudreault <bbeaudreault@apache.org>
1 parent b75c72d commit 1ae057b

File tree

8 files changed

+237
-21
lines changed

8 files changed

+237
-21
lines changed

‎hbase-client/src/main/java/org/apache/hadoop/hbase/client/OnlineLogRecord.java‎

Lines changed: 31 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717
*/
1818
package org.apache.hadoop.hbase.client;
1919

20+
import java.util.Optional;
2021
import org.apache.commons.lang3.builder.EqualsBuilder;
2122
import org.apache.commons.lang3.builder.HashCodeBuilder;
2223
import org.apache.commons.lang3.builder.ToStringBuilder;
@@ -52,6 +53,11 @@ final public class OnlineLogRecord extends LogEntry {
5253
if (slowLogPayload.getMultiServiceCalls() == 0) {
5354
jsonObj.remove("multiServiceCalls");
5455
}
56+
if (slowLogPayload.getScan().isPresent()) {
57+
jsonObj.add("scan", gson.toJsonTree(slowLogPayload.getScan().get().toMap()));
58+
} else {
59+
jsonObj.remove("scan");
60+
}
5561
return jsonObj;
5662
}).create();
5763

@@ -72,6 +78,7 @@ final public class OnlineLogRecord extends LogEntry {
7278
private final int multiGetsCount;
7379
private final int multiMutationsCount;
7480
private final int multiServiceCalls;
81+
private final Optional<Scan> scan;
7582

7683
public long getStartTime() {
7784
return startTime;
@@ -136,11 +143,20 @@ public int getMultiServiceCalls() {
136143
return multiServiceCalls;
137144
}
138145

139-
private OnlineLogRecord(final long startTime, final int processingTime, final int queueTime,
146+
/**
147+
* If {@value org.apache.hadoop.hbase.HConstants#SLOW_LOG_SCAN_PAYLOAD_ENABLED} is enabled then
148+
* this value may be present and should represent the Scan that produced the given
149+
* {@link OnlineLogRecord}
150+
*/
151+
public Optional<Scan> getScan() {
152+
return scan;
153+
}
154+
155+
OnlineLogRecord(final long startTime, final int processingTime, final int queueTime,
140156
final long responseSize, final long blockBytesScanned, final String clientAddress,
141157
final String serverClass, final String methodName, final String callDetails, final String param,
142158
final String regionName, final String userName, final int multiGetsCount,
143-
final int multiMutationsCount, final int multiServiceCalls) {
159+
final int multiMutationsCount, final int multiServiceCalls, final Scan scan) {
144160
this.startTime = startTime;
145161
this.processingTime = processingTime;
146162
this.queueTime = queueTime;
@@ -156,6 +172,7 @@ private OnlineLogRecord(final long startTime, final int processingTime, final in
156172
this.multiGetsCount = multiGetsCount;
157173
this.multiMutationsCount = multiMutationsCount;
158174
this.multiServiceCalls = multiServiceCalls;
175+
this.scan = Optional.ofNullable(scan);
159176
}
160177

161178
public static class OnlineLogRecordBuilder {
@@ -174,6 +191,7 @@ public static class OnlineLogRecordBuilder {
174191
private int multiGetsCount;
175192
private int multiMutationsCount;
176193
private int multiServiceCalls;
194+
private Scan scan = null;
177195

178196
public OnlineLogRecordBuilder setStartTime(long startTime) {
179197
this.startTime = startTime;
@@ -253,10 +271,15 @@ public OnlineLogRecordBuilder setMultiServiceCalls(int multiServiceCalls) {
253271
return this;
254272
}
255273

274+
public OnlineLogRecordBuilder setScan(Scan scan) {
275+
this.scan = scan;
276+
return this;
277+
}
278+
256279
public OnlineLogRecord build() {
257280
return new OnlineLogRecord(startTime, processingTime, queueTime, responseSize,
258281
blockBytesScanned, clientAddress, serverClass, methodName, callDetails, param, regionName,
259-
userName, multiGetsCount, multiMutationsCount, multiServiceCalls);
282+
userName, multiGetsCount, multiMutationsCount, multiServiceCalls, scan);
260283
}
261284
}
262285

@@ -280,15 +303,17 @@ public boolean equals(Object o) {
280303
.append(multiServiceCalls, that.multiServiceCalls).append(clientAddress, that.clientAddress)
281304
.append(serverClass, that.serverClass).append(methodName, that.methodName)
282305
.append(callDetails, that.callDetails).append(param, that.param)
283-
.append(regionName, that.regionName).append(userName, that.userName).isEquals();
306+
.append(regionName, that.regionName).append(userName, that.userName).append(scan, that.scan)
307+
.isEquals();
284308
}
285309

286310
@Override
287311
public int hashCode() {
288312
return new HashCodeBuilder(17, 37).append(startTime).append(processingTime).append(queueTime)
289313
.append(responseSize).append(blockBytesScanned).append(clientAddress).append(serverClass)
290314
.append(methodName).append(callDetails).append(param).append(regionName).append(userName)
291-
.append(multiGetsCount).append(multiMutationsCount).append(multiServiceCalls).toHashCode();
315+
.append(multiGetsCount).append(multiMutationsCount).append(multiServiceCalls).append(scan)
316+
.toHashCode();
292317
}
293318

294319
@Override
@@ -305,7 +330,7 @@ public String toString() {
305330
.append("methodName", methodName).append("callDetails", callDetails).append("param", param)
306331
.append("regionName", regionName).append("userName", userName)
307332
.append("multiGetsCount", multiGetsCount).append("multiMutationsCount", multiMutationsCount)
308-
.append("multiServiceCalls", multiServiceCalls).toString();
333+
.append("multiServiceCalls", multiServiceCalls).append("scan", scan).toString();
309334
}
310335

311336
}

‎hbase-client/src/main/java/org/apache/hadoop/hbase/client/SlowLogParams.java‎

Lines changed: 18 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,8 @@
2323
import org.apache.commons.lang3.builder.ToStringBuilder;
2424
import org.apache.yetus.audience.InterfaceAudience;
2525

26+
import org.apache.hadoop.hbase.shaded.protobuf.generated.ClientProtos;
27+
2628
/**
2729
* SlowLog params object that contains detailed info as params and region name : to be used for
2830
* filter purpose
@@ -32,15 +34,24 @@ public class SlowLogParams {
3234

3335
private final String regionName;
3436
private final String params;
37+
private final ClientProtos.Scan scan;
38+
39+
public SlowLogParams(String regionName, String params, ClientProtos.Scan scan) {
40+
this.regionName = regionName;
41+
this.params = params;
42+
this.scan = scan;
43+
}
3544

3645
public SlowLogParams(String regionName, String params) {
3746
this.regionName = regionName;
3847
this.params = params;
48+
this.scan = null;
3949
}
4050

4151
public SlowLogParams(String params) {
4252
this.regionName = StringUtils.EMPTY;
4353
this.params = params;
54+
this.scan = null;
4455
}
4556

4657
public String getRegionName() {
@@ -51,10 +62,14 @@ public String getParams() {
5162
return params;
5263
}
5364

65+
public ClientProtos.Scan getScan() {
66+
return scan;
67+
}
68+
5469
@Override
5570
public String toString() {
5671
return new ToStringBuilder(this).append("regionName", regionName).append("params", params)
57-
.toString();
72+
.append("scan", scan).toString();
5873
}
5974

6075
@Override
@@ -67,11 +82,11 @@ public boolean equals(Object o) {
6782
}
6883
SlowLogParams that = (SlowLogParams) o;
6984
return new EqualsBuilder().append(regionName, that.regionName).append(params, that.params)
70-
.isEquals();
85+
.append("scan", scan).isEquals();
7186
}
7287

7388
@Override
7489
public int hashCode() {
75-
return new HashCodeBuilder(17, 37).append(regionName).append(params).toHashCode();
90+
return new HashCodeBuilder(17, 37).append(regionName).append(params).append(scan).toHashCode();
7691
}
7792
}

‎hbase-client/src/main/java/org/apache/hadoop/hbase/shaded/protobuf/ProtobufUtil.java‎

Lines changed: 20 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -126,6 +126,8 @@
126126
import org.apache.hadoop.hbase.util.VersionInfo;
127127
import org.apache.hadoop.ipc.RemoteException;
128128
import org.apache.yetus.audience.InterfaceAudience;
129+
import org.slf4j.Logger;
130+
import org.slf4j.LoggerFactory;
129131

130132
import org.apache.hbase.thirdparty.com.google.common.io.ByteStreams;
131133
import org.apache.hbase.thirdparty.com.google.gson.JsonArray;
@@ -226,6 +228,8 @@
226228
@InterfaceAudience.Private // TODO: some clients (Hive, etc) use this class
227229
public final class ProtobufUtil {
228230

231+
private static final Logger LOG = LoggerFactory.getLogger(ProtobufUtil.class.getName());
232+
229233
private ProtobufUtil() {
230234
}
231235

@@ -2111,15 +2115,19 @@ private static String getStringForByteString(ByteString bs) {
21112115
* @param message Message object {@link Message}
21122116
* @return SlowLogParams with regionName(for filter queries) and params
21132117
*/
2114-
public static SlowLogParams getSlowLogParams(Message message) {
2118+
public static SlowLogParams getSlowLogParams(Message message, boolean slowLogScanPayloadEnabled) {
21152119
if (message == null) {
21162120
return null;
21172121
}
21182122
if (message instanceof ScanRequest) {
21192123
ScanRequest scanRequest = (ScanRequest) message;
21202124
String regionName = getStringForByteString(scanRequest.getRegion().getValue());
21212125
String params = TextFormat.shortDebugString(message);
2122-
return new SlowLogParams(regionName, params);
2126+
if (slowLogScanPayloadEnabled) {
2127+
return new SlowLogParams(regionName, params, scanRequest.getScan());
2128+
} else {
2129+
return new SlowLogParams(regionName, params);
2130+
}
21232131
} else if (message instanceof MutationProto) {
21242132
MutationProto mutationProto = (MutationProto) message;
21252133
String params = "type= " + mutationProto.getMutateType().toString();
@@ -3326,7 +3334,7 @@ public static Set<String> toCompactedStoreFiles(byte[] bytes) throws IOException
33263334
* @return SlowLog Payload for client usecase
33273335
*/
33283336
private static LogEntry getSlowLogRecord(final TooSlowLog.SlowLogPayload slowLogPayload) {
3329-
OnlineLogRecord onlineLogRecord =
3337+
OnlineLogRecord.OnlineLogRecordBuilder onlineLogRecord =
33303338
new OnlineLogRecord.OnlineLogRecordBuilder().setCallDetails(slowLogPayload.getCallDetails())
33313339
.setClientAddress(slowLogPayload.getClientAddress())
33323340
.setMethodName(slowLogPayload.getMethodName())
@@ -3338,8 +3346,15 @@ private static LogEntry getSlowLogRecord(final TooSlowLog.SlowLogPayload slowLog
33383346
.setResponseSize(slowLogPayload.getResponseSize())
33393347
.setBlockBytesScanned(slowLogPayload.getBlockBytesScanned())
33403348
.setServerClass(slowLogPayload.getServerClass()).setStartTime(slowLogPayload.getStartTime())
3341-
.setUserName(slowLogPayload.getUserName()).build();
3342-
return onlineLogRecord;
3349+
.setUserName(slowLogPayload.getUserName());
3350+
if (slowLogPayload.hasScan()) {
3351+
try {
3352+
onlineLogRecord.setScan(ProtobufUtil.toScan(slowLogPayload.getScan()));
3353+
} catch (Exception e) {
3354+
LOG.warn("Failed to convert Scan proto {}", slowLogPayload.getScan(), e);
3355+
}
3356+
}
3357+
return onlineLogRecord.build();
33433358
}
33443359

33453360
/**

‎hbase-client/src/test/java/org/apache/hadoop/hbase/client/TestOnlineLogRecord.java‎

Lines changed: 56 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,56 @@
1+
/*
2+
* Licensed to the Apache Software Foundation (ASF) under one
3+
* or more contributor license agreements. See the NOTICE file
4+
* distributed with this work for additional information
5+
* regarding copyright ownership. The ASF licenses this file
6+
* to you under the Apache License, Version 2.0 (the
7+
* "License"); you may not use this file except in compliance
8+
* with the License. You may obtain a copy of the License at
9+
*
10+
* http://www.apache.org/licenses/LICENSE-2.0
11+
*
12+
* Unless required by applicable law or agreed to in writing, software
13+
* distributed under the License is distributed on an "AS IS" BASIS,
14+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15+
* See the License for the specific language governing permissions and
16+
* limitations under the License.
17+
*/
18+
package org.apache.hadoop.hbase.client;
19+
20+
import org.apache.hadoop.hbase.HBaseClassTestRule;
21+
import org.apache.hadoop.hbase.testclassification.ClientTests;
22+
import org.apache.hadoop.hbase.testclassification.SmallTests;
23+
import org.apache.hadoop.hbase.util.Bytes;
24+
import org.junit.Assert;
25+
import org.junit.ClassRule;
26+
import org.junit.Test;
27+
import org.junit.experimental.categories.Category;
28+
29+
@Category({ ClientTests.class, SmallTests.class })
30+
public class TestOnlineLogRecord {
31+
32+
@ClassRule
33+
public static final HBaseClassTestRule CLASS_RULE =
34+
HBaseClassTestRule.forClass(TestOnlineLogRecord.class);
35+
36+
@Test
37+
public void itSerializesScan() {
38+
Scan scan = new Scan();
39+
scan.withStartRow(Bytes.toBytes(123));
40+
scan.withStopRow(Bytes.toBytes(456));
41+
String expectedOutput = "{\n" + " \"startTime\": 1,\n" + " \"processingTime\": 2,\n"
42+
+ " \"queueTime\": 3,\n" + " \"responseSize\": 4,\n" + " \"blockBytesScanned\": 5,\n"
43+
+ " \"multiGetsCount\": 6,\n" + " \"multiMutationsCount\": 7,\n" + " \"scan\": {\n"
44+
+ " \"startRow\": \"\\\\x00\\\\x00\\\\x00{\",\n"
45+
+ " \"stopRow\": \"\\\\x00\\\\x00\\\\x01\\\\xC8\",\n" + " \"batch\": -1,\n"
46+
+ " \"cacheBlocks\": true,\n" + " \"totalColumns\": 0,\n"
47+
+ " \"maxResultSize\": -1,\n" + " \"families\": {},\n" + " \"caching\": -1,\n"
48+
+ " \"maxVersions\": 1,\n" + " \"timeRange\": [\n" + " 0,\n"
49+
+ " 9223372036854775807\n" + " ]\n" + " }\n" + "}";
50+
OnlineLogRecord o =
51+
new OnlineLogRecord(1, 2, 3, 4, 5, null, null, null, null, null, null, null, 6, 7, 0, scan);
52+
String actualOutput = o.toJsonPrettyPrint();
53+
System.out.println(actualOutput);
54+
Assert.assertEquals(actualOutput, expectedOutput);
55+
}
56+
}

‎hbase-common/src/main/java/org/apache/hadoop/hbase/HConstants.java‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1656,6 +1656,9 @@ public enum OperationStatusCode {
16561656
// Default 10 mins.
16571657
public static final int DEFAULT_SLOW_LOG_SYS_TABLE_CHORE_DURATION = 10 * 60 * 1000;
16581658

1659+
public static final String SLOW_LOG_SCAN_PAYLOAD_ENABLED = "hbase.slowlog.scan.payload.enabled";
1660+
public static final boolean SLOW_LOG_SCAN_PAYLOAD_ENABLED_DEFAULT = false;
1661+
16591662
public static final String SHELL_TIMESTAMP_FORMAT_EPOCH_KEY =
16601663
"hbase.shell.timestamp.format.epoch";
16611664

‎hbase-protocol-shaded/src/main/protobuf/TooSlowLog.proto‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,8 @@ option java_outer_classname = "TooSlowLog";
2727
option java_generate_equals_and_hash = true;
2828
option optimize_for = SPEED;
2929

30+
import "Client.proto";
31+
3032
message SlowLogPayload {
3133
required int64 start_time = 1;
3234
required int32 processing_time = 2;
@@ -45,6 +47,7 @@ message SlowLogPayload {
4547
required Type type = 15;
4648

4749
optional int64 block_bytes_scanned = 16;
50+
optional Scan scan = 17;
4851

4952
// SLOW_LOG is RPC call slow in nature whereas LARGE_LOG is RPC call quite large.
5053
// Majority of times, slow logs are also large logs and hence, ALL is combination of

‎hbase-server/src/main/java/org/apache/hadoop/hbase/namequeues/impl/SlowLogQueueService.java‎

Lines changed: 11 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -65,10 +65,13 @@ public class SlowLogQueueService implements NamedQueueService {
6565
private final boolean isSlowLogTableEnabled;
6666
private final SlowLogPersistentService slowLogPersistentService;
6767
private final Queue<TooSlowLog.SlowLogPayload> slowLogQueue;
68+
private final boolean slowLogScanPayloadEnabled;
6869

6970
public SlowLogQueueService(Configuration conf) {
7071
this.isOnlineLogProviderEnabled = conf.getBoolean(HConstants.SLOW_LOG_BUFFER_ENABLED_KEY,
7172
HConstants.DEFAULT_ONLINE_LOG_PROVIDER_ENABLED);
73+
this.slowLogScanPayloadEnabled = conf.getBoolean(HConstants.SLOW_LOG_SCAN_PAYLOAD_ENABLED,
74+
HConstants.SLOW_LOG_SCAN_PAYLOAD_ENABLED_DEFAULT);
7275

7376
if (!isOnlineLogProviderEnabled) {
7477
this.isSlowLogTableEnabled = false;
@@ -129,7 +132,8 @@ public void consumeEventFromDisruptor(NamedQueuePayload namedQueuePayload) {
129132
long endTime = EnvironmentEdgeManager.currentTime();
130133
int processingTime = (int) (endTime - startTime);
131134
int qTime = (int) (startTime - receiveTime);
132-
final SlowLogParams slowLogParams = ProtobufUtil.getSlowLogParams(param);
135+
final SlowLogParams slowLogParams =
136+
ProtobufUtil.getSlowLogParams(param, slowLogScanPayloadEnabled);
133137
int numGets = 0;
134138
int numMutations = 0;
135139
int numServiceCalls = 0;
@@ -152,16 +156,19 @@ public void consumeEventFromDisruptor(NamedQueuePayload namedQueuePayload) {
152156
final String userName = rpcCall.getRequestUserName().orElse(StringUtils.EMPTY);
153157
final String methodDescriptorName =
154158
methodDescriptor != null ? methodDescriptor.getName() : StringUtils.EMPTY;
155-
TooSlowLog.SlowLogPayload slowLogPayload = TooSlowLog.SlowLogPayload.newBuilder()
159+
TooSlowLog.SlowLogPayload.Builder slowLogPayloadBuilder = TooSlowLog.SlowLogPayload.newBuilder()
156160
.setCallDetails(methodDescriptorName + "(" + param.getClass().getName() + ")")
157161
.setClientAddress(clientAddress).setMethodName(methodDescriptorName).setMultiGets(numGets)
158162
.setMultiMutations(numMutations).setMultiServiceCalls(numServiceCalls)
159163
.setParam(slowLogParams != null ? slowLogParams.getParams() : StringUtils.EMPTY)
160164
.setProcessingTime(processingTime).setQueueTime(qTime)
161165
.setRegionName(slowLogParams != null ? slowLogParams.getRegionName() : StringUtils.EMPTY)
162166
.setResponseSize(responseSize).setBlockBytesScanned(blockBytesScanned)
163-
.setServerClass(className).setStartTime(startTime).setType(type).setUserName(userName)
164-
.build();
167+
.setServerClass(className).setStartTime(startTime).setType(type).setUserName(userName);
168+
if (slowLogParams != null && slowLogParams.getScan() != null) {
169+
slowLogPayloadBuilder.setScan(slowLogParams.getScan());
170+
}
171+
TooSlowLog.SlowLogPayload slowLogPayload = slowLogPayloadBuilder.build();
165172
slowLogQueue.add(slowLogPayload);
166173
if (isSlowLogTableEnabled) {
167174
if (!slowLogPayload.getRegionName().startsWith("hbase:slowlog")) {

0 commit comments

Comments
 (0)