# HG changeset patch # User prappo # Date 1523024443 -3600 # Node ID 0ba90c4f1e3f0e9a8290c57aa38cd7df7bd0e516 # Parent 701dd37aa97a7dd415e066aba16bab4d999d7f6d http-client-branch: review comment - check for logging level being enabled before logging (for performance reasons) diff -r 701dd37aa97a -r 0ba90c4f1e3f src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageDecoder.java --- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageDecoder.java Fri Apr 06 13:41:14 2018 +0100 +++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageDecoder.java Fri Apr 06 15:20:43 2018 +0100 @@ -73,13 +73,17 @@ @Override public void fin(boolean value) { - debug.log(Level.DEBUG, "fin %s", value); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "fin %s", value); + } fin = value; } @Override public void rsv1(boolean value) { - debug.log(Level.DEBUG, "rsv1 %s", value); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "rsv1 %s", value); + } if (value) { throw new FailWebSocketException("Unexpected rsv1 bit"); } @@ -87,7 +91,9 @@ @Override public void rsv2(boolean value) { - debug.log(Level.DEBUG, "rsv2 %s", value); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "rsv2 %s", value); + } if (value) { throw new FailWebSocketException("Unexpected rsv2 bit"); } @@ -95,7 +101,9 @@ @Override public void rsv3(boolean value) { - debug.log(Level.DEBUG, "rsv3 %s", value); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "rsv3 %s", value); + } if (value) { throw new FailWebSocketException("Unexpected rsv3 bit"); } @@ -103,7 +111,9 @@ @Override public void opcode(Opcode v) { - debug.log(Level.DEBUG, "opcode %s", v); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "opcode %s", v); + } if (v == Opcode.PING || v == Opcode.PONG || v == Opcode.CLOSE) { if (!fin) { throw new FailWebSocketException("Fragmented control frame " + v); @@ -131,7 +141,9 @@ @Override public void mask(boolean value) { - debug.log(Level.DEBUG, "mask %s", value); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "mask %s", value); + } if (value) { throw new FailWebSocketException("Masked frame received"); } @@ -139,7 +151,9 @@ @Override public void payloadLen(long value) { - debug.log(Level.DEBUG, "payloadLen %s", value); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "payloadLen %s", value); + } if (opcode.isControl()) { if (value > Frame.MAX_CONTROL_FRAME_PAYLOAD_LENGTH) { throw new FailWebSocketException( @@ -167,7 +181,9 @@ @Override public void payloadData(ByteBuffer data) { - debug.log(Level.DEBUG, "payload %s", data); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "payload %s", data); + } unconsumedPayloadLen -= data.remaining(); boolean lastPayloadChunk = unconsumedPayloadLen == 0; if (opcode.isControl()) { @@ -212,7 +228,9 @@ @Override public void endFrame() { - debug.log(Level.DEBUG, "end frame"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "end frame"); + } if (opcode.isControl()) { binaryData.flip(); } diff -r 701dd37aa97a -r 0ba90c4f1e3f src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageEncoder.java --- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageEncoder.java Fri Apr 06 13:41:14 2018 +0100 +++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageEncoder.java Fri Apr 06 15:20:43 2018 +0100 @@ -129,8 +129,10 @@ public boolean encodeText(CharBuffer src, boolean last, ByteBuffer dst) throws IOException { - debug.log(Level.DEBUG, "encode text src=[pos=%s lim=%s cap=%s] last=%s dst=%s", - src.position(), src.limit(), src.capacity(), last, dst); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "encode text src=[pos=%s lim=%s cap=%s] last=%s dst=%s", + src.position(), src.limit(), src.capacity(), last, dst); + } if (closed) { throw new IOException("Output closed"); } @@ -145,15 +147,21 @@ charsetEncoder.reset(); } while (true) { - debug.log(Level.DEBUG, "put"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "put"); + } if (!putAvailable(headerBuffer, dst)) { return false; } - debug.log(Level.DEBUG, "mask"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "mask"); + } if (maskAvailable(intermediateBuffer, dst) < 0) { return false; } - debug.log(Level.DEBUG, "moreText"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "moreText"); + } if (!moreText) { previousFin = last; previousText = true; @@ -180,7 +188,9 @@ throw new IOException("Malformed text message", e); } } - debug.log(Level.DEBUG, "frame #%s", headerCount); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "frame #%s", headerCount); + } intermediateBuffer.flip(); Opcode opcode = previousFin && headerCount == 0 ? Opcode.TEXT : Opcode.CONTINUATION; @@ -207,8 +217,10 @@ public boolean encodeBinary(ByteBuffer src, boolean last, ByteBuffer dst) throws IOException { - debug.log(Level.DEBUG, "encode binary src=%s last=%s dst=%s", - src, last, dst); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "encode binary src=%s last=%s dst=%s", + src, last, dst); + } if (closed) { throw new IOException("Output closed"); } @@ -245,7 +257,9 @@ public boolean encodePing(ByteBuffer src, ByteBuffer dst) throws IOException { - debug.log(Level.DEBUG, "encode ping src=%s dst=%s", src, dst); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "encode ping src=%s dst=%s", src, dst); + } if (closed) { throw new IOException("Output closed"); } @@ -271,8 +285,10 @@ public boolean encodePong(ByteBuffer src, ByteBuffer dst) throws IOException { - debug.log(Level.DEBUG, "encode pong src=%s dst=%s", - src, dst); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "encode pong src=%s dst=%s", + src, dst); + } if (closed) { throw new IOException("Output closed"); } @@ -298,22 +314,30 @@ public boolean encodeClose(int statusCode, CharBuffer reason, ByteBuffer dst) throws IOException { - debug.log(Level.DEBUG, "encode close statusCode=%s reason=[pos=%s lim=%s cap=%s] dst=%s", - statusCode, reason.position(), reason.limit(), reason.capacity(), dst); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "encode close statusCode=%s reason=[pos=%s lim=%s cap=%s] dst=%s", + statusCode, reason.position(), reason.limit(), reason.capacity(), dst); + } if (closed) { throw new IOException("Output closed"); } if (!started) { - debug.log(Level.DEBUG, "reason [pos=%s lim=%s cap=%s]", - reason.position(), reason.limit(), reason.capacity()); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "reason [pos=%s lim=%s cap=%s]", + reason.position(), reason.limit(), reason.capacity()); + } intermediateBuffer.position(0).limit(Frame.MAX_CONTROL_FRAME_PAYLOAD_LENGTH); intermediateBuffer.putChar((char) statusCode); CoderResult r = charsetEncoder.reset().encode(reason, intermediateBuffer, true); if (r.isUnderflow()) { - debug.log(Level.DEBUG, "flushing"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "flushing"); + } r = charsetEncoder.flush(intermediateBuffer); } - debug.log(Level.DEBUG, "encoding result: %s", r); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "encoding result: %s", r); + } if (r.isError()) { try { r.throwException(); @@ -330,7 +354,9 @@ setupHeader(Opcode.CLOSE, true, intermediateBuffer.remaining()); started = true; closed = true; - debug.log(Level.DEBUG, "intermediateBuffer=%s", intermediateBuffer); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "intermediateBuffer=%s", intermediateBuffer); + } } if (!putAvailable(headerBuffer, dst)) { return false; @@ -339,8 +365,10 @@ } private void setupHeader(Opcode opcode, boolean fin, long payloadLen) { - debug.log(Level.DEBUG, "frame opcode=%s fin=%s len=%s", - opcode, fin, payloadLen); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "frame opcode=%s fin=%s len=%s", + opcode, fin, payloadLen); + } headerBuffer.clear(); int mask = maskingKeySource.nextInt(); headerWriter.fin(fin) diff -r 701dd37aa97a -r 0ba90c4f1e3f src/java.net.http/share/classes/jdk/internal/net/http/websocket/TransportImpl.java --- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/TransportImpl.java Fri Apr 06 13:41:14 2018 +0100 +++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/TransportImpl.java Fri Apr 06 15:20:43 2018 +0100 @@ -96,16 +96,22 @@ private ByteBuffer createWriteBuffer() { String name = "jdk.httpclient.websocket.writeBufferSize"; int capacity = Utils.getIntegerNetProperty(name, 16384); - debug.log(Level.DEBUG, "write buffer capacity %s", capacity); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "write buffer capacity %s", capacity); + } // TODO (optimization?): allocateDirect if SSL? return ByteBuffer.allocate(capacity); } private boolean write() throws IOException { - debug.log(Level.DEBUG, "writing to the channel"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "writing to the channel"); + } long count = channel.write(dstArray, 0, dstArray.length); - debug.log(Level.DEBUG, "%s bytes written", count); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "%s bytes written", count); + } for (ByteBuffer b : dstArray) { if (b.hasRemaining()) { return false; @@ -141,7 +147,9 @@ } catch (IOException e) { f.completeExceptionally(e); } - debug.log(Level.DEBUG, "exit send text %s returned %s", id, f); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send text %s returned %s", id, f); + } return f; } @@ -163,7 +171,9 @@ } catch (IOException e) { f.completeExceptionally(e); } - debug.log(Level.DEBUG, "exit send binary %s returned %s", id, f); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send binary %s returned %s", id, f); + } return f; } @@ -184,7 +194,9 @@ } catch (IOException e) { f.completeExceptionally(e); } - debug.log(Level.DEBUG, "exit send ping %s returned %s", id, f); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send ping %s returned %s", id, f); + } return f; } @@ -205,7 +217,9 @@ } catch (IOException e) { f.completeExceptionally(e); } - debug.log(Level.DEBUG, "exit send pong %s returned %s", id, f); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send pong %s returned %s", id, f); + } return f; } @@ -226,7 +240,9 @@ } catch (IOException e) { f.completeExceptionally(e); } - debug.log(Level.DEBUG, "exit send pong %s returned %s", id, f); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send pong %s returned %s", id, f); + } return f; } @@ -248,13 +264,17 @@ } catch (IOException e) { f.completeExceptionally(e); } - debug.log(Level.DEBUG, "exit send close %s returned %s", id, f); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send close %s returned %s", id, f); + } return f; } @Override public void request(long n) { - debug.log(Level.DEBUG, "request %s", n); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "request %s", n); + } if (demand.increase(n)) { receiveScheduler.runOrSchedule(); } @@ -270,7 +290,9 @@ @Override public void closeOutput() throws IOException { - debug.log(Level.DEBUG, "closeOutput"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "closeOutput"); + } synchronized (closeLock) { if (!outputClosed) { outputClosed = true; @@ -293,7 +315,9 @@ */ @Override public void closeInput() throws IOException { - debug.log(Level.DEBUG, "closeInput"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "closeInput"); + } synchronized (closeLock) { if (!inputClosed) { inputClosed = true; @@ -485,12 +509,16 @@ // Could have been only called in one of the following cases: // (a) A message has been added to the queue // (b) The channel is ready for writing - debug.log(Level.DEBUG, "enter send task"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "enter send task"); + } while (!queue.isEmpty()) { try { if (dst.hasRemaining()) { - debug.log(Level.DEBUG, "%s bytes remaining in buffer %s", - dst.remaining(), dst); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "%s bytes remaining in buffer %s", + dst.remaining(), dst); + } // The previous part of the binary representation of the // message hasn't been fully written if (!tryCompleteWrite()) { @@ -500,7 +528,9 @@ if (firstPass) { firstPass = false; queue.peek(loadCallback); - debug.log(Level.DEBUG, "load message"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "load message"); + } } dst.clear(); encoded = queue.peek(encodingCallback); @@ -514,7 +544,9 @@ removeAndComplete(null); } } catch (Throwable t) { - debug.log(Level.DEBUG, "send task exception %s", (Object) t); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "send task exception %s", (Object) t); + } // buffer cleanup: if there is an exception, the buffer // should appear empty for the next write as there is // nothing to write @@ -523,29 +555,41 @@ removeAndComplete(t); } } - debug.log(Level.DEBUG, "exit send task"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send task"); + } } private boolean tryCompleteWrite() throws IOException { - debug.log(Level.DEBUG, "enter writing"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "enter writing"); + } boolean finished = false; loop: while (true) { final ChannelState ws = writeState.get(); - debug.log(Level.DEBUG, "write state: %s", ws); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "write state: %s", ws); + } switch (ws) { case WAITING: break loop; case UNREGISTERED: - debug.log(Level.DEBUG, "registering write event"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "registering write event"); + } channel.registerEvent(writeEvent); writeState.compareAndSet(UNREGISTERED, WAITING); - debug.log(Level.DEBUG, "registered write event"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "registered write event"); + } break loop; case AVAILABLE: boolean written = write(); if (written) { - debug.log(Level.DEBUG, "finished writing to the channel"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "finished writing to the channel"); + } finished = true; break loop; // All done } else { @@ -558,13 +602,17 @@ throw new InternalError(String.valueOf(ws)); } } - debug.log(Level.DEBUG, "exit writing"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit writing"); + } return finished; } @SuppressWarnings("unchecked") private void removeAndComplete(Throwable error) { - debug.log(Level.DEBUG, "removeAndComplete error=%s", (Object) error); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "removeAndComplete error=%s", (Object) error); + } queue.remove(); if (error != null) { try { @@ -591,13 +639,17 @@ @Override public void run() { - debug.log(Level.DEBUG, "enter receive task"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "enter receive task"); + } loop: while (!receiveScheduler.isStopped()) { ChannelState rs = readState; if (data.hasRemaining()) { - debug.log(Level.DEBUG, "remaining bytes received %s", - data.remaining()); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "remaining bytes received %s", + data.remaining()); + } if (!demand.isFulfilled()) { try { int oldPos = data.position(); @@ -616,7 +668,9 @@ } break loop; } - debug.log(Level.DEBUG, "receive state: %s", rs); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "receive state: %s", rs); + } switch (rs) { case WAITING: break loop; @@ -651,7 +705,9 @@ throw new InternalError(String.valueOf(rs)); } } - debug.log(Level.DEBUG, "exit receive task"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit receive task"); + } } } @@ -664,12 +720,16 @@ @Override public void handle() { - debug.log(Level.DEBUG, "write event"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "write event"); + } ChannelState s; do { s = writeState.get(); if (s == CLOSED) { - debug.log(Level.DEBUG, "write state %s", s); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "write state %s", s); + } break; } } while (!writeState.compareAndSet(s, AVAILABLE)); @@ -686,7 +746,9 @@ @Override public void handle() { - debug.log(Level.DEBUG, "read event"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "read event"); + } readState = AVAILABLE; receiveScheduler.runOrSchedule(); } diff -r 701dd37aa97a -r 0ba90c4f1e3f src/java.net.http/share/classes/jdk/internal/net/http/websocket/WebSocketImpl.java --- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/WebSocketImpl.java Fri Apr 06 13:41:14 2018 +0100 +++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/WebSocketImpl.java Fri Apr 06 15:20:43 2018 +0100 @@ -183,7 +183,9 @@ result = transport.sendText(message, last, this, (r, e) -> clearPendingTextOrBinary()); } - debug.log(Level.DEBUG, "exit send text %s returned %s", id, result); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send text %s returned %s", id, result); + } return replaceNull(result); } @@ -205,7 +207,9 @@ result = transport.sendBinary(message, last, this, (r, e) -> clearPendingTextOrBinary()); } - debug.log(Level.DEBUG, "exit send binary %s returned %s", id, result); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send binary %s returned %s", id, result); + } return replaceNull(result); } @@ -242,7 +246,9 @@ result = transport.sendPing(message, this, (r, e) -> clearPendingPingOrPong()); } - debug.log(Level.DEBUG, "exit send ping %s returned %s", id, result); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send ping %s returned %s", id, result); + } return replaceNull(result); } @@ -261,7 +267,9 @@ result = transport.sendPong(message, this, (r, e) -> clearPendingPingOrPong()); } - debug.log(Level.DEBUG, "exit send pong %s returned %s", id, result); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send pong %s returned %s", id, result); + } return replaceNull(result); } @@ -298,7 +306,9 @@ } else { result = sendClose0(statusCode, reason); } - debug.log(Level.DEBUG, "exit send close %s returned %s", id, result); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit send close %s returned %s", id, result); + } return replaceNull(result); } @@ -342,7 +352,9 @@ @Override public void request(long n) { - debug.log(Level.DEBUG, "request %s", n); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "request %s", n); + } if (demand.increase(n)) { receiveScheduler.runOrSchedule(); } @@ -365,7 +377,9 @@ @Override public void abort() { - debug.log(Level.DEBUG, "abort"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "abort"); + } inputClosed = true; outputClosed.set(true); receiveScheduler.stop(); @@ -402,11 +416,15 @@ @Override public void run() { - debug.log(Level.DEBUG, "enter receive task"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "enter receive task"); + } loop: while (!receiveScheduler.isStopped()) { State s = state.get(); - debug.log(Level.DEBUG, "receive state: %s", s); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "receive state: %s", s); + } try { switch (s) { case OPEN: @@ -452,19 +470,25 @@ signalError(t); } } - debug.log(Level.DEBUG, "exit receive task"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit receive task"); + } } private void processError() throws IOException { - debug.log(Level.DEBUG, "processError"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "processError"); + } transport.closeInput(); receiveScheduler.stop(); Throwable err = error.get(); if (err instanceof FailWebSocketException) { int code1 = ((FailWebSocketException) err).getStatusCode(); err = new ProtocolException().initCause(err); - debug.log(Level.DEBUG, "failing %s with error=%s statusCode=%s", - WebSocketImpl.this, err, code1); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "failing %s with error=%s statusCode=%s", + WebSocketImpl.this, err, code1); + } sendCloseSilently(code1); } long id = 0; @@ -475,7 +499,9 @@ try { listener.onError(WebSocketImpl.this, err); } finally { - debug.log(Level.DEBUG, "exit onError %s", id); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit onError %s", id); + } } } @@ -509,9 +535,11 @@ code = statusCode; } cs.whenComplete((r, e) -> { - debug.log(Level.DEBUG, - "CompletionStage returned by onClose completed result=%s error=%s", - r, e); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, + "CompletionStage returned by onClose completed result=%s error=%s", + r, e); + } sendCloseSilently(code); }); } @@ -527,12 +555,16 @@ try { cs = listener.onPong(WebSocketImpl.this, binaryData); } finally { - debug.log(Level.DEBUG, "exit onPong %s returned %s", id, cs); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit onPong %s returned %s", id, cs); + } } } private void processPing() { - debug.log(Level.DEBUG, "processPing"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "processPing"); + } // A full copy of this (small) data is made. This way sending a // replying Pong could be done in parallel with the listener // handling this Ping. @@ -562,7 +594,9 @@ try { cs = listener.onPing(WebSocketImpl.this, slice); } finally { - debug.log(Level.DEBUG, "exit onPing %s returned %s", id, cs); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit onPing %s returned %s", id, cs); + } } } @@ -577,7 +611,9 @@ try { cs = listener.onBinary(WebSocketImpl.this, binaryData, last); } finally { - debug.log(Level.DEBUG, "exit onBinary %s returned %s", id, cs); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit onBinary %s returned %s", id, cs); + } } } @@ -593,7 +629,9 @@ try { cs = listener.onText(WebSocketImpl.this, text, last); } finally { - debug.log(Level.DEBUG, "exit onText %s returned %s", id, cs); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit onText %s returned %s", id, cs); + } } } @@ -606,7 +644,9 @@ try { listener.onOpen(WebSocketImpl.this); } finally { - debug.log(Level.DEBUG, "exit onOpen %s", id); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exit onOpen %s", id); + } } } } @@ -614,8 +654,10 @@ private void sendCloseSilently(int statusCode) { sendClose0(statusCode, "").whenComplete((r, e) -> { if (e != null) { - debug.log(Level.DEBUG, "automatic closure completed with error", - (Object) e); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "automatic closure completed with error", + (Object) e); + } } }); } @@ -654,8 +696,10 @@ break; } } - debug.log(Level.DEBUG, "swapped automatic pong from %s to %s", - message, copy); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "swapped automatic pong from %s to %s", + message, copy); + } return swapped; } @@ -665,11 +709,15 @@ } private void signalError(Throwable error) { - debug.log(Level.DEBUG, "signalError %s", (Object) error); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "signalError %s", (Object) error); + } inputClosed = true; outputClosed.set(true); if (!this.error.compareAndSet(null, error) || !trySetState(ERROR)) { - debug.log(Level.DEBUG, "signalError", error); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "signalError", error); + } Log.logError(error); } else { close(); @@ -677,7 +725,9 @@ } private void close() { - debug.log(Level.DEBUG, "close"); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "close"); + } Throwable first = null; try { transport.closeInput(); @@ -700,7 +750,9 @@ e = second; } if (e != null) { - debug.log(Level.DEBUG, "exception in close", e); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exception in close", e); + } } } } @@ -712,14 +764,18 @@ this.statusCode = statusCode; this.reason = reason; boolean managed = trySetState(CLOSE); - debug.log(Level.DEBUG, - "signalClose statusCode=%s reason.length=%s: %s", - statusCode, reason.length(), managed); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, + "signalClose statusCode=%s reason.length=%s: %s", + statusCode, reason.length(), managed); + } if (managed) { try { transport.closeInput(); } catch (Throwable t) { - debug.log(Level.DEBUG, "exception closing input", (Object) t); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "exception closing input", (Object) t); + } } } } @@ -787,8 +843,10 @@ break; } } - debug.log(Level.DEBUG, "set state %s (previous %s) %s", - newState, currentState, success); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "set state %s (previous %s) %s", + newState, currentState, success); + } return success; } @@ -803,8 +861,10 @@ // from IDLE to WAITING: the state has changed to terminal throw new InternalError(); } - debug.log(Level.DEBUG, "change state from %s to %s %s", - expectedState, newState, success); + if (debug.isLoggable(Level.DEBUG)) { + debug.log(Level.DEBUG, "change state from %s to %s %s", + expectedState, newState, success); + } return success; }