[mythtv-users] Getting slower

Tue Aug 18 21:09:23 UTC 2020

On 09/08/2020 05:12, DaveD wrote:
> On 8/2/20 4:00 PM, jam at tigger.ws wrote:
>> Over the last few releases mythtv has got slower to start and stop.
>> What is the delay looking for ipv6 dtuff?
>>
>> This trace is from my mac frontrnd, my linux frontend start is
>> similar, the stop takes 3 sec.
>>
>> If the issue is not my config should we not gently think about start
>> and stop times from a dev point of view?
>>
>> James
>>
>> 00.730068 I  Setup Interrupt: 2 handler
>> 00.730091 I  Setup Terminated: 15 handler
>> 00.730098 I  Setup Segmentation fault: 11 handler
>> 00.730104 I  Setup Abort trap: 6 handler
>> 00.730109 I  Setup Bus error: 10 handler
>> 00.730115 I  Setup Floating point exception: 8 handler
>> 00.730123 I  Setup Illegal instruction: 4 handler
>> 00.730130 I  Setup User defined signal 1: 30 handler
>> 00.730137 I  Setup User defined signal 2: 31 handler
>> .....
> 
> I finally caught a slow startup (my wife usually has it started by the
> time I get to it) and here's the frontend output:
> 
>> /usr/bin/mythfrontend --loglevel warning -O PowerOffTVOnExit=0 -O
> libCECEnabled=0 -geometry 1920x1080+1920+0
> qt.core.logging: Ignoring malformed logging rule: '’*.debug=false’'
> "Display: Requesting EGL for 'Mesa Project, 1.4'"
> 2020-08-08 20:44:32.526210 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup Interrupt handler
> 2020-08-08 20:44:32.526259 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup Terminated handler
> 2020-08-08 20:44:32.526288 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup Segmentation fault handler
> 2020-08-08 20:44:32.526300 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup Aborted handler
> 2020-08-08 20:44:32.526311 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup Bus error handler
> 2020-08-08 20:44:32.526321 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup Floating point exception
> handler
> 2020-08-08 20:44:32.526344 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup Illegal instruction handler
> 2020-08-08 20:44:32.526358 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup Real-time signal 0 handler
> 2020-08-08 20:44:32.526378 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup User defined signal 1
> handler
> 2020-08-08 20:44:32.526387 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup User defined signal 2
> handler
> 2020-08-08 20:44:32.526402 I [2264517/2264517] thread_unknown
> signalhandling.cpp:191:SetHandlerPrivate  Setup Hangup handler
> 2020-08-08 20:44:32.526587 C [2264517/2264517] thread_unknown
> mythcommandlineparser.cpp:2602:ConfigureLogging  mythfrontend version:
> fixes/31 [v31.0-v31.0-47-gfc90482281] www.mythtv.org
> 2020-08-08 20:44:32.526606 C [2264517/2264517] thread_unknown
> mythcommandlineparser.cpp:2606:ConfigureLogging  Qt version: compile:
> 5.13.2, runtime: 5.13.2
> 2020-08-08 20:44:32.526669 I [2264517/2264517] thread_unknown
> mythcommandlineparser.cpp:2608:ConfigureLogging  Fedora 31 (Workstation
> Edition) (x86_64)
> 2020-08-08 20:44:32.526674 N [2264517/2264517] thread_unknown
> mythcommandlineparser.cpp:2610:ConfigureLogging  Enabled verbose msgs: 
> general
> 2020-08-08 20:44:32.863781 E [2264517/2264517] CoreContext
> mythdb.cpp:181:DBError  DB Error (StorageGroup::StorageGroup()):
> Query was:
> 
> Driver error was [1/]:
> Driver not loaded
> Database error was:
> Driver not loaded
> 
> 2020-08-08 20:44:32.969563 E [2264517/2264517] CoreContext
> serverpool.cpp:550:bind  Failed binding to UDP [::]:0 - Error 10:
> Protocol type not supported
> libEGL warning: FIXME: egl/x11 doesn't support front buffer rendering.
> 2020-08-08 20:44:37.078916 E [2264517/2264517] CoreContext
> serverpool.cpp:427:listen  Failed listening on TCP [::]:6547 - Error 10:
> Protocol type not supported
> libva info: VA-API version 1.6.0
> libva info: Trying to open /usr/lib64/dri/i965_drv_video.so
> libva info: Found init function __vaDriverInit_1_6
> libva info: va_openDriver() returns 0
> libva info: VA-API version 1.6.0
> libva info: Trying to open /usr/lib64/dri/i965_drv_video.so
> libva info: Found init function __vaDriverInit_1_6
> libva info: va_openDriver() returns 0
> Cannot load libcuda.so.1
> 
> The above lines come out very quickly, then the hard drive thrashes for
> a long time before the next line comes up and the menu appears on the
> screen.  The difference between the timestamps (20:44:37 to 20:45:25) is
> pretty much the time the hard drive is working (48 secs).
> 
> 2020-08-08 20:45:25.153977 A [2264517/2264517] CoreContext
> mediamonitor-unix.cpp:204:CheckMountable  MMUnix:CheckMountable: DBus
> interface error: The name is not activatable
> 2020-08-08 20:45:25.155653 W [2264517/2264517] CoreContext
> mediamonitor-unix.cpp:212:CheckMountable  MMUnix:UDisks2 service found.
> Media Monitor does not support this yet!
> 2020-08-08 20:45:25.204403 W [2264517/2264517] CoreContext
> mythplugin.cpp:110:MythPluginManager  No libraries in plugins directory
> /usr/lib64/mythtv/plugins
> 
> All is normal after that.  Should I increase the verbosity?  Will it
> tell me what's going on during all that hard drive activity? After this
> startup, I exited and re-ran the frontend and it was ready to go in
> about 6 seconds.  Here's that output:
> 
> 2020-08-08 20:50:11.231130 I [2265508/2265508] thread_unknown
> mythcommandlineparser.cpp:2608:ConfigureLogging  Fedora 31 (Workstation
> Edition) (x86_64)
> 2020-08-08 20:50:11.231131 N [2265508/2265508] thread_unknown
> mythcommandlineparser.cpp:2610:ConfigureLogging Enabled verbose msgs: 
> general
> 2020-08-08 20:50:11.341611 E [2265508/2265508] CoreContext
> mythdb.cpp:181:DBError  DB Error (StorageGroup::StorageGroup()):
> Query was:
> 
> Driver error was [1/]:
> Driver not loaded
> Database error was:
> Driver not loaded
> 
> 2020-08-08 20:50:11.388052 E [2265508/2265508] CoreContext
> serverpool.cpp:550:bind  Failed binding to UDP [::]:0 - Error 10:
> Protocol type not supported
> libEGL warning: FIXME: egl/x11 doesn't support front buffer rendering.
> 2020-08-08 20:50:14.259651 E [2265508/2265508] CoreContext
> serverpool.cpp:427:listen  Failed listening on TCP [::]:6547 - Error 10:
> Protocol type not supported
> libva info: VA-API version 1.6.0
> libva info: Trying to open /usr/lib64/dri/i965_drv_video.so
> libva info: Found init function __vaDriverInit_1_6
> libva info: va_openDriver() returns 0
> libva info: VA-API version 1.6.0
> libva info: Trying to open /usr/lib64/dri/i965_drv_video.so
> libva info: Found init function __vaDriverInit_1_6
> libva info: va_openDriver() returns 0
> Cannot load libcuda.so.1
> 2020-08-08 20:50:17.821604 A [2265508/2265508] CoreContext
> mediamonitor-unix.cpp:204:CheckMountable MMUnix:CheckMountable: DBus
> interface error: The name is not activatable
> 2020-08-08 20:50:17.822071 W [2265508/2265508] CoreContext
> mediamonitor-unix.cpp:212:CheckMountable MMUnix:UDisks2 service found.
> Media Monitor does not support this yet!
> 
> Same output, very different startup time.  What's the difference?
> 

Right, I know what is going on here.

The first time it starts up, it's trying to connect via DBus to the
service "org.freedesktop.UDisks" which fails to activate.

"CheckMountable MMUnix:CheckMountable: DBus interface error: The name is
not activatable" <-- That's the error. Code is here [1]

The second time through, DBus knows the service can't be activated
(or caches the result of the first time), and returns quickly with
the activation failure.

Regarding these DBus endpoints. UDisks is so old, it's deprecation
notice now has mold on it. UDisks2 is newer, but nobody has been
sufficiently interested to write support for it.

Anyway, I suspect that your system(s) still advertise UDisks via
DBus and it is trying this that takes the time. Please send the
output of the following command

$ dbus-send --system --print-reply --dest=org.freedesktop.DBus
/org/freedesktop/DBus org.freedesktop.DBus.ListNames | grep
org.freedesktop.UDisks

Regards
Stuart

[1] -
https://github.com/MythTV/mythtv/blob/master/mythtv/libs/libmyth/mediamonitor-unix.cpp#L193

> Dave D.
> 
> 
> _______________________________________________
> mythtv-users mailing list
> mythtv-users at mythtv.org
> http://lists.mythtv.org/mailman/listinfo/mythtv-users
> http://wiki.mythtv.org/Mailing_List_etiquette
> MythTV Forums: https://forum.mythtv.org