[mythtv-users] Many instances of mythlogserver running and taking up 98% of CPU
Bill Meek
keemllib at gmail.com
Wed Dec 5 20:19:39 UTC 2012
On 12/05/2012 10:27 AM, Matthias wrote:
Full disclosure, Since there's an open ticket on this, I suspect the
problem is bigger than I can fix. But I'll try to answer questions.
If you want, locate one of the bad logservers, get its PID and type:
sudo gdb mythlogserver <PID> | tee -a /tmp/gdb.out
When gdb finishes printing, type:
thread apply all bt full
quit
Then pastebinit /tmp/gdb.out. That *may* give a clue where the
logserver is hung. However, you may need to load symbols for it
do be of any value. (http://www.mythtv.org/wiki/Debugging#Basic_backtrace)
I'm guessing that you haven't already done that.
Comments in line:
> 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.
You're right, the PID wraps at 65535, I believe, so by itself, the number doesn't
guarantee sequence (lots of other process could have started in between.)
> 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.
18406 with user myth, suggests that it was the frontend (if myth is your login)
and that its script/command line uses --syslog.
> 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?
The logserver itself does produce log messages (the ones you had seen in /var/log/syslog.)
I can't speak to the interference question, but I don't have a problem with it on my boxes.
I've seen no checks in the code related to logging option changes. But I could have easily
missed it.
> 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?
Yes, it does work, however, I believe when using rsyslog, the owner of
/var/log/mythtv isn't mythtv:mythtv. When you write "it does not work",
if that means no files were created, permissions would explain it. If
you want to experiment, create /var/log/mythtv-logpath and make its
owner and group mythtv mode, 664. Then use --logpath /var/log/mythtv-logpath.
While I prefer that level of logging, I'm not convinced, at all, that
it would solve this problem. Make sure your user can write to it too
(for when the frontend runs.)
> 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...
This (using SSD) is interesting. Before release, there were fixes on the commits list for
the logserver relating to a race condition and to multiple startups. Both were
fixed long before 0.26 hit the field. In whatever you "fiddled" with, can you
add additional delay. I use this before setting my lock:
for ATTEMPTS in $(seq 10); do
ps -C mythbackend 2>&1>/dev/null
if [ $? -ne 0 ]; then
echo "Sleeping 1 second to let the backend come up"
sleep 1
else
mythshutdown --nodblog --lock
break
fi
done
In my case, it usually ends up waiting 6 seconds.
> 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
...
deleted the 'good' one.
...
> 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
Interesting that the 'bad' PIDs have 4 threads each and not the 'normal' 16.
> You also suggested to poste my rsyslog.d/40-mythtv.conf:
> http://paste.ubuntu.com/1412771/
Thanks, that explains why you're seeing mythlogserver entries in /var/log/syslog. The
2nd half of http://www.mythtv.org/wiki/Simple_rsyslog_Configuration has the 0.26+
version of that file. Although I don't use it, I did test it as have others on this
list. It removes the "mythlogserver:" part of the confusing "mythlogserver: mythbackend:"
text (for all programs.) Stop everything myth*, replace the file and restart rsyslog then
MythTV.
> 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?
You started out with that. The only difference I saw was --quiet when some process
was started, probably by the backend. If you wanted to prove that, add -v system to
your mythtv-backend.conf file.
If the startup script for the backend and the script/command line for the frontend have the
same logging options, your logging will be the same, *unless* some other command runs 1st.
For example the case I cited where I ran mythshutdown --lock run before the backend started (with
different options.)
You've found where to set the backend options.
I suspect if you type: locate -b '\mythfrontend', you'll find it in /usr/bin/mythfrontend.
And, if you ls -ld on the file it will be a symbolic link to /usr/share/mythtv/mythfrontend.sh.
There, the logging is fixed at --syslog local7. So if you wanted both the same, then you'd
need to edit that file. For example, changing --syslog local7 to --logpath /var/log/mythtv-logpath.
--
Bill
More information about the mythtv-users
mailing list