High CPU load with local screen grabber enabled (75% Xorg)

fightforlife commented 3 years ago

[x] I confirm that this is an issue rather than a question.

Bug report

As soon as I enable local screen capture my CPU usage of the Xorg process goes to 75%. It does not matter if it is XCB or X11. This was not always the case. I am not sure what changed.

Steps to reproduce

Install Kodi standalone and hyperion Alpha 10 and use the following services on Ubuntu 21.10. Platform is an Intel J3455.

Kodi service

[Unit]
Description=Starts instance of Kodi using xinit
After=systemd-user-sessions.service network-online.target sound.target
# mysqld.service
Requires=network-online.target
Conflicts=getty@tty1.service

[Service]
User=kodi
Group=kodi
PAMName=login
TTYPath=/dev/tty1
ExecStart=/usr/bin/xinit /usr/bin/kodi-standalone -- :0 -nolisten tcp vt1
Restart=on-abort
StandardInput=tty

[Install]
WantedBy=multi-user.target

hyperion service

[Unit]
Description=Hyperion ambient light systemd service  for user %i
After=network.target

[Service]
ExecStart=/usr/bin/hyperiond
WorkingDirectory=/usr/share/hyperion/bin
User=hyperion
Group=dialout
TimeoutStopSec=5
KillMode=mixed
Restart=on-failure
RestartSec=2
Environment="DISPLAY=:0"

[Install]
WantedBy=multi-user.target

What is expected?

CPU load of around 10-20% max when using local xcb screen grabber

What is actually happening?

CPU load of Xorg process of 75% and stuttering

System

Hyperion Server:

Build: (HEAD detached at 2.0.0-alpha.10) (Paulchen-Panther-975f969/b1a4e95-1626550299)
Build time: Jul 17 2021 21:50:23
Git Remote: https://github.com/hyperion-project/hyperion.ng
Version: 2.0.0-alpha.10
UI Lang: auto (BrowserLang: en-US)
UI Access: default
Avail Capt: v4l2,framebuffer,x11,xcb,qt
Database: read/write

Hyperion Server OS:

Distribution: Ubuntu 21.04
Architecture: x86_64
CPU Model: Intel(R) Celeron(R) CPU J3455 @ 1.50GHz
CPU Type: 92
Kernel: linux (5.11.0-31-generic (WS: 64))
Qt Version: 5.15.2
Python Version: 3.9.5
Browser: Mozilla/5.0 (Windows NT 10.0; Win64; x64)

Paulchen-Panther commented 3 years ago

Can you provide us with a log? Thanks

"System" -> "Log" -> "LogLevel" set to Debug and click on "Copy Log to Clipboard" at the bottom right.

fightforlife commented 3 years ago

Hyperion System Summary Report (Server), Reported instance: First LED Hardware instance

< ----- System information -------------------- >
Hyperion Server: 
- Build:           (HEAD detached at 2.0.0-alpha.10) (Paulchen-Panther-975f969/b1a4e95-1626550299)
- Build time:      Jul 17 2021 21:50:23
- Git Remote:      https://github.com/hyperion-project/hyperion.ng
- Version:         2.0.0-alpha.10
- UI Lang:         auto (BrowserLang: en-US)
- UI Access:       default
- Avail Capt:      v4l2,framebuffer,x11,xcb,qt
- Database:        read/write

Hyperion Server OS: 
- Distribution:   Ubuntu 21.04
- Architecture:   x86_64
- CPU Model:      Intel(R) Celeron(R) CPU J3455 @ 1.50GHz
- CPU Type:       92
- Kernel:         linux (5.11.0-31-generic (WS: 64))
- Qt Version:     5.15.2
- Python Version: 3.9.5
- Browser:        Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.31 Safari/537.36

< ----- Configured Instances ------------------ >
0: First LED Hardware instance Running: true

< ----- This instance's priorities ------------ >
254:  VISIBLE! (EFFECT) Owner: Candle
priorities_autoselect: true

< ----- This instance components' status ------->
ALL - true
SMOOTHING - true
BLACKBORDER - true
FORWARDER - false
BOBLIGHTSERVER - false
GRABBER - true
V4L - false
LEDDEVICE - true

< ----- This instance's configuration --------- >
{"backgroundEffect":{"color":[255,138,0],"effect":"Candle","enable":true,"type":"effect"},"blackborderdetector":{"blurRemoveCnt":1,"borderFrameCnt":50,"enable":true,"maxInconsistentCnt":10,"mode":"default","threshold":5,"unknownFrameCnt":600},"boblightServer":{"enable":false,"port":19333,"priority":128},"color":{"channelAdjustment":[{"backlightColored":false,"backlightThreshold":0,"blue":[0,0,255],"brightness":100,"brightnessCompensation":100,"cyan":[0,255,255],"gammaBlue":1.5,"gammaGreen":1.5,"gammaRed":1.5,"green":[0,255,0],"id":"default","leds":"*","magenta":[255,0,255],"red":[255,0,0],"white":[255,255,255],"yellow":[255,255,0]}],"imageToLedMappingType":"multicolor_mean"},"device":{"colorOrder":"rgb","delayAfterConnect":200,"hardwareLedCount":50,"latchTime":30,"lightberry_apa102_mode":false,"output":"ttyUSB0","rate":500000,"rewriteTime":1000,"type":"adalight"},"effects":{"disable":[""],"paths":["$ROOT/custom-effects"]},"flatbufServer":{"enable":false,"port":19400,"timeout":5},"foregroundEffect":{"color":[0,0,255],"duration_ms":3000,"effect":"Rainbow swirl fast","enable":true,"type":"effect"},"forwarder":{"enable":false,"flat":["127.0.0.1:19401"],"json":["127.0.0.1:19446"]},"framegrabber":{"available_devices":"XCB","cropBottom":0,"cropLeft":0,"cropRight":0,"cropTop":0,"device":"xcb","device_inputs":"0","enable":true,"fps":25,"framerates":"25","height":2160,"input":0,"pixelDecimation":30,"resolutions":"0","width":3840},"general":{"configVersion":"2.0.0-alpha.10","name":"Server","previousVersion":"2.0.0-alpha.10","showOptHelp":true,"watchedVersionBranch":"Alpha"},"grabberV4L2":{"blueSignalThreshold":5,"cecDetection":false,"cropBottom":0,"cropLeft":0,"cropRight":0,"cropTop":0,"device":"auto","enable":false,"flip":"NO_CHANGE","fps":15,"fpsSoftwareDecimation":0,"greenSignalThreshold":5,"hardware_brightness":0,"hardware_contrast":0,"hardware_hue":0,"hardware_saturation":0,"height":0,"input":0,"noSignalCounterThreshold":200,"redSignalThreshold":5,"sDHOffsetMax":0.75,"sDHOffsetMin":0.25,"sDVOffsetMax":0.75,"sDVOffsetMin":0.25,"signalDetection":false,"sizeDecimation":8,"standard":"NO_CHANGE","width":0},"instCapture":{"systemEnable":true,"systemGrabberDevice":"XCB","systemPriority":199,"v4lEnable":false,"v4lGrabberDevice":"NONE","v4lPriority":240},"jsonServer":{"port":19444},"ledConfig":{"classic":{"bottom":0,"edgegap":0,"glength":0,"gpos":0,"hdepth":8,"left":14,"overlap":0,"pblh":0,"pblv":100,"pbrh":100,"pbrv":100,"position":36,"ptlh":0,"ptlv":0,"ptrh":100,"ptrv":0,"reverse":true,"right":14,"top":22,"vdepth":5},"ledBlacklist":[],"matrix":{"cabling":"snake","ledshoriz":10,"ledsvert":10,"start":"top-left"}},"leds":[{"hmax":1,"hmin":0.95,"vmax":1,"vmin":0.9286},{"hmax":1,"hmin":0.95,"vmax":0.9286,"vmin":0.8571},{"hmax":1,"hmin":0.95,"vmax":0.8571,"vmin":0.7857},{"hmax":1,"hmin":0.95,"vmax":0.7857,"vmin":0.7143},{"hmax":1,"hmin":0.95,"vmax":0.7143,"vmin":0.6429},{"hmax":1,"hmin":0.95,"vmax":0.6429,"vmin":0.5714},{"hmax":1,"hmin":0.95,"vmax":0.5714,"vmin":0.5},{"hmax":1,"hmin":0.95,"vmax":0.5,"vmin":0.4286},{"hmax":1,"hmin":0.95,"vmax":0.4286,"vmin":0.3571},{"hmax":1,"hmin":0.95,"vmax":0.3571,"vmin":0.2857},{"hmax":1,"hmin":0.95,"vmax":0.2857,"vmin":0.2143},{"hmax":1,"hmin":0.95,"vmax":0.2143,"vmin":0.1429},{"hmax":1,"hmin":0.95,"vmax":0.1429,"vmin":0.0714},{"hmax":1,"hmin":0.95,"vmax":0.0714,"vmin":0},{"hmax":1,"hmin":0.9545,"vmax":0.08,"vmin":0},{"hmax":0.9545,"hmin":0.9091,"vmax":0.08,"vmin":0},{"hmax":0.9091,"hmin":0.8636,"vmax":0.08,"vmin":0},{"hmax":0.8636,"hmin":0.8182,"vmax":0.08,"vmin":0},{"hmax":0.8182,"hmin":0.7727,"vmax":0.08,"vmin":0},{"hmax":0.7727,"hmin":0.7273,"vmax":0.08,"vmin":0},{"hmax":0.7273,"hmin":0.6818,"vmax":0.08,"vmin":0},{"hmax":0.6818,"hmin":0.6364,"vmax":0.08,"vmin":0},{"hmax":0.6364,"hmin":0.5909,"vmax":0.08,"vmin":0},{"hmax":0.5909,"hmin":0.5455,"vmax":0.08,"vmin":0},{"hmax":0.5455,"hmin":0.5,"vmax":0.08,"vmin":0},{"hmax":0.5,"hmin":0.4545,"vmax":0.08,"vmin":0},{"hmax":0.4545,"hmin":0.4091,"vmax":0.08,"vmin":0},{"hmax":0.4091,"hmin":0.3636,"vmax":0.08,"vmin":0},{"hmax":0.3636,"hmin":0.3182,"vmax":0.08,"vmin":0},{"hmax":0.3182,"hmin":0.2727,"vmax":0.08,"vmin":0},{"hmax":0.2727,"hmin":0.2273,"vmax":0.08,"vmin":0},{"hmax":0.2273,"hmin":0.1818,"vmax":0.08,"vmin":0},{"hmax":0.1818,"hmin":0.1364,"vmax":0.08,"vmin":0},{"hmax":0.1364,"hmin":0.0909,"vmax":0.08,"vmin":0},{"hmax":0.0909,"hmin":0.0455,"vmax":0.08,"vmin":0},{"hmax":0.0455,"hmin":0,"vmax":0.08,"vmin":0},{"hmax":0.05,"hmin":0,"vmax":0.0714,"vmin":0},{"hmax":0.05,"hmin":0,"vmax":0.1429,"vmin":0.0714},{"hmax":0.05,"hmin":0,"vmax":0.2143,"vmin":0.1429},{"hmax":0.05,"hmin":0,"vmax":0.2857,"vmin":0.2143},{"hmax":0.05,"hmin":0,"vmax":0.3571,"vmin":0.2857},{"hmax":0.05,"hmin":0,"vmax":0.4286,"vmin":0.3571},{"hmax":0.05,"hmin":0,"vmax":0.5,"vmin":0.4286},{"hmax":0.05,"hmin":0,"vmax":0.5714,"vmin":0.5},{"hmax":0.05,"hmin":0,"vmax":0.6429,"vmin":0.5714},{"hmax":0.05,"hmin":0,"vmax":0.7143,"vmin":0.6429},{"hmax":0.05,"hmin":0,"vmax":0.7857,"vmin":0.7143},{"hmax":0.05,"hmin":0,"vmax":0.8571,"vmin":0.7857},{"hmax":0.05,"hmin":0,"vmax":0.9286,"vmin":0.8571},{"hmax":0.05,"hmin":0,"vmax":1,"vmin":0.9286}],"logger":{"level":"debug"},"network":{"apiAuth":false,"internetAccessAPI":false,"ipWhitelist":[],"localAdminAuth":false,"localApiAuth":false,"restirctedInternetAccessAPI":false},"protoServer":{"enable":false,"port":19445,"timeout":5},"smoothing":{"continuousOutput":true,"enable":true,"time_ms":200,"type":"linear","updateDelay":0,"updateFrequency":25},"webConfig":{"crtPath":"","document_root":"","keyPassPhrase":"","keyPath":"","port":8090,"sslPort":8092}}

< ----- Current Log --------------------------- >
2021-09-07T19:09:20.274Z [hyperiond DAEMON] (INFO) CEC handler created
2021-09-07T19:09:20.341Z [hyperiond EFFECTFILES] (INFO) 39 effects loaded from directory :/effects/
2021-09-07T19:09:20.344Z [hyperiond EFFECTFILES] (INFO) 22 effect schemas loaded from directory :/effects/schema/
2021-09-07T19:09:20.352Z [hyperiond EFFECTFILES] (INFO) 0 effects loaded from directory /home/hyperion/.hyperion/custom-effects/
2021-09-07T19:09:20.363Z [hyperiond SETTINGSMGR] (DEBUG) (SettingsManager.cpp:164:SettingsManager()) Settings database initialized
2021-09-07T19:09:20.364Z [hyperiond BLACKBORDER] (DEBUG) (BlackBorderProcessor.cpp:64:handleSettingsUpdate()) Set mode to: default
2021-09-07T19:09:20.364Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Blackborder detector: enabled
2021-09-07T19:09:20.482Z [hyperiond DAEMON] (INFO) set screen capture device to 'xcb'
2021-09-07T19:09:20.482Z [hyperiond XCBGRABBER] (INFO) Set image size decimation to 30
2021-09-07T19:09:20.482Z [hyperiond DAEMON] (INFO) XCB grabber created
2021-09-07T19:09:20.488Z [hyperiond DAEMON] (DEBUG) (hyperiond.cpp:608:handleSettingsUpdate()) V4L2 grabber created
2021-09-07T19:09:20.493Z [hyperiond JSONSERVER] (DEBUG) (JsonServer.cpp:28:JsonServer()) Created instance
2021-09-07T19:09:20.520Z [hyperiond JSONSERVER] (INFO) Started on port 19444
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (INFO) Start LedDevice 'adalight'.
2021-09-07T19:09:20.498Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Smoothing: enabled
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (LedDevice.cpp:148:init()) deviceConfig: [{"colorOrder":"rgb","currentLedCount":50,"delayAfterConnect":200,"hardwareLedCount":50,"latchTime":30,"lightberry_apa102_mode":false,"output":"ttyUSB0","rate":500000,"rewriteTime":1000,"type":"adalight"}]
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (LedDevice.cpp:413:setLatchTime()) LatchTime updated to 30ms
2021-09-07T19:09:20.498Z [hyperiond SMOOTHING] (DEBUG) (LinearColorSmoothing.cpp:701:selectConfig()) cfg [0]:  Type: linear - Time: 200 ms, outputRate 25.000000 Hz, interpolationRate: 25.000000 Hz, timer: 40 ms, Dithering: 0, Decay: 1.000000 -> HalfTime: 100.000000 ms
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (LedDevice.cpp:438:setRewriteTime()) Refresh interval = 1000ms
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (LedDevice.cpp:444:setRewriteTime()) RewriteTime updated to 1000ms
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:48:init()) DeviceType   : adalight
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:49:init()) LedCount     : 50
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:50:init()) ColorOrder   : rgb
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:51:init()) RefreshTime  : 1000
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:52:init()) LatchTime    : 30
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:73:init()) DeviceName   : ttyUSB0
2021-09-07T19:09:20.498Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:75:init()) AutoDevice   : 0
2021-09-07T19:09:20.499Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:76:init()) baudRate_Hz  : 500000
2021-09-07T19:09:20.499Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:77:init()) delayAfCon ms: 200
2021-09-07T19:09:20.499Z [hyperiond LEDDEVICE] (DEBUG) (LedDeviceAdalight.cpp:58:init()) Adalight header for 50 leds: Ada 0x00 0x31 0x64
2021-09-07T19:09:20.499Z [hyperiond SMOOTHING] (DEBUG) (LinearColorSmoothing.cpp:701:selectConfig()) Previous line repeats 1 times
2021-09-07T19:09:20.499Z [hyperiond LEDDEVICE] (INFO) Opening UART: ttyUSB0
2021-09-07T19:09:20.499Z [hyperiond FLATBUFCONN] (INFO) Connecting to Hyperion: 127.0.0.1:19401
2021-09-07T19:09:20.499Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:170:tryOpen()) _rs232Port.open(QIODevice::ReadWrite): ttyUSB0, Baud rate [500000]bps
2021-09-07T19:09:20.500Z [hyperiond EFFECTENGINE] (INFO) Run effect "Rainbow swirl fast" on channel 1
2021-09-07T19:09:20.539Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:175:tryOpen()) portName:          ttyUSB0
2021-09-07T19:09:20.539Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:176:tryOpen()) systemLocation:    /dev/ttyUSB0
2021-09-07T19:09:20.539Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:177:tryOpen()) description:       FT232R USB UART
2021-09-07T19:09:20.539Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:178:tryOpen()) manufacturer:      FTDI
2021-09-07T19:09:20.539Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:179:tryOpen()) vendorIdentifier:  0x403
2021-09-07T19:09:20.539Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:180:tryOpen()) productIdentifier: 0x6001
2021-09-07T19:09:20.539Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:181:tryOpen()) serialNumber:      A98VVXTL
2021-09-07T19:09:20.546Z [hyperiond WEBSERVER] (DEBUG) (WebServer.cpp:33:initServer()) Initialize Webserver
2021-09-07T19:09:20.545Z [hyperiond WEBSERVER] (DEBUG) (WebServer.cpp:33:initServer()) Initialize Webserver
2021-09-07T19:09:20.564Z [hyperiond WEBSERVER] (DEBUG) (WebServer.cpp:91:handleSettingsUpdate()) Apply Webserver settings
2021-09-07T19:09:20.564Z [hyperiond WEBSERVER] (DEBUG) (WebServer.cpp:109:handleSettingsUpdate()) Set document root to: :/webconfig
2021-09-07T19:09:20.590Z [hyperiond WEBSERVER] (DEBUG) (WebServer.cpp:91:handleSettingsUpdate()) Apply Webserver settings
2021-09-07T19:09:20.591Z [hyperiond WEBSERVER] (DEBUG) (WebServer.cpp:175:handleSettingsUpdate()) Setup SSL certificate
2021-09-07T19:09:20.592Z [hyperiond WEBSERVER] (DEBUG) (WebServer.cpp:191:handleSettingsUpdate()) Setup private SSL key
2021-09-07T19:09:20.592Z [hyperiond EFFECTENGINE] (DEBUG) (EffectEngine.cpp:181:runEffectScript()) Start the effect: name [Rainbow swirl fast], smoothCfg [2]
2021-09-07T19:09:20.592Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:165:registerInput()) Register new input 'System/EFFECT' with priority 1 as inactive
2021-09-07T19:09:20.592Z [hyperiond HYPERION] (INFO) Initial foreground effect 'Rainbow swirl fast' started
2021-09-07T19:09:20.595Z [hyperiond EFFECTENGINE] (INFO) Run effect "Candle" on channel 254
2021-09-07T19:09:20.595Z [hyperiond EFFECTENGINE] (DEBUG) (EffectEngine.cpp:181:runEffectScript()) Start the effect: name [Candle], smoothCfg [2]
2021-09-07T19:09:20.591Z [hyperiond WEBSERVER] (DEBUG) (WebServer.cpp:109:handleSettingsUpdate()) Set document root to: :/webconfig
2021-09-07T19:09:20.595Z [hyperiond WEBSERVER] (INFO) Started on port 8090 name 'Hyperion Webserver'
2021-09-07T19:09:20.596Z [hyperiond WEBSERVER] (INFO) Started on port 8092 name 'Hyperion Webserver'
2021-09-07T19:09:20.595Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:165:registerInput()) Register new input 'System/EFFECT' with priority 254 as inactive
2021-09-07T19:09:20.596Z [hyperiond HYPERION] (INFO) Initial background effect 'Candle' started
2021-09-07T19:09:20.596Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:165:registerInput()) Register new input 'System/GRABBER' with priority 199 as inactive
2021-09-07T19:09:20.596Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Framegrabber: enabled
2021-09-07T19:09:20.597Z [hyperiond XCB] (DEBUG) (GrabberWrapper.cpp:62:start()) Grabber start()
2021-09-07T19:09:20.597Z [hyperiond BOBLIGHT] (DEBUG) (BoblightServer.cpp:28:BoblightServer()) Instance created
2021-09-07T19:09:20.598Z [hyperiond HYPERION] (INFO) Hyperion instance 'First LED Hardware instance' has been started
2021-09-07T19:09:24.311Z [hyperiond XCBGRABBER] (INFO) XcbRandR=[available] XcbRender=[available] XcbShm=[available] XcbPixmap=[available]
2021-09-07T19:09:24.311Z [hyperiond XCBGRABBER] (INFO) Update of screen resolution: [0x0]  to [3840x2160]
2021-09-07T19:09:24.311Z [hyperiond XCBGRABBER] (INFO) Using XcbRender for grabbing [128x72]
2021-09-07T19:09:24.313Z [hyperiond XCBGRABBER] (INFO) Capture interface is now enabled
2021-09-07T19:09:20.695Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:212:tryOpen()) delayAfterConnect for 200 ms - start
2021-09-07T19:09:20.879Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:271:setInputImage()) Priority 1 is now active
2021-09-07T19:09:20.879Z [hyperiond HYPERION] (DEBUG) (BGEffectHandler.h:91:handlePriorityUpdate()) Stop background (color-) effect as it moved out of scope
2021-09-07T19:09:20.879Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:292:clearInput()) Removed source priority 254
2021-09-07T19:09:20.879Z [hyperiond EFFECTENGINE] (INFO) Run effect "Candle" on channel 254
2021-09-07T19:09:20.880Z [hyperiond EFFECTENGINE] (DEBUG) (EffectEngine.cpp:181:runEffectScript()) Start the effect: name [Candle], smoothCfg [2]
2021-09-07T19:09:20.880Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:165:registerInput()) Register new input 'System/EFFECT' with priority 254 as inactive
2021-09-07T19:09:20.880Z [hyperiond HYPERION] (INFO) Initial background effect 'Candle' started
2021-09-07T19:09:20.880Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:374:setCurrentTime()) Set visible priority to 1
2021-09-07T19:09:20.880Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:559:handlePriorityChangedLedDevice()) priority[1], previousPriority[255]
2021-09-07T19:09:20.880Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:569:handlePriorityChangedLedDevice()) new source available -> switch LED-Device on
2021-09-07T19:09:20.880Z [hyperiond HYPERION] (DEBUG) (BGEffectHandler.h:91:handlePriorityUpdate()) Stop background (color-) effect as it moved out of scope
2021-09-07T19:09:20.880Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:292:clearInput()) Removed source priority 254
2021-09-07T19:09:20.896Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:219:tryOpen()) delayAfterConnect for 200 ms - finished
2021-09-07T19:09:20.896Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) LED device: enabled
2021-09-07T19:09:20.897Z [hyperiond SMOOTHING] (DEBUG) (LinearColorSmoothing.cpp:701:selectConfig()) cfg [2]:  Type: linear - Time: 200 ms, outputRate 25.000000 Hz, interpolationRate: 25.000000 Hz, timer: 40 ms, Dithering: 0, Decay: 1.000000 -> HalfTime: 100.000000 ms
2021-09-07T19:09:20.907Z [hyperiond EFFECTENGINE] (INFO) effect finished
2021-09-07T19:09:23.926Z [hyperiond EFFECTENGINE] (INFO) Previous line repeats 2 times
2021-09-07T19:09:23.926Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:337:setCurrentTime()) Timeout clear for priority 1
2021-09-07T19:09:23.926Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:374:setCurrentTime()) Set visible priority to 255
2021-09-07T19:09:23.926Z [hyperiond SMOOTHING] (DEBUG) (LinearColorSmoothing.cpp:701:selectConfig()) cfg [0]:  Type: linear - Time: 200 ms, outputRate 25.000000 Hz, interpolationRate: 25.000000 Hz, timer: 40 ms, Dithering: 0, Decay: 1.000000 -> HalfTime: 100.000000 ms
2021-09-07T19:09:23.926Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:559:handlePriorityChangedLedDevice()) priority[255], previousPriority[1]
2021-09-07T19:09:23.926Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:562:handlePriorityChangedLedDevice()) No source left -> switch LED-Device off
2021-09-07T19:09:23.926Z [hyperiond EFFECTENGINE] (INFO) Run effect "Candle" on channel 254
2021-09-07T19:09:23.927Z [hyperiond EFFECTENGINE] (DEBUG) (EffectEngine.cpp:181:runEffectScript()) Start the effect: name [Candle], smoothCfg [2]
2021-09-07T19:09:23.927Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:165:registerInput()) Register new input 'System/EFFECT' with priority 254 as inactive
2021-09-07T19:09:23.927Z [hyperiond HYPERION] (INFO) Initial background effect 'Candle' started
2021-09-07T19:09:23.985Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:220:setInput()) Priority 254 is now active
2021-09-07T19:09:23.985Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:374:setCurrentTime()) Set visible priority to 254
2021-09-07T19:09:23.986Z [hyperiond SMOOTHING] (DEBUG) (LinearColorSmoothing.cpp:701:selectConfig()) cfg [2]:  Type: linear - Time: 200 ms, outputRate 25.000000 Hz, interpolationRate: 25.000000 Hz, timer: 40 ms, Dithering: 0, Decay: 1.000000 -> HalfTime: 100.000000 ms
2021-09-07T19:09:23.986Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:559:handlePriorityChangedLedDevice()) priority[254], previousPriority[255]
2021-09-07T19:09:23.987Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:569:handlePriorityChangedLedDevice()) new source available -> switch LED-Device on
2021-09-07T19:09:24.381Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:271:setInputImage()) Priority 199 is now active
2021-09-07T19:09:24.381Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:374:setCurrentTime()) Set visible priority to 199
2021-09-07T19:09:24.381Z [hyperiond SMOOTHING] (DEBUG) (LinearColorSmoothing.cpp:701:selectConfig()) cfg [0]:  Type: linear - Time: 200 ms, outputRate 25.000000 Hz, interpolationRate: 25.000000 Hz, timer: 40 ms, Dithering: 0, Decay: 1.000000 -> HalfTime: 100.000000 ms
2021-09-07T19:09:24.381Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:559:handlePriorityChangedLedDevice()) priority[199], previousPriority[254]
2021-09-07T19:09:24.382Z [hyperiond HYPERION] (DEBUG) (BGEffectHandler.h:91:handlePriorityUpdate()) Stop background (color-) effect as it moved out of scope
2021-09-07T19:09:24.382Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:292:clearInput()) Removed source priority 254
2021-09-07T19:09:24.393Z [hyperiond EFFECTENGINE] (INFO) effect finished
2021-09-07T19:10:15.740Z [hyperiond WEBSOCKET] (DEBUG) (WebSocketClient.cpp:30:WebSocketClient()) New connection from ::ffff:192.168.1.12
2021-09-07T19:10:15.740Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:122:handleInstanceSwitch()) Client '::ffff:192.168.1.12' switch to Hyperion instance 0
2021-09-07T19:10:17.318Z [hyperiond WEBSOCKET] (DEBUG) (WebSocketClient.cpp:30:WebSocketClient()) New connection from ::ffff:192.168.1.12
2021-09-07T19:10:17.318Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:122:handleInstanceSwitch()) Client '::ffff:192.168.1.12' switch to Hyperion instance 0
2021-09-07T19:10:27.821Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:50:handleCompStateChangeRequest()) Disable Hyperion, store current component states
2021-09-07T19:10:27.821Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Hyperion: disabled
2021-09-07T19:10:27.821Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Smoothing: disabled
2021-09-07T19:10:27.822Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Blackborder detector: disabled
2021-09-07T19:10:27.822Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:292:clearInput()) Removed source priority 199
2021-09-07T19:10:27.822Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:374:setCurrentTime()) Set visible priority to 255
2021-09-07T19:10:27.822Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:559:handlePriorityChangedLedDevice()) priority[255], previousPriority[199]
2021-09-07T19:10:27.823Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:562:handlePriorityChangedLedDevice()) No source left -> switch LED-Device off
2021-09-07T19:10:27.823Z [hyperiond EFFECTENGINE] (INFO) Run effect "Candle" on channel 254
2021-09-07T19:10:27.823Z [hyperiond EFFECTENGINE] (DEBUG) (EffectEngine.cpp:181:runEffectScript()) Start the effect: name [Candle], smoothCfg [2]
2021-09-07T19:10:27.823Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:165:registerInput()) Register new input 'System/EFFECT' with priority 254 as inactive
2021-09-07T19:10:27.824Z [hyperiond HYPERION] (INFO) Initial background effect 'Candle' started
2021-09-07T19:10:27.825Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Framegrabber: disabled
2021-09-07T19:10:27.893Z [hyperiond XCB] (DEBUG) (GrabberWrapper.cpp:76:stop()) Grabber stop()
2021-09-07T19:10:27.825Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:115:close()) Flush was successful
2021-09-07T19:10:27.825Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:117:close()) Close UART: ttyUSB0
2021-09-07T19:10:27.833Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) LED device: disabled
2021-09-07T19:10:27.855Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:238:writeBytes()) !_rs232Port.isOpen()
2021-09-07T19:10:27.855Z [hyperiond LEDDEVICE] (INFO) Opening UART: ttyUSB0
2021-09-07T19:10:27.855Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:170:tryOpen()) _rs232Port.open(QIODevice::ReadWrite): ttyUSB0, Baud rate [500000]bps
2021-09-07T19:10:27.918Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:175:tryOpen()) portName:          ttyUSB0
2021-09-07T19:10:27.918Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:176:tryOpen()) systemLocation:    /dev/ttyUSB0
2021-09-07T19:10:27.918Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:177:tryOpen()) description:       FT232R USB UART
2021-09-07T19:10:27.918Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:178:tryOpen()) manufacturer:      FTDI
2021-09-07T19:10:27.919Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:179:tryOpen()) vendorIdentifier:  0x403
2021-09-07T19:10:27.919Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:180:tryOpen()) productIdentifier: 0x6001
2021-09-07T19:10:27.919Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:181:tryOpen()) serialNumber:      A98VVXTL
2021-09-07T19:10:27.928Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:212:tryOpen()) delayAfterConnect for 5000 ms - start
2021-09-07T19:10:27.941Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:220:setInput()) Priority 254 is now active
2021-09-07T19:10:27.941Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:374:setCurrentTime()) Set visible priority to 254
2021-09-07T19:10:27.941Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:559:handlePriorityChangedLedDevice()) priority[254], previousPriority[255]
2021-09-07T19:10:27.941Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:569:handlePriorityChangedLedDevice()) new source available -> switch LED-Device on
2021-09-07T19:10:33.181Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:219:tryOpen()) delayAfterConnect for 5000 ms - finished
2021-09-07T19:14:30.647Z [hyperiond WEBSOCKET] (DEBUG) (WebSocketClient.cpp:30:WebSocketClient()) New connection from ::ffff:192.168.1.12
2021-09-07T19:14:30.648Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:122:handleInstanceSwitch()) Client '::ffff:192.168.1.12' switch to Hyperion instance 0
2021-09-07T20:14:12.083Z [hyperiond WEBSOCKET] (DEBUG) (WebSocketClient.cpp:215:sendClose()) send close: 1000 
2021-09-07T20:14:12.954Z [hyperiond WEBSOCKET] (DEBUG) (WebSocketClient.cpp:30:WebSocketClient()) New connection from ::ffff:192.168.1.12
2021-09-07T20:14:12.954Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:122:handleInstanceSwitch()) Client '::ffff:192.168.1.12' switch to Hyperion instance 0
2021-09-07T20:14:32.191Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:1058:handleLoggingCommand()) log streaming activated for client ::ffff:192.168.1.12
2021-09-07T20:15:13.986Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:67:handleCompStateChangeRequest()) Enable Hyperion, recover previous component states
2021-09-07T20:15:13.986Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Hyperion: enabled
2021-09-07T20:15:13.987Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Smoothing: enabled
2021-09-07T20:15:13.987Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Blackborder detector: enabled
2021-09-07T20:15:13.987Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:165:registerInput()) Register new input 'System/GRABBER' with priority 199 as inactive
2021-09-07T20:15:13.987Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) Framegrabber: enabled
2021-09-07T20:15:13.988Z [hyperiond XCB] (DEBUG) (GrabberWrapper.cpp:62:start()) Grabber start()
2021-09-07T20:15:13.988Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:212:tryOpen()) delayAfterConnect for 200 ms - start
2021-09-07T20:15:14.189Z [hyperiond LEDDEVICE] (DEBUG) (ProviderRs232.cpp:219:tryOpen()) delayAfterConnect for 200 ms - finished
2021-09-07T20:15:14.189Z [hyperiond COMPONENTREG] (DEBUG) (ComponentRegister.cpp:36:setNewComponentState()) LED device: enabled
2021-09-07T20:15:14.190Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:271:setInputImage()) Priority 199 is now active
2021-09-07T20:15:14.190Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:374:setCurrentTime()) Set visible priority to 199
2021-09-07T20:15:14.190Z [hyperiond HYPERION] (DEBUG) (Hyperion.cpp:559:handlePriorityChangedLedDevice()) priority[199], previousPriority[254]
2021-09-07T20:15:14.190Z [hyperiond HYPERION] (DEBUG) (BGEffectHandler.h:91:handlePriorityUpdate()) Stop background (color-) effect as it moved out of scope
2021-09-07T20:15:14.191Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:292:clearInput()) Removed source priority 254
2021-09-07T20:15:14.191Z [hyperiond HYPERION] (ERROR) setInput() used without registerInput() for priority '254', probably the priority reached timeout
2021-09-07T20:15:14.383Z [hyperiond EFFECTENGINE] (INFO) effect finished
2021-09-07T20:15:16.024Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:1067:handleLoggingCommand()) log streaming deactivated for client  ::ffff:192.168.1.12
2021-09-07T20:15:16.024Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:1058:handleLoggingCommand()) log streaming activated for client ::ffff:192.168.1.12
2021-09-07T20:15:16.024Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:1058:handleLoggingCommand()) log streaming activated for client ::ffff:192.168.1.12

fightforlife commented 3 years ago

Is there something else I can provide to aanlyse this?

fightforlife commented 3 years ago

I fixed it by installing Kodi by following the following guide: https://forum.kodi.tv/showthread.php?tid=231955 I am not sure what the problem was. Maybe something regarding HW acceleration.

fightforlife commented 1 year ago

For anyone finding this, I am still fighting with this problem.

Edit> Maybe found the solution:

If I tell xorg xserver to use the intel driver it works with very low CPu consumpion:

/etc/X11/xorg.conf.d/xorg.conf 10-intel.conf

Section "Device"
        Identifier "Intel"
        Driver "intel"
#       Option "AccelMethod" "uxa"
EndSection

hyperion-project / hyperion.ng