NorthScale client 100% CPU
Hi,
We have a critical issue with the .net web application with NorthScale client. The problem can be reproduced in this way:
1. server of web application with northscale client should be under load
2. delete server from the server warm / stop to send requests to the server
3. deploy new version of the web application (simple copy of dll + other files)
4. (IIS perform application pool recycle)
5. Send one request in which NorthScale client is used to the web application. Server sends correctly the response.
At this point after few seconds CPU usage start to grow up to 100%. No new requests, no other activities on the server.
This problem can be resolved after stop / start of the application pool, but for us it is better to implement other solution (we have an heals system which check for working processes and send an alert if some process is down)
Other issues: after implementing the NorthScale cache solution out build machine start to log warning such as “Error while unloading appdomain” after integration test execution where northscale cline is used.
My idea is that there is some northscale connection pool / background threads which prevent to unload application domain
Probably these two issues are related.
The problem does not present without NorthScale client.
Can you please help us to solve this issue? Do you have some ideas? Is it possible to close all pending connections to the northscale server?
Thanks
Hello,
If you tail your log when you restart your application, watch out for errors and let us know. In the past this has happened and customers found out that some of their objects were not serializable.
Please let us know, and send us the zipped log.
Bhawana
Hello Bhawana,
I've done a quick check and we don't have classes without serializable attribute. Here you can find a log. It does not contain error messages:
Do you have some other ideas?
p.s. Request per seconds up to 12 K
Thank you very much
Alex
All log message looks like this:
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. 832861a2-ccdb-4b4c-b97d-ba014d3057a9
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket 832861a2-ccdb-4b4c-b97d-ba014d3057a9
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.15:11211
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket f311436a-c799-4af6-97b8-72b7ef6b1ee4 was reset
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. f311436a-c799-4af6-97b8-72b7ef6b1ee4
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket f311436a-c799-4af6-97b8-72b7ef6b1ee4
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.15:11211
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket 11fd858f-8cfe-4c7d-85f7-e0451f7b365c was reset
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. 11fd858f-8cfe-4c7d-85f7-e0451f7b365c
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket 11fd858f-8cfe-4c7d-85f7-e0451f7b365c
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.133:11211
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket 4727967f-ce6e-4d31-a505-9ffa7d2b173b was reset
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. 4727967f-ce6e-4d31-a505-9ffa7d2b173b
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket 4727967f-ce6e-4d31-a505-9ffa7d2b173b
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.174:11211
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket 1c56c172-827f-4002-83a7-a851ae20fba9 was reset
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. 1c56c172-827f-4002-83a7-a851ae20fba9
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket 1c56c172-827f-4002-83a7-a851ae20fba9
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.10:11211
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket 0a3d83b3-a4f6-46e1-9876-e7b07b05b0de was reset
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. 0a3d83b3-a4f6-46e1-9876-e7b07b05b0de
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket 0a3d83b3-a4f6-46e1-9876-e7b07b05b0de
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.10:11211
12:32:30.254 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket 72df0f62-88d1-42bf-9ca6-8fb8a885d087 was reset
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. 72df0f62-88d1-42bf-9ca6-8fb8a885d087
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket 72df0f62-88d1-42bf-9ca6-8fb8a885d087
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.117:11211
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket d10991b3-3d31-402c-b269-79b0b6c6f734 was reset
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. d10991b3-3d31-402c-b269-79b0b6c6f734
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket d10991b3-3d31-402c-b269-79b0b6c6f734
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.117:11211
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket f8f9c1e6-f669-458a-9b88-d1ddf73c54f8 was reset
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. f8f9c1e6-f669-458a-9b88-d1ddf73c54f8
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket f8f9c1e6-f669-458a-9b88-d1ddf73c54f8
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.94:11211
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket a377915a-260b-4f3a-b739-cc062fb61033 was reset
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. a377915a-260b-4f3a-b739-cc062fb61033
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket a377915a-260b-4f3a-b739-cc062fb61033
12:32:30.269 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.94:11211
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket 5a67d53e-ef3c-4f15-a58f-c748d7b22d31 was reset
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. 5a67d53e-ef3c-4f15-a58f-c748d7b22d31
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket 5a67d53e-ef3c-4f15-a58f-c748d7b22d31
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.15:11211
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket 5c91224e-ff41-4970-be8c-decbadec9323 was reset
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. 5c91224e-ff41-4970-be8c-decbadec9323
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket 5c91224e-ff41-4970-be8c-decbadec9323
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.15:11211
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket b6579c2a-6316-4dd4-9107-a1b3eeab0c6a was reset
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. b6579c2a-6316-4dd4-9107-a1b3eeab0c6a
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket b6579c2a-6316-4dd4-9107-a1b3eeab0c6a
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.15:11211
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket d2d88158-bf46-4ef1-8437-cf399df55667 was reset
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. d2d88158-bf46-4ef1-8437-cf399df55667
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket d2d88158-bf46-4ef1-8437-cf399df55667
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.15:11211
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket 15b09f7c-7a17-4fda-acc1-9ce0bda05664 was reset
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. 15b09f7c-7a17-4fda-acc1-9ce0bda05664
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket 15b09f7c-7a17-4fda-acc1-9ce0bda05664
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.117:11211
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket d5cd744b-6a53-4c2c-8b56-0eaa7db6e87a was reset
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. d5cd744b-6a53-4c2c-8b56-0eaa7db6e87a
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket d5cd744b-6a53-4c2c-8b56-0eaa7db6e87a
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Acquiring stream from pool. xxx.xx.120.133:11211
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Enyim.Caching.Memcached.PooledSocket - Socket 4527baba-0715-4f71-8584-06d98bef1c0d was reset
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Socket was reset. 4527baba-0715-4f71-8584-06d98bef1c0d
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Releasing socket 4527baba-0715-4f71-8584-06d98bef1c0d
12:32:30.285 SERVERNAME [tid:APPNAME #0] DEBUG Caching.Memcached.MemcachedNode.InternalPoolImpl - Are we alive? True
Alex,
Can you please keep an eye on any errors in the logs. Our Engineer is looking into this and I will write to you as soon as we have something. Can you also send us any other symptoms/obervations you may have about when this occurs.
Bhawana
Just fyi, we have high cpu usage as well on Windows 2008 environment, this is on the membase service itself. It seems to happen under load and under flush-all.
Just fyi, we have high cpu usage as well on Windows 2008 environment, this is on the membase service itself. It seems to happen under load and under flush-all.
Brian,
Do you mean that you are seeing high CPU usgae on the membase service now? Is this correct to say that you have high CPU usgae on the client and on the server. Also, How are you using flush-all?
Bhawana
Hi Bhawana,
Do you have some news for our problem? If you need we can create a simple solution to reproduse the problem. Thanks.
Alex
What Northscale Client are you using?
Hi,
we are using Northscale.Store 2.9.0.0, Enyim.Caching 2.6.0.0.
Thanks in adavance
Alex
p.s.
We are world wide leading online shop and this issue a very critical for us. We need to find a solution soon...
After some testing my suspicion is that your client instances are not disposed. The MembaseClient has a background thread for the configuration management, and this must be stopped by disposing the client.
The easiest solution is to add the following to your Global.asax:
protected void Application_End(object sender, EventArgs e) { // dispose the clients here }
Also, there is a new beta version on github, which has some protection against not disposing the clients.
(But it only helps if my previous post solved your problems.)
Hi Attila! This solution seems to work! Thank you very much. We have tested the new implementation on more than 10 servers and the issue described above is not present. Do you have some technical explanation for it? Dispose method should be called on object finalization automatically (by GC), isn't it? Alex
when you tear down an appdomain (like the Unload done by asp.net), finalizers are not guaranteed to be called
that's why it's important to dispose every object which implements the idisposable
Ok :((
Thank you very much from all our team for a good work!
Alex
The Engineers are looking into this.
Thanks
Bhawana
Forum support is great for free but sometimes you need a guaranteed response time and dedicated resources for your questions or issues.
Consider purchasing enterprise-level support from Membase: http://www.membase.com/products-and-services/overview
Call or email "sales -at- membase -dot- com" today!