From ababe3d9b05b375678bb7ae8f197cd77ec4e19af Mon Sep 17 00:00:00 2001 From: Anmol Asrani Date: Thu, 5 Oct 2023 00:25:03 +0530 Subject: [PATCH] HADOOP-18875. ABFS: Add sendMs and recvMs information for each AbfsHttpOperation by default. (#6008) Contributed By: Anmol Asrani --- .../azurebfs/services/AbfsHttpOperation.java | 68 ++++++------------- .../services/TestAbfsPerfTracker.java | 4 +- 2 files changed, 23 insertions(+), 49 deletions(-) diff --git a/hadoop-tools/hadoop-azure/src/main/java/org/apache/hadoop/fs/azurebfs/services/AbfsHttpOperation.java b/hadoop-tools/hadoop-azure/src/main/java/org/apache/hadoop/fs/azurebfs/services/AbfsHttpOperation.java index 67ac0c3166..7f5df6066f 100644 --- a/hadoop-tools/hadoop-azure/src/main/java/org/apache/hadoop/fs/azurebfs/services/AbfsHttpOperation.java +++ b/hadoop-tools/hadoop-azure/src/main/java/org/apache/hadoop/fs/azurebfs/services/AbfsHttpOperation.java @@ -79,8 +79,6 @@ public class AbfsHttpOperation implements AbfsPerfLoggable { private int expectedBytesToBeSent; private long bytesReceived; - // optional trace enabled metrics - private final boolean isTraceEnabled; private long connectionTimeMs; private long sendRequestTimeMs; private long recvResponseTimeMs; @@ -104,7 +102,6 @@ public static AbfsHttpOperation getAbfsHttpOperationWithFixedResult( protected AbfsHttpOperation(final URL url, final String method, final int httpStatus) { - this.isTraceEnabled = LOG.isTraceEnabled(); this.url = url; this.method = method; this.statusCode = httpStatus; @@ -188,14 +185,12 @@ public String toString() { sb.append(getClientRequestId()); sb.append(",rid="); sb.append(requestId); - if (isTraceEnabled) { - sb.append(",connMs="); - sb.append(connectionTimeMs); - sb.append(",sendMs="); - sb.append(sendRequestTimeMs); - sb.append(",recvMs="); - sb.append(recvResponseTimeMs); - } + sb.append(",connMs="); + sb.append(connectionTimeMs); + sb.append(",sendMs="); + sb.append(sendRequestTimeMs); + sb.append(",recvMs="); + sb.append(recvResponseTimeMs); sb.append(",sent="); sb.append(bytesSent); sb.append(",recv="); @@ -218,18 +213,16 @@ public String getLogString() { .append(" ci=") .append(getClientRequestId()) .append(" ri=") - .append(requestId); + .append(requestId) - if (isTraceEnabled) { - sb.append(" ct=") - .append(connectionTimeMs) - .append(" st=") - .append(sendRequestTimeMs) - .append(" rt=") - .append(recvResponseTimeMs); - } + .append(" ct=") + .append(connectionTimeMs) + .append(" st=") + .append(sendRequestTimeMs) + .append(" rt=") + .append(recvResponseTimeMs) - sb.append(" bs=") + .append(" bs=") .append(bytesSent) .append(" br=") .append(bytesReceived) @@ -271,7 +264,6 @@ public String getMaskedEncodedUrl() { */ public AbfsHttpOperation(final URL url, final String method, final List requestHeaders) throws IOException { - this.isTraceEnabled = LOG.isTraceEnabled(); this.url = url; this.method = method; @@ -319,9 +311,7 @@ public void sendRequest(byte[] buffer, int offset, int length) throws IOExceptio // send the request body long startTime = 0; - if (this.isTraceEnabled) { - startTime = System.nanoTime(); - } + startTime = System.nanoTime(); OutputStream outputStream = null; // Updates the expected bytes to be sent based on length. this.expectedBytesToBeSent = length; @@ -360,9 +350,7 @@ public void sendRequest(byte[] buffer, int offset, int length) throws IOExceptio if (outputStream != null) { outputStream.close(); } - if (this.isTraceEnabled) { - this.sendRequestTimeMs = elapsedTimeMs(startTime); - } + this.sendRequestTimeMs = elapsedTimeMs(startTime); } } @@ -379,15 +367,10 @@ public void processResponse(final byte[] buffer, final int offset, final int len // get the response long startTime = 0; - if (this.isTraceEnabled) { - startTime = System.nanoTime(); - } + startTime = System.nanoTime(); this.statusCode = getConnResponseCode(); - - if (this.isTraceEnabled) { - this.recvResponseTimeMs = elapsedTimeMs(startTime); - } + this.recvResponseTimeMs = elapsedTimeMs(startTime); this.statusDescription = getConnResponseMessage(); @@ -404,15 +387,11 @@ public void processResponse(final byte[] buffer, final int offset, final int len return; } - if (this.isTraceEnabled) { - startTime = System.nanoTime(); - } + startTime = System.nanoTime(); if (statusCode >= HttpURLConnection.HTTP_BAD_REQUEST) { processStorageErrorResponse(); - if (this.isTraceEnabled) { - this.recvResponseTimeMs += elapsedTimeMs(startTime); - } + this.recvResponseTimeMs += elapsedTimeMs(startTime); this.bytesReceived = this.connection.getHeaderFieldLong(HttpHeaderConfigurations.CONTENT_LENGTH, 0); } else { // consume the input stream to release resources @@ -454,9 +433,7 @@ public void processResponse(final byte[] buffer, final int offset, final int len LOG.debug("IO Error: ", ex); throw ex; } finally { - if (this.isTraceEnabled) { - this.recvResponseTimeMs += elapsedTimeMs(startTime); - } + this.recvResponseTimeMs += elapsedTimeMs(startTime); this.bytesReceived = totalBytesRead; } } @@ -472,9 +449,6 @@ public void setRequestProperty(String key, String value) { * @throws IOException if an error occurs. */ private HttpURLConnection openConnection() throws IOException { - if (!isTraceEnabled) { - return (HttpURLConnection) url.openConnection(); - } long start = System.nanoTime(); try { return (HttpURLConnection) url.openConnection(); diff --git a/hadoop-tools/hadoop-azure/src/test/java/org/apache/hadoop/fs/azurebfs/services/TestAbfsPerfTracker.java b/hadoop-tools/hadoop-azure/src/test/java/org/apache/hadoop/fs/azurebfs/services/TestAbfsPerfTracker.java index 191d6e77ae..ef52f244f7 100644 --- a/hadoop-tools/hadoop-azure/src/test/java/org/apache/hadoop/fs/azurebfs/services/TestAbfsPerfTracker.java +++ b/hadoop-tools/hadoop-azure/src/test/java/org/apache/hadoop/fs/azurebfs/services/TestAbfsPerfTracker.java @@ -113,7 +113,7 @@ public void verifyTrackingForSingletonLatencyRecords() throws Exception { assertThat(latencyDetails).describedAs("AbfsPerfTracker should return non-null record").isNotNull(); assertThat(latencyDetails).describedAs("Latency record should be in the correct format") .containsPattern("h=[^ ]* t=[^ ]* a=bogusFilesystemName c=bogusAccountName cr=oneOperationCaller" - + " ce=oneOperationCallee r=Succeeded l=[0-9]+ s=0 e= ci=[^ ]* ri=[^ ]* bs=0 br=0 m=GET" + + " ce=oneOperationCallee r=Succeeded l=[0-9]+ s=0 e= ci=[^ ]* ri=[^ ]* ct=[^ ]* st=[^ ]* rt=[^ ]* bs=0 br=0 m=GET" + " u=http%3A%2F%2Fwww.microsoft.com%2FbogusFile"); } @@ -154,7 +154,7 @@ public void verifyTrackingForAggregateLatencyRecords() throws Exception { assertThat(latencyDetails).describedAs("Latency record should be in the correct format") .containsPattern("h=[^ ]* t=[^ ]* a=bogusFilesystemName c=bogusAccountName cr=oneOperationCaller" + " ce=oneOperationCallee r=Succeeded l=[0-9]+ ls=[0-9]+ lc=" + TEST_AGGREGATE_COUNT - + " s=0 e= ci=[^ ]* ri=[^ ]* bs=0 br=0 m=GET u=http%3A%2F%2Fwww.microsoft.com%2FbogusFile"); + + " s=0 e= ci=[^ ]* ri=[^ ]* ct=[^ ]* st=[^ ]* rt=[^ ]* bs=0 br=0 m=GET u=http%3A%2F%2Fwww.microsoft.com%2FbogusFile"); } latencyDetails = abfsPerfTracker.getClientLatency();