But Mats, you are continuing to use M6? Everyone else had to downgrade back to M5 to keep things working.
Hate to say it but the zwave binding seems to be the only common factor I can see
different platforms, different java versions
Just to recap:
I was on M5 and decided on Monday 2. December in the evening to take M6 for a spin.
After the apt-get update/upgrade the CPU hogged without me really noticing.
Usually things act up after an upgrade and I often have to do a power-cycle after some minutes to get up and running.
This time, after a power-cycle, M6 came back up with all my paperUI added things missing.
Downgraded to M5, things still missing.
So, before adding the 100+ things in the Inbox, I upgraded to M6 again.
Back on M6, I then started adding things, but the first thing I did, was manually re-adding my ZWave stick. After doing that, all ZWave things also appeared in the inbox.
This is were I was not paying enough attention. I was re-adding my things in paperUI (simple mode with auto linking) and I was almost half way through when the things view in paperUI became unresponsive and I noticed the CPU was hogged.
I then downgraded to M5 again, and was able to re-add the rest of my inbox.
I attach my log from that evening in case you are able to see something interesting. Good luck!
(ftr: Iβm still on M5)
Yes, I am still on M6, because after disabling 5 hue things, everything else works just fine, including zwave. Both Paper UI and Sitemap, in phone,works with no lag and no spaming of log file!
My log right now:
2019-12-06 06:06:21.886 [vent.ItemStateChangedEvent] - astro_moon_local_position_azimuth changed from 335.9097347240755 to 337.3227453122973
2019-12-06 06:06:21.887 [vent.ItemStateChangedEvent] - astro_moon_local_position_elevation changed from -33.23811348448288 to -33.47460736851912
2019-12-06 06:06:22.642 [vent.ItemStateChangedEvent] - astro_sun_local_position_azimuth changed from 105.1242003528871 to 106.13293835990552
2019-12-06 06:06:22.646 [vent.ItemStateChangedEvent] - astro_sun_local_position_elevation changed from -17.107970842958316 to -16.47411296729548
2019-12-06 06:06:30.421 [vent.ItemStateChangedEvent] - ntpDay changed from 2019-12-06T06:05:30.421+0100 to 2019-12-06T06:06:30.422+0100
2019-12-06 06:06:30.423 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2019-12-06T06:05:30.421+0100 to 2019-12-06T06:06:30.422+0100
2019-12-06 06:06:30.423 [vent.ItemStateChangedEvent] - ntpDate changed from 2019-12-06T06:05:30.421+0100 to 2019-12-06T06:06:30.422+0100
2019-12-06 06:06:30.424 [vent.ItemStateChangedEvent] - ntpTime changed from 2019-12-06T06:05:30.421+0100 to 2019-12-06T06:06:30.422+0100
2019-12-06 06:06:30.425 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from 2019-12-06 06:05:30 CET to 2019-12-06 06:06:30 CET
2019-12-06 06:06:39.307 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64712 to 64713
2019-12-06 06:06:39.312 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node23_sensor_power changed from 0.6 to 0.5
2019-12-06 06:06:39.313 [vent.ItemStateChangedEvent] - Jul2_power changed from 0.6 to 0.5
2019-12-06 06:06:40.308 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64713 to 64714
2019-12-06 06:06:40.312 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node23_sensor_power changed from 0.5 to 0.4
2019-12-06 06:06:40.313 [vent.ItemStateChangedEvent] - Jul2_power changed from 0.5 to 0.4
2019-12-06 06:06:41.307 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64714 to 64715
2019-12-06 06:06:41.313 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node23_sensor_power changed from 0.4 to 0.5
2019-12-06 06:06:41.313 [vent.ItemStateChangedEvent] - Jul2_power changed from 0.4 to 0.5
2019-12-06 06:06:43.308 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64715 to 64716
2019-12-06 06:06:43.311 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node23_sensor_power changed from 0.5 to 0.6
2019-12-06 06:06:43.312 [vent.ItemStateChangedEvent] - Jul2_power changed from 0.5 to 0.6
2019-12-06 06:06:44.308 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64716 to 64717
2019-12-06 06:06:44.311 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node23_sensor_power changed from 0.6 to 0.7
2019-12-06 06:06:44.312 [vent.ItemStateChangedEvent] - Jul2_power changed from 0.6 to 0.7
2019-12-06 06:06:57.569 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64717 to 64718
2019-12-06 06:06:57.575 [vent.ItemStateChangedEvent] - PlugV2MBdrmWinLamp_watts changed from 0 to 0.521
2019-12-06 06:06:57.576 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node3_meter_watts changed from 0 to 0.521
2019-12-06 06:07:00.570 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64718 to 64719
2019-12-06 06:07:00.575 [vent.ItemStateChangedEvent] - PlugV2MBdrmWinLamp_watts changed from 0.521 to 0
2019-12-06 06:07:00.576 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node3_meter_watts changed from 0.521 to 0
2019-12-06 06:07:02.163 [vent.ItemStateChangedEvent] - MatsMobilUptime changed from 33523 to 33583
2019-12-06 06:07:02.164 [vent.ItemStateChangedEvent] - MatsMobilLastSeen changed from 2019-12-06T06:06:00.000+0100 to 2019-12-06T06:07:00.000+0100
2019-12-06 06:07:02.170 [vent.ItemStateChangedEvent] - MadeleinesMobilUptime changed from 22889 to 22949
2019-12-06 06:07:02.171 [vent.ItemStateChangedEvent] - MadeleinesMobilLastSeen changed from 2019-12-06T06:06:00.000+0100 to 2019-12-06T06:07:00.000+0100
2019-12-06 06:07:02.176 [vent.ItemStateChangedEvent] - AlmasMobilUptime changed from 9370 to 9430
2019-12-06 06:07:02.177 [vent.ItemStateChangedEvent] - AlmasMobilLastSeen changed from 2019-12-06T06:06:00.000+0100 to 2019-12-06T06:07:00.000+0100
2019-12-06 06:07:02.178 [vent.ItemStateChangedEvent] - AlmasMobilRSSI changed from 19 to 21
2019-12-06 06:07:07.308 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64719 to 64720
2019-12-06 06:07:07.311 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node23_sensor_power changed from 0.7 to 0.5
2019-12-06 06:07:07.312 [vent.ItemStateChangedEvent] - Jul2_power changed from 0.7 to 0.5
2019-12-06 06:07:08.308 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64720 to 64721
2019-12-06 06:07:08.313 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node23_sensor_power changed from 0.5 to 0.6
2019-12-06 06:07:08.313 [vent.ItemStateChangedEvent] - Jul2_power changed from 0.5 to 0.6
2019-12-06 06:07:10.308 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64721 to 64722
2019-12-06 06:07:10.312 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node23_sensor_power changed from 0.6 to 0.5
2019-12-06 06:07:10.313 [vent.ItemStateChangedEvent] - Jul2_power changed from 0.6 to 0.5
2019-12-06 06:07:11.308 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64722 to 64723
2019-12-06 06:07:11.313 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node23_sensor_power changed from 0.5 to 0.6
2019-12-06 06:07:11.314 [vent.ItemStateChangedEvent] - Jul2_power changed from 0.5 to 0.6
2019-12-06 06:07:16.307 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64723 to 64724
2019-12-06 06:07:16.312 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node23_sensor_power changed from 0.6 to 0.5
2019-12-06 06:07:16.313 [vent.ItemStateChangedEvent] - Jul2_power changed from 0.6 to 0.5
2019-12-06 06:07:21.569 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64724 to 64725
2019-12-06 06:07:21.575 [vent.ItemStateChangedEvent] - PlugV2MBdrmWinLamp_watts changed from 0 to 0.528
2019-12-06 06:07:21.576 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node3_meter_watts changed from 0 to 0.528
2019-12-06 06:07:24.570 [vent.ItemStateChangedEvent] - zwave_serial_zstick_d844b98a_serial_sof changed from 64725 to 64726
2019-12-06 06:07:24.575 [vent.ItemStateChangedEvent] - PlugV2MBdrmWinLamp_watts changed from 0.528 to 0
2019-12-06 06:07:24.575 [vent.ItemStateChangedEvent] - zwave_device_d844b98a_node3_meter_watts changed from 0.528 to 0
2019-12-06 06:07:30.425 [vent.ItemStateChangedEvent] - ntpDay changed from 2019-12-06T06:06:30.422+0100 to 2019-12-06T06:07:30.424+0100
2019-12-06 06:07:30.426 [vent.ItemStateChangedEvent] - ntp_ntp_local_dateTime changed from 2019-12-06T06:06:30.422+0100 to 2019-12-06T06:07:30.424+0100
2019-12-06 06:07:30.427 [vent.ItemStateChangedEvent] - ntpDate changed from 2019-12-06T06:06:30.422+0100 to 2019-12-06T06:07:30.424+0100
2019-12-06 06:07:30.428 [vent.ItemStateChangedEvent] - ntpTime changed from 2019-12-06T06:06:30.422+0100 to 2019-12-06T06:07:30.424+0100
2019-12-06 06:07:30.429 [vent.ItemStateChangedEvent] - ntp_ntp_local_string changed from 2019-12-06 06:06:30 CET to 2019-12-06 06:07:30 CET
Since my update to M6 (Raspbian on SD-card of a Pi 3), I also get a βSystem Startedβ event caused by my system started rule. It appears at approx. 03:15 in the morning.
Nothing else, no complete system restart.
Any ideas?
This can happen when you modify or some automatism βtouchesβ a rules, items or thing file. βTouchingβ includes all changes, but also to e.g. change file permissions or the last modified date of a file (only).
Behavior shouldnβt have changed since M5 but it could be some change in an underlying library or similar to go unnoticed. Or you skipped installing the interim version this was introduced in. Or it has been there for some time already without that you noticed.
Hope this hint helps you in tracking down whatβs running on your box at those times to cause such file changes.
I am on M6, and no issues with z-wave.
My only issues are with broadcomm binding, which is still 3rd-party, and for whom M6 had some breaking changes. But z-wave seems pretty stable
Hello,
I can confirm the hue issue in M6 release. I get an unuseable system after upgrading. If I remove the hue things it becomes normal again, but after including only one hue thing, logfile will be spammed with hue events and CPU consumption is 100% an memory is increasing over 5GB.
I am using openhab with docker and I also started a test with new conf, addon and userdata folder, but got the same behavior after only installing hue binding and including one hue thing. After removing the one hue thing the cpu consumption stays at 100 percent but log spamming stopped.
First I will switch back to M5 release and will still watch this forum for new informations about this topic.
For openHABian Xms/Xmx defaults are 250/350 which is fine for a 1GB ARM system and on x86 or ARM boxes with more mem probably not more harmful than the defaults.
Actually, on this recent install on a Pi 3B+ the OPTS is blank. I inslled Java using openHABian, used apt to install Milestone 5 and then used openHABian to set the defaults. I specifically wanted Milestone 5 because I was testing the upgrade from 5 to 6.
Iβve seen Java go to 100% and stay there, too.
First Iβve seen a number of 2019-12-08 14:40:19.398 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@ffb7f8' takes more than 5000ms.
until I restarted.
Now this time (and only this time) I got
2019-12-08 14:39:33.351 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception:
java.lang.OutOfMemoryError: Java heap space
2019-12-08 14:39:33.373 [DEBUG] [nal.provider.AbstractCallbackServlet] - Post message received from OwnTracks tracker: {"_type":"location","acc":16,"alt":0,"batt":78,"conn":"w","lat":XX.XXX,"lon":XX.XXX,"t":"p","tid":"XX","tst":1575812344,"vac":0,"vel":0}
and quickly after that
2019-12-08 14:40:09.039 [WARN ] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread.
java.lang.IllegalStateException: Queue full
at java.util.AbstractQueue.add(AbstractQueue.java:98) ~[?:1.8.0_222]
at java.util.concurrent.ArrayBlockingQueue.add(ArrayBlockingQueue.java:312) ~[?:1.8.0_222]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.processReceiveMessage(ZWaveTransactionManager.java:417) ~[bundleFile:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveController.incomingPacket(ZWaveController.java:1072) ~[bundleFile:?]
at org.openhab.binding.zwave.handler.ZWaveControllerHandler.incomingMessage(ZWaveControllerHandler.java:411) ~[bundleFile:?]
at org.openhab.binding.zwave.handler.ZWaveSerialHandler$ZWaveReceiveThread.run(ZWaveSerialHandler.java:331) [bundleFile:?]
2019-12-08 14:40:19.398 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@ffb7f8' takes more than 5000ms.
So the prime candidate I believe is the gpstracker binding (pinging @gbicskei), the following ZWave error (pinging @chris) may or may not be a followup problem.
Will raise -Xmx java limit but I would think that should not be the cause as I believe the whole JVM should crash if that limit is hit, shouldnβt it? Which it does not. Memory usage also was pretty constant i.e. no visible leak.
Iβve also been thinking of a relationship to VScode because Iβve only been seeing this since I recently started to use that, but I havenβt been able to verify or falsify yet. At least it does not touch the dir or files which would cause that 100% due to a recompile of many rules or items.