Return-Path: X-Original-To: apmail-hc-dev-archive@www.apache.org Delivered-To: apmail-hc-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id B7C49101D4 for ; Mon, 22 Apr 2013 16:25:17 +0000 (UTC) Received: (qmail 77946 invoked by uid 500); 22 Apr 2013 16:25:16 -0000 Delivered-To: apmail-hc-dev-archive@hc.apache.org Received: (qmail 77897 invoked by uid 500); 22 Apr 2013 16:25:16 -0000 Mailing-List: contact dev-help@hc.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: "HttpComponents Project" Delivered-To: mailing list dev@hc.apache.org Received: (qmail 77738 invoked by uid 99); 22 Apr 2013 16:25:16 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 22 Apr 2013 16:25:16 +0000 Date: Mon, 22 Apr 2013 16:25:16 +0000 (UTC) From: "Clinton Nielsen (JIRA)" To: dev@hc.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (HTTPASYNC-39) SocketTimeoutException occurs too soon MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HTTPASYNC-39?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13638138#comment-13638138 ] Clinton Nielsen commented on HTTPASYNC-39: ------------------------------------------ I'm trying to reproduce this locally, and am also having a hard time. For reference, the code I'm using looks something like this (cleaned for brevity): final long start = System.currentTimeMillis(); cachingHttpAsyncClient.execute(appInfo.httpMethod, new BasicHttpContext(), new FutureCallback() { public void failed(final Exception e) { logger.error(e + ", Time (ms): " + (System.currentTimeMillis() - start)); ... } ... }); When trying locally, with SocketTimeout set to 30,000 ms, when the failed method is called, the output in the logs consistently shows time taken to be between 30,000 and 31,000 milliseconds. On production, however, using the same code, the logs look something like this. Notice that the time taken is never anywhere near the 30,000ms mark. It's always much shorter, or much longer: java.net.SocketTimeoutException, Time(ms): 0 java.net.SocketTimeoutException, Time(ms): 0 java.net.SocketTimeoutException, Time(ms): 1 java.net.SocketTimeoutException, Time(ms): 0 java.net.SocketTimeoutException, Time(ms): 46194 java.net.SocketTimeoutException, Time(ms): 50692 java.net.SocketTimeoutException, Time(ms): 49626 java.net.SocketTimeoutException, Time(ms): 45256 java.net.SocketTimeoutException, Time(ms): 0 java.net.SocketTimeoutException, Time(ms): 1 java.net.SocketTimeoutException, Time(ms): 10 java.net.SocketTimeoutException, Time(ms): 1 java.net.SocketTimeoutException, Time(ms): 1 java.net.SocketTimeoutException, Time(ms): 1 java.net.SocketTimeoutException, Time(ms): 1 java.net.SocketTimeoutException, Time(ms): 1 java.net.SocketTimeoutException, Time(ms): 1 java.net.SocketTimeoutException, Time(ms): 1 java.net.SocketTimeoutException, Time(ms): 1 java.net.SocketTimeoutException, Time(ms): 50656 java.net.SocketTimeoutException, Time(ms): 46603 java.net.SocketTimeoutException, Time(ms): 88 On a maybe related not, when load goes up we're also seeing a lot of the following, none of which were present when using the non-async client: java.net.ConnectException: Connection timed out (usually around the 21,000 ms mark) java.io.IOException: Connection timed out (this occurs at the ~15 minute mark!) Either way, I'll keep playing with it and maybe get more information and hopefully reproduce in controlled conditions. Thanks. > SocketTimeoutException occurs too soon > -------------------------------------- > > Key: HTTPASYNC-39 > URL: https://issues.apache.org/jira/browse/HTTPASYNC-39 > Project: HttpComponents HttpAsyncClient > Issue Type: Bug > Affects Versions: 4.0-beta3 > Reporter: Clinton Nielsen > > In a highly concurrent environment, where SocketTimeout is set to 30,000 milliseconds, we are often seeing a timeoutexception after only 0 or 1 or 2 milliseconds has actually passed. > I get the impression that in the AbstractIOReactor timeoutCheck function, session.getLastAccessTime is being called on the session before the lastAccessTime is set on the session for the current session (ie. the lastAccessTime being retrieved is the time that was set on the session object for the previous http session) -- This message is automatically generated by JIRA. If you think it was sent incorrectly, please contact your JIRA administrators For more information on JIRA, see: http://www.atlassian.com/software/jira --------------------------------------------------------------------- To unsubscribe, e-mail: dev-unsubscribe@hc.apache.org For additional commands, e-mail: dev-help@hc.apache.org