openhab / openhab-core

Core framework of openHAB
https://www.openhab.org/
Eclipse Public License 2.0
897 stars 415 forks source link

Extreme CPU and Memory Load since 2.5 Build 1579 #829

Closed RobertHerter closed 5 years ago

RobertHerter commented 5 years ago

Since Build 1579 there is extreme high CPU-Load and Memory consumption.

OSGIEventManager uses nearly tue complete CPU. Reverting to 1578 instantly fixes this.

Even a Fresh install ends up in this, weit no Bundle found causing this.

Testet on an I5 and RPI3 both show same behaviour resulting in an nearly unusable system.

5iver commented 5 years ago

I see something similar on an older dual core desktop system (Fedore 28, OpenJDK Runtime Environment (build 1.8.0_201-b09)). I have other things running on the box, but it's resting load was typically 0.25-0.40. On S1597 and previous, it is 0.80-1.00 with Java taking 43% RAM. I thought this started with S1566 and the start of the ESH integration builds, but could have been a later build as suggested by the OP.

I see similar high load in my test environment with an i7.

maggu2810 commented 5 years ago

I would like to have a look at.

Can you tell me what needs to be done to reproduce the problem?

$ java -version
java version "1.8.0_202"
Java(TM) SE Runtime Environment (build 1.8.0_202-b08)
Java HotSpot(TM) 64-Bit Server VM (build 25.202-b08, mixed mode)

$ uname -a
Linux m3800 5.0.7-gentoo #1 SMP Thu Apr 11 15:48:53 CEST 2019 x86_64 Intel(R) Core(TM) i7-4712HQ CPU @ 2.30GHz GenuineIntel GNU/Linux
J-N-K commented 5 years ago

I‘m running 1592 on an APU2 with Debian 9 and don‘t see that problem either. Maybe it is specific to openHabian or a certain Java Version?

RobertHerter commented 5 years ago

For me same Problem on RPI with Oracle vm and Ubuntu 18.04 x64 with Oracle for openjdk. Just have to get events on the event bus and some rules to see it. Have a system with 3-5 Item changes per second. No difference which addons causes the load. If any gets load on the eventbus the CPU and memory raises to unusable. Switching back to 1578 instantly fixed the problem.

davidgraeff commented 5 years ago

Might be caused by recent changes to the server send events part? Each event bus event is send via SSE.

maggu2810 commented 5 years ago

Might be caused by recent changes to the server send events part?

Which changes do you refer to?

I remember to (both done by me)

None of there "should" be related.

I assume it would be simpler if someone provides the (minimal) steps to reproduce the problems with a newly downloaded distribution. Otherwise we just can guess if there needs to be an UI opened (or any other SSE consumer) or not.

grzegorz914 commented 5 years ago

For me same Problem on RPI with Oracle vm and Ubuntu 18.04 x64 with Oracle for openjdk. Just have to get events on the event bus and some rules to see it. Have a system with 3-5 Item changes per second. No difference which addons causes the load. If any gets load on the eventbus the CPU and memory raises to unusable. Switching back to 1578 instantly fixed the problem.

Same Problem for me but on RPI with openHABian, after installed and run Simatic Binding the CPU Load raises over 200%, in end effect the system slow down and after some time faulty. Latest test with building OH2.5.0 build 1602, problem exist.

olemr commented 5 years ago

Still a problem on #1607 Ubuntu 16.04.6 LTS (GNU/Linux 4.4.0-62-generic x86_64) image

System extremely sluggish. Zwave and http events take 5-10 minutes to show up in logs. Back to M1 again.

cweitkamp commented 5 years ago

Hi all,

You can either try to identify the causing thread by running the shell:threads --list command from Karaf console. It will show you all running openHAB related threads. Copy & paste the result into e.g. Excel and sort them by column “CPU time” like in the following example:

Id Name CPU time
261 HTTP Refresh Service 111645194 64,20 %
89 ESH-OSGiEventManager 13145542 7,56 %
985 ESH-ruleEngine-5 4121879 2,37 %
1092 ESH-ruleEngine-9 3898312 2,24 %
1144 ESH-ruleEngine-10 3875214 2,23 %
1070 ESH-ruleEngine-7 3773624 2,17 %
1375 ESH-ruleEngine-12 3772949 2,17 %
182 items-1 2132966 1,23 %
185 items-4 2129908 1,22 %
184 items-3 2127034 1,22 %

Or when your system has been running for a while you could make a heap dump and analyze where all the memory is consumed by with Eclipse Memory Analyzer Tool (MAT). If you configure the runtime such that it will always write a heap dump on OutOfMemoryErrors (OOM) you can always analyze them after they just occurred. Usually I check the “dominator tree” to find the object/field that is consuming a lot of memory (using the object address). I am very interested in the results.

E.g. in the provided heap dump for https://github.com/openhab/openhabian/issues/469 there was a taskQueue with ~1.5 million tasks in the QueueingThreadPoolExecutor.

26b8d703990eb0b7f8488b09cd9b20ed2d1719d9

Thanks in advance.

mhilbush commented 5 years ago

Adding some info from what I'm seeing on a system running build 1606. This system was restarted at about 07:50:00.

Edit: There are no openHAB UIs open during the collection of any of these stats.

Edit: The system has an Intel Celeron 4 core 1.60GHz CPU and 4 GB RAM.

Here are the top 8 cpu consuming threads as of 08:48.

while true; do /opt/openhab2/runtime/bin/client -p habopen -l 0 -- threads --list | awk -F"│" '{print $4 $2}' | sort --numeric-sort --reverse | head --lines 8; done
 72796     ESH-OSGiEventManager                                                                           
 60946     Start Level: Equinox Container: ebb06d82-f887-474a-88be-32362764bb2f                           
 10367     sshd-SshServer[491e44ed]-nio2-thread-1                                                         
 10047     ESH-usb-serial-discovery-linux-sysfs-1                                                         
 10046     sshd-SshServer[491e44ed]-nio2-thread-2                                                         
 5602      Timer-7                                                                                        
 5511      ResourcePublisher                                                                              
 3367      pool-19-thread-1  

Looking at memory using pidstat (pidstat -r -p 4530 2) I see memory slowly, but constantly, increasing. During openHAB startup, it quickly grew to about 16%, then started to increase slowly.

07:54:24 AM   UID       PID  minflt/s  majflt/s     VSZ     RSS   %MEM  Command
07:54:26 AM     0      4530     60.00      0.00 4747684  557184  16.15  java
07:54:28 AM     0      4530    142.00      0.00 4747684  557776  16.17  java
07:54:30 AM     0      4530    284.00      0.00 4747688  558888  16.20  java
07:54:32 AM     0      4530    121.00      0.00 4747836  559536  16.22  java
07:54:34 AM     0      4530    402.50      0.00 4749768  562300  16.30  java
07:54:36 AM     0      4530     67.00      0.00 4749768  562816  16.31  java
07:54:38 AM     0      4530     70.50      0.00 4749768  563216  16.33  java
07:54:40 AM     0      4530     12.00      0.00 4749768  563476  16.33  java
07:54:42 AM     0      4530     18.00      0.00 4749768  563844  16.34  java
07:54:44 AM     0      4530     22.00      0.00 4749768  563972  16.35  java
07:54:46 AM     0      4530     92.50      0.00 4749768  564572  16.36  java
07:54:48 AM     0      4530     15.00      0.00 4749768  564640  16.37  java
07:54:50 AM     0      4530      1.50      0.00 4749768  564640  16.37  java
07:54:52 AM     0      4530     18.00      0.00 4749768  564740  16.37  java
07:54:54 AM     0      4530     15.00      0.00 4749768  564808  16.37  java
...
08:30:36 AM     0      4530     40.50      0.00 4770172  624472  18.10  java
08:30:38 AM     0      4530      1.00      0.00 4770172  624472  18.10  java
08:30:40 AM     0      4530     31.50      0.00 4770172  624476  18.10  java
08:30:42 AM     0      4530     57.00      0.00 4770172  624592  18.10  java
08:30:44 AM     0      4530      2.50      0.00 4770172  624592  18.10  java
08:30:58 AM     0      4530     13.50      0.00 4773256  625544  18.13  java
08:31:00 AM     0      4530     31.00      0.00 4773256  625636  18.13  java
08:31:02 AM     0      4530     38.50      0.00 4774284  625636  18.13  java
08:31:04 AM     0      4530      8.00      0.00 4774284  625724  18.14  java
08:31:06 AM     0      4530     41.00      0.00 4774284  625768  18.14  java
08:31:08 AM     0      4530     34.00      0.00 4774284  625792  18.14  java
08:31:10 AM     0      4530      2.00      0.00 4774284  625812  18.14  java
...
08:49:48 AM     0      4530      0.00      0.00 4720972  637732  18.49  java
08:49:50 AM     0      4530      6.00      0.00 4720972  637732  18.49  java
08:49:52 AM     0      4530      8.00      0.00 4720972  637732  18.49  java
08:49:54 AM     0      4530      0.50      0.00 4720972  637732  18.49  java
08:49:56 AM     0      4530      0.00      0.00 4720972  637732  18.49  java
08:49:58 AM     0      4530      7.96      0.00 4720972  637732  18.49  java
08:50:00 AM     0      4530     13.00      0.00 4721088  637732  18.49  java
08:50:02 AM     0      4530      8.50      0.00 4720972  637732  18.49  java
08:50:04 AM     0      4530      0.00      0.00 4720972  637732  18.49  java
08:50:06 AM     0      4530      0.00      0.00 4720972  637732  18.49  java
08:50:08 AM     0      4530      0.50      0.00 4720972  637732  18.49  java

Looking at CPU load using pidstat (pidstat -u -p 4530 2), I see fairly regular and small CPU spikes.

08:30:45 AM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
08:30:47 AM     0      4530   85.00    1.50    0.00   86.50     1  java
08:30:49 AM     0      4530  118.00    2.00    0.00  120.00     1  java
08:30:51 AM     0      4530   15.00    0.50    0.00   15.50     1  java
08:30:53 AM     0      4530   36.00    2.50    0.00   38.50     1  java
08:30:55 AM     0      4530    5.50    0.00    0.00    5.50     1  java
08:30:57 AM     0      4530   16.50    1.00    0.00   17.50     1  java
08:30:59 AM     0      4530   23.00    0.50    0.00   23.50     1  java
08:31:01 AM     0      4530    2.99    0.00    0.00    2.99     1  java
08:31:03 AM     0      4530   33.50    1.50    0.00   35.00     1  java
08:31:05 AM     0      4530   22.50    1.00    0.00   23.50     1  java
08:31:07 AM     0      4530    2.00    0.50    0.00    2.50     1  java
08:31:09 AM     0      4530   19.00    2.00    0.00   21.00     1  java
08:31:11 AM     0      4530    4.50    0.50    0.00    5.00     1  java
08:31:13 AM     0      4530   29.00    1.50    0.00   30.50     1  java
08:31:15 AM     0      4530   23.50    1.50    0.00   25.00     1  java
08:31:17 AM     0      4530    4.00    1.00    0.00    5.00     1  java
08:31:19 AM     0      4530   62.50    2.50    0.00   65.00     1  java
08:31:21 AM     0      4530   15.50    0.50    0.00   16.00     1  java
08:31:23 AM     0      4530    7.00    0.50    0.00    7.50     1  java
08:31:25 AM     0      4530   36.00    2.50    0.00   38.50     1  java
08:31:27 AM     0      4530    7.50    0.50    0.00    8.00     1  java

Looking at the top CPU consuming thread, its CPU time is growing pretty rapidly. This system is running a relatively light load.

$ while true; do /opt/openhab2/runtime/bin/client -p habopen -l 0 -- threads --list | awk -F"│" '{print $4 $2}' | sort --numeric-sort --reverse | head --lines 1; done
 64527     ESH-OSGiEventManager                                                                           
 64527     ESH-OSGiEventManager                                                                           
 64533     ESH-OSGiEventManager                                                                           
 64714     ESH-OSGiEventManager                                                                           
 64714     ESH-OSGiEventManager                                                                           
 64714     ESH-OSGiEventManager                                                                           
 64719     ESH-OSGiEventManager                                                                           
 64890     ESH-OSGiEventManager                                                                           
 64890     ESH-OSGiEventManager                                                                           
 64896     ESH-OSGiEventManager                                                                           
 65063     ESH-OSGiEventManager                                                                           
 65083     ESH-OSGiEventManager                                                                           
 65088     ESH-OSGiEventManager                                                                           
 65251     ESH-OSGiEventManager                                                                           
 65251     ESH-OSGiEventManager                                                                           
 65256     ESH-OSGiEventManager                                                                           
 65381     ESH-OSGiEventManager                                                                           
 65430     ESH-OSGiEventManager                                                                           
 65435     ESH-OSGiEventManager                                                                           
...
 82442     ESH-OSGiEventManager                                                                           
 82630     ESH-OSGiEventManager                                                                           
 82630     ESH-OSGiEventManager                                                                           
 82630     ESH-OSGiEventManager                                                                           
 82814     ESH-OSGiEventManager                                                                           
 82814     ESH-OSGiEventManager                                                                           
 82814     ESH-OSGiEventManager                                                                           
 82819     ESH-OSGiEventManager                                                                           

By comparison, on another system running an older build (1502) that is much more heavily loaded than the above system, the CPU time is growing at a much lower rate.

 174068    ESH-OSGiEventManager                                                                           
 174069    ESH-OSGiEventManager                                                                           
 174070    ESH-OSGiEventManager                                                                           
 174070    ESH-OSGiEventManager                                                                           
 174070    ESH-OSGiEventManager                                                                           
 174070    ESH-OSGiEventManager                                                                           
 174072    ESH-OSGiEventManager                                                                           
 174073    ESH-OSGiEventManager                                                                           
 174076    ESH-OSGiEventManager                                                                           
 174076    ESH-OSGiEventManager                                                                           
 174081    ESH-OSGiEventManager                                                                           
 174082    ESH-OSGiEventManager                                                                           
 174083    ESH-OSGiEventManager                                                                           
 174084    ESH-OSGiEventManager                                                                           
 174084    ESH-OSGiEventManager                                                                           
 174085    ESH-OSGiEventManager                                                                           
 174085    ESH-OSGiEventManager                                                                           
 174086    ESH-OSGiEventManager                                                                           
 174087    ESH-OSGiEventManager                                                                           
 174088    ESH-OSGiEventManager                                                                           
 174089    ESH-OSGiEventManager                                                                           
 174089    ESH-OSGiEventManager                                                                           
 174090    ESH-OSGiEventManager                                                                           
 174090    ESH-OSGiEventManager                                                                           
 174092    ESH-OSGiEventManager                                                                           
 174092    ESH-OSGiEventManager                                                                           
 174092    ESH-OSGiEventManager                                                                           
 174093    ESH-OSGiEventManager                                                                           
 174096    ESH-OSGiEventManager                                                                           
 174097    ESH-OSGiEventManager                                                                           
 174097    ESH-OSGiEventManager                                                                           
 174098    ESH-OSGiEventManager                                                                           

I know there's an issue with memory consumption when karaf tries to load a bogus binding (see here), but I ruled that out as a possible cause here.

maggu2810 commented 5 years ago

Let's have a look at the events...

mhilbush commented 5 years ago

@maggu2810 Ok. I'm on vacation this week and we're heading out for a few hours. I can do some more analysis later when we get back.

All I see is this every 10 seconds from the Unifi and GlobalCache bindings.

2019-06-05 09:56:23.965 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/PresenceMark/state, source=unifi:wirelessClient:mark:online, type=ItemStateEvent, payload={"type":"OnOff","value":"OFF"}, timestamp=1559742983965})
2019-06-05 09:56:23.980 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Site_Mark/state, source=unifi:wirelessClient:mark:site, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742983966})
2019-06-05 09:56:23.994 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/MAC_Mark/state, source=unifi:wirelessClient:mark:macAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742983967})
2019-06-05 09:56:24.009 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/IP_Mark/state, source=unifi:wirelessClient:mark:ipAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742983967})
2019-06-05 09:56:24.024 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Uptime_Mark/state, source=unifi:wirelessClient:mark:uptime, type=ItemStateEvent, payload={"type":"Decimal","value":"0"}, timestamp=1559742983967})
2019-06-05 09:56:24.038 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/LastSeenMark/state, source=unifi:wirelessClient:mark:lastSeen, type=ItemStateEvent, payload={"type":"DateTime","value":"2019-06-02T09:20:14.000-0400"}, timestamp=1559742983967})
2019-06-05 09:56:24.052 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/PresenceCathy/state, source=unifi:wirelessClient:cathy:online, type=ItemStateEvent, payload={"type":"OnOff","value":"OFF"}, timestamp=1559742983967})
2019-06-05 09:56:24.065 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Site_Cathy/state, source=unifi:wirelessClient:cathy:site, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742983967})
2019-06-05 09:56:24.079 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/MAC_Cathy/state, source=unifi:wirelessClient:cathy:macAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742983967})
2019-06-05 09:56:24.093 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/IP_Cathy/state, source=unifi:wirelessClient:cathy:ipAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742983968})
2019-06-05 09:56:24.106 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Uptime_Cathy/state, source=unifi:wirelessClient:cathy:uptime, type=ItemStateEvent, payload={"type":"Decimal","value":"0"}, timestamp=1559742983968})
2019-06-05 09:56:24.120 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/LastSeenCathy/state, source=unifi:wirelessClient:cathy:lastSeen, type=ItemStateEvent, payload={"type":"DateTime","value":"2019-06-02T09:20:14.000-0400"}, timestamp=1559742983968})
2019-06-05 09:56:26.512 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/inbox/globalcache:itachCC:000C1E039BCF/updated, type=InboxUpdatedEvent, payload={"flag":"NEW","label":"GlobalCache iTachWF2CC","properties":{"uid":"GlobalCache_000C1E039BCF","macAddress":"000C1E039BCF","serialNumber":"000C1E039BCF","modelId":"iTachWF2CC","vendor":"GlobalCache","ipAddress":"192.168.1.92","hardwareVersion":"025-0031-01","firmwareVersion":"710-1010-05"},"thingUID":"globalcache:itachCC:000C1E039BCF","thingTypeUID":"globalcache:itachCC"}, timestamp=1559742986511})
2019-06-05 09:56:34.495 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/PresenceMark/state, source=unifi:wirelessClient:mark:online, type=ItemStateEvent, payload={"type":"OnOff","value":"OFF"}, timestamp=1559742994495})
2019-06-05 09:56:34.509 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Site_Mark/state, source=unifi:wirelessClient:mark:site, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742994495})
2019-06-05 09:56:34.522 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/MAC_Mark/state, source=unifi:wirelessClient:mark:macAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742994495})
2019-06-05 09:56:34.535 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/IP_Mark/state, source=unifi:wirelessClient:mark:ipAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742994495})
2019-06-05 09:56:34.741 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Uptime_Mark/state, source=unifi:wirelessClient:mark:uptime, type=ItemStateEvent, payload={"type":"Decimal","value":"0"}, timestamp=1559742994495})
2019-06-05 09:56:34.754 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/LastSeenMark/state, source=unifi:wirelessClient:mark:lastSeen, type=ItemStateEvent, payload={"type":"DateTime","value":"2019-06-02T09:20:14.000-0400"}, timestamp=1559742994496})
2019-06-05 09:56:34.771 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/PresenceCathy/state, source=unifi:wirelessClient:cathy:online, type=ItemStateEvent, payload={"type":"OnOff","value":"OFF"}, timestamp=1559742994496})
2019-06-05 09:56:34.784 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Site_Cathy/state, source=unifi:wirelessClient:cathy:site, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742994496})
2019-06-05 09:56:34.799 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/MAC_Cathy/state, source=unifi:wirelessClient:cathy:macAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742994496})
2019-06-05 09:56:34.814 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/IP_Cathy/state, source=unifi:wirelessClient:cathy:ipAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559742994496})
2019-06-05 09:56:34.828 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Uptime_Cathy/state, source=unifi:wirelessClient:cathy:uptime, type=ItemStateEvent, payload={"type":"Decimal","value":"0"}, timestamp=1559742994496})
2019-06-05 09:56:34.842 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/LastSeenCathy/state, source=unifi:wirelessClient:cathy:lastSeen, type=ItemStateEvent, payload={"type":"DateTime","value":"2019-06-02T09:20:14.000-0400"}, timestamp=1559742994496})
2019-06-05 09:56:36.515 [TRACE] [me.core.internal.events.EventHandler] - Handle OSGi event (event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/inbox/globalcache:itachCC:000C1E039BCF/updated, type=InboxUpdatedEvent, payload={"flag":"NEW","label":"GlobalCache iTachWF2CC","properties":{"uid":"GlobalCache_000C1E039BCF","macAddress":"000C1E039BCF","serialNumber":"000C1E039BCF","modelId":"iTachWF2CC","vendor":"GlobalCache","ipAddress":"192.168.1.92","hardwareVersion":"025-0031-01","firmwareVersion":"710-1010-05"},"thingUID":"globalcache:itachCC:000C1E039BCF","thingTypeUID":"globalcache:itachCC"}, timestamp=1559742996512})
5iver commented 5 years ago

This is after running for nearly a week on S1603...

Id Name State CPU time Usr time
66 ESH-OSGiEventManager RUNNABLE 170048631 166189920
333 ESH-usb-serial-discovery-linux-sysfs-1 TIMED_WAITING 1107910 609540
134 Timer-4 WAITING 773633 648030
342 MQTT Ping: paho410394061874915 TIMED_WAITING 594665 221410
120 pool-1-thread-1 TIMED_WAITING 543923 295940
375 ZWaveReceiveInputThread RUNNABLE 369900 249790
122 pool-5-thread-1 WAITING 225642 160250
336 MQTT Rec: paho410394061874915 RUNNABLE 215840 199420
61 openHAB-job-scheduler_Worker-1 TIMED_WAITING 191547 157590
62 openHAB-job-scheduler_Worker-2 TIMED_WAITING 183640 151990
34 EventAdminAsyncThread #11 WAITING 165043 135350
36 EventAdminAsyncThread #12 WAITING 163229 134360
377 ZWaveReceiveProcessorThread WAITING 151889 132790
181 upnp-main-2 RUNNABLE 94348 81280
39 fileinstall-/opt/openhab2/addons TIMED_WAITING 87060 52180

image

image

davidgraeff commented 5 years ago

So it's a WeakCache somewhere that causes the mem leak and the event manager using too much cpu.

Every item change/update causes an event. But the only listeners that I know of are the rule engine (and DSL rule engine as well I guess) and SSE. SSE got changed a bit, but not in a way that it should behave much different than before. What happened however was the upgrade of xtend, so the DSL rule engine has changed.

5iver commented 5 years ago

In case this matters, I only have one DSL rule that I use for testing.

mhilbush commented 5 years ago

@maggu2810 Here's a snip of the log using the logging from your pull request. I waited for the system to start up and reach "steady state".

2019-06-05 16:13:16.600 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:17.683 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/inbox/globalcache:itachCC:000C1E039BCF/updated, type=InboxUpdatedEvent, payload={"flag":"NEW","label":"GlobalCache iTachWF2CC","properties":{"uid":"GlobalCache_000C1E039BCF","macAddress":"000C1E039BCF","serialNumber":"000C1E039BCF","modelId":"iTachWF2CC","vendor":"GlobalCache","ipAddress":"192.168.1.92","hardwareVersion":"025-0031-01","firmwareVersion":"710-1010-05"},"thingUID":"globalcache:itachCC:000C1E039BCF","thingTypeUID":"globalcache:itachCC"}, timestamp=1559765597682}
2019-06-05 16:13:17.684 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:17.692 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:17.701 [TRACE] [internal.events.ThreadedEventHandler] - wait for event

2019-06-05 16:13:26.851 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/PresenceMark/state, source=unifi:wirelessClient:mark:online, type=ItemStateEvent, payload={"type":"OnOff","value":"OFF"}, timestamp=1559765606851}
2019-06-05 16:13:26.853 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:26.861 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:26.869 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:26.873 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:26.877 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:26.881 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:26.885 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:26.886 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Site_Mark/state, source=unifi:wirelessClient:mark:site, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765606852}
2019-06-05 16:13:26.886 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:26.890 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:26.894 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:26.898 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:26.902 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:26.907 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:26.910 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:26.911 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/MAC_Mark/state, source=unifi:wirelessClient:mark:macAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765606853}
2019-06-05 16:13:26.912 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:26.915 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:26.919 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:26.923 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:26.927 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:26.930 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:26.934 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:26.935 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/IP_Mark/state, source=unifi:wirelessClient:mark:ipAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765606853}
2019-06-05 16:13:26.935 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:26.939 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:26.942 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:26.946 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:26.951 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:26.954 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:26.958 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:26.959 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Uptime_Mark/state, source=unifi:wirelessClient:mark:uptime, type=ItemStateEvent, payload={"type":"Decimal","value":"0"}, timestamp=1559765606853}
2019-06-05 16:13:26.959 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:26.963 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:26.966 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:26.970 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:26.974 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:26.978 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:26.981 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:26.982 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/LastSeenMark/state, source=unifi:wirelessClient:mark:lastSeen, type=ItemStateEvent, payload={"type":"DateTime","value":"2019-06-02T09:20:14.000-0400"}, timestamp=1559765606854}
2019-06-05 16:13:26.983 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:26.986 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:26.990 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:26.993 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:26.997 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:27.001 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:27.004 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:27.005 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/PresenceCathy/state, source=unifi:wirelessClient:cathy:online, type=ItemStateEvent, payload={"type":"OnOff","value":"OFF"}, timestamp=1559765606855}
2019-06-05 16:13:27.005 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:27.009 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:27.013 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:27.017 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:27.021 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:27.024 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:27.028 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:27.029 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Site_Cathy/state, source=unifi:wirelessClient:cathy:site, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765606855}
2019-06-05 16:13:27.029 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:27.032 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:27.036 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:27.039 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:27.043 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:27.046 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:27.050 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:27.051 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/MAC_Cathy/state, source=unifi:wirelessClient:cathy:macAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765606855}
2019-06-05 16:13:27.051 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:27.054 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:27.058 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:27.062 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:27.065 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:27.069 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:27.073 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:27.073 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/IP_Cathy/state, source=unifi:wirelessClient:cathy:ipAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765606856}
2019-06-05 16:13:27.074 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:27.077 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:27.080 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:27.084 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:27.087 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:27.091 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:27.095 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:27.095 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Uptime_Cathy/state, source=unifi:wirelessClient:cathy:uptime, type=ItemStateEvent, payload={"type":"Decimal","value":"0"}, timestamp=1559765606856}
2019-06-05 16:13:27.096 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:27.099 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:27.102 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:27.106 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:27.110 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:27.113 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:27.117 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:27.117 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/LastSeenCathy/state, source=unifi:wirelessClient:cathy:lastSeen, type=ItemStateEvent, payload={"type":"DateTime","value":"2019-06-02T09:20:14.000-0400"}, timestamp=1559765606856}
2019-06-05 16:13:27.118 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:27.121 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:27.126 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:27.129 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:27.133 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:27.136 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:27.140 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:27.689 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/inbox/globalcache:itachCC:000C1E039BCF/updated, type=InboxUpdatedEvent, payload={"flag":"NEW","label":"GlobalCache iTachWF2CC","properties":{"uid":"GlobalCache_000C1E039BCF","macAddress":"000C1E039BCF","serialNumber":"000C1E039BCF","modelId":"iTachWF2CC","vendor":"GlobalCache","ipAddress":"192.168.1.92","hardwareVersion":"025-0031-01","firmwareVersion":"710-1010-05"},"thingUID":"globalcache:itachCC:000C1E039BCF","thingTypeUID":"globalcache:itachCC"}, timestamp=1559765607688}
2019-06-05 16:13:27.690 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:27.700 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:27.708 [TRACE] [internal.events.ThreadedEventHandler] - wait for event

2019-06-05 16:13:37.590 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/PresenceMark/state, source=unifi:wirelessClient:mark:online, type=ItemStateEvent, payload={"type":"OnOff","value":"OFF"}, timestamp=1559765617590}
2019-06-05 16:13:37.591 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.596 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.600 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.604 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.608 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.612 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.616 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.616 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Site_Mark/state, source=unifi:wirelessClient:mark:site, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765617590}
2019-06-05 16:13:37.617 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.621 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.624 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.628 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.632 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.636 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.639 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.640 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/MAC_Mark/state, source=unifi:wirelessClient:mark:macAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765617590}
2019-06-05 16:13:37.640 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.644 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.647 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.651 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.655 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.659 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.662 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.663 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/IP_Mark/state, source=unifi:wirelessClient:mark:ipAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765617591}
2019-06-05 16:13:37.664 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.667 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.671 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.675 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.679 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.686 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.690 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.690 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Uptime_Mark/state, source=unifi:wirelessClient:mark:uptime, type=ItemStateEvent, payload={"type":"Decimal","value":"0"}, timestamp=1559765617591}
2019-06-05 16:13:37.691 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.695 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.698 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.702 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.706 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.710 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.714 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.714 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/LastSeenMark/state, source=unifi:wirelessClient:mark:lastSeen, type=ItemStateEvent, payload={"type":"DateTime","value":"2019-06-02T09:20:14.000-0400"}, timestamp=1559765617592}
2019-06-05 16:13:37.715 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.719 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.723 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.727 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.732 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.737 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.741 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.741 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/PresenceCathy/state, source=unifi:wirelessClient:cathy:online, type=ItemStateEvent, payload={"type":"OnOff","value":"OFF"}, timestamp=1559765617592}
2019-06-05 16:13:37.742 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.746 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.750 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.754 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.758 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.762 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.766 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.767 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Site_Cathy/state, source=unifi:wirelessClient:cathy:site, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765617593}
2019-06-05 16:13:37.768 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.772 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.776 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.780 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.784 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.788 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.792 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.792 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/MAC_Cathy/state, source=unifi:wirelessClient:cathy:macAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765617593}
2019-06-05 16:13:37.793 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.797 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.801 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.804 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.809 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.813 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.816 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.817 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/IP_Cathy/state, source=unifi:wirelessClient:cathy:ipAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765617593}
2019-06-05 16:13:37.817 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.821 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.825 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.829 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.833 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.836 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.840 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.841 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Uptime_Cathy/state, source=unifi:wirelessClient:cathy:uptime, type=ItemStateEvent, payload={"type":"Decimal","value":"0"}, timestamp=1559765617593}
2019-06-05 16:13:37.841 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.845 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.849 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.853 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.857 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.861 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.865 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.865 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/LastSeenCathy/state, source=unifi:wirelessClient:cathy:lastSeen, type=ItemStateEvent, payload={"type":"DateTime","value":"2019-06-02T09:20:14.000-0400"}, timestamp=1559765617594}
2019-06-05 16:13:37.866 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:37.871 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:37.875 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:37.879 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.883 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:37.887 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.892 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:37.892 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/inbox/globalcache:itachCC:000C1E039BCF/updated, type=InboxUpdatedEvent, payload={"flag":"NEW","label":"GlobalCache iTachWF2CC","properties":{"uid":"GlobalCache_000C1E039BCF","macAddress":"000C1E039BCF","serialNumber":"000C1E039BCF","modelId":"iTachWF2CC","vendor":"GlobalCache","ipAddress":"192.168.1.92","hardwareVersion":"025-0031-01","firmwareVersion":"710-1010-05"},"thingUID":"globalcache:itachCC:000C1E039BCF","thingTypeUID":"globalcache:itachCC"}, timestamp=1559765617684}
2019-06-05 16:13:37.893 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:37.896 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:37.900 [TRACE] [internal.events.ThreadedEventHandler] - wait for event

2019-06-05 16:13:47.685 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/inbox/globalcache:itachCC:000C1E039BCF/updated, type=InboxUpdatedEvent, payload={"flag":"NEW","label":"GlobalCache iTachWF2CC","properties":{"uid":"GlobalCache_000C1E039BCF","macAddress":"000C1E039BCF","serialNumber":"000C1E039BCF","modelId":"iTachWF2CC","vendor":"GlobalCache","ipAddress":"192.168.1.92","hardwareVersion":"025-0031-01","firmwareVersion":"710-1010-05"},"thingUID":"globalcache:itachCC:000C1E039BCF","thingTypeUID":"globalcache:itachCC"}, timestamp=1559765627684}
2019-06-05 16:13:47.685 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:47.691 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:47.696 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.087 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/PresenceMark/state, source=unifi:wirelessClient:mark:online, type=ItemStateEvent, payload={"type":"OnOff","value":"OFF"}, timestamp=1559765628086}
2019-06-05 16:13:48.088 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.093 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.100 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.105 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.109 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.113 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.117 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.118 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Site_Mark/state, source=unifi:wirelessClient:mark:site, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765628086}
2019-06-05 16:13:48.118 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.122 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.126 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.130 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.134 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.137 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.141 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.142 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/MAC_Mark/state, source=unifi:wirelessClient:mark:macAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765628087}
2019-06-05 16:13:48.142 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.146 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.150 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.154 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.157 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.161 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.165 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.166 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/IP_Mark/state, source=unifi:wirelessClient:mark:ipAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765628088}
2019-06-05 16:13:48.166 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.170 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.173 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.177 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.181 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.185 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.189 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.190 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Uptime_Mark/state, source=unifi:wirelessClient:mark:uptime, type=ItemStateEvent, payload={"type":"Decimal","value":"0"}, timestamp=1559765628088}
2019-06-05 16:13:48.190 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.195 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.199 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.202 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.206 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.210 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.213 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.214 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/LastSeenMark/state, source=unifi:wirelessClient:mark:lastSeen, type=ItemStateEvent, payload={"type":"DateTime","value":"2019-06-02T09:20:14.000-0400"}, timestamp=1559765628089}
2019-06-05 16:13:48.215 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.218 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.222 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.226 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.230 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.234 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.238 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.238 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/PresenceCathy/state, source=unifi:wirelessClient:cathy:online, type=ItemStateEvent, payload={"type":"OnOff","value":"OFF"}, timestamp=1559765628089}
2019-06-05 16:13:48.239 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.242 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.246 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.250 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.254 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.258 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.262 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.262 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Site_Cathy/state, source=unifi:wirelessClient:cathy:site, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765628090}
2019-06-05 16:13:48.263 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.266 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.270 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.274 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.277 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.281 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.285 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.285 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/MAC_Cathy/state, source=unifi:wirelessClient:cathy:macAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765628090}
2019-06-05 16:13:48.286 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.290 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.293 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.297 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.301 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.305 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.308 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.309 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/IP_Cathy/state, source=unifi:wirelessClient:cathy:ipAddress, type=ItemStateEvent, payload={"type":"UnDef","value":"UNDEF"}, timestamp=1559765628090}
2019-06-05 16:13:48.309 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.313 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.316 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.320 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.324 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.327 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.332 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.332 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/Uptime_Cathy/state, source=unifi:wirelessClient:cathy:uptime, type=ItemStateEvent, payload={"type":"Decimal","value":"0"}, timestamp=1559765628091}
2019-06-05 16:13:48.333 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.336 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.340 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.343 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.347 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.351 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.354 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
2019-06-05 16:13:48.355 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=smarthome] {topic=smarthome/items/LastSeenCathy/state, source=unifi:wirelessClient:cathy:lastSeen, type=ItemStateEvent, payload={"type":"DateTime","value":"2019-06-02T09:20:14.000-0400"}, timestamp=1559765628091}
2019-06-05 16:13:48.356 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.events.internal.EventBridge).
2019-06-05 16:13:48.359 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.thing.internal.CommunicationManager).
2019-06-05 16:13:48.363 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.core.internal.items.ItemUpdater).
2019-06-05 16:13:48.367 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.monitor.internal.EventLogger).
2019-06-05 16:13:48.370 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl).
2019-06-05 16:13:48.374 [TRACE] [me.core.internal.events.EventHandler] - Delegate event to subscriber (class org.eclipse.smarthome.io.rest.sse.internal.listeners.SseEventSubscriber).
2019-06-05 16:13:48.378 [TRACE] [internal.events.ThreadedEventHandler] - wait for event
maggu2810 commented 5 years ago

The event subscribers are notified by the event handler using an async safe caller, so the time the event subscribers consume to handle the event should not be part of the event manager thread at all. The event manager is using a blocking queue to wait for events, so while waiting no time should be consumed. I don't understand why the delegation of the events result into such a high CPU time. As you can see the thread should sleep between the "wait for event" and "inspect event" calls.

In your log that's about 9-10 seconds sleep and then much lower then 1 seconds load. I would expect that results in a really small load number.

cweitkamp commented 5 years ago

So it's a WeakCache somewhere that causes the mem leak

Yes, I can confirm that.

854a785af37e8f95ef78aad2ae875472c0483320

davidgraeff commented 5 years ago

To my amusement I also spotted quite a few large numbered xtext entries in the given screenshots. Still a dream to get rid of that crap specific technology, I guess :)

maggu2810 commented 5 years ago

@cweitkamp Can you debug the constructor call of WeakCache? I realized on every new SafeCaller creation a new WeakCache CacheValue and CacheKey is created, but I don't identify (while generating a lot of state updates) a new WeakCache creation.

cweitkamp commented 5 years ago

Not much time for debugging but what I got from Google: java.lang.reflect.Proxy uses class WeakCache to retain details of Proxy classes associated with a given class loader. We extend ClassLoader in CombinedClassLoader which is called in SafeCallerBuilderImpl. Do not know if that helps.

https://github.com/openhab/openhab-core/blob/306165dcfb72a23c2fa23de14eedc1c8b0e104a3/bundles/org.openhab.core/src/main/java/org/eclipse/smarthome/core/internal/common/SafeCallerBuilderImpl.java#L70-L73

maggu2810 commented 5 years ago

I tried to find a way how to automate the tracing of special function calls. Perhaps someone is interested in:

I checked the line numbers of the stuff I am interested in for my currently used Java version.

all the time this method is called, I would like a stacktrace and then the debugger should continue.

Let's use the command line debugger jdb and attach it to the remote application on port 5005:

jdb -attach 5005

Set monitors ("execute command each time the program stops") to dump the stacktrace and continue the execution from the breakpoint:

monitor where
monitor cont

After that set the breakpoints:

stop at java.lang.reflect.WeakCache:81
stop at java.lang.reflect.WeakCache$CacheKey:344  
stop at java.lang.reflect.WeakCache$CacheValue:302

Now, you will get a trace of all calls.

If you want to look other method calls, just change your breakpoints.

J-N-K commented 5 years ago

Nice

mhilbush commented 5 years ago

Not sure if this is helpful. If you need a longer trace, let me know. These were being produced every 10 seconds, presumably to coincide with the events that are being generated as shown in one of my previous posts.

Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
> 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheKey.<init>(), line=344 bci=0

  [1] java.lang.reflect.WeakCache$CacheKey.<init> (WeakCache.java:344)
  [2] java.lang.reflect.WeakCache$CacheKey.valueOf (WeakCache.java:333)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:105)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$414.748659291.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:140)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:98)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:70)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:69)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$396.1844826445.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > 
Breakpoint hit: "thread=ESH-OSGiEventManager", java.lang.reflect.WeakCache$CacheValue.<init>(), line=302 bci=0

  [1] java.lang.reflect.WeakCache$CacheValue.<init> (WeakCache.java:302)
  [2] java.lang.reflect.WeakCache$Factory.get (WeakCache.java:240)
  [3] java.lang.reflect.WeakCache.get (WeakCache.java:127)
  [4] java.lang.reflect.Proxy.getProxyClass0 (Proxy.java:419)
  [5] java.lang.reflect.Proxy.newProxyInstance (Proxy.java:719)
  [6] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.lambda$0 (SafeCallerBuilderImpl.java:70)
  [7] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl$$Lambda$481.573866004.run (null)
  [8] java.security.AccessController.doPrivileged (native method)
  [9] org.eclipse.smarthome.core.internal.common.SafeCallerBuilderImpl.build (SafeCallerBuilderImpl.java:61)
  [10] org.eclipse.smarthome.core.internal.events.EventHandler.dispatchESHEvent (EventHandler.java:141)
  [11] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:100)
  [12] org.eclipse.smarthome.core.internal.events.EventHandler.handleEvent (EventHandler.java:72)
  [13] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler.lambda$0 (ThreadedEventHandler.java:67)
  [14] org.eclipse.smarthome.core.internal.events.ThreadedEventHandler$$Lambda$476.1560574933.run (null)
  [15] java.lang.Thread.run (Thread.java:748)
ESH-OSGiEventManager[1] > > Input stream closed.
maggu2810 commented 5 years ago

AFAI can judge the WeakCache's CacheKey and CacheValue created because of the SafeCallerBuilderImpl are freed on a GC run. At least mine ones went away after a click on Perform GC in visualvm. So for me it seems IF the only extreme usage of that cache is by the safe caller, it will be freed before it gets critical.

maggu2810 commented 5 years ago

I would be very interested if the high load is caused by https://github.com/openhab/openhab-core/pull/763 Is someone able to revert that commit and check the runtime performance impacts?

mhilbush commented 5 years ago

@maggu2810 I reverted that commit. The rate of CPU consumption of the ESH-OSGiEventManager thread looks like it's back to what it was before the change.

 1112      ESH-OSGiEventManager                                                                           
 1112      ESH-OSGiEventManager                                                                           
 1118      ESH-OSGiEventManager                                                                           
 1118      ESH-OSGiEventManager                                                                           
 1120      ESH-OSGiEventManager                                                                           
 1126      ESH-OSGiEventManager                                                                           
 1127      ESH-OSGiEventManager                                                                           
 1127      ESH-OSGiEventManager                                                                           
 1133      ESH-OSGiEventManager                                                                           
 1134      ESH-OSGiEventManager                                                                           
 1134      ESH-OSGiEventManager                                                                           
 1141      ESH-OSGiEventManager                                                                           
 1142      ESH-OSGiEventManager                                                                           
 1142      ESH-OSGiEventManager                                                                           
 1148      ESH-OSGiEventManager                                                                           
 1148      ESH-OSGiEventManager                                                                           
 1148      ESH-OSGiEventManager                                                                           
 1154      ESH-OSGiEventManager                                                                           
 1154      ESH-OSGiEventManager                                                                           
 1154      ESH-OSGiEventManager                                                                           

However, the gradual uptick of memory consumption has not changed, so perhaps we are seeing symptoms from more than one cause?

mhilbush commented 5 years ago

@maggu2810 I installed visualvm, but I'm not quite sure what to look for. If you could give me some pointers on things I should look at, I can post the results here.

I took a few screen snips of the visualvm panels. Maybe this will provide some clues where to look further. Note that the version I'm running has the CombinedClassLoader reverted. From what I can see, the ESH-OSGiEventManager cpu time is very low and is growing only very, very slowly. Given the info below, I'd suggest that CPU time used by ESH-OSGiEventManager with the CombinedClassLoader change, while high, is not a contributor to the memory and CPU issues I'm seeing.

Monitor panel - note the huge memory growth spurts...

monitor

CPU panels

cpu-samples

thread-cpu-time

Memory

heap-histo

per-thread

Some additional info from pidstat. Memory

04:34:06 PM   UID       PID  minflt/s  majflt/s     VSZ     RSS   %MEM  Command
04:34:10 PM     0     28009   2702.50      0.00 4432912  163396   4.74  java
04:34:14 PM     0     28009   9097.50      0.00 4457544  300840   8.72  java
04:34:18 PM     0     28009   9299.50      0.00 4483832  435740  12.63  java
04:34:22 PM     0     28009   1122.50      0.00 4489836  449732  13.04  java
04:34:26 PM     0     28009   4538.25      0.00 4530796  510420  14.80  java
04:34:30 PM     0     28009   7602.75      0.00 4651796  589404  17.08  java
04:34:34 PM     0     28009    934.75      0.00 4661968  603432  17.49  java
04:34:38 PM     0     28009    537.00      0.00 4664016  594760  17.24  java
04:34:42 PM     0     28009    728.00      0.00 4666064  606372  17.58  java
04:34:46 PM     0     28009    292.50      0.00 4666080  610932  17.71  java
04:34:50 PM     0     28009      5.25      0.00 4666080  610932  17.71  java
04:34:54 PM     0     28009     52.75      0.00 4666080  611644  17.73  java
04:34:58 PM     0     28009     45.50      0.00 4666080  612344  17.75  java
04:35:02 PM     0     28009      5.75      0.00 4666080  612344  17.75  java
04:35:06 PM     0     28009   1399.75      0.00 4666080  634248  18.38  java
...
08:24:03 PM     0     28009     28.00      0.00 4895188  842960  24.43  java
08:24:07 PM     0     28009     21.50      0.00 4895188  842960  24.43  java
08:24:11 PM     0     28009     17.00      0.00 4895188  842960  24.43  java
08:24:15 PM     0     28009   6189.75      0.00 4895188  939576  27.24  java
08:24:19 PM     0     28009   8475.50      0.00 4895188 1074152  31.14  java
08:24:23 PM     0     28009   2761.50      0.00 4895188 1118276  32.41  java
08:24:27 PM     0     28009    110.25      0.00 4895188 1119788  32.46  java
08:24:31 PM     0     28009    114.50      0.00 4895188 1121288  32.50  java
08:24:35 PM     0     28009    316.25      0.00 4895188 1125912  32.64  java
08:24:39 PM     0     28009    154.25      0.00 4895188 1128216  32.70  java
...
08:35:51 PM     0     28009     25.50      0.00 4895188 1149068  33.31  java
08:35:55 PM     0     28009     20.25      0.00 4895188 1149068  33.31  java
08:35:59 PM     0     28009     21.50      0.00 4895188 1149072  33.31  java
08:36:03 PM     0     28009   4490.00      0.00 4895188 1218080  35.31  java
08:36:07 PM     0     28009    615.50      0.00 4895188 1227128  35.57  java
08:36:11 PM     0     28009     19.50      0.00 4895188 1227128  35.57  java
08:36:15 PM     0     28009     16.50      0.00 4895188 1227128  35.57  java
08:36:19 PM     0     28009     15.00      0.00 4895188 1227128  35.57  java
08:36:23 PM     0     28009    185.75      0.00 4895188 1229768  35.65  java
...
09:08:39 PM     0     28009     15.50      0.00 4899300 1375584  39.87  java
09:08:43 PM     0     28009     18.50      0.00 4899300 1375588  39.87  java
09:08:47 PM     0     28009   7525.25      0.00 4899300 1494844  43.33  java
09:08:51 PM     0     28009    530.00      0.00 4899300 1502568  43.55  java
09:08:55 PM     0     28009      2.00      0.00 4899300 1502568  43.55  java
09:08:59 PM     0     28009     70.50      0.00 4899300 1502872  43.56  java
09:09:03 PM     0     28009     93.25      0.00 4899300 1503928  43.59  java
09:09:07 PM     0     28009     24.75      0.00 4895188 1503888  43.59  java

CPU

04:34:10 PM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
...
04:37:46 PM     0     28009   55.50    1.00    0.00   56.50     1  java
04:37:48 PM     0     28009    6.00    0.50    0.00    6.50     1  java
04:37:50 PM     0     28009   36.00    1.00    0.00   37.00     1  java
04:37:52 PM     0     28009   11.50    1.00    0.00   12.50     1  java
04:37:54 PM     0     28009   73.50    2.50    0.00   76.00     1  java
04:37:56 PM     0     28009   25.00    0.50    0.00   25.50     1  java
04:37:58 PM     0     28009    7.50    0.50    0.00    8.00     1  java
04:38:00 PM     0     28009   25.00    1.50    0.00   26.50     1  java
04:38:02 PM     0     28009   14.50    0.50    0.00   15.00     1  java
04:38:04 PM     0     28009   27.50    2.00    0.00   29.50     1  java
04:38:06 PM     0     28009   34.00    0.50    0.00   34.50     1  java
04:38:08 PM     0     28009    8.50    1.00    0.00    9.50     1  java
04:38:10 PM     0     28009   32.50    2.00    0.00   34.50     1  java
...
09:16:37 PM     0     28009  101.50    4.50    0.00  106.00     1  java
09:16:39 PM     0     28009  117.00    5.00    0.00  122.00     1  java
09:16:41 PM     0     28009  132.00    2.50    0.00  134.50     1  java
09:16:43 PM     0     28009   81.00    3.00    0.00   84.00     1  java
09:16:45 PM     0     28009  134.50    3.00    0.00  137.50     1  java
09:16:47 PM     0     28009   90.50    3.00    0.00   93.50     1  java
09:16:49 PM     0     28009  110.50    3.50    0.00  114.00     1  java
09:16:51 PM     0     28009  106.00    3.00    0.00  109.00     1  java
09:16:53 PM     0     28009  107.00    3.50    0.00  110.50     1  java
09:16:55 PM     0     28009  127.50    4.50    0.00  132.00     1  java
09:16:57 PM     0     28009   79.00    3.00    0.00   82.00     1  java
09:16:59 PM     0     28009  132.50    2.50    0.00  135.00     1  java
09:17:01 PM     0     28009  104.50    3.00    0.00  107.50     1  java
09:17:03 PM     0     28009  104.50    3.00    0.00  107.50     1  java
5iver commented 5 years ago

After reverting #763 in S1607, I'm also seeing much reduced load and memory usage. I'll run some stats tomorrow.

kaikreuzer commented 5 years ago

May I suggest that we revert #763 for now and only revisit it when we have a better understanding of its performance impact? This issue here is one of the few that prevents us from doing a milestone release.

maggu2810 commented 5 years ago

If you read https://blog.osgi.org/2008/08/classy-solutions-to-tricky-proxies.html I don't think we can get rid of the CombinedClassLoader. But what I am currently don't understand is why we need the safe caller in that place at all? The safe caller creates a proxy so you can use that proxy object as the "normal" one and the user don't need to know that it is a safe caller. The creation of a proxy is not necessary in this situation at all. Why is it used? We just can submit the event subscriber information to the scheduler (perhaps some try catch wrapping). If we want to cancel the execution after some max. time, we can (IMHO) use the CompletableFuture mechanism provided by the standard Java VM.

kaikreuzer commented 5 years ago

I wasn't suggesting to "get rid of" the CombinedClassLoader, just temporarily revert it in the hope that https://github.com/openhab/openhab2-addons/issues/5519 is less of an impact than the CPU load issue atm.

But what I am currently don't understand is why we need the safe caller in that place at all?

What exactly do you refer to as "in that place"? Do you mean this code?

maggu2810 commented 5 years ago

I started to write my comment before your appears. So mine comment about "I don't think we can get rid of" has been written before I read that you really intent to revert the changes.

Yes, I mean the code that calls eventSubscriber.receive(event) in dispatchESHEvent. I assume the CPU and memory footprint can be reduced a lot (and we also don't need a new classloader etc.). I we just enqueue that call to an executor. I don't see the need for a proxy (and all its impact) at all.

maggu2810 commented 5 years ago

@mhilbush @openhab-5iver Could you please check your CPU and memory consumption using this patch https://github.com/maggu2810/openhab-core/commit/48ab0c48e37c9db42647719970f7819beb877322

mhilbush commented 5 years ago

@maggu2810 I'll give this a try today. Note, however, that I was still seeing CPU and memory gradually increase even with #763 reverted.

Yesterday, I restored an old backup on that system (build #1502, an early 2.5 SNAPSHOT), which resulted in much more stable CPU and memory consumption. That old build has been running for about 18 hours without issue. Perhaps there's something else going on with my installation if @openhab-5iver saw no issues with #763 reverted.

mhilbush commented 5 years ago

In an attempt to figure out what's going on, I configured my test system similarly to the system that was experiencing growing CPU and memory consumption. Low and behold, it started exhibiting the same symptoms.

Saw this in my log when trying to install restdocs bundle.

2019-06-09 10:47:50.138 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-ui-restdocs': Error restarting bundles:
    Exception in org.eclipse.smarthome.io.rest.sse.internal.SseActivator.start() of bundle org.openhab.core.io.rest.sse.

Tried stopping and starting sse in the console and saw this.

openhab> bundle:start org.openhab.core.io.rest.sse
Error executing command: Error executing command on bundles:
    Error starting bundle 155: Exception in org.eclipse.smarthome.io.rest.sse.internal.SseActivator.start() of bundle org.openhab.core.io.rest.sse.

Got this in the log at some point.

2019-06-09 10:53:24.044 [ERROR] [org.openhab.core.io.rest.sse        ] - FrameworkEvent ERROR - org.openhab.core.io.rest.sse
org.osgi.framework.BundleException: Exception in org.eclipse.smarthome.io.rest.sse.internal.SseActivator.start() of bundle org.openhab.core.io.rest.sse.
    at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:800) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:729) [?:?]
    at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:933) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:309) ~[?:?]
    at org.eclipse.osgi.container.Module.doStart(Module.java:581) ~[?:?]
    at org.eclipse.osgi.container.Module.start(Module.java:449) ~[?:?]
    at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:468) ~[?:?]
    at org.eclipse.osgi.container.ModuleContainer.start(ModuleContainer.java:750) ~[?:?]
    at org.eclipse.osgi.container.ModuleContainer.applyDelta(ModuleContainer.java:741) ~[?:?]
    at org.eclipse.osgi.container.ModuleContainer.resolveAndApply(ModuleContainer.java:511) ~[?:?]
    at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:457) ~[?:?]
    at org.eclipse.osgi.container.ModuleContainer.refresh(ModuleContainer.java:1001) ~[?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerWiring.dispatchEvent(ModuleContainer.java:1382) ~[?:?]
    at org.eclipse.osgi.container.ModuleContainer$ContainerWiring.dispatchEvent(ModuleContainer.java:1) ~[?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230) [?:?]
    at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340) [?:?]
Caused by: java.lang.LinkageError: ClassCastException: attempting to castbundleresource://34.fwk550147359/javax/ws/rs/ext/RuntimeDelegate.class to bundleresource://34.fwk550147359/javax/ws/rs/ext/RuntimeDelegate.class
    at javax.ws.rs.ext.RuntimeDelegate.findDelegate(RuntimeDelegate.java:146) ~[?:?]
    at javax.ws.rs.ext.RuntimeDelegate.getInstance(RuntimeDelegate.java:120) ~[?:?]
    at javax.ws.rs.core.MediaType.valueOf(MediaType.java:179) ~[?:?]
    at org.glassfish.jersey.media.sse.SseFeature.<clinit>(SseFeature.java:62) ~[?:?]
    at org.eclipse.smarthome.io.rest.sse.internal.SseActivator.start(SseActivator.java:47) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:779) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1) ~[?:?]
    at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:772) ~[?:?]
    ... 15 more
2019-06-09 10:53:24.061 [DEBUG] [org.openhab.core.io.rest.voice      ] - BundleEvent STARTED - org.openhab.core.io.rest.voice

CPU #5 is presently pegged at 100%...

I'll continue trying to diagnose what's going on. I think I need to get this sorted out before I try the latest patch...

mhilbush commented 5 years ago
Caused by: java.lang.LinkageError: ClassCastException: attempting to castbundleresource://34.fwk550147359/javax/ws/rs/ext/RuntimeDelegate.class to 
bundleresource://34.fwk550147359/javax/ws/rs/ext/RuntimeDelegate.class

What does that mean? Why a CCE if it's the same class...

maggu2810 commented 5 years ago

Classes differ if they are supplied from different classloader. This error is already tracked by some issue in core.

maggu2810 commented 5 years ago

@mhilbush As you are such a good tester, can you also this one give a try: https://github.com/openhab/openhab-core/issues/597#issuecomment-500229054

kaikreuzer commented 5 years ago

I assume the CPU and memory footprint can be reduced a lot (and we also don't need a new classloader etc.). I we just enqueue that call to an executor. I don't see the need for a proxy (and all its impact) at all.

I tend to agree. I do not see the need for the safeCaller (and especially for a proxy) and think it was only used because "it was available". Working with CompletableFuture should be a valid alternative.

5iver commented 5 years ago

After reverting 763 on S1607, ESH-OSGiEventManager has been tamed...

Id Name State CPU time Usr time
336 ESH-usb-serial-discovery-linux-sysfs-1 TIMED_WAITING 119893 53260
342 MQTT Ping: paho1286399914659300 TIMED_WAITING 109830 37920
142 Timer-4 WAITING 106139 90430
63 ESH-OSGiEventManager TIMED_WAITING 102996 85640
353 Thread-122 RUNNABLE 77276 23370
334 pool-32-thread-1 TIMED_WAITING 60481 57650
380 ZWaveReceiveInputThread RUNNABLE 45938 31510
122 pool-1-thread-1 TIMED_WAITING 32809 14970
355 AshFrameHandler TIMED_WAITING 28150 20150
382 ZWaveReceiveProcessorThread WAITING 26061 23100
132 openHAB-job-scheduler_Worker-1 TIMED_WAITING 22421 18050
133 openHAB-job-scheduler_Worker-2 TIMED_WAITING 17378 13440
34 EventAdminAsyncThread #11 WAITING 15642 12040
35 EventAdminAsyncThread #12 WAITING 15638 12040
14 Start Level: Equinox Container: 1de23613-d4fe-46ed-95f9-ab949e353812 WAITING 14634 13320
338 MQTT Rec: paho1286399914659300 RUNNABLE 14301 12380
12421 items-541 TIMED_WAITING 13567 7200
198 upnp-main-2 RUNNABLE 11163 9640
39 fileinstall-/opt/openhab2/addons TIMED_WAITING 10766 5530

image

image

Markus, I'm about to put in your changes from #861 and your test workaround for SSEActivator. Should 763 stay reverted?

mhilbush commented 5 years ago

Classes differ if they are supplied from different classloader. This error is already tracked by some issue in core.

Thanks. I see it now. I'll disregard this one.

can you also this one give a try: #597 (comment)

If I can reproduce the issue again, I'll try it, assuming I'm able to reproduce the problem consistently like before.

As @openhab-5iver has confirmed the taming of ESH-OSGiEventManager after reverting CombinedClassLoader, I don't think I need to test with CombinedClassLoader reverted. FWIW, I see no other ill effects of ESH-OSGiEventManager without the reverted CombinedClassLoader (other than it being a CPU hog with cpu time of 7630749 after a couple hours of run time at 31.4 events per second [more on this later]).

From my latest testing...

After uninstalling restdocs, upgrading to build 1607, and restarting openHAB, I'm running much more stable now. This issue with restdocs I've seen before. 🙄

At 31.4 events/second, memory is holding steady at ~15.4% of 8 GB, and CPU is ranging between 25% and 85% on one core. Note I'm measuring events per second this way, with all event types in org.ops4j.pax.logging.cfg set to INFO level. Is there a better way to measure/monitor events per second?

tail -f /opt/openhab2/userdata/logs/events.log | pv --line-mode --average-rate > /dev/null

I'm going to add restdocs back into the mix to confirm that the CPU/memory problem does not reoccur (as was the case with the issue cited above).

Barring any issues with that, I'm going to test #861.

mhilbush commented 5 years ago

Initial results with #861...

Events per second: 31.4 (measured as described in previous post) -- same as before

CPU ranging between 5% and 30% (on one core) -- compared with 25-85%

Memory < 8% (out of 8 GB total) -- compared with > 15%

OH-OSGiEventManager thread CPU time growing VERY slowly (measured at 10 second intervals)

 547       OH-OSGiEventManager
 567       OH-OSGiEventManager
 585       OH-OSGiEventManager
 603       OH-OSGiEventManager
 622       OH-OSGiEventManager
 641       OH-OSGiEventManager
 659       OH-OSGiEventManager
 679       OH-OSGiEventManager
 698       OH-OSGiEventManager
 715       OH-OSGiEventManager

As compared to before.

 8322719   ESH-OSGiEventManager
 8328524   ESH-OSGiEventManager
 8334892   ESH-OSGiEventManager
 8341976   ESH-OSGiEventManager
maggu2810 commented 5 years ago

Initial results with #861...

So, it looks much better.

mhilbush commented 5 years ago

No, it looks MUCH better!! 😁

maggu2810 commented 5 years ago

Just to state, there are three threads:

The last two should continue with "-1" but just look at the prefix.

The events that are received from the OSGi event admin are placed in a queue. The OH-OSGiEventManager thread takes the event from that queue (and waits if there is no one). The taken event is handled by the event subscribers using the thread OH-EventHandlerExecutor. The OH-EventHandlerWatcher thread is used to log a warning if a event subscriber needs more then five seconds to handle the event.

So, to be more precise you need to add the CPU time of this three threads.

5iver commented 5 years ago

Should 763 still be reverted?

maggu2810 commented 5 years ago

Should 763 still be reverted?

IMHO: No!

763 must be present to have a fully working safe caller in an OSGi environment.

The current safe caller implementation is at it is but needs to be correct.

We just don't need to use the safe caller here (and perhaps other places).

mhilbush commented 5 years ago

On 10 second intervals as before. And still MUCH better.

 2839      OH-OSGiEventManager
 10243     OH-EventHandlerExecutor-1
 758       OH-EventHandlerWatcher-1
-----------------------
 2854      OH-OSGiEventManager
 10301     OH-EventHandlerExecutor-1
 762       OH-EventHandlerWatcher-1
-----------------------
 2868      OH-OSGiEventManager
 10354     OH-EventHandlerExecutor-1
 766       OH-EventHandlerWatcher-1
-----------------------
 2884      OH-OSGiEventManager
 10412     OH-EventHandlerExecutor-1
 770       OH-EventHandlerWatcher-1
-----------------------
 2900      OH-OSGiEventManager
 10471     OH-EventHandlerExecutor-1
 775       OH-EventHandlerWatcher-1

Should 763 still be reverted?

I built org.openhab.core from a new clone with just #861. So, this still has the CombinedClassLoader, right?

maggu2810 commented 5 years ago

I built org.openhab.core from a new clone with just #861. So, this still has the CombinedClassLoader, right?

Correct.