search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.9k stars 3.59k forks source link

[yamahareceiver] high CPU usage bursts after adding zone things (RX-A3020) #7184

Closed olemr closed 3 years ago

olemr commented 4 years ago

My environment: openhab 2.5.2 Release Build, x64 platform, Ubuntu Server 18.04 LTS 286 │ Active │ 80 │ 2.5.2 │ openHAB Add-ons :: Bundles :: Yamaha Receiver Binding

This issue is 100% reproducible using my Yamaha RX-A3020 (fw 1.98) wired Eth LAN. After installing this item, all is fine, CPU usage is normal 5-6% watched over a period of several minutes. : image

After installing MAIN Zone, CPU usage spikes to 100-150% for 5-10s every 30s. image

This is the trace log from 2 such periods. Note how the log entries only last for some 150ms out of the 5-10s period:

    2020-03-15 18:53:33.722 [TRACE] [internal.handler.YamahaBridgeHandler] - updateAllZoneInformation
    2020-03-15 18:53:33.723 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.1.107:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Power_Control><Power>GetParam</Power></Power_Control></System></YAMAHA_AV>
    2020-03-15 18:53:33.752 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response
    2020-03-15 18:53:33.765 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.1.107:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Party_Mode><Mode>GetParam</Mode></Party_Mode></System></YAMAHA_AV>
    2020-03-15 18:53:33.788 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response
    2020-03-15 18:53:33.800 [DEBUG] [ternal.protocol.xml.SystemControlXML] - System state - power: true, partyMode: false
    2020-03-15 18:53:33.801 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.1.107:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Input><Input_Sel_Item>GetParam</Input_Sel_Item></Input></Main_Zone></YAMAHA_AV>
    2020-03-15 18:53:33.802 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.1.107:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>
    2020-03-15 18:53:33.837 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response
    2020-03-15 18:53:33.856 [TRACE] [rnal.protocol.xml.XMLProtocolService] - Zone Main_Zone - inputs: Napster:RW, NET RADIO:RW, SERVER:RW, AirPlay:RW, USB:RW, iPod (USB):R, TUNER:RW, AV1:RW, AV2:RW, AV3:RW, AV4:RW, AV5:RW, AV6:RW, AV7:RW, AUDIO1:RW, AUDIO2:RW, AUDIO3:RW, AUDIO4:RW, PHONO:RW, V-AUX:RW, MULTI CH:RW
    2020-03-15 18:53:33.857 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name Napster to NAPSTER - as per legacy mapping
    2020-03-15 18:53:33.858 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name NET RADIO to NET RADIO - as per no conversion rule
    2020-03-15 18:53:33.859 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response
    2020-03-15 18:53:33.859 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name SERVER to SERVER - as per legacy mapping
    2020-03-15 18:53:33.860 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AirPlay to AIRPLAY - as per legacy mapping
    2020-03-15 18:53:33.861 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name USB to USB - as per legacy mapping
    2020-03-15 18:53:33.861 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name TUNER to TUNER - as per legacy mapping
    2020-03-15 18:53:33.862 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV1 to AV1 - as per legacy mapping
    2020-03-15 18:53:33.863 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV2 to AV2 - as per legacy mapping
    2020-03-15 18:53:33.864 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV3 to AV3 - as per legacy mapping
    2020-03-15 18:53:33.864 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV4 to AV4 - as per legacy mapping
    2020-03-15 18:53:33.865 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV5 to AV5 - as per legacy mapping
    2020-03-15 18:53:33.866 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV6 to AV6 - as per legacy mapping
    2020-03-15 18:53:33.866 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV7 to AV7 - as per legacy mapping
    2020-03-15 18:53:33.867 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO1 to AUDIO1 - as per no conversion rule
    2020-03-15 18:53:33.868 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO2 to AUDIO2 - as per no conversion rule
    2020-03-15 18:53:33.868 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO3 to AUDIO3 - as per no conversion rule
    2020-03-15 18:53:33.869 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO4 to AUDIO4 - as per no conversion rule
    2020-03-15 18:53:33.869 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name PHONO to PHONO - as per legacy mapping
    2020-03-15 18:53:33.870 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name V-AUX to V-AUX - as per legacy mapping
    2020-03-15 18:53:33.870 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name MULTI CH to MULTI_CH - as per legacy mapping
    2020-03-15 18:53:33.871 [TRACE] [.protocol.xml.ZoneAvailableInputsXML] - Zone Main_Zone - available inputs: AIRPLAY, AUDIO1, AUDIO2, AUDIO3, AUDIO4, AV1, AV2, AV3, AV4, AV5, AV6, AV7, MULTI_CH, NAPSTER, NET RADIO, PHONO, SERVER, TUNER, USB, V-AUX
    2020-03-15 18:53:33.877 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO1 to AUDIO1 - as per no conversion rule
    2020-03-15 18:53:33.878 [DEBUG] [internal.protocol.xml.ZoneControlXML] - Zone Main_Zone state - power: true, mute: false, volumeDB: -46.5, input: AUDIO1, surroundProgram: Surround Decoder
    2020-03-15 18:54:03.272 [INFO ] [e.smarthome.model.script.SmokeAlarms] - Changed: Smokealarms=OFF
    2020-03-15 18:54:03.273 [INFO ] [.model.script.UniversalBinarySensor2] - Update: UniversalBinarySensor2=OFF

    2020-03-15 18:54:11.048 [WARN ] [.ZWaveThermostatSetpointCommandClass] - Reached max tries to init the setpont Furnace, this will be our last attempt
    2020-03-15 18:54:12.646 [INFO ] [smarthome.model.script.HVAC:Setpoint] - HVACVindfangsetPoint=22.5 °C

    2020-03-15 18:54:33.802 [TRACE] [internal.handler.YamahaBridgeHandler] - updateAllZoneInformation
    2020-03-15 18:54:33.803 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.1.107:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Power_Control><Power>GetParam</Power></Power_Control></System></YAMAHA_AV>
    2020-03-15 18:54:33.832 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response
    2020-03-15 18:54:33.845 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.1.107:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Party_Mode><Mode>GetParam</Mode></Party_Mode></System></YAMAHA_AV>
    2020-03-15 18:54:33.868 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response
    2020-03-15 18:54:33.881 [DEBUG] [ternal.protocol.xml.SystemControlXML] - System state - power: true, partyMode: false
    2020-03-15 18:54:33.882 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.1.107:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Input><Input_Sel_Item>GetParam</Input_Sel_Item></Input></Main_Zone></YAMAHA_AV>
    2020-03-15 18:54:33.886 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.1.107:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>
    2020-03-15 18:54:33.924 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response
    2020-03-15 18:54:33.930 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response
    2020-03-15 18:54:33.942 [TRACE] [rnal.protocol.xml.XMLProtocolService] - Zone Main_Zone - inputs: Napster:RW, NET RADIO:RW, SERVER:RW, AirPlay:RW, USB:RW, iPod (USB):R, TUNER:RW, AV1:RW, AV2:RW, AV3:RW, AV4:RW, AV5:RW, AV6:RW, AV7:RW, AUDIO1:RW, AUDIO2:RW, AUDIO3:RW, AUDIO4:RW, PHONO:RW, V-AUX:RW, MULTI CH:RW
    2020-03-15 18:54:33.943 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name Napster to NAPSTER - as per legacy mapping
    2020-03-15 18:54:33.944 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name NET RADIO to NET RADIO - as per no conversion rule
    2020-03-15 18:54:33.944 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name SERVER to SERVER - as per legacy mapping
    2020-03-15 18:54:33.945 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AirPlay to AIRPLAY - as per legacy mapping
    2020-03-15 18:54:33.945 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name USB to USB - as per legacy mapping
    2020-03-15 18:54:33.946 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name TUNER to TUNER - as per legacy mapping
    2020-03-15 18:54:33.946 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV1 to AV1 - as per legacy mapping
    2020-03-15 18:54:33.947 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV2 to AV2 - as per legacy mapping
    2020-03-15 18:54:33.948 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV3 to AV3 - as per legacy mapping
    2020-03-15 18:54:33.948 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV4 to AV4 - as per legacy mapping
    2020-03-15 18:54:33.949 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV5 to AV5 - as per legacy mapping
    2020-03-15 18:54:33.949 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV6 to AV6 - as per legacy mapping
    2020-03-15 18:54:33.950 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AV7 to AV7 - as per legacy mapping
    2020-03-15 18:54:33.951 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO1 to AUDIO1 - as per no conversion rule
    2020-03-15 18:54:33.951 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO2 to AUDIO2 - as per no conversion rule
    2020-03-15 18:54:33.951 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO1 to AUDIO1 - as per no conversion rule
    2020-03-15 18:54:33.953 [DEBUG] [internal.protocol.xml.ZoneControlXML] - Zone Main_Zone state - power: true, mute: false, volumeDB: -46.5, input: AUDIO1, surroundProgram: Surround Decoder
    2020-03-15 18:54:33.951 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO3 to AUDIO3 - as per no conversion rule
    2020-03-15 18:54:33.955 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO4 to AUDIO4 - as per no conversion rule
    2020-03-15 18:54:33.955 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name PHONO to PHONO - as per legacy mapping
    2020-03-15 18:54:33.956 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name V-AUX to V-AUX - as per legacy mapping
    2020-03-15 18:54:33.956 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name MULTI CH to MULTI_CH - as per legacy mapping
    2020-03-15 18:54:33.957 [TRACE] [.protocol.xml.ZoneAvailableInputsXML] - Zone Main_Zone - available inputs: AIRPLAY, AUDIO1, AUDIO2, AUDIO3, AUDIO4, AV1, AV2, AV3, AV4, AV5, AV6, AV7, MULTI_CH, NAPSTER, NET RADIO, PHONO, SERVER, TUNER, USB, V-AUX

Adding more Zone things, Zone2,3,4 the issue gets worse, flattening out on a continuous CPU usage of 180%. After deleting all zone things, CPU usage is back to normal.

zarusz commented 4 years ago

Can anyone else from the community confirm the issue on their setup?

I wonder if the differential update optimization done as part of this one will ease the CPU spikes after updates: #6832

olemr commented 4 years ago

Well, I did a test on a RPi4. Same issue, but not so prominent. Added all 4 Zones, CPU goes up to about 100% for 5-10s every 60s The Pi runs openjdk 11.0.6, the Ubuntu Java 1.8.0_201

olemr commented 4 years ago

Still a problem on :

2.5.4 Release Build
254 │ Active │  80 │ 2.5.4                   │ openHAB Add-ons :: Bundles :: Yamaha Receiver Binding
olemr commented 4 years ago

Did a WireShark capture whilst adding the MAIN Zone. https://1drv.ms/u/s!Ak62_W4agNNTogGQWs99jLeWoYkn?e=o8znW7

lolodomo commented 4 years ago

Looking at the code, I see we have a refresh job scheduled by default every 60 seconds. This job will trigger for each zone the run of 2 until 6 commands, each command being run asynchronously in a separate thread. The used thread pool is the common OH thread pool dedicated to bindings. While the refresh is already run in a separate thread, I see no reason to call the commands asynchronously. They could be run in sequence by the same thread. This would reduce the number of commands run in parallel.

lolodomo commented 4 years ago

I proposed a fix that avoids starting multiplke commands in parallel in different threads (the used thrread pool has a very limioted size).

lolodomo commented 4 years ago

@olemr : are you able to test my proposal ? We need someone to confirm that:

  1. the binding is still working after my change
  2. your issue is fixed

I can build and provide the jar file.

olemr commented 4 years ago

Sorry for my late reply. Sure, I'll be happy to test your change/jar.

lolodomo commented 4 years ago

Do you need I build the jar file for you?

olemr commented 4 years ago

Yes, please. That would be great. I have never done it before ... (Or does it just involve pressing a button in Jenkins somewhere?)

lolodomo commented 4 years ago

Here is a jar for testing: org.openhab.binding.yamahareceiver-2.5.6-SNAPSHOT.zip

olemr commented 4 years ago

Thanks. Sorry to say, it behaves exactly as the old one:

        2.5.5
        Release Build

openhab> list | grep -i yama
284 │ Active │  80 │ 2.5.6.202006031211      │ openHAB Add-ons :: Bundles :: Yamaha Receiver Binding

Uninstalled the old binding, copied the .jar and restarted OH2

lolodomo commented 4 years ago

Ok, thank you for the test, I will close my proposal in this case.

olemr commented 4 years ago

Just re-tested on 2.5.8, still the same. As soon as I add the Main Zone, the CPU hogging starts.

olemr commented 3 years ago

Re-tested on OH3.0.0 Release Build and now all is OK.