Skip to content

Commit f645e2f

Browse files
shenyunlongshenyunlong
committed
add trace-id in log
1 parent a2c88e3 commit f645e2f

File tree

7 files changed

+64
-39
lines changed

7 files changed

+64
-39
lines changed

‎src/main/java/com/alipay/oceanbase/rpc/ObTableClient.java‎

Lines changed: 21 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,7 @@
6767
import static com.alipay.oceanbase.rpc.property.Property.*;
6868
import static com.alipay.oceanbase.rpc.protocol.payload.impl.execute.ObTableOperationType.*;
6969
import static com.alipay.oceanbase.rpc.util.TableClientLoggerFactory.*;
70+
import static com.alipay.oceanbase.rpc.util.TraceUtil.formatTraceMessage;
7071

7172
public class ObTableClient extends AbstractObTableClient implements Lifecycle {
7273
private static final Logger logger = TableClientLoggerFactory
@@ -1506,7 +1507,7 @@ public Map<String, Object> execute(ObPair<Long, ObTable> obPair) throws Exceptio
15061507
checkObTableOperationResult(obTable.getIp(), obTable.getPort(), request, result);
15071508

15081509
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1509-
MONITOR.info(logMessage(tableName, "GET", endpoint, rowKey,
1510+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "GET", endpoint, rowKey,
15101511
(ObTableOperationResult) result, getTableTime - startTime,
15111512
System.currentTimeMillis() - getTableTime));
15121513
return ((ObTableOperationResult) result).getEntity().getSimpleProperties();
@@ -1542,7 +1543,7 @@ public Long execute(ObPair<Long, ObTable> obPair) throws Exception {
15421543
request.setPartitionId(partId);
15431544
ObPayload result = obPair.getRight().execute(request);
15441545
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1545-
MONITOR.info(logMessage(tableName, "UPDATE", endpoint, rowKey,
1546+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "UPDATE", endpoint, rowKey,
15461547
(ObTableOperationResult) result, getTableTime - start,
15471548
System.currentTimeMillis() - getTableTime));
15481549
checkObTableOperationResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -1581,7 +1582,7 @@ public ObPayload execute(ObPair<Long, ObTable> obPair) throws Exception {
15811582
request.setPartitionId(partId);
15821583
ObPayload result = obTable.execute(request);
15831584
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1584-
MONITOR.info(logMessage(tableName, "UPDATE", endpoint, rowKey,
1585+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "UPDATE", endpoint, rowKey,
15851586
(ObTableOperationResult) result, TableTime - start,
15861587
System.currentTimeMillis() - TableTime));
15871588
checkResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -1611,7 +1612,7 @@ public static String buildParamsString(List<Object> rowKeys) {
16111612
return stringBuilder.toString();
16121613
}
16131614

1614-
private String logMessage(String tableName, String methodName, String endpoint,
1615+
private String logMessage(String traceId, String tableName, String methodName, String endpoint,
16151616
Object[] rowKeys, ObTableQueryAndMutateResult result,
16161617
long routeTableTime, long executeTime) {
16171618
if (org.apache.commons.lang.StringUtils.isNotBlank(endpoint)) {
@@ -1624,15 +1625,15 @@ private String logMessage(String tableName, String methodName, String endpoint,
16241625
String res = String.valueOf(result.getAffectedRows());
16251626

16261627
StringBuilder stringBuilder = new StringBuilder();
1627-
stringBuilder.append(",").append(database).append(",").append(tableName).append(",")
1628+
stringBuilder.append(traceId).append(",").append(database).append(",").append(tableName).append(",")
16281629
.append(methodName).append(",").append(endpoint).append(",").append(argsValue)
16291630
.append(",").append(result.toString()).append(",").append(res).append(",")
16301631
.append(routeTableTime).append(",").append(executeTime).append(",")
16311632
.append(executeTime + routeTableTime);
16321633
return stringBuilder.toString();
16331634
}
16341635

1635-
private String logMessage(String tableName, String methodName, String endpoint,
1636+
private String logMessage(String traceId, String tableName, String methodName, String endpoint,
16361637
Object[] rowKeys, ObTableOperationResult result, long routeTableTime,
16371638
long executeTime) {
16381639
if (org.apache.commons.lang.StringUtils.isNotBlank(endpoint)) {
@@ -1657,7 +1658,7 @@ private String logMessage(String tableName, String methodName, String endpoint,
16571658
String errorCodeStringValue = resultCode.toString();
16581659

16591660
StringBuilder stringBuilder = new StringBuilder();
1660-
stringBuilder.append(",").append(database).append(",").append(tableName).append(",")
1661+
stringBuilder.append(traceId).append(",").append(database).append(",").append(tableName).append(",")
16611662
.append(methodName).append(",").append(endpoint).append(",").append(argsValue)
16621663
.append(",").append(errorCodeStringValue).append(",").append(res).append(",")
16631664
.append(routeTableTime).append(",").append(executeTime).append(",")
@@ -1693,7 +1694,7 @@ public Long execute(ObPair<Long, ObTable> obPair) throws Exception {
16931694
request.setPartitionId(partId);
16941695
ObPayload result = obPair.getRight().execute(request);
16951696
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1696-
MONITOR.info(logMessage(tableName, "DELETE", endpoint, rowKey,
1697+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "DELETE", endpoint, rowKey,
16971698
(ObTableOperationResult) result, getTableTime - start,
16981699
System.currentTimeMillis() - getTableTime));
16991700
checkObTableOperationResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -1729,7 +1730,7 @@ public ObPayload execute(ObPair<Long, ObTable> obPair) throws Exception {
17291730
request.setPartitionId(partId);
17301731
ObPayload result = obTable.execute(request);
17311732
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1732-
MONITOR.info(logMessage(tableName, "DELETE", endpoint, rowKey,
1733+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "DELETE", endpoint, rowKey,
17331734
(ObTableOperationResult) result, TableTime - start,
17341735
System.currentTimeMillis() - TableTime));
17351736
checkResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -1766,7 +1767,7 @@ public Long execute(ObPair<Long, ObTable> obPair) throws Exception {
17661767
request.setPartitionId(partId);
17671768
ObPayload result = obPair.getRight().execute(request);
17681769
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1769-
MONITOR.info(logMessage(tableName, "INSERT", endpoint, rowKey,
1770+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "INSERT", endpoint, rowKey,
17701771
(ObTableOperationResult) result, getTableTime - start,
17711772
System.currentTimeMillis() - getTableTime));
17721773
checkObTableOperationResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -1805,7 +1806,7 @@ public ObPayload execute(ObPair<Long, ObTable> obPair) throws Exception {
18051806
request.setPartitionId(partId);
18061807
ObPayload result = obTable.execute(request);
18071808
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1808-
MONITOR.info(logMessage(tableName, "INSERT", endpoint, rowKey,
1809+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "INSERT", endpoint, rowKey,
18091810
(ObTableOperationResult) result, TableTime - start,
18101811
System.currentTimeMillis() - TableTime));
18111812
checkResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -1842,7 +1843,7 @@ public Long execute(ObPair<Long, ObTable> obPair) throws Exception {
18421843
request.setPartitionId(partId);
18431844
ObPayload result = obPair.getRight().execute(request);
18441845
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1845-
MONITOR.info(logMessage(tableName, "REPLACE", endpoint, rowKey,
1846+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "REPLACE", endpoint, rowKey,
18461847
(ObTableOperationResult) result, getTableTime - start,
18471848
System.currentTimeMillis() - getTableTime));
18481849
checkObTableOperationResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -1881,7 +1882,7 @@ public ObPayload execute(ObPair<Long, ObTable> obPair) throws Exception {
18811882
request.setPartitionId(partId);
18821883
ObPayload result = obTable.execute(request);
18831884
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1884-
MONITOR.info(logMessage(tableName, "REPLACE", endpoint, rowKey,
1885+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "REPLACE", endpoint, rowKey,
18851886
(ObTableOperationResult) result, TableTime - start,
18861887
System.currentTimeMillis() - TableTime));
18871888
checkResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -1918,7 +1919,7 @@ public Long execute(ObPair<Long, ObTable> obPair) throws Exception {
19181919
request.setPartitionId(partId);
19191920
ObPayload result = obPair.getRight().execute(request);
19201921
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1921-
MONITOR.info(logMessage(tableName, "INERT_OR_UPDATE", endpoint, rowKey,
1922+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "INERT_OR_UPDATE", endpoint, rowKey,
19221923
(ObTableOperationResult) result, getTableTime - start,
19231924
System.currentTimeMillis() - getTableTime));
19241925
checkObTableOperationResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -1958,7 +1959,7 @@ public ObPayload execute(ObPair<Long, ObTable> obPair) throws Exception {
19581959
request.setPartitionId(partId);
19591960
ObPayload result = obTable.execute(request);
19601961
String endpoint = obTable.getIp() + ":" + obTable.getPort();
1961-
MONITOR.info(logMessage(tableName, "INERT_OR_UPDATE", endpoint, rowKey,
1962+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "INERT_OR_UPDATE", endpoint, rowKey,
19621963
(ObTableOperationResult) result, TableTime - start,
19631964
System.currentTimeMillis() - TableTime));
19641965
checkResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -2007,7 +2008,7 @@ public Map<String, Object> execute(ObPair<Long, ObTable> obPair) throws Exceptio
20072008
request.setPartitionId(partId);
20082009
ObPayload result = obPair.getRight().execute(request);
20092010
String endpoint = obTable.getIp() + ":" + obTable.getPort();
2010-
MONITOR.info(logMessage(tableName, "INCREMENT", endpoint, rowKey,
2011+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "INCREMENT", endpoint, rowKey,
20112012
(ObTableOperationResult) result, getTableTime - start,
20122013
System.currentTimeMillis() - getTableTime));
20132014
checkObTableOperationResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -2052,7 +2053,7 @@ public ObPayload execute(ObPair<Long, ObTable> obPair) throws Exception {
20522053
request.setPartitionId(partId);
20532054
ObPayload result = obTable.execute(request);
20542055
String endpoint = obTable.getIp() + ":" + obTable.getPort();
2055-
MONITOR.info(logMessage(tableName, "INCREMENT", endpoint, rowKey,
2056+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "INCREMENT", endpoint, rowKey,
20562057
(ObTableOperationResult) result, TableTime - start,
20572058
System.currentTimeMillis() - TableTime));
20582059
checkResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -2086,7 +2087,7 @@ public Map<String, Object> execute(ObPair<Long, ObTable> obPair) throws Exceptio
20862087
request.setPartitionId(partId);
20872088
ObPayload result = obPair.getRight().execute(request);
20882089
String endpoint = obTable.getIp() + ":" + obTable.getPort();
2089-
MONITOR.info(logMessage(tableName, "APPEND", endpoint, rowKey,
2090+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "APPEND", endpoint, rowKey,
20902091
(ObTableOperationResult) result, getTableTime - start,
20912092
System.currentTimeMillis() - getTableTime));
20922093
checkObTableOperationResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -2126,7 +2127,7 @@ public ObPayload execute(ObPair<Long, ObTable> obPair) throws Exception {
21262127
request.setPartitionId(partId);
21272128
ObPayload result = obTable.execute(request);
21282129
String endpoint = obTable.getIp() + ":" + obTable.getPort();
2129-
MONITOR.info(logMessage(tableName, "APPEND", endpoint, rowKey,
2130+
MONITOR.info(logMessage(tableName, formatTraceMessage(request), "APPEND", endpoint, rowKey,
21302131
(ObTableOperationResult) result, TableTime - start,
21312132
System.currentTimeMillis() - TableTime));
21322133
checkResult(obTable.getIp(), obTable.getPort(), request, result);
@@ -2187,7 +2188,7 @@ public ObPayload execute(ObPair<Long, ObTable> obPair) throws Exception {
21872188
} else {
21882189
curRowKey = rowKey;
21892190
}
2190-
MONITOR.info(logMessage(tableQuery.toString(), type.toString(), endpoint,
2191+
MONITOR.info(logMessage(formatTraceMessage(request), tableQuery.toString(), type.toString(), endpoint,
21912192
curRowKey, (ObTableQueryAndMutateResult) result, TableTime - start,
21922193
System.currentTimeMillis() - TableTime));
21932194
checkResult(obTable.getIp(), obTable.getPort(), request, result);

‎src/main/java/com/alipay/oceanbase/rpc/bolt/transport/ObTableConnection.java‎

Lines changed: 19 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,9 +28,11 @@
2828
import com.alipay.remoting.Connection;
2929
import org.slf4j.Logger;
3030

31-
import java.util.UUID;
3231
import java.util.concurrent.atomic.AtomicLong;
3332

33+
import static com.alipay.oceanbase.rpc.util.TableClientLoggerFactory.MONITOR;
34+
import static com.alipay.oceanbase.rpc.util.TraceUtil.formatTraceMessage;
35+
3436
public class ObTableConnection {
3537

3638
private static final Logger LOGGER = TableClientLoggerFactory
@@ -81,6 +83,7 @@ private synchronized boolean connect() throws Exception {
8183
if (checkAvailable()) { // double check status available
8284
return false;
8385
}
86+
final long start = System.currentTimeMillis();
8487
Exception cause = null;
8588
int tries = 0;
8689
int maxTryTimes = obTable.getObTableConnectTryTimes();
@@ -95,6 +98,8 @@ private synchronized boolean connect() throws Exception {
9598
"connect failed at " + tries + " try " + TraceUtil.formatIpPort(obTable), e);
9699
}
97100
}
101+
String endpoint = obTable.getIp() + ":" + obTable.getPort();
102+
MONITOR.info(logMessage("", "CONNECT", endpoint, System.currentTimeMillis() - start));
98103

99104
if (tries >= maxTryTimes) {
100105
throw new ObTableServerConnectException("connect failed after max " + maxTryTimes
@@ -113,6 +118,7 @@ private synchronized boolean connect() throws Exception {
113118
}
114119

115120
private synchronized void login() throws Exception {
121+
final long start = System.currentTimeMillis();
116122
ObTableLoginRequest request = new ObTableLoginRequest();
117123
request.setTenantName(obTable.getTenantName());
118124
request.setUserName(obTable.getUserName());
@@ -146,6 +152,8 @@ private synchronized void login() throws Exception {
146152
}
147153
}
148154

155+
String endpoint = obTable.getIp() + ":" + obTable.getPort();
156+
MONITOR.info(logMessage(formatTraceMessage(request), "LOGIN", endpoint, System.currentTimeMillis() - start));
149157
if (tries >= maxTryTimes) {
150158
throw new ObTableServerConnectException("login failed after max " + maxTryTimes
151159
+ " tries " + TraceUtil.formatIpPort(obTable),
@@ -276,4 +284,14 @@ public long getNextSequence() {
276284
return sequence.incrementAndGet();
277285
}
278286

287+
private String logMessage(String traceId, String methodName, String endpoint, long executeTime) {
288+
if (org.apache.commons.lang.StringUtils.isNotBlank(endpoint)) {
289+
endpoint = endpoint.replaceAll(",", "#");
290+
}
291+
292+
StringBuilder stringBuilder = new StringBuilder();
293+
stringBuilder.append(traceId).append(",").append(methodName).append(",").append(endpoint).append(",").append(executeTime);
294+
return stringBuilder.toString();
295+
}
296+
279297
}

0 commit comments

Comments
 (0)