Skip to content

Commit

Permalink
pool: fix stopwatch error
Browse files Browse the repository at this point in the history 
Motivation:

Observer following stacktrace:

    java.lang.IllegalStateException: This stopwatch is already stopped.
            at com.google.common.base.Preconditions.checkState(Preconditions.java:504) ~[guava-24.1-jre.jar:na]
            at com.google.common.base.Stopwatch.stop(Stopwatch.java:165) ~[guava-24.1-jre.jar:na]
            at org.dcache.pool.statistics.IoStatisticsChannel.readCompleted(IoStatisticsChannel.java:136) ~[dcache-core-5.0.0-SNAPSHOT.jar:5.0.0-SNAPSHOT]
            at org.dcache.pool.statistics.IoStatisticsChannel.read(IoStatisticsChannel.java:284) ~[dcache-core-5.0.0-SNAPSHOT.jar:5.0.0-SNAPSHOT]
            at org.dcache.pool.movers.MoverChannel.read(MoverChannel.java:116) ~[dcache-core-5.0.0-SNAPSHOT.jar:5.0.0-SNAPSHOT]
            at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:65) ~[na:1.8.0_191]
            at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:109) ~[na:1.8.0_191]
            at sun.nio.ch.ChannelInputStream.read(ChannelInputStream.java:103) ~[na:1.8.0_191]
            at org.apache.http.entity.InputStreamEntity.writeTo(InputStreamEntity.java:140) ~[httpcore-4.4.6.jar:4.4.6]
            at org.apache.http.impl.execchain.RequestEntityProxy.writeTo(RequestEntityProxy.java:121) ~[httpclient-4.5.3.jar:4.5.3]
            at org.apache.http.impl.DefaultBHttpClientConnection.sendRequestEntity(DefaultBHttpClientConnection.java:156) ~[httpcore-4.4.6.jar:4.4.6]
            at org.apache.http.impl.conn.CPoolProxy.sendRequestEntity(CPoolProxy.java:160) ~[httpclient-4.5.3.jar:4.5.3]
            at org.apache.http.protocol.HttpRequestExecutor.doSendRequest(HttpRequestExecutor.java:238) ~[httpcore-4.4.6.jar:4.4.6]
            at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:123) ~[httpcore-4.4.6.jar:4.4.6]
            at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272) ~[httpclient-4.5.3.jar:4.5.3]
            at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) ~[httpclient-4.5.3.jar:4.5.3]
            at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) ~[httpclient-4.5.3.jar:4.5.3]
            at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111) ~[httpclient-4.5.3.jar:4.5.3]
            at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) ~[httpclient-4.5.3.jar:4.5.3]
            at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) ~[httpclient-4.5.3.jar:4.5.3]
            at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108) ~[httpclient-4.5.3.jar:4.5.3]
            at org.dcache.pool.movers.RemoteHttpDataTransferProtocol.sendFile(RemoteHttpDataTransferProtocol.java:357) ~[dcache-core-5.0.0-SNAPSHOT.jar:5.0.0-SNAPSHOT]
            at org.dcache.pool.movers.RemoteHttpDataTransferProtocol.sendAndCheckFile(RemoteHttpDataTransferProtocol.java:338) ~[dcache-core-5.0.0-SNAPSHOT.jar:5.0.0-SNAPSHOT]
            at org.dcache.pool.movers.RemoteHttpDataTransferProtocol.runIO(RemoteHttpDataTransferProtocol.java:231) ~[dcache-core-5.0.0-SNAPSHOT.jar:5.0.0-SNAPSHOT]
            at org.dcache.pool.movers.RemoteHttpsDataTransferProtocol.runIO(RemoteHttpsDataTransferProtocol.java:60) ~[dcache-core-5.0.0-SNAPSHOT.jar:5.0.0-SNAPSHOT]
            at org.dcache.pool.classic.AbstractMoverProtocolTransferService$MoverTask.runMover(AbstractMoverProtocolTransferService.java:174) ~[dcache-core-5.0.0-SNAPSHOT.jar:5.0.0-SNAPSHOT]
            at org.dcache.pool.classic.AbstractMoverProtocolTransferService$MoverTask.run(AbstractMoverProtocolTransferService.java:145) ~[dcache-core-5.0.0-SNAPSHOT.jar:5.0.0-SNAPSHOT]
            at org.dcache.util.CDCExecutorServiceDecorator$WrappedRunnable.run(CDCExecutorServiceDecorator.java:149) [dcache-core-5.0.0-SNAPSHOT.jar:5.0.0-SNAPSHOT]
            at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_191]
            at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_191]
            at java.lang.Thread.run(Thread.java:748) [na:1.8.0_191]

The only way I can see this problem being triggered is a race-condition
between close and a read request, or if one of the read methods is
called after close.

Modification:

Update logic to be robust against RepositoryChannel misuse.

Change log-level to ensure such misuse is recorded.

Result:

Ensure IO-statistics collecting is more robust, avoiding stack-traces
with the message 'This stopwatch is already stopped.'

Target: master
Request: 4.2
Request: 4.1
Requires-notes: yes
Requires-book: no
Patch: https://rb.dcache.org/r/11337/
Acked-by: Albert Rossi
  • Loading branch information
@paulmillar
paulmillar committed Nov 9, 2018
1 parent eb161be commit 272c627
Showing 1 changed file with 32 additions and 12 deletions.
44 changes: 32 additions & 12 deletions modules/dcache/src/main/java/org/dcache/pool/statistics/IoStatisticsChannel.java
View file
Expand Up @@ -99,17 +99,26 @@ private synchronized int writeStarted()
firstWrite = now;
}
latestWrite = now;
if (!isClosed && concurrentWrites == 0) {
writeIdle.stop();
writeActive.start();

if (concurrentWrites++ == 0) {
if (writeIdle.isRunning()) {
writeIdle.stop();
}

if (!isClosed) {
writeActive.start();
}
}
return ++concurrentWrites;
return concurrentWrites;
}

private synchronized void writeCompleted()
{
if (--concurrentWrites == 0) {
writeActive.stop();
if (writeActive.isRunning()) {
writeActive.stop();
}

if (!isClosed) {
writeIdle.start();
}
Expand All @@ -123,17 +132,26 @@ private synchronized int readStarted()
firstRead = now;
}
latestRead = now;
if (!isClosed && concurrentReads == 0) {
readIdle.stop();
readActive.start();

if (concurrentReads++ == 0) {
if (readIdle.isRunning()) {
readIdle.stop();
}

if (!isClosed) {
readActive.start();
}
}
return ++concurrentReads;
return concurrentReads;
}

private synchronized void readCompleted()
{
if (--concurrentReads == 0) {
readActive.stop();
if (readActive.isRunning()) {
readActive.stop();
}

if (!isClosed) {
readIdle.start();
}
Expand Down Expand Up @@ -310,13 +328,15 @@ public void close() throws IOException
if (concurrentReads == 0) {
readIdle.stop();
} else {
LOGGER.debug("close called with in-flight read request");
LOGGER.warn("close called with in-flight read request");
// allow in-flight read request(s) to stop readActive stopwatch.
}

if (concurrentWrites == 0) {
writeIdle.stop();
} else {
LOGGER.debug("close called with in-flight write request");
LOGGER.warn("close called with in-flight write request");
// allow in-flight write request(s) to stop writeActive stopwatch.
}
}
}
Expand Down

0 comments on commit 272c627

Please sign in to comment.