Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Critical Critical
    • Resolution: Fixed
    • Affects Version/s: 6.0.0beta8, 6.0.0beta9, 6.0.0beta10, 6.0.0beta11, 6.0.0beta12, 6.0.0beta14, 6.0.0beta15, 6.0.0RC0
    • Fix Version/s: 6.0.0rc1
    • Component/s: HTTP, NIO
    • Labels:
      None
    • Environment:
      FreeBSD 5.4-RELEASE-p3
      Java HotSpot(TM) Server VM (build diablo-1.5.0_06-b00, mixed mode)
    • Number of attachments :
      4

      Description

      New Jetty, apparently, leaks socket descriptors. When running unattended, Jetty would take all available OS descriptors, leading to the "Too many open files in system" (ENFILE?) error affecting the whole system. (There were no such problem with Jetty5).

      root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
      Thu May 25 11:21:29 CEST 2006
      30
      111
      50
      root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
      Thu May 25 11:27:42 CEST 2006
      90
      221
      180
      root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
      Thu May 25 11:34:42 CEST 2006
      102
      203
      306
      root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
      Thu May 25 11:43:03 CEST 2006
      109
      326
      446
      root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
      Thu May 25 11:50:05 CEST 2006
      118
      299
      544
      root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
      Thu May 25 12:00:57 CEST 2006
      103
      187
      677
      root@alf.bizlink.ru:~/# date; sockstat | grep 15379 | wc -l; netstat -p tcp -n | grep 80.83.180.18.80 | wc -l; fstat -p 15379 | grep tcp | wc -l
      Thu May 25 12:19:59 CEST 2006
      105
      305
      987

      Here we see, that amount of open sockets (sockstat) remain roughly the same, amount of TCP/IP stack entries (netstat) - too, but the amount of socket descriptors used by the process (fstat | grep tcp) - increases.

      The leak was present at the time of beta8 till today (last tested was the SVN version of Jetty from 2006-05-25).
      I can give JVMDI (java debugger) access to the machine to a specific IP.

        Activity

        Hide
        Greg Wilkins added a comment -

        I can't reproduce this problem. using jdk1.5 on ubuntu linux and measuring the open files with lsof

        running the test webapp, 111 FD's are used when idle. Under load (250 clients) this increases and
        stabilizes around 250 to 310 and then falls back to 111 once the load is removed.

        Can you tell me more about your webapp? or can you reproduce against the test webapp?

        Show
        Greg Wilkins added a comment - I can't reproduce this problem. using jdk1.5 on ubuntu linux and measuring the open files with lsof running the test webapp, 111 FD's are used when idle. Under load (250 clients) this increases and stabilizes around 250 to 310 and then falls back to 111 once the load is removed. Can you tell me more about your webapp? or can you reproduce against the test webapp?
        Hide
        Artem Kozarezov added a comment -

        I've run our program under HPROF (http://java.sun.com/developer/technicalArticles/Programming/HPROF.html)
        Unfortunately, it does not provide information why the instance is held in memory,
        but it shows what IS in memory, and, i think, it proves that something is wrong here.

        Here is excerpt from the hprof file, of what i thought is related to that problem:
        SITES BEGIN (ordered by live bytes) Fri May 26 13:30:09 2006
        percent live alloc'ed stack class
        rank self accum bytes objs bytes objs trace name
        43 0.39% 71.66% 120120 1001 306360 2553 307394 java.net.SocksSocketImpl
        45 0.37% 72.40% 112112 1001 285936 2553 307964 sun.nio.ch.SocketChannelImpl
        56 0.26% 75.64% 79288 901 217096 2467 308007 org.mortbay.jetty.HttpConnection
        61 0.24% 76.89% 72080 901 197360 2467 308238 org.mortbay.jetty.HttpGenerator
        65 0.21% 77.78% 64872 901 177624 2467 308001 org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint
        76 0.17% 79.79% 52192 932 142912 2552 308002 org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint$IdleTask
        80 0.17% 80.46% 50456 901 138152 2467 308008 org.mortbay.jetty.HttpURI
        81 0.17% 80.63% 50456 901 138152 2467 308226 org.mortbay.jetty.Response
        83 0.16% 80.94% 48000 1000 122496 2552 307984 sun.nio.ch.SocketAdaptor
        91 0.13% 82.06% 38472 687 108528 1938 312369 org.mortbay.io.ByteArrayBuffer
        102 0.10% 83.28% 30816 428 80568 1119 312355 org.mortbay.jetty.HttpConnection$OutputWriter
        108 0.09% 83.85% 28520 713 80680 2017 312147 org.mortbay.jetty.HttpConnection$Output
        116 0.08% 84.52% 24024 1001 61272 2553 307959 java.net.Inet4Address
        117 0.08% 84.60% 24024 1001 61272 2553 307960 java.net.InetSocketAddress
        121 0.08% 84.91% 23184 966 59208 2467 307997 java.nio.channels.SelectionKey[]
        128 0.07% 85.42% 22296 929 60816 2534 312358 java.net.InetSocketAddress
        129 0.07% 85.50% 22176 396 57120 1020 305827 sun.nio.cs.StreamEncoder$CharsetSE
        135 0.07% 85.91% 20360 509 77040 1926 310806 javax.servlet.http.Cookie
        136 0.07% 85.98% 20272 362 183232 3272 300046 java.nio.DirectByteBuffer
        138 0.06% 86.11% 19776 412 89760 1870 303161 sun.nio.cs.ISO_8859_1$Encoder
        145 0.06% 86.52% 17120 428 44760 1119 312356 org.mortbay.jetty.HttpConnection$1
        149 0.05% 86.74% 16632 297 33152 592 308244 org.mortbay.io.nio.NIOBuffer
        156 0.05% 87.11% 16016 1001 40864 2554 307953 java.io.FileDescriptor
        157 0.05% 87.17% 16000 1000 40832 2552 307994 sun.nio.ch.SocketChannelImpl$1
        158 0.05% 87.22% 16000 1000 40832 2552 307992 sun.nio.ch.OptionAdaptor
        159 0.05% 87.27% 16000 1000 40832 2552 308248 java.nio.channels.spi.AbstractInterruptibleChannel$1
        160 0.05% 87.32% 16000 1000 40832 2552 307996 sun.nio.ch.SocketOptsImpl$IP$TCP
        161 0.05% 87.38% 15960 665 23880 995 309114 java.util.concurrent.locks.ReentrantLock$NonfairSync
        169 0.05% 87.78% 14912 932 40832 2552 308009 org.mortbay.jetty.HttpConnection$RequestHandler
        175 0.05% 88.07% 14520 605 14520 605 301162 java.net.Inet4Address
        176 0.05% 88.11% 14480 362 130880 3272 300050 sun.misc.Cleaner
        177 0.05% 88.16% 14400 600 14400 600 301163 java.net.InetAddress$CacheEntry
        184 0.04% 88.47% 13240 331 233800 5845 300021 sun.nio.cs.ISO_8859_1$Decoder
        190 0.04% 88.73% 12792 123 15496 149 307858 org.mortbay.thread.BoundedThreadPool$PoolThread
        217 0.03% 89.74% 9888 412 44880 1870 303165 sun.nio.cs.Surrogate$Parser
        219 0.03% 89.80% 9616 599 9616 599 307982 java.net.InetAddress[]
        223 0.03% 89.92% 9336 389 24144 1006 312368 java.io.OutputStreamWriter
        266 0.02% 91.09% 7520 188 102120 2553 307851 sun.nio.ch.SelectionKeyImpl
        268 0.02% 91.14% 7416 309 187560 7815 300020 java.lang.StringCoding$CharsetSD
        269 0.02% 91.16% 7416 309 7536 314 303459 java.security.Provider$ServiceKey
        275 0.02% 91.31% 7296 152 184848 3851 310761 ru.webcrm.base.cms.Visitor
        300 0.02% 91.87% 6456 269 63384 2641 308251 java.nio.DirectByteBuffer$Deallocator
        304 0.02% 91.95% 6200 155 159280 3982 300102 sun.nio.cs.UTF_8$Decoder
        342 0.02% 92.64% 4960 31 13600 85 310532 org.mortbay.jetty.Request
        350 0.02% 92.77% 4720 118 102120 2553 307978 java.net.SocketPermission
        365 0.01% 92.99% 4416 184 4488 187 303470 java.security.Provider$ServiceKey

        When this dump was made, there were about 50 active sockets (sockstat) and 500 tcp/ip file descriptors used (fstat | grep tcp). In the heap dump we can see that there is only 31 org.mortbay.jetty.Request instance, and amount of other working objects, like "ru.webcrm.base.cms.Visitor", is around 150, while amount of a lot of Jetty resources, like "java.io.FileDescriptor" and "org.mortbay.jetty.HttpConnection", is much higher (and seems relative to the number of open file descriptors).

        Some traces, to complete the picture above:

        TRACE 307953:
        java.io.FileDescriptor.<init>(FileDescriptor.java:34)
        sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:136)
        org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:403)
        org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183)

        TRACE 308007:
        org.mortbay.jetty.HttpConnection.<init>(HttpConnection.java:83)
        org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint.<init>(SelectChannelConnector.java:540)
        org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:314)
        org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183)

        TRACE 308248:
        java.nio.channels.spi.AbstractInterruptibleChannel$1.<init>(AbstractInterruptibleChannel.java:140)
        java.nio.channels.spi.AbstractInterruptibleChannel.begin(AbstractInterruptibleChannel.java:139)
        sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:147)
        org.mortbay.io.nio.ChannelEndPoint.fill(ChannelEndPoint.java:115)

        TRACE 310761:
        ru.webcrm.base.cms.Visitor.<init>(Visitor.java:50)
        ru.webcrm.base.cms.Waitress.receiveGuests(Waitress.java:165)
        ru.webcrm.base.cms.Servlet.service(Servlet.java:125)
        javax.servlet.http.HttpServlet.service(HttpServlet.java:860)

        Can you tell me more about your webapp?

        We use a single custom Servlet (DefaultServlet from Jetty isn't used). Nothing special (Continuations aren't used). The load might involve a lot of requests from proxy servers (we happen to test proxy servers by using the http://glim.ru/env.cgi there). Currently Jetty (and everything else) runs under URLClassLoader with special Java security permissions, but that is optional and i've checked that the leak remains with this sandbox turned off.

        Show
        Artem Kozarezov added a comment - I've run our program under HPROF ( http://java.sun.com/developer/technicalArticles/Programming/HPROF.html ) Unfortunately, it does not provide information why the instance is held in memory, but it shows what IS in memory, and, i think, it proves that something is wrong here. Here is excerpt from the hprof file, of what i thought is related to that problem: SITES BEGIN (ordered by live bytes) Fri May 26 13:30:09 2006 percent live alloc'ed stack class rank self accum bytes objs bytes objs trace name 43 0.39% 71.66% 120120 1001 306360 2553 307394 java.net.SocksSocketImpl 45 0.37% 72.40% 112112 1001 285936 2553 307964 sun.nio.ch.SocketChannelImpl 56 0.26% 75.64% 79288 901 217096 2467 308007 org.mortbay.jetty.HttpConnection 61 0.24% 76.89% 72080 901 197360 2467 308238 org.mortbay.jetty.HttpGenerator 65 0.21% 77.78% 64872 901 177624 2467 308001 org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint 76 0.17% 79.79% 52192 932 142912 2552 308002 org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint$IdleTask 80 0.17% 80.46% 50456 901 138152 2467 308008 org.mortbay.jetty.HttpURI 81 0.17% 80.63% 50456 901 138152 2467 308226 org.mortbay.jetty.Response 83 0.16% 80.94% 48000 1000 122496 2552 307984 sun.nio.ch.SocketAdaptor 91 0.13% 82.06% 38472 687 108528 1938 312369 org.mortbay.io.ByteArrayBuffer 102 0.10% 83.28% 30816 428 80568 1119 312355 org.mortbay.jetty.HttpConnection$OutputWriter 108 0.09% 83.85% 28520 713 80680 2017 312147 org.mortbay.jetty.HttpConnection$Output 116 0.08% 84.52% 24024 1001 61272 2553 307959 java.net.Inet4Address 117 0.08% 84.60% 24024 1001 61272 2553 307960 java.net.InetSocketAddress 121 0.08% 84.91% 23184 966 59208 2467 307997 java.nio.channels.SelectionKey[] 128 0.07% 85.42% 22296 929 60816 2534 312358 java.net.InetSocketAddress 129 0.07% 85.50% 22176 396 57120 1020 305827 sun.nio.cs.StreamEncoder$CharsetSE 135 0.07% 85.91% 20360 509 77040 1926 310806 javax.servlet.http.Cookie 136 0.07% 85.98% 20272 362 183232 3272 300046 java.nio.DirectByteBuffer 138 0.06% 86.11% 19776 412 89760 1870 303161 sun.nio.cs.ISO_8859_1$Encoder 145 0.06% 86.52% 17120 428 44760 1119 312356 org.mortbay.jetty.HttpConnection$1 149 0.05% 86.74% 16632 297 33152 592 308244 org.mortbay.io.nio.NIOBuffer 156 0.05% 87.11% 16016 1001 40864 2554 307953 java.io.FileDescriptor 157 0.05% 87.17% 16000 1000 40832 2552 307994 sun.nio.ch.SocketChannelImpl$1 158 0.05% 87.22% 16000 1000 40832 2552 307992 sun.nio.ch.OptionAdaptor 159 0.05% 87.27% 16000 1000 40832 2552 308248 java.nio.channels.spi.AbstractInterruptibleChannel$1 160 0.05% 87.32% 16000 1000 40832 2552 307996 sun.nio.ch.SocketOptsImpl$IP$TCP 161 0.05% 87.38% 15960 665 23880 995 309114 java.util.concurrent.locks.ReentrantLock$NonfairSync 169 0.05% 87.78% 14912 932 40832 2552 308009 org.mortbay.jetty.HttpConnection$RequestHandler 175 0.05% 88.07% 14520 605 14520 605 301162 java.net.Inet4Address 176 0.05% 88.11% 14480 362 130880 3272 300050 sun.misc.Cleaner 177 0.05% 88.16% 14400 600 14400 600 301163 java.net.InetAddress$CacheEntry 184 0.04% 88.47% 13240 331 233800 5845 300021 sun.nio.cs.ISO_8859_1$Decoder 190 0.04% 88.73% 12792 123 15496 149 307858 org.mortbay.thread.BoundedThreadPool$PoolThread 217 0.03% 89.74% 9888 412 44880 1870 303165 sun.nio.cs.Surrogate$Parser 219 0.03% 89.80% 9616 599 9616 599 307982 java.net.InetAddress[] 223 0.03% 89.92% 9336 389 24144 1006 312368 java.io.OutputStreamWriter 266 0.02% 91.09% 7520 188 102120 2553 307851 sun.nio.ch.SelectionKeyImpl 268 0.02% 91.14% 7416 309 187560 7815 300020 java.lang.StringCoding$CharsetSD 269 0.02% 91.16% 7416 309 7536 314 303459 java.security.Provider$ServiceKey 275 0.02% 91.31% 7296 152 184848 3851 310761 ru.webcrm.base.cms.Visitor 300 0.02% 91.87% 6456 269 63384 2641 308251 java.nio.DirectByteBuffer$Deallocator 304 0.02% 91.95% 6200 155 159280 3982 300102 sun.nio.cs.UTF_8$Decoder 342 0.02% 92.64% 4960 31 13600 85 310532 org.mortbay.jetty.Request 350 0.02% 92.77% 4720 118 102120 2553 307978 java.net.SocketPermission 365 0.01% 92.99% 4416 184 4488 187 303470 java.security.Provider$ServiceKey When this dump was made, there were about 50 active sockets (sockstat) and 500 tcp/ip file descriptors used (fstat | grep tcp). In the heap dump we can see that there is only 31 org.mortbay.jetty.Request instance, and amount of other working objects, like "ru.webcrm.base.cms.Visitor", is around 150, while amount of a lot of Jetty resources, like "java.io.FileDescriptor" and "org.mortbay.jetty.HttpConnection", is much higher (and seems relative to the number of open file descriptors). Some traces, to complete the picture above: TRACE 307953: java.io.FileDescriptor.<init>(FileDescriptor.java:34) sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:136) org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:403) org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183) TRACE 308007: org.mortbay.jetty.HttpConnection.<init>(HttpConnection.java:83) org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint.<init>(SelectChannelConnector.java:540) org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:314) org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183) TRACE 308248: java.nio.channels.spi.AbstractInterruptibleChannel$1.<init>(AbstractInterruptibleChannel.java:140) java.nio.channels.spi.AbstractInterruptibleChannel.begin(AbstractInterruptibleChannel.java:139) sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:147) org.mortbay.io.nio.ChannelEndPoint.fill(ChannelEndPoint.java:115) TRACE 310761: ru.webcrm.base.cms.Visitor.<init>(Visitor.java:50) ru.webcrm.base.cms.Waitress.receiveGuests(Waitress.java:165) ru.webcrm.base.cms.Servlet.service(Servlet.java:125) javax.servlet.http.HttpServlet.service(HttpServlet.java:860) Can you tell me more about your webapp? We use a single custom Servlet (DefaultServlet from Jetty isn't used). Nothing special (Continuations aren't used). The load might involve a lot of requests from proxy servers (we happen to test proxy servers by using the http://glim.ru/env.cgi there). Currently Jetty (and everything else) runs under URLClassLoader with special Java security permissions, but that is optional and i've checked that the leak remains with this sandbox turned off.
        Hide
        Artem Kozarezov added a comment -

        I'm installing everything required to run the JMP under a VNC session. If it works, expect some news from me on sunday.

        Show
        Artem Kozarezov added a comment - I'm installing everything required to run the JMP under a VNC session. If it works, expect some news from me on sunday.
        Hide
        Artem Kozarezov added a comment -

        From evaluating behaviour of Jetty with out application under JMP (http://www.khelekore.org/jmp/) i can draw the followin:
        1)
        HPROF was a bit misleading about amount of some object, in particular, org.mortbay.jetty.Request instance is allocated as much as everything else bundled with HttpConnection.
        2)
        java.io.FileDescriptor
        is referenced from
        sun.nio.ch.SocketChannelImpl
        which is referenced from
        org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint
        which is practically always referenced from
        org.mortbay.jetty.HttpConnection$OutputWriter
        org.mortbay.jetty.HttpGenerator
        org.mortbay.jetty.Request
        org.mortbay.jetty.HttpParser
        org.mortbay.jetty.HttpConnection
        org.mortbay.jetty.nio.SelectChannerlConnector$HttpEndPoint$IdleTask
        but only referenced from
        sun.nio.ch.SelectionKeyImpl
        when there is an actual socket connection.

        It looks like there is a pool of all the resources (or a leak?) which includes, thru sun.nio.ch.SocketChannelImpl, even file descriptors... Perhaps it is possible to a) shrink that pool, b) set the reference, which points from org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint to sun.nio.ch.SocketChannelImpl to null when the connection is no longer used (or otherwise close this channel).

        Show
        Artem Kozarezov added a comment - From evaluating behaviour of Jetty with out application under JMP ( http://www.khelekore.org/jmp/ ) i can draw the followin: 1) HPROF was a bit misleading about amount of some object, in particular, org.mortbay.jetty.Request instance is allocated as much as everything else bundled with HttpConnection. 2) java.io.FileDescriptor is referenced from sun.nio.ch.SocketChannelImpl which is referenced from org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint which is practically always referenced from org.mortbay.jetty.HttpConnection$OutputWriter org.mortbay.jetty.HttpGenerator org.mortbay.jetty.Request org.mortbay.jetty.HttpParser org.mortbay.jetty.HttpConnection org.mortbay.jetty.nio.SelectChannerlConnector$HttpEndPoint$IdleTask but only referenced from sun.nio.ch.SelectionKeyImpl when there is an actual socket connection. It looks like there is a pool of all the resources (or a leak?) which includes, thru sun.nio.ch.SocketChannelImpl , even file descriptors... Perhaps it is possible to a) shrink that pool, b) set the reference, which points from org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint to sun.nio.ch.SocketChannelImpl to null when the connection is no longer used (or otherwise close this channel).
        Hide
        Jan Bartel added a comment -

        Artem,

        If you run jetty with jconsole (java -Dcom.sun.management.jmxremote -jar start.jar and start jconsole), does performing a manual garbage collection help with this at all?

        Show
        Jan Bartel added a comment - Artem, If you run jetty with jconsole (java -Dcom.sun.management.jmxremote -jar start.jar and start jconsole), does performing a manual garbage collection help with this at all?
        Hide
        Artem Kozarezov added a comment -

        bt. If you run jetty with jconsole (java -Dcom.sun.management.jmxremote -jar start.jar and start jconsole), does performing a manual garbage collection help with this at all?

        First, our application performs System.gc every minute (a feature i'm planning to remove), and, secondly, JMP have a button to perform GC, and i've pressed it regularly (since it helps a bit with the speed of JMP doing and processing its memory dump), so my results were made after the full GC. So, the answer is no, full GC doesn't change anything.
        If memory behaviour i'm experiencing is not as it should be, i can try to further investigate it by somehow examining the JMP heap dump itself (it's a 95 mb text file). But i've suspected, that these resources are held by org.mortbay.jetty.nio.SelectChannerlConnector$HttpEndPoint$IdleTask, which looks (by it's name) as it was intended to held them...

        Show
        Artem Kozarezov added a comment - bt. If you run jetty with jconsole (java -Dcom.sun.management.jmxremote -jar start.jar and start jconsole), does performing a manual garbage collection help with this at all? First, our application performs System.gc every minute (a feature i'm planning to remove), and, secondly, JMP have a button to perform GC, and i've pressed it regularly (since it helps a bit with the speed of JMP doing and processing its memory dump), so my results were made after the full GC. So, the answer is no, full GC doesn't change anything. If memory behaviour i'm experiencing is not as it should be, i can try to further investigate it by somehow examining the JMP heap dump itself (it's a 95 mb text file). But i've suspected, that these resources are held by org.mortbay.jetty.nio.SelectChannerlConnector$HttpEndPoint$IdleTask, which looks (by it's name) as it was intended to held them...
        Hide
        Jan Bartel added a comment -

        Artem,

        What are the open files that are reported in fstat?

        Also see: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6215050

        Does it sound something like you are describing? If so, it is fixed in the version of jdk1.5 that was released on the 25th May (jdk1.5_07) - you could try with that jdk.

        Show
        Jan Bartel added a comment - Artem, What are the open files that are reported in fstat? Also see: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6215050 Does it sound something like you are describing? If so, it is fixed in the version of jdk1.5 that was released on the 25th May (jdk1.5_07) - you could try with that jdk.
        Hide
        Greg Wilkins added a comment -

        Artem,

        What is holding IdleTask in memory? It should only be there for the maxIdleTime of the connector as it is on a timer
        list.

        Does shortening MaxIdleTime reduce this leak? It may simply be that the idle timeout is not being cancelled and
        you have a lot of new connections... so these connections are being held in memory for that period of time.

        Note that lots of work has been done on the idle timeout recently - so If changing the idle timeout does
        change the rate of HttpConnection retention, then I would suggest trying Jetty head/trunk from SVN.

        I will double check now that the idle timeout is cancelled when a connection is closed.

        Show
        Greg Wilkins added a comment - Artem, What is holding IdleTask in memory? It should only be there for the maxIdleTime of the connector as it is on a timer list. Does shortening MaxIdleTime reduce this leak? It may simply be that the idle timeout is not being cancelled and you have a lot of new connections... so these connections are being held in memory for that period of time. Note that lots of work has been done on the idle timeout recently - so If changing the idle timeout does change the rate of HttpConnection retention, then I would suggest trying Jetty head/trunk from SVN. I will double check now that the idle timeout is cancelled when a connection is closed.
        Hide
        Greg Wilkins added a comment -

        ooops I was not cancelling the idle timeout when a connection was closed! So it was not being leaked, but it was being held in memory for 30s or whatever you have maxIdleTime set to.

        So if you have a high connection rate (and not many persistent connections), this would cause the symptoms you are seeing.

        Fix was simple and is in SVN head now.

        Please can you test so I can close this issue.

        Show
        Greg Wilkins added a comment - ooops I was not cancelling the idle timeout when a connection was closed! So it was not being leaked, but it was being held in memory for 30s or whatever you have maxIdleTime set to. So if you have a high connection rate (and not many persistent connections), this would cause the symptoms you are seeing. Fix was simple and is in SVN head now. Please can you test so I can close this issue.
        Hide
        Artem Kozarezov added a comment -

        Answering Jan Bartel questions:

        What are the open files that are reported in fstat?

        fstat.txt was attached to the bug report in the first place.

        Also see: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6215050 - Does it sound something like you are describing?

        No, as i've said, nor netstat neither sockstat report these leaked descriptors. A socket in the CLOSE_WAIT state will be reported by netstat.

        Answering Greg Wilkins:

        ooops I was not cancelling the idle timeout when a connection was closed! So it was not being leaked, but it was being held in memory for 30s or whatever you have maxIdleTime set to.

        This looks like it! I will test and report.
        BTW, the maxIdleTime behaviour has changed in Jetty6. We had tasks which take a very long time to complete, and Jetty began to simply drop connections (this is becouse SO_TIMEOUT is set to 30 seconds, and connection is simply dropped by the OS after that perios), therefore we had to set maxIdleTime to 600 seconds! So, what you've described looks like the reason for this problem, indeed.

        Show
        Artem Kozarezov added a comment - Answering Jan Bartel questions : What are the open files that are reported in fstat? fstat.txt was attached to the bug report in the first place. Also see: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6215050 - Does it sound something like you are describing? No, as i've said, nor netstat neither sockstat report these leaked descriptors. A socket in the CLOSE_WAIT state will be reported by netstat. Answering Greg Wilkins : ooops I was not cancelling the idle timeout when a connection was closed! So it was not being leaked, but it was being held in memory for 30s or whatever you have maxIdleTime set to. This looks like it! I will test and report. BTW, the maxIdleTime behaviour has changed in Jetty6. We had tasks which take a very long time to complete, and Jetty began to simply drop connections (this is becouse SO_TIMEOUT is set to 30 seconds, and connection is simply dropped by the OS after that perios), therefore we had to set maxIdleTime to 600 seconds! So, what you've described looks like the reason for this problem, indeed.
        Hide
        Artem Kozarezov added a comment -

        With Jetty SVN 550, and MaxIdleTime set to 60 seconds, amount of used file descriptors remains low.
        With MaxIdleTime of 600 seconds it is still very high, though not indefinitely as before.

        P.S.
        I think using MaxIdleTime for active connections is a bug. When browser awaits result from a working server thread, connection is not exactly "idle". Under heavy load, it is practically always desirable to sat "idle" timeout (which, i suspect, is used for "keep-alive" connections, and have a separate timeout tweak in Apache) to be smaller than the general connection timeout.

        Show
        Artem Kozarezov added a comment - With Jetty SVN 550, and MaxIdleTime set to 60 seconds, amount of used file descriptors remains low. With MaxIdleTime of 600 seconds it is still very high, though not indefinitely as before. P.S. I think using MaxIdleTime for active connections is a bug. When browser awaits result from a working server thread, connection is not exactly "idle". Under heavy load, it is practically always desirable to sat "idle" timeout (which, i suspect, is used for "keep-alive" connections, and have a separate timeout tweak in Apache) to be smaller than the general connection timeout.
        Hide
        Artem Kozarezov added a comment -

        Correction to my previous coment. I think connection which have an allocated thread should be subject to a "working" connection timeout, and connection whose thread is released, that is, no longer in HttpServlet#service, should be subject to another connection timeout. If i understand it correctly, Jetty6 can benefit the application by buffering the response, so that HttpServlet#service may exit and thread be released while Jetty still is about to send what remains of response to the client. HttpServlet#service induced timeout should be separated somehow from pure TCP/IP timeout. Perhaps SO_TIMEOUT can simply be set to 0 until HttpServlet#service exit.

        Show
        Artem Kozarezov added a comment - Correction to my previous coment. I think connection which have an allocated thread should be subject to a "working" connection timeout, and connection whose thread is released, that is, no longer in HttpServlet#service, should be subject to another connection timeout. If i understand it correctly, Jetty6 can benefit the application by buffering the response, so that HttpServlet#service may exit and thread be released while Jetty still is about to send what remains of response to the client. HttpServlet#service induced timeout should be separated somehow from pure TCP/IP timeout. Perhaps SO_TIMEOUT can simply be set to 0 until HttpServlet#service exit.
        Hide
        Artem Kozarezov added a comment -

        Hmm, maybe i was too eager to say that it's working. After running for a hour with MaxIdleTime set to 60 seconds, amount of tcp file descriptors slowly increased from 70 to 230... While nestat (which includes TIME_WAIT sessions, whose timeout, if i'm remeber correctly, is two minutes!) shows only 90 connections.
        But we might be on the right track, as the leak definitely scales with MaxIdleTime...

        Show
        Artem Kozarezov added a comment - Hmm, maybe i was too eager to say that it's working. After running for a hour with MaxIdleTime set to 60 seconds, amount of tcp file descriptors slowly increased from 70 to 230... While nestat (which includes TIME_WAIT sessions, whose timeout, if i'm remeber correctly, is two minutes!) shows only 90 connections. But we might be on the right track, as the leak definitely scales with MaxIdleTime...
        Hide
        Artem Kozarezov added a comment -

        Now it's 140 in netstat against 340 in fstat.
        BTW, I have 121 IOException and 23 NullPointerException in the log.
        A sample IOException:

        java.io.IOException: Broken pipe
        at sun.nio.ch.FileDispatcher.write0(Native Method)
        at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:29)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:104)
        at sun.nio.ch.IOUtil.write(IOUtil.java:75)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:302)
        at org.mortbay.io.nio.ChannelEndPoint.flush(ChannelEndPoint.java:151)
        at org.mortbay.jetty.nio.SelectChannelConnector$HttpChannelEndPoint.flush(SelectChannelConnector.java:
        at org.mortbay.jetty.HttpGenerator.flushBuffers(HttpGenerator.java:758)
        at org.mortbay.jetty.HttpGenerator.complete(HttpGenerator.java:721)
        at org.mortbay.jetty.HttpConnection.completeResponse(HttpConnection.java:437)
        at org.mortbay.jetty.Response.complete(Response.java:896)
        at org.mortbay.jetty.HttpConnection.handlerRequest(HttpConnection.java:399)
        at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:614)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:487)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:197)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:288)
        at org.mortbay.jetty.nio.SelectChannelConnector$HttpChannelEndPoint.run(SelectChannelConnector.java:80
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475)

        and a sample NPE:

        java.lang.NullPointerException
        at org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:400)
        at org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183)
        at org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:611)
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475)

        Could this be related to leaked IdleTask's?

        Show
        Artem Kozarezov added a comment - Now it's 140 in netstat against 340 in fstat. BTW, I have 121 IOException and 23 NullPointerException in the log. A sample IOException: java.io.IOException: Broken pipe at sun.nio.ch.FileDispatcher.write0(Native Method) at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:29) at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:104) at sun.nio.ch.IOUtil.write(IOUtil.java:75) at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:302) at org.mortbay.io.nio.ChannelEndPoint.flush(ChannelEndPoint.java:151) at org.mortbay.jetty.nio.SelectChannelConnector$HttpChannelEndPoint.flush(SelectChannelConnector.java: at org.mortbay.jetty.HttpGenerator.flushBuffers(HttpGenerator.java:758) at org.mortbay.jetty.HttpGenerator.complete(HttpGenerator.java:721) at org.mortbay.jetty.HttpConnection.completeResponse(HttpConnection.java:437) at org.mortbay.jetty.Response.complete(Response.java:896) at org.mortbay.jetty.HttpConnection.handlerRequest(HttpConnection.java:399) at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnection.java:614) at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:487) at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:197) at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:288) at org.mortbay.jetty.nio.SelectChannelConnector$HttpChannelEndPoint.run(SelectChannelConnector.java:80 at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475) and a sample NPE: java.lang.NullPointerException at org.mortbay.jetty.nio.SelectChannelConnector$SelectSet.accept(SelectChannelConnector.java:400) at org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:183) at org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:611) at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:475) Could this be related to leaked IdleTask's?
        Hide
        Artem Kozarezov added a comment -

        "lsof -i -n" output, with a lot of leaked descriptors
        (meanwhile, "netstat -p tcp -a -n | wc -l" shows only 22 TCP/IP slots)

        Show
        Artem Kozarezov added a comment - "lsof -i -n" output, with a lot of leaked descriptors (meanwhile, "netstat -p tcp -a -n | wc -l" shows only 22 TCP/IP slots)
        Hide
        Greg Wilkins added a comment -

        I still think this could be a JVM issue as I don't think anything in Jetty can put a socket
        into the state : TCP no PCB, CANTSENDMORE, CANTRCVMORE

        we always call close and never just shutdown.

        Can you repreoduce this problem running against the jetty test webapp?
        Alternately can you send me a webapp that does have this problem so that I can
        confirm that I am testing against the same conditions that you are.

        Show
        Greg Wilkins added a comment - I still think this could be a JVM issue as I don't think anything in Jetty can put a socket into the state : TCP no PCB, CANTSENDMORE, CANTRCVMORE we always call close and never just shutdown. Can you repreoduce this problem running against the jetty test webapp? Alternately can you send me a webapp that does have this problem so that I can confirm that I am testing against the same conditions that you are.
        Hide
        Artem Kozarezov added a comment -

        > I still think this could be a JVM issue as I don't think anything in Jetty can put a socket
        > into the state : TCP no PCB, CANTSENDMORE, CANTRCVMORE

        But i've traced, with JMP, that there are opened java.io.FileDescriptor's, referenced from sun.nio.ch.SocketChannelImpl, referenced from org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint...

        > Can you repreoduce this problem running against the jetty test webapp?
        > Alternately can you send me a webapp that does have this problem so that I can
        > confirm that I am testing against the same conditions that you are.

        I understand that you need more info. Please, wait until i have time to further trace why there is a lot of used SelectChannelConnector$HttpEndPoint objects (way too much) and/or write a test app, in an attempt to prove the problem. I can provide you with my app, but i suspect that a simple brute-force test won't lead to the same results.

        Show
        Artem Kozarezov added a comment - > I still think this could be a JVM issue as I don't think anything in Jetty can put a socket > into the state : TCP no PCB, CANTSENDMORE, CANTRCVMORE But i've traced, with JMP, that there are opened java.io.FileDescriptor's, referenced from sun.nio.ch.SocketChannelImpl, referenced from org.mortbay.jetty.nio.SelectChannelConnector$HttpEndPoint... > Can you repreoduce this problem running against the jetty test webapp? > Alternately can you send me a webapp that does have this problem so that I can > confirm that I am testing against the same conditions that you are. I understand that you need more info. Please, wait until i have time to further trace why there is a lot of used SelectChannelConnector$HttpEndPoint objects (way too much) and/or write a test app, in an attempt to prove the problem. I can provide you with my app, but i suspect that a simple brute-force test won't lead to the same results.
        Hide
        Artem Kozarezov added a comment -

        With Jetty 6 i have a problem, practically always on a Windows box, when using localhost, and very seldom on a unix box, when a User-Agent session with Jetty hangs for no apparent reason after two or three subsequent request (loading a framed page with iframes). There is no such behaviour with the same page in Jetty 5. I suspect this might be related to the "leaked file descriptors" problem.

        Here is the trace of hanging thread (using jetty-6.0.0rc0):
        Thread [btpool0-0 - Acceptor0 SelectChannelConnector @ localhost:80] (Suspended)
        owns: WindowsSelectorImpl (id=29)
        owns: Collections$UnmodifiableSet<E> (id=30)
        owns: Util$1 (id=31)
        WindowsSelectorImpl$SubSelector.poll0(long, int, int[], int[], int[], long) line: not available [native method]
        WindowsSelectorImpl$SubSelector.poll() line: 275
        WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl$SubSelector) line: 257
        WindowsSelectorImpl.doSelect(long) line: 138
        WindowsSelectorImpl(SelectorImpl).lockAndDoSelect(long) line: 69
        WindowsSelectorImpl(SelectorImpl).select(long) line: 80
        SelectChannelConnector$SelectSet.accept() line: 361
        SelectChannelConnector.accept(int) line: 177
        AbstractConnector$Acceptor.run() line: 630
        BoundedThreadPool$PoolThread.run() line: 475

        In the SelectChannelConnector$SelectSet.accept() the variables are:

        this= SelectChannelConnector$SelectSet (id=55)
        _change= 0
        _changes= ArrayList<E>[2] (id=70)
        _idleTimeout= Timeout (id=71)
        _duration= 60000
        _head= Timeout$Task (id=93)
        _now= 1152535639178
        _nextSet= 0
        _retryTimeout= Timeout (id=73)
        _duration= 0
        _head= Timeout$Task (id=95)
        _now= 1152535639178
        _selector= WindowsSelectorImpl (id=29)
        cancelledKeys= HashSet<E> (id=96)
        channelArray= SelectionKeyImpl[8] (id=100)
        fdMap= WindowsSelectorImpl$FdMap (id=101)
        finishLock= WindowsSelectorImpl$FinishLock (id=106)
        INIT_CAP= 8
        interruptLock= Object (id=108)
        interruptor= AbstractSelector$1 (id=109)
        interruptTriggered= false
        keys= HashSet<E> (id=112)
        pollWrapper= PollArrayWrapper (id=113)
        provider= WindowsSelectorProvider (id=115)
        publicKeys= Collections$UnmodifiableSet<E> (id=30)
        publicSelectedKeys= Util$1 (id=31)
        selectedKeys= HashSet<E> (id=120)
        selectorOpen= AtomicBoolean (id=121)
        startLock= WindowsSelectorImpl$StartLock (id=123)
        subSelector= WindowsSelectorImpl$SubSelector (id=54)
        threads= ArrayList<E> (id=125)
        threadsCount= 0
        timeout= 58477
        totalChannels= 4
        updateCount= 29
        wakeupPipe= PipeImpl (id=126)
        wakeupSinkFd= 2212
        wakeupSourceFd= 2224
        _setID= 0
        _shortIdleTimeout= Timeout (id=76)
        _duration= 2500
        _head= Timeout$Task (id=168)
        _now= 1152535639178
        this$0= SelectChannelConnector (id=56)
        _acceptChannel= ServerSocketChannelImpl (id=131)
        _acceptKey= SelectionKeyImpl (id=141)
        _acceptors= 1
        _acceptorThread= Thread[1] (id=144)
        _acceptQueueSize= 0
        _confidentialPort= 0
        _confidentialScheme= "https"
        _connections= 0
        _connectionsDurationMax= 0
        _connectionsDurationMin= 0
        _connectionsDurationTotal= 0
        _connectionsOpen= 0
        _connectionsOpenMax= 0
        _connectionsOpenMin= 0
        _connectionsRequestsMax= 0
        _connectionsRequestsMin= 0
        _delaySelectKeyUpdate= false
        _headerBuffers= ArrayList<E> (id=148)
        _headerBufferSize= 4096
        _host= "localhost"
        _integralPort= 0
        _integralScheme= "https"
        _lowResourceMaxIdleTime= 2500
        _maxIdleTime= 60000
        _name= null
        _port= 80
        _requestBuffers= ArrayList<E> (id=150)
        _requestBufferSize= 8192
        _requests= 0
        _responseBuffers= ArrayList<E> (id=151)
        _responseBufferSize= 32768
        _selectSets= SelectChannelConnector$SelectSet[1] (id=152)
        _server= Server (id=153)
        _soLingerTime= 1000
        _state= 2
        _statsLock= Object (id=161)
        _statsStartedAt= -1
        _threadPool= BoundedThreadPool (id=162)
        _useDNS= false
        FAILED= -1
        STARTED= 2
        STARTING= 1
        STOPPED= 0
        STOPPING= 3
        short_next= -1
        idle_next= 58477
        retry_next= -1
        changes= ArrayList<E> (id=59)
        wait= 58477

        I will now attach the captured packets of that session.

        Show
        Artem Kozarezov added a comment - With Jetty 6 i have a problem, practically always on a Windows box, when using localhost, and very seldom on a unix box, when a User-Agent session with Jetty hangs for no apparent reason after two or three subsequent request (loading a framed page with iframes). There is no such behaviour with the same page in Jetty 5. I suspect this might be related to the "leaked file descriptors" problem. Here is the trace of hanging thread (using jetty-6.0.0rc0): Thread [btpool0-0 - Acceptor0 SelectChannelConnector @ localhost:80] (Suspended) owns: WindowsSelectorImpl (id=29) owns: Collections$UnmodifiableSet<E> (id=30) owns: Util$1 (id=31) WindowsSelectorImpl$SubSelector.poll0(long, int, int[], int[], int[], long) line: not available [native method] WindowsSelectorImpl$SubSelector.poll() line: 275 WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl$SubSelector) line: 257 WindowsSelectorImpl.doSelect(long) line: 138 WindowsSelectorImpl(SelectorImpl).lockAndDoSelect(long) line: 69 WindowsSelectorImpl(SelectorImpl).select(long) line: 80 SelectChannelConnector$SelectSet.accept() line: 361 SelectChannelConnector.accept(int) line: 177 AbstractConnector$Acceptor.run() line: 630 BoundedThreadPool$PoolThread.run() line: 475 In the SelectChannelConnector$SelectSet.accept() the variables are: this= SelectChannelConnector$SelectSet (id=55) _change= 0 _changes= ArrayList<E> [2] (id=70) _idleTimeout= Timeout (id=71) _duration= 60000 _head= Timeout$Task (id=93) _now= 1152535639178 _nextSet= 0 _retryTimeout= Timeout (id=73) _duration= 0 _head= Timeout$Task (id=95) _now= 1152535639178 _selector= WindowsSelectorImpl (id=29) cancelledKeys= HashSet<E> (id=96) channelArray= SelectionKeyImpl [8] (id=100) fdMap= WindowsSelectorImpl$FdMap (id=101) finishLock= WindowsSelectorImpl$FinishLock (id=106) INIT_CAP= 8 interruptLock= Object (id=108) interruptor= AbstractSelector$1 (id=109) interruptTriggered= false keys= HashSet<E> (id=112) pollWrapper= PollArrayWrapper (id=113) provider= WindowsSelectorProvider (id=115) publicKeys= Collections$UnmodifiableSet<E> (id=30) publicSelectedKeys= Util$1 (id=31) selectedKeys= HashSet<E> (id=120) selectorOpen= AtomicBoolean (id=121) startLock= WindowsSelectorImpl$StartLock (id=123) subSelector= WindowsSelectorImpl$SubSelector (id=54) threads= ArrayList<E> (id=125) threadsCount= 0 timeout= 58477 totalChannels= 4 updateCount= 29 wakeupPipe= PipeImpl (id=126) wakeupSinkFd= 2212 wakeupSourceFd= 2224 _setID= 0 _shortIdleTimeout= Timeout (id=76) _duration= 2500 _head= Timeout$Task (id=168) _now= 1152535639178 this$0= SelectChannelConnector (id=56) _acceptChannel= ServerSocketChannelImpl (id=131) _acceptKey= SelectionKeyImpl (id=141) _acceptors= 1 _acceptorThread= Thread [1] (id=144) _acceptQueueSize= 0 _confidentialPort= 0 _confidentialScheme= "https" _connections= 0 _connectionsDurationMax= 0 _connectionsDurationMin= 0 _connectionsDurationTotal= 0 _connectionsOpen= 0 _connectionsOpenMax= 0 _connectionsOpenMin= 0 _connectionsRequestsMax= 0 _connectionsRequestsMin= 0 _delaySelectKeyUpdate= false _headerBuffers= ArrayList<E> (id=148) _headerBufferSize= 4096 _host= "localhost" _integralPort= 0 _integralScheme= "https" _lowResourceMaxIdleTime= 2500 _maxIdleTime= 60000 _name= null _port= 80 _requestBuffers= ArrayList<E> (id=150) _requestBufferSize= 8192 _requests= 0 _responseBuffers= ArrayList<E> (id=151) _responseBufferSize= 32768 _selectSets= SelectChannelConnector$SelectSet [1] (id=152) _server= Server (id=153) _soLingerTime= 1000 _state= 2 _statsLock= Object (id=161) _statsStartedAt= -1 _threadPool= BoundedThreadPool (id=162) _useDNS= false FAILED= -1 STARTED= 2 STARTING= 1 STOPPED= 0 STOPPING= 3 short_next= -1 idle_next= 58477 retry_next= -1 changes= ArrayList<E> (id=59) wait= 58477 I will now attach the captured packets of that session.
        Hide
        Artem Kozarezov added a comment -

        On a second thought, perhaps it is a separate issue, i don't think the file descriptor is leaked here...

        Show
        Artem Kozarezov added a comment - On a second thought, perhaps it is a separate issue, i don't think the file descriptor is leaked here...
        Hide
        Artem Kozarezov added a comment -

        properly filtered

        Show
        Artem Kozarezov added a comment - properly filtered
        Hide
        Artem Kozarezov added a comment -

        Perhaps the browser is hanging becouse the last "302 Found" response is empty.
        Shouldn't there be two "0"'s instead of one?
        (Reconstruction of last keepalive request follows)

        GET /cmsIface/i568948258i/ HTTP/1.1
        Host: localhost
        User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; ru; rv:1.8.0.4) Gecko/20060508 Firefox/1.5.0.4
        Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,/;q=0.5
        Accept-Language: ru-ru,ru;q=0.8,en-us;q=0.5,en;q=0.3
        Accept-Encoding: gzip,deflate
        Accept-Charset: windows-1251,utf-8;q=0.7,*;q=0.7
        Keep-Alive: 300
        Connection: keep-alive
        Referer: http://localhost/cmsIface/
        Cookie: wcForumSession1=1691zp24s1ov3_j1zdtt

        HTTP/1.1 302 Found
        Server: WebCRM/1.2 (via Jetty6)
        Content-Type: text/html; charset=UTF-8
        WWW-Authenticate: Basic realm="quadro cmsIface"
        Cache-Control: no-cache
        Pragma: no-cache
        Location: /cmsIface/error&gvgyr=Gur~20yvax~20unf~20rkcverq~20~28gung~27f~20BX~29.&glcr=wnin.ynat.Rkprcgvba&fgnpxUnfu=ZUB&qngr=rcti9lvy
        Transfer-Encoding: chunked
        Connection: keep-alive

        0

        Show
        Artem Kozarezov added a comment - Perhaps the browser is hanging becouse the last "302 Found" response is empty. Shouldn't there be two "0"'s instead of one? (Reconstruction of last keepalive request follows) GET /cmsIface/i568948258i/ HTTP/1.1 Host: localhost User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; ru; rv:1.8.0.4) Gecko/20060508 Firefox/1.5.0.4 Accept: text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png, / ;q=0.5 Accept-Language: ru-ru,ru;q=0.8,en-us;q=0.5,en;q=0.3 Accept-Encoding: gzip,deflate Accept-Charset: windows-1251,utf-8;q=0.7,*;q=0.7 Keep-Alive: 300 Connection: keep-alive Referer: http://localhost/cmsIface/ Cookie: wcForumSession1=1691zp24s1ov3_j1zdtt HTTP/1.1 302 Found Server: WebCRM/1.2 (via Jetty6) Content-Type: text/html; charset=UTF-8 WWW-Authenticate: Basic realm="quadro cmsIface" Cache-Control: no-cache Pragma: no-cache Location: /cmsIface/error&gvgyr=Gur~20yvax~20unf~20rkcverq~20~28gung~27f~20BX~29.&glcr=wnin.ynat.Rkprcgvba&fgnpxUnfu=ZUB&qngr=rcti9lvy Transfer-Encoding: chunked Connection: keep-alive 0
        Hide
        Artem Kozarezov added a comment -

        BTW, apparently, Jetty 6 waits for a next KeepAlive request with a blocking IO operation here, using the "btpool0-0 - Acceptor0 SelectChannelConnector @ localhost:80" thread. I thought that Jetty 6 will do this with a non-blocking IO. Shouldn't it?

        Show
        Artem Kozarezov added a comment - BTW, apparently, Jetty 6 waits for a next KeepAlive request with a blocking IO operation here, using the "btpool0-0 - Acceptor0 SelectChannelConnector @ localhost:80" thread. I thought that Jetty 6 will do this with a non-blocking IO. Shouldn't it?
        Hide
        Greg Wilkins added a comment -

        Artem,

        The single 0 is OK - it is a zero chunk and indicates no content. Although generally speaking
        I prefer if jetty was to send back a content-length: 0 instead of an empty chunk.

        But the strange this is that there is a WWW-Authenticate challenge in a 302 response?
        This should be a 401 response?

        What is your security constraint configuration?
        this really should be a new issue! Can you open a new issue and attach your web.xml

        Show
        Greg Wilkins added a comment - Artem, The single 0 is OK - it is a zero chunk and indicates no content. Although generally speaking I prefer if jetty was to send back a content-length: 0 instead of an empty chunk. But the strange this is that there is a WWW-Authenticate challenge in a 302 response? This should be a 401 response? What is your security constraint configuration? this really should be a new issue! Can you open a new issue and attach your web.xml
        Hide
        Greg Wilkins added a comment -

        YIPEEEEE!!!!!!!!!!!!!!!!!! fixed!

        The issue was that ab (and I expect other clients) sends a strange ack for the last data packet... which causes
        the server to reset the connection rather than close it gracefully. This caused socket.shutdownOutput()
        to throw an alreadyShutdown exception, which caused the calls to socket.close() and channel.close() to be missed!

        The reason the socket.shutdownOutput and socket.close are there is because a pure channel.close() does
        not appear to allow the socket to close quickly and there is a big delay injected.

        So the fix is to protect all of these with finally calls, so that all three methods will always be called.
        Obvious with 20:20 hindsight!

        Thanks all for your perseverence in helping me find this one and thanks Christian for giving me access to
        his machine.

        Show
        Greg Wilkins added a comment - YIPEEEEE!!!!!!!!!!!!!!!!!! fixed! The issue was that ab (and I expect other clients) sends a strange ack for the last data packet... which causes the server to reset the connection rather than close it gracefully. This caused socket.shutdownOutput() to throw an alreadyShutdown exception, which caused the calls to socket.close() and channel.close() to be missed! The reason the socket.shutdownOutput and socket.close are there is because a pure channel.close() does not appear to allow the socket to close quickly and there is a big delay injected. So the fix is to protect all of these with finally calls, so that all three methods will always be called. Obvious with 20:20 hindsight! Thanks all for your perseverence in helping me find this one and thanks Christian for giving me access to his machine.
        Hide
        Artem Kozarezov added a comment -

        Cool.

        Show
        Artem Kozarezov added a comment - Cool.
        Hide
        Kirill Lastovirya added a comment -

        was the issue solved? I see very similar behavior on jetty versions starting from 6.1.16
        can I create an issue, I can provide detailed description

        Show
        Kirill Lastovirya added a comment - was the issue solved? I see very similar behavior on jetty versions starting from 6.1.16 can I create an issue, I can provide detailed description
        Hide
        Jesse McConnell added a comment -

        yes this issue was resolved ages ago

        if your having a similar problem then please do open a new issue and provide details

        Show
        Jesse McConnell added a comment - yes this issue was resolved ages ago if your having a similar problem then please do open a new issue and provide details

          People

          • Assignee:
            Greg Wilkins
            Reporter:
            Artem Kozarezov
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: