search

kennychou0529 / openhab

Automatically exported from code.google.com/p/openhab
0 stars 0 forks source link

TCP binding causes 100% cpu load #482

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
What steps will reproduce the problem?
1. Copy org.openhab.binding.tcp-1.3.1.jar to addons folder
2. Start openHAB
 --- everything is fine until now ---
3. Add an Item with TCP binding
 --- load goes up to 100% --

What is the expected output? What do you see instead?
-Everything works as expected, except for high cpu load.

What version of the product are you using? On what operating system?
-Seen on:
  Raspberry PI with Raspbian, openhab-runtime-1.3.1, jdk-8-ea-b108-linux-arm-vfp-hflt-18_sep_2013, org.openhab.binding.tcp-1.3.1.jar

-Repoduced on:
  X86 Intel Core2 Duo @ 2.20GHz, openhab-runtime-1.3.1, jdk-8-ea-bin-b109-linux-x64-26_sep_2013, org.openhab.binding.tcp-1.3.1.jar

Please provide any additional information below.

Output, startet with start_debug.sh:

Launching the openHAB runtime in debug mode...
Listening for transport dt_socket at address: 8001
osgi> 13:58:22.951 DEBUG o.o.c.s.i.SchedulerActivator[:56] - Scheduler has been 
started.
13:58:23.057 INFO  o.q.impl.StdSchedulerFactory[:1175] - Using default 
implementation for ThreadExecutor
13:58:23.088 INFO  o.q.core.SchedulerSignalerImpl[:61] - Initialized Scheduler 
Signaller of type: class org.quartz.core.SchedulerSignalerImpl
13:58:23.091 INFO  o.quartz.core.QuartzScheduler[:243] - Quartz Scheduler 
v.2.1.7 created.
13:58:23.093 INFO  org.quartz.simpl.RAMJobStore[:154] - RAMJobStore initialized.
13:58:23.094 INFO  o.quartz.core.QuartzScheduler[:268] - Scheduler meta-data: 
Quartz Scheduler (v2.1.7) 'openHAB-job-scheduler' with instanceId 
'NON_CLUSTERED'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 2 threads.
  Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.

13:58:23.095 INFO  o.q.impl.StdSchedulerFactory[:1324] - Quartz scheduler 
'openHAB-job-scheduler' initialized from specified file: 
'./etc/quartz.properties'
13:58:23.097 INFO  o.q.impl.StdSchedulerFactory[:1328] - Quartz scheduler 
version: 2.1.7
13:58:23.098 INFO  o.quartz.core.QuartzScheduler[:534] - Scheduler 
openHAB-job-scheduler_$_NON_CLUSTERED started.
13:58:23.111 DEBUG o.o.c.core.ConfigDispatcher[:166] - Processing openHAB 
default configuration file '/opt/openhab/configurations/openhab_default.cfg'.
13:58:23.593 DEBUG o.o.c.core.ConfigDispatcher[:188] - Processing openHAB main 
configuration file '/opt/openhab/configurations/openhab.cfg'.
13:58:23.971 DEBUG o.o.c.internal.CoreActivator[:124] - UUID file already 
exists at '/opt/openhab/webapps/static/uuid' with content 
'e7ceb7c8-5ae9-4001-ba99-003e5e49acc0'
13:58:24.429 DEBUG o.o.c.internal.CoreActivator[:146] - Created file 
'/opt/openhab/webapps/static/version' with content '1.3.1'
13:58:24.429 INFO  o.o.c.internal.CoreActivator[:92] - openHAB runtime has been 
started (v1.3.1).
13:58:24.505 DEBUG o.o.c.a.i.AutoUpdateActivator[:51] - AutoUpdate binding has 
been started.
13:58:26.343 DEBUG o.o.m.p.i.PersistenceModelActivator[:43] - Registered 
'persistence' configuration parser
13:58:26.359 DEBUG o.o.c.t.i.TransformationActivator[:58] - Transformation 
Service has been started.
13:58:26.486 DEBUG o.o.i.g.internal.GCalActivator[:54] - Google Calendar IO has 
been started.
13:58:26.538 DEBUG o.o.i.m.i.MultimediaActivator[:54] - Multimedia I/O bundle 
has been started.
13:58:26.622 DEBUG o.o.i.s.i.DiscoveryServiceActivator[:47] - Discovery service 
has been started.
13:58:26.642 DEBUG o.o.i.t.mqtt.MqttService[:138] - Starting MQTT Service...
13:58:26.992 DEBUG o.o.m.i.i.ItemModelActivator[:44] - Registered 'item' 
configuration parser
13:58:27.156 DEBUG o.o.c.i.items.ItemRegistryImpl[:157] - Item provider 
'GenericItemProvider' has been added.
13:58:28.143 DEBUG o.o.m.s.i.SitemapModelActivator[:43] - Registered 'sitemap' 
configuration parser
13:58:28.360 DEBUG o.o.i.r.internal.RESTActivator[:53] - REST API has been 
started.
13:58:28.450 INFO  o.o.i.s.i.DiscoveryServiceImpl[:92] - mDNS service has been 
started
13:58:28.715 INFO  o.a.cpr.AtmosphereFramework[:742] - Installing 
BroadcastFilter class(es) org.atmosphere.client.FormParamFilter
13:58:28.769 INFO  o.a.cpr.AtmosphereFramework[:1118] - Auto detecting 
atmosphere handlers /WEB-INF/classes/
13:58:28.818 WARN  o.a.cpr.AtmosphereFramework[:814] - Missing 
META-INF/atmosphere.xml but found the Jersey runtime. Starting Jersey
13:58:28.893 INFO  o.a.cpr.AtmosphereFramework[:364] - Installed 
AtmosphereHandler org.atmosphere.handler.ReflectorServletProcessor mapped to 
context-path: /*
13:58:28.894 INFO  o.a.cpr.AtmosphereFramework[:1173] - Auto detecting 
WebSocketHandler in /WEB-INF/classes/
13:58:29.148 INFO  o.a.cpr.AtmosphereFramework[:1099] - Atmosphere is using 
async support: org.atmosphere.container.JettyAsyncSupportWithWebSocket running 
under container: jetty/8.1.3.v20120522 with WebSocket enabled.
13:58:29.149 INFO  o.a.cpr.AtmosphereFramework[:902] - Installed 
WebSocketProtocol org.atmosphere.websocket.protocol.SimpleHttpProtocol 
13:58:29.271 INFO  o.a.h.ReflectorServletProcessor[:126] - Installing Servlet 
com.sun.jersey.spi.container.servlet.ServletContainer
13:58:29.513 INFO  c.s.j.s.i.a.WebApplicationImpl[:791] - Initiating Jersey 
application, version 'Jersey: 1.11 12/09/2011 11:05 AM'
13:58:29.515 INFO  c.s.j.s.i.a.WebApplicationImpl[:802] - Adding the following 
classes declared in META-INF/services/jersey-server-components to the resource 
configuration:
  class org.atmosphere.jersey.AtmosphereResourceConfigurator
13:58:29.616 INFO  c.s.j.s.i.a.DeferredResourceConfig[:97] - Instantiated the 
Application class org.openhab.io.rest.internal.RESTApplication
13:58:30.906 INFO  o.a.cpr.AtmosphereFramework[:589] - Installed Default 
AtmosphereInterceptor [Android Interceptor Support, SSE Interceptor Support, 
JSONP Interceptor Support]. Set 
org.atmosphere.cpr.AtmosphereInterceptor.disableDefaults in your xml to disable 
them.
13:58:30.907 WARN  o.a.cpr.AtmosphereFramework[:509] - No BroadcasterCache 
configured. Broadcasted message between client reconnection will be LOST. It is 
recommended to configure the HeaderBroadcasterCache.
13:58:30.909 WARN  o.a.cpr.AtmosphereFramework[:533] - Neither 
TrackMessageSizeInterceptor or TrackMessageSizeFilter are installed. 
atmosphere.js may receive glued and incomplete message.
13:58:30.909 INFO  o.a.cpr.AtmosphereFramework[:537] - HttpSession supported: 
false
13:58:30.910 INFO  o.a.cpr.AtmosphereFramework[:538] - Using 
BroadcasterFactory: org.atmosphere.cpr.DefaultBroadcasterFactory
13:58:30.913 INFO  o.a.cpr.AtmosphereFramework[:539] - Using 
WebSocketProcessor: org.atmosphere.websocket.DefaultWebSocketProcessor
13:58:30.914 INFO  o.a.cpr.AtmosphereFramework[:540] - Using Broadcaster: 
org.atmosphere.jersey.JerseyBroadcaster
13:58:30.916 INFO  o.a.cpr.AtmosphereFramework[:541] - Atmosphere Framework 
1.0.4 started.
13:58:30.924 INFO  o.o.i.r.i.RESTApplication[:158] - Started REST API at /rest
13:58:30.925 DEBUG o.o.i.s.i.DiscoveryServiceImpl[:63] - Registering new 
service _openhab-server._tcp.local. at port 8080
13:58:35.832 INFO  o.o.m.c.i.ModelRepositoryImpl[:99] - Loading model 
'demo.sitemap'
13:58:35.998 DEBUG o.o.i.s.i.DiscoveryServiceImpl[:63] - Registering new 
service _openhab-server-ssl._tcp.local. at port 8443
13:58:36.197 INFO  o.o.m.c.i.ModelRepositoryImpl[:99] - Loading model 
'demo.script'
13:58:36.416 INFO  o.o.m.c.i.ModelRepositoryImpl[:99] - Loading model 
'demo.items'
13:58:36.632 DEBUG o.o.m.i.i.GenericItemProvider[:154] - Read items from model 
'demo.items'
13:58:38.909 INFO  o.o.u.w.i.s.WebAppServlet[:99] - Started Classic UI at 
/openhab.app
13:58:39.339 DEBUG o.o.m.r.i.RuleModelActivator[:62] - Registered 'rules' 
configuration parser
13:58:39.354 DEBUG o.o.m.r.i.engine.RuleEngine[:98] - Started rule engine
13:58:42.133 DEBUG o.o.b.t.internal.TCPActivator[:51] - TCP/UDP binding has 
been started.
13:58:46.689 INFO  o.o.m.c.i.ModelRepositoryImpl[:99] - Loading model 
'demo.rules'
13:58:46.853 DEBUG o.o.m.r.i.engine.RuleEngine[:277] - Executing startup rule 
'Startup'

--->                            Here I added the following line to demo.items:  
                                       <---
---> Switch TcpTest "Set Relais" (GF_Living) { 
tcp=">[ON:192.168.1.4:3000:S201#0F], >[OFF:192.168.1.4:3000:S201#00]" } <---

14:01:20.027 INFO  o.o.m.c.i.ModelRepositoryImpl[:117] - Refreshing model 
'demo.items'
14:01:20.053 DEBUG o.o.m.i.i.GenericItemProvider[:154] - Read items from model 
'demo.items'
14:01:20.154 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:251] - 
Setting up a connection to /192.168.1.4:3000
14:01:20.156 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:145] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@6
90ccf8d channel already exists
14:01:20.156 INFO  o.o.b.t.AbstractChannelEventSubscriberBinding[:145] - 
org.openhab.binding.tcp.AbstractSocketChannelEventSubscriberBinding$MuxChannel@6
90ccf8d channel already exists

--->                                       cpu load goes to 100%                
                                       <---

Original issue reported on code.google.com by daniel.g...@gmail.com on 3 Oct 2013 at 12:18

GoogleCodeExporter commented 9 years ago

Original comment by kai.openhab on 5 Oct 2013 at 3:29

GoogleCodeExporter commented 9 years ago 
This issue was merged with #478, which is marked as fixed. But for me, this 
Issue isn't fixed!
I checked out latest master (2013-10-05 06:35:05 
345fed9dcbde0dec3d330c89939cb9372324832e) and build it with yoxos eclipse.
The cpu load still goes up to 100% on one core.

Original comment by daniel.g...@gmail.com on 7 Oct 2013 at 7:18

GoogleCodeExporter commented 9 years ago 
Same 100% CPU experienced here with OH 1.4.0.

Original comment by jasonhec...@gmail.com on 8 Oct 2013 at 8:03

GoogleCodeExporter commented 9 years ago 
Reopened issue 478.

Original comment by kai.openhab on 8 Oct 2013 at 8:46