Return-Path: X-Original-To: apmail-tomcat-users-archive@www.apache.org Delivered-To: apmail-tomcat-users-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id D4AE910380 for ; Fri, 13 Dec 2013 13:12:56 +0000 (UTC) Received: (qmail 51801 invoked by uid 500); 13 Dec 2013 13:12:49 -0000 Delivered-To: apmail-tomcat-users-archive@tomcat.apache.org Received: (qmail 51740 invoked by uid 500); 13 Dec 2013 13:12:43 -0000 Mailing-List: contact users-help@tomcat.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: "Tomcat Users List" Delivered-To: mailing list users@tomcat.apache.org Received: (qmail 51725 invoked by uid 99); 13 Dec 2013 13:12:42 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 13 Dec 2013 13:12:42 +0000 X-ASF-Spam-Status: No, hits=2.2 required=5.0 tests=HTML_MESSAGE,RCVD_IN_DNSWL_NONE,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of bob.deremer@thingworx.com designates 207.46.163.186 as permitted sender) Received: from [207.46.163.186] (HELO na01-bn1-obe.outbound.protection.outlook.com) (207.46.163.186) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 13 Dec 2013 13:12:34 +0000 Received: from BLUPR06MB193.namprd06.prod.outlook.com (10.242.191.143) by BLUPR06MB195.namprd06.prod.outlook.com (10.242.191.144) with Microsoft SMTP Server (TLS) id 15.0.837.10; Fri, 13 Dec 2013 13:12:08 +0000 Received: from BLUPR06MB193.namprd06.prod.outlook.com ([169.254.16.191]) by BLUPR06MB193.namprd06.prod.outlook.com ([169.254.16.191]) with mapi id 15.00.0837.004; Fri, 13 Dec 2013 13:12:08 +0000 From: Bob DeRemer To: Tomcat Users List Subject: high CPU usage with NIO and 1000+ websockets on Tomcat 7.0.49? Thread-Topic: high CPU usage with NIO and 1000+ websockets on Tomcat 7.0.49? Thread-Index: Ac74BNvxes0WgpYzQmGFJgTMkhI+zg== Date: Fri, 13 Dec 2013 13:12:08 +0000 Message-ID: <8bb973b1edae4aaba972939934946472@BLUPR06MB193.namprd06.prod.outlook.com> Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: yes X-MS-TNEF-Correlator: x-originating-ip: [96.245.114.98] x-forefront-prvs: 00594E8DBA x-forefront-antispam-report: SFV:NSPM;SFS:(10019001)(5423002)(189002)(199002)(164054003)(50944004)(16601075003)(87936001)(81686001)(66066001)(76176001)(76796001)(4396001)(76786001)(2656002)(81816001)(19300405004)(77096001)(80976001)(80022001)(85306002)(83322001)(90146001)(56816005)(19580405001)(65816001)(19580395003)(81342001)(49866001)(33646001)(47976001)(15975445006)(18206015023)(50986001)(81542001)(76576001)(47736001)(56776001)(74706001)(74662001)(47446002)(74502001)(54316002)(87266001)(63696002)(74876001)(15202345003)(59766001)(31966008)(77982001)(54356001)(69226001)(74366001)(85852003)(83072002)(17760045001)(53806001)(76482001)(74316001)(16236675002)(79102001)(51856001)(46102001)(24736002);DIR:OUT;SFP:1102;SCL:1;SRVR:BLUPR06MB195;H:BLUPR06MB193.namprd06.prod.outlook.com;CLIP:96.245.114.98;FPR:;RD:InfoNoRecords;MX:1;A:1;LANG:en; Content-Type: multipart/related; boundary="_004_8bb973b1edae4aaba972939934946472BLUPR06MB193namprd06pro_"; type="multipart/alternative" MIME-Version: 1.0 X-OriginatorOrg: thingworx.com X-Virus-Checked: Checked by ClamAV on apache.org --_004_8bb973b1edae4aaba972939934946472BLUPR06MB193namprd06pro_ Content-Type: multipart/alternative; boundary="_000_8bb973b1edae4aaba972939934946472BLUPR06MB193namprd06pro_" --_000_8bb973b1edae4aaba972939934946472BLUPR06MB193namprd06pro_ Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable Hi Mark (et al), We're seeing really high CPU utilization with just a 1000 active websockets= that are sending/receiving 100 byte binary messages. The profiling snipp= et below was with 1000 connections. If we start to increase the number of = connections, the time spent in the NIO logic starts to consume the majority= of the processing. As a result, I'm trying to verify: * Is this something that can be tuned/improved using Tomcat's NIO s= ettings? * Is this a bug in Tomcat 7 (websocket/NIO)? * Are we hitting some issue with 1000+ highly active NIO sockets? The nature of this application is that it's primary functionality is to pro= cess binary messages on (ideally 10 - 20K websockets), forward them to anot= her server for processing, then send the responses back. As a result, the = performance of the websocket communication is a critical factor for success= . Please let me know if you'd like to discuss this - I'm available any time. Thanks, Bob We have been profiling this in YourKit and as we increase the number of web= sockets, naturally we see the CPU utilization increase. The concern is tha= t we're seeing this at what seems to be a fairly low number of websockets. = The YourKit profiling showed 41% of the time being spent in the following = code. My apologies for the formatting. I can provide an attachment out-of= -band if it would be helpful. | +---org.apache.tomcat.util.net.NioEndpoint$Poller.run() = | 38,594 41 % | 0 = | | | | = | | = | | | +---sun.nio.ch.SelectorImpl.select(long) = | 25,615 27 % | 0 = | | | | | = | | = | | | | +---sun.nio.ch.SelectorImpl.lockAndDoSelect(long) = | 25,615 27 % | 0 = | | | | | = | | = | | | | +---sun.nio.ch.WindowsSelectorImpl.doSelect(long) = | 25,615 27 % | 46 = | | | | | = | | = | | | | +---sun.nio.ch.WindowsSelectorImpl.resetWakeupSocket() = | 13,681 14 % | 1,107 = | | | | | = | | = | | | | +---sun.nio.ch.WindowsSelectorImpl$StartLock.access$300(Wind= owsSelectorImpl$StartLock) | 10,826 11 % | 0 = | | | | | = | | = | | | | +---sun.nio.ch.WindowsSelectorImpl.updateSelectedKeys() = | 1,029 1 % | 0 = | | | | | = | | = | | | | +---sun.nio.ch.SelectorImpl.processDeregisterQueue() = | 31 0 % | 0 = | | | | = | | = | | | +---org.apache.tomcat.util.net.NioEndpoint$Poller.processKey(Selec= tionKey, NioEndpoint$KeyAttachment) | 11,996 13 % | 31 = | | | | | = | | = | | | | +---org.apache.tomcat.util.net.NioEndpoint.processSocket(NioChan= nel, SocketStatus, boolean) | 11,778 12 % | 0 = | | | | | | = | | = | | | | | +---org.apache.tomcat.util.threads.ThreadPoolExecutor.execute(= Runnable) | 11,746 12 % | 0 = | | | | | | | = | | = | | | | | | +---org.apache.tomcat.util.threads.ThreadPoolExecutor.execut= e(Runnable, long, TimeUnit) | 11,746 12 % | 0 = | | | | | | | = | | = | | | | | | +---java.util.concurrent.ThreadPoolExecutor.execute(Runnab= le) | 11,746 12 % | 15 = | | | | | | | = | | = | | | | | | +---org.apache.tomcat.util.threads.TaskQueue.offer(Objec= t) | 11,731 12 % | 0 = | | | | | | | = | | = | | | | | | +---org.apache.tomcat.util.threads.TaskQueue.offer(Run= nable) | 11,731 12 % | 46 = | | | | | | | = | | = | | | | | | +---java.util.concurrent.LinkedBlockingQueue.offer(O= bject) | 11,668 12 % | 15 = | Bob DeRemer Senior Director, Architecture and Development [Description: Description: Description: Description: cid:image001.png@01CBE= 3DE.51A12030] http://www.thingworx.com Skype: bob.deremer.thingworx O: 610.594.6200 x812 M: 717.881.3986 --_000_8bb973b1edae4aaba972939934946472BLUPR06MB193namprd06pro_ Content-Type: text/html; charset="us-ascii" Content-Transfer-Encoding: quoted-printable

Hi Mark (et al),

 

We’re seeing really high CPU utilization with = just a 1000 active websockets that are sending/receiving 100 byte binary me= ssages.   The profiling snippet below was with 1000 connections.&= nbsp; If we start to increase the number of connections, the time spent in the NIO logic starts to consume the majority of the proc= essing.  As a result, I’m trying to verify:

 

·         Is this something that can be tuned/improved= using Tomcat’s NIO settings?

·         Is this a bug in Tomcat 7 (websocket/NIO)?

·         Are we hitting some issue with 1000+ hig= hly active NIO sockets?

 

The nature of this application is that it’s pr= imary functionality is to process binary messages on (ideally 10 – 20= K websockets), forward them to another server for processing, then send the= responses back.  As a result, the performance of the websocket communication is a critical factor for success.

 

Please let me know if you’d like to discuss th= is – I’m available any time.

 

Thanks,

Bob

 <= /p>

 

We have been profiling this in YourKit and as we inc= rease the number of websockets, naturally we see the CPU utilization increa= se.  The concern is that we’re seeing this at what seems to be a= fairly low number of websockets.  The YourKit profiling showed 41% of the time being spent in the following code.  = My apologies for the formatting.  I can provide an attachment out-of-b= and if it would be helpful.  

 

|      +---org.apache.t= omcat.util.net.NioEndpoint$Poller.run()      =             &nb= sp;            =             &nb= sp;        |  38,594   41= %  |           = ;   0  |

|      | |   = ;            &n= bsp;            = ;            &n= bsp;            = ;             &= nbsp;           &nbs= p;            &= nbsp;           &nbs= p;|            =      |        &= nbsp;        |

|      | +---sun.nio.ch= .SelectorImpl.select(long)        &= nbsp;           &nbs= p;            &= nbsp;           &nbs= p;            &= nbsp;      |  25,615   27 %  |=             &nb= sp; 0  |

|      | | |  &nb= sp;             = ;            &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;            = ;           | &= nbsp;           &nbs= p;   |          = ;       |

|      | | +---sun.nio.= ch.SelectorImpl.lockAndDoSelect(long)      &n= bsp;            = ;            &n= bsp;            = ;          |  25,615 = ;  27 %  |         &= nbsp;    0  |

|      | |   |&nb= sp;            =             &nb= sp;            =             &nb= sp;            =             &nb= sp;            =             | &= nbsp;           &nbs= p;   |          = ;       |

|      | |   += ;---sun.nio.ch.WindowsSelectorImpl.doSelect(long)    &n= bsp;            = ;             &= nbsp;           &nbs= p;         |  25,615 = ;  27 %  |         &= nbsp;   46  |

|      | |   = ;  |           =             &nb= sp;            =             &nb= sp;            =             &nb= sp;            =             | &= nbsp;           &nbs= p;   |          = ;       |

|      | |   = ;  +---sun.nio.ch.WindowsSelectorImpl.resetWakeupSocket() &nb= sp;            =             &nb= sp;            =       |  13,681   14 %  | = ;         1,107  |<= /p>

|      | |   = ;  |           =             &nb= sp;            =             &nb= sp;            =             &nb= sp;            =             | &= nbsp;           &nbs= p;   |          &nbs= p;      |

|      | |   = ;  +---sun.nio.ch.WindowsSelectorImpl$StartLock.access$300(Windows= SelectorImpl$StartLock)        &nbs= p;    |  10,826   11 %  |  &nb= sp;           0  |

|      | |   = ;  |           =             &nb= sp;            =             &nb= sp;            =              &n= bsp;            = ;           | &= nbsp;           &nbs= p;   |          = ;       |

|      | |   = ;  +---sun.nio.ch.WindowsSelectorImpl.updateSelectedKeys() &n= bsp;            = ;            &n= bsp;            = ;     |   1,029    1 %  |=             &nb= sp; 0  |

|      | |   = ;  |           =              &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;            = ;           | &= nbsp;           &nbs= p;   |          = ;       |

|      | |   = ;  +---sun.nio.ch.SelectorImpl.processDeregisterQueue()  = ;            &n= bsp;            = ;            &n= bsp;       |      31=     0 %  |       &nb= sp;      0  |

|      | |   = ;            &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;            = ; |            =      |        &= nbsp;        |

|      | +---org.apache= .tomcat.util.net.NioEndpoint$Poller.processKey(SelectionKey, NioEndpoint$Ke= yAttachment)    |  11,996   13 %  | = ;            31 = ; |

|      | | |  &nb= sp;            =             &nb= sp;            =             &nb= sp;            =             &nb= sp;            =             | &= nbsp;           &nbs= p;   |          = ;       |

|      | | +---org.apac= he.tomcat.util.net.NioEndpoint.processSocket(NioChannel, SocketStatus, bool= ean)            |&nb= sp; 11,778   12 %  |      &nbs= p;       0  |

|      | | | |  &= nbsp;           &nbs= p;            &= nbsp;           &nbs= p;            &= nbsp;           &nbs= p;            &= nbsp;            &nb= sp;         |   = ;            &n= bsp; |           &nb= sp;     |

|      | | | +---org.ap= ache.tomcat.util.threads.ThreadPoolExecutor.execute(Runnable)  &n= bsp;            = ;            &n= bsp;  |  11,746   12 %  |    &= nbsp;         0  |<= /p>

|      | | | | |  = ;            &n= bsp;            = ;             &= nbsp;           &nbs= p;            &= nbsp;           &nbs= p;            &= nbsp;       |    &nb= sp;            |&nbs= p;            &= nbsp;   |

|      | | | | +---org.= apache.tomcat.util.threads.ThreadPoolExecutor.execute(Runnable, long, TimeU= nit)            |&nb= sp; 11,746   12 %  |      &nbs= p;       0  |

|      | | | |   = |            &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;        |    &nb= sp;            |&nbs= p;            &= nbsp;   |

|      | | | |   = +---java.util.concurrent.ThreadPoolExecutor.execute(Runnable) &nbs= p;            &= nbsp;           &nbs= p;         |  11,746 &nbs= p; 12 %  |          =    15  |

|      | | | |  &= nbsp;  |          &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;        |    &nb= sp;            |&nbs= p;            &= nbsp;   |

|      | | | |  &= nbsp;  +---org.apache.tomcat.util.threads.TaskQueue.offer(Object)&= nbsp;           &nbs= p;            &= nbsp;           |  1= 1,731   12 %  |       &nb= sp;      0  |

|      | | | |  &= nbsp;    |        &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;        |    &nb= sp;            |&nbs= p;            &= nbsp;   |

|      | | | |   =     +---org.apache.tomcat.util.threads.TaskQueue.of= fer(Runnable)          &n= bsp;            = ;          |  11,731 = ;  12 %  |         &= nbsp;   46  |

|      | | | |  &= nbsp;      |      &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;            = ;            &n= bsp;        |     &n= bsp;           |&nbs= p;            &= nbsp;   |

|      | | | |  &= nbsp;      +---java.util.concurrent.LinkedBloc= kingQueue.offer(Object)        &nbs= p;            &= nbsp;           |  1= 1,668   12 %  |       &nb= sp;     15  |

 

 

 

 

 

 

 

 

 

Bob DeRemer

Senior Director, Architec= ture and Development

 

3D"Description:

http://www.thingworx.com

Skype: bob.deremer.thingworx=

O: 610.594.6200 x812

M: 717.881.3986

 

--_000_8bb973b1edae4aaba972939934946472BLUPR06MB193namprd06pro_-- --_004_8bb973b1edae4aaba972939934946472BLUPR06MB193namprd06pro_--