[mythtv-users] Getting slower

Tue Aug 18 22:01:29 UTC 2020

On 18/08/2020 22:09, Stuart Auchterlonie wrote:
> 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
> 

Acutally, looking at
https://code.mythtv.org/trac/ticket/12307#comment:11

we weren't checking to see if the user had disabled
the media monitor early enough, so it was still calling
out to dbus.

I've committed a fix to respect the user setting thereby
bypassing this check at startup, and backported it to
fixes/31. This should be in updated packages in the next
24hrs or so.

Regards
Stuart