[mythtv-users] Many instances of mythlogserver running and taking up 98% of CPU
Matthias
lists at thyroff.net
Wed Dec 5 16:27:16 UTC 2012
Am 05.12.2012 00:11, schrieb Bill Meek:
> On 12/04/2012 04:17 PM, Ross Boylan wrote:
>> I am having a similar problem with myth 0.26 on Debian, from Marillat's
>> repository. I currently have 52 mythlogserver processes according to ps
>> ax. The terminal from which I launched mythfrontend (which is not
>> running, and has not been running for 12 hours) shows repeated
>> launchings (small excerpt):
>>
>> 2012-12-03 23:15:24.033887 I Starting mythlogserver
>> 2012-12-03 23:15:54.058060 I Starting mythlogserver
>> 2012-12-03 23:16:24.035382 I Starting mythlogserver
>> 2012-12-03 23:16:54.067322 I Starting mythlogserver
>> 2012-12-03 23:17:24.002527 I Starting mythlogserver
>> 2012-12-03 23:17:54.071256 I Starting mythlogserver
>> 2012-12-03 23:18:54.034736 I Starting mythlogserver
>> 2012-12-03 23:19:24.045114 I Starting mythlogserver
>> 2012-12-03 23:19:54.022222 I Starting mythlogserver
>>
>>
>> I suspect this has something to do with the fact that I'm running in a
>> chroot.
>>
>> I do not see any actual logging in syslog or /var/log/mythtv except for
>> mythtranscode (/var/log/mythtv is on the host system since syslog goes
>> to the host syslog; I have updated rsyslog rules on the host to capture
>> myth).
>
> Hi;
>
> I just noticed these:
>
> http://ubuntuforums.org/showthread.php?t=2074184
> http://code.mythtv.org/trac/ticket/11230
>
> It may be of interest to see what logging options were selected
> by users with this failure. I don't have it and use the following:
>
> --logpath /var/log/mythtv --quiet --nodblog (default --loglevel of
> info)
>
> I did replace --logpath... with --syslog local7 when testing the 0.26
> update
> to the rsyslog Wiki and didn't see the problem.
>
> http://www.mythtv.org/wiki/Simple_rsyslog_Configuration
>
Hello Bill,
this morning I had one mythlogserver gone wild, had left it for analisis
in the afternoon, now I have two:
top - 16:31:27 up 3 days, 3:55, 3 users, load average: 3.86, 4.00, 3.81
Tasks: 322 total, 1 running, 319 sleeping, 0 stopped, 2 zombie
Cpu(s): 94.9%us, 2.8%sy, 1.7%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.6%si,
0.0%st
Mem: 2061452k total, 1939104k used, 122348k free, 25888k buffers
Swap: 8191996k total, 393596k used, 7798400k free, 724684k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2561 mythtv 20 0 202m 26m 1660 S 95 1.3 40:34.45 mythlogserver
20396 mythtv 20 0 202m 1104 1104 S 80 0.1 1229:38 mythlogserver
2685 mythtv 37 17 306m 57m 4948 S 6 2.9 2:46.07 mythcommflag
30606 mth 20 0 85880 57m 3180 S 5 2.9 16:24.36 nxagent
7022 mythtv 20 0 577m 54m 5204 S 4 2.7 94:32.02 mythbackend
24058 myth 20 0 917m 341m 25m S 2 16.9 16:48.99 mythfrontend.re
18046 myth 20 0 318m 2236 1300 S 1 0.1 47:58.08 mythlogserver
30270 nx 20 0 12024 1548 648 S 1 0.1 2:13.44 sshd
The PID 2561 is the one that came after 20396. Does the PID say anything
about the age of the process? I thought the PID would just be counted
up, but mythcommflag is definetely a newer process than the
mythlogserver with 20396. OK, appearently not.
2561 ? Ssl 43:00 /usr/bin/mythlogserver --daemon --verbose
general --logpath /var/log/mythtv --loglevel info --quiet
2918 pts/6 S+ 0:00 grep mythlogserver
18046 ? Ssl 47:59 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
20396 ? Ssl 1231:59 /usr/bin/mythlogserver --daemon --verbose
general --logpath /var/log/mythtv --loglevel info --quiet
About the logging options: I have changed to use the --logpath option in
the /etc/init/mythbackend.conf file. This indicates loosely, that the
"healthy" mythlogserver is started by somebody else, and the two mad
ones by the backend. It is not a proof for anything, but I have never
seen the situation with mythlogserver going wild with all processes with
the same options.
This makes me ask, why do we need logging options in the mythlogserver
process? Logging options are controlled by the individual myth
applications, is there not a risk of interference if the mythlogserver
also has his settings (inherited at a startup earlier on)? Is it
necessary to start a new logging thread when (1) no one is running and
(2) the one that is running has the wrong logging options?
OK, see the output of
root@*****:/var/log/mythtv# grep "Starting mythlogserver" *.log | grep
"Dec 5"
root@*****:/var/log/mythtv#
Exactly, none for today... ??? Likewise, none for yesterday, just
root@*****:/var/log/mythtv# grep "Starting mythlogserver" *.log | grep
"Dec 3"
mythbackend.log:Dec 3 00:35:48 ***** mythlogserver: mythbackend[1875]:
I Logger logging.cpp:487 (launchLogServer) Starting mythlogserver
mythcommflag.log:Dec 3 00:35:47 ***** mythlogserver:
mythcommflag[15197]: I Logger logging.cpp:487 (launchLogServer) Starting
mythlogserver
mythcommflag.log:Dec 3 00:35:48 ***** mythlogserver:
mythcommflag[16432]: I Logger logging.cpp:487 (launchLogServer) Starting
mythlogserver
mythcommflag.log:Dec 3 19:07:34 ***** mythlogserver:
mythcommflag[26561]: I Logger logging.cpp:487 (launchLogServer) Starting
mythlogserver
mythfrontend.log:Dec 3 00:35:47 ***** mythlogserver:
mythfrontend[6364]: I Logger logging.cpp:487 (launchLogServer) Starting
mythlogserver
mythmetadatalookup.log:Dec 3 15:57:23 ***** mythlogserver:
mythmetadatalookup[25266]: I Logger logging.cpp:487 (launchLogServer)
Starting mythlogserver
mythpreviewgen.log:Dec 3 00:49:07 ***** mythlogserver:
mythpreviewgen[18298]: I Logger logging.cpp:487 (launchLogServer)
Starting mythlogserver
mythpreviewgen.log:Dec 3 00:55:32 ***** mythlogserver:
mythpreviewgen[18454]: I Logger logging.cpp:487 (launchLogServer)
Starting mythlogserver
root@*****:/var/log/mythtv#
No suprise, looking at the last line of mythbackend.log:
Dec 3 19:57:13 ***** mythlogserver: mythbackend[1875]: I CoreContext
mythcontext.cpp:1169 (~MythContext) Waiting for threads to exit.
Same in mythcommflag.log, mythpreviewgen.log, no logging since the day
before yesterday. But I did not have a bad mythlogserver process during
the day of yesterday (Dec 4)
The file modification date of /etc/init/mythtvbackend.conf is, btw
-rw-r--r-- 1 root root 620 Dez 3 19:40 /etc/init/mythtv-backend.conf
and it says
script
test -f /etc/default/locale && . /etc/default/locale || true
LANG=$LANG /usr/bin/mythbackend --logpath /var/log/mythtv
--user mythtv
end script
(the change I did at the time was changing --syslog local 7 for what it
says now. I am inclined to change it back because it does not work, but
it should work, should it not?
The processes logging on happily are mythfrontend and mythexport-daemon,
where the latter does not seem to log through mythlogserver, but the
former does:
24029 ? S 0:00 /bin/sh /usr/bin/mythfrontend --service
24058 ? Sl 17:24 /usr/bin/mythfrontend.real --syslog local7
The first process to run on my system should be mythbackend, but it also
might be mythfrontend... when I switched to an SSD root partition I had
to fiddle around to make sure mythbackend runs when the frontend tries
to connect, but it might be tight...
To be complete, here also this output:
bash-4.2$ ps axH | grep mythlog
2561 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --logpath /var/log/mythtv --loglevel info --quiet
2561 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --logpath /var/log/mythtv --loglevel info --quiet
2561 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --logpath /var/log/mythtv --loglevel info --quiet
2561 ? Rsl 72:53 /usr/bin/mythlogserver --daemon --verbose
general --logpath /var/log/mythtv --loglevel info --quiet
3189 pts/6 S+ 0:00 grep mythlog
18046 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 2:11 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 35:06 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:14 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:29 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:21 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:04 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 6:54 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:10 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:34 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 1:09 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:09 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
18046 ? Ssl 0:54 /usr/bin/mythlogserver --daemon --verbose
general --loglevel info --syslog local7
20396 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --logpath /var/log/mythtv --loglevel info --quiet
20396 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --logpath /var/log/mythtv --loglevel info --quiet
20396 ? Ssl 0:00 /usr/bin/mythlogserver --daemon --verbose
general --logpath /var/log/mythtv --loglevel info --quiet
20396 ? Rsl 1262:04 /usr/bin/mythlogserver --daemon --verbose
general --logpath /var/log/mythtv --loglevel info --quiet
You also suggested to poste my rsyslog.d/40-mythtv.conf:
http://paste.ubuntu.com/1412771/
I am just poking with a stick here - no way I see for me to troubleshoot
this problem. I am going to reset the backend logging options and kill
the crazy mythlogservers. Maybe I get a hint on when and by who the
logservers are triggered.
I think it might be a good idea to have uniform logging options on all
processes, but I do not know where to set that.
What do you think?
Best regards,
Matthias
More information about the mythtv-users
mailing list