[mythtv-users] Many instances of mythlogserver running and taking up 98% of CPU

[Matthias.myth]

Am 02.12.2012 18:21, schrieb Bill Meek:
> On 12/02/2012 06:32 AM, Matthias.myth wrote:
>
> Hi;
>
> Summary; there are things below that can make the logging easier to 
> read, but
> the key issue is the multiple copies and abnormally high CPU usage. So 
> far, I
> don't see the answer to that.
>
> Comments in line.
>
>> thanks for your reply. I had read the entry in the wiki, but I did 
>> not really get much out of it.
>
> Sorry to hear that.
>
> You'd asked how the logserver is started, which others have asked. The 
> answer is in
> the Wiki, and the reasons for starting/stopping are there too. The 
> Wiki doesn't
> address how the various distributions elect to do their logging. It 
> does have links
> to options that could be used.
>
>> I also have few lines in the syslog:
>>
>> Dec  2 07:45:41 **** mythlogserver: mythlogserver[27342]: I 
>> LogForward loggingserver.cpp:1310 (forwardMessage) New Client:
>> 0092bb6f0a51854f99bf1e98ee4adbdb2f (#4)
>> Dec  2 08:11:30 **** mythlogserver: mythlogserver[27342]: I 
>> LogForward loggingserver.cpp:1204 (expireClients) Expiring client
>> 0092bb6f0a51854f99bf1e98ee4adbdb2f (#3)
>
> These entries are generated by mythlogserver itself. In the above, 
> note "mythlogserver:",
> that's the program name. everything after the ":" is the message for 
> the logfile. This is
> normal for 0.26 using --syslog.
>
> There is a way around this. See: 
> http://www.mythtv.org/wiki/Simple_rsyslog_Configuration.
> Be sure to see the 0.26 version halfway down the page. I tested it and 
> it works. Stop
> your backend and kill the logserver (or wait for it to time out in 5 
> minutes.) Then
> restart the backend.
>
> Or, you can replace "--syslog local7" in your 
> /etc/init/mythbackend.conf file with
> "--logpath /var/log/mythtv".
>
> I wouldn't suggest changing now, just had to write it for completeness.
>
>> But I have many lines in /var/log/mythtv/mythbackend.log, see at the 
>> end of this message.
>
> I deleted all but 1 line and moved it here:
>
> > Dec  2 11:02:28 ***** mythlogserver: mythbackend[27816]: N Expire 
> autoexpire.cpp:264 .....
>
> The program making the log entry is mythlogserver, its client is 
> mythbackend. This is not a problem.
> The rsyslog solution just mentioned cleans this up.
>
> (Thanks for pasting without line wrapping, wish everyone would do that)
>
>> I have also read the page about logging in the wiki; but 
>> unfortunately, the distribution-dependant information is (obviously) 
>> not here. So I
>> have checked, and I can find in /etc/init/mythbackend.conf, how 
>> mythbackend is started:
>>
>> /usr/bin/mythbackend --syslog local7 --user mythtv
>
> Correct, that's the only place the backend sets the logging. Unless
> Mythbuntu uses a wrapper script for the backend. It doesn't look like
> it from the "top" output you posted. Unless you typed the command
> manually (not using sudo start mythtv-backend.)
>
> Remember, as in the mythlogserver Wiki, the 1st program to run will kick
> off the logserver. I have used "mythshutdown --lock --nodblog --quiet" in
> my own .profile and when starting the machine, mythshutdown ran before
> mythbackend, so the logging was based on the parameters passed to
> mythshutdown. Unusual, but it happened.
>
>> About how I was finding the multiple copies: I have been looking at top:
>>
>> root@*****:/home/mth# top
>> Cpu(s): 96.7%us,  2.6%sy,  0.0%ni,  0.0%id,  0.0%wa, 0.0%hi, 0.7%si, 
>> 0.0%st
>>    PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM TIME+ COMMAND
>>   1416 mythtv    20   0  202m  27m 2972 R  182  1.3 929:39.28 
>> mythlogserver
>> 27816 mythtv    20   0  516m  32m 6380 S    2  1.6 64:25.29 mythbackend
>> 15787 myth      20   0 1300m 537m  28m S    1 26.7 235:04.10 
>> mythfrontend.re
>> 27342 mythtv    20   0  326m 2500 1756 S    1  0.1 13:24.32 
>> mythlogserver
> ...
>>
>> You can see that at this moment, I have one process of mythlogserver 
>> going to 200%, if it can, and one with 1% CPU. That was different the 
>> last
>> times I looked, the crazy one would only go to 100%.... -> ?
>
> Now to the important part of your post. With the above and the next 
> ps, you should
> be able to look in your log files (both /var/log/syslog for 
> mythlogserver and
> /var/log/mythtv/myth*.log for *anything* else) to see who is starting up
> mythlogserver.
>
>> ps ax | grep mythlog will give me 2, like top at this moment:
> >
>>   1416 ?        Rsl  932:20 /usr/bin/mythlogserver --daemon --verbose 
>> general --loglevel info --quiet --syslog local7
>> 10290 pts/8    S+     0:00 grep mythlog
>> 27342 ?        Ssl   13:25 /usr/bin/mythlogserver --daemon --verbose 
>> general --loglevel info --syslog local7
>
> Recall from the Wiki that logserver's logging options are inherited 
> from the program that
> starts it. By now you probably guessed that I wrote the Wiki ;)
>
> Note that in PID 1416 the options include --quiet, but in PID 27342 
> --quiet is gone.
> That suggests logserver was started by different programs. The 2nd 
> instance probably
> by the line in mythtv-backend.conf. The 1st, ???
>
>> but ps axH will give me 16.
>
> 16 is the same as I have, I said 17 in my  previous post, but forgot 
> to exclude "grep mythlog".
>
>> In the top list you can see that it is the mythlogserver with id 
>> 1416, the oder one, which goes crazy. I tried a "killall 
>> mythlogserver", both
>> instances were killed and now I have only one process left, id 22346. 
>> I notice that, according to the process id and the time, the instance 
>> that
>> went mad seems to be quite old... but I had killall'ed them 
>> yesterday, too, with the load going back to normal, so I am not sure 
>> what this means.
>
> Neither do I. I've never had more than one logserver running.
>
> I'd have expected to see "sudo killall...", unless you're running as root
> (which I *rarely* do) or mythtv. Both instances of the logserver are 
> owned
> by mythtv. When this happens again, try using "kill <theOldPidNumber>" 
> rather
> than "killall...".
>
> But, I'd still try to figure out what process is starting the "mad" 
> logserver by
> looking at the timestamps in all the logs as mentioned above. Look for 
> text like:
>
>     Logger logging.cpp:488 (launchLogServer) - Starting mythlogserver
>
> They could be in any /var/log/mythtv/myth*.log file. Although that 
> again depends
> on your distribution. If you have /etc/rsyslog.d/40-mythtv.conf or 
> something like
> it and want to use pastebinit <filename>, put the link in a response 
> here.
>

Hello Bill,

thank you very much for your help! If I do not get much information (or 
at least, not the information I expect) out of the wiki post, that is 
probably because I do not know enough about how things work in myth... 
sorry for sounding negative...

I have checked for "Starting mythlogserver" entries in 
/var/log/mythtv/*.log files, and there are many. What I see is that, 
just by quickly looking at the results, there are cases where it has 
been started twice within periods of a few seconds, or even twice in the 
same second:

mythpreviewgen.log:Nov 30 23:40:47 ***** mythlogserver: 
mythpreviewgen[19343]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver
mythpreviewgen.log:Nov 30 23:40:47 ***** mythlogserver: 
mythpreviewgen[19343]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver
mythpreviewgen.log:Nov 30 23:40:49 ***** mythlogserver: 
mythpreviewgen[19365]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver
mythpreviewgen.log:Nov 30 23:41:16 ***** mythlogserver: 
mythpreviewgen[19443]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver
mythpreviewgen.log:Nov 30 23:43:10 ***** mythlogserver: 
mythpreviewgen[19520]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver
mythpreviewgen.log:Dec  1 00:19:22 ***** mythlogserver: 
mythpreviewgen[19756]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver
mythpreviewgen.log:Dec  1 00:21:46 ***** mythlogserver: 
mythpreviewgen[19903]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver
... etc. and

mythmetadatalookup.log:Nov 23 17:01:33 ***** mythlogserver: 
mythmetadatalookup[3783]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver
mythmetadatalookup.log:Nov 23 17:01:33 ***** mythlogserver: 
mythmetadatalookup[3783]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver
or
mythmetadatalookup.log:Nov 28 17:40:03 ***** mythlogserver: 
mythmetadatalookup[25102]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver
mythmetadatalookup.log:Nov 28 17:40:03 ***** mythlogserver: 
mythmetadatalookup[25102]: I Logger logging.cpp:487 (launchLogServer) 
Starting mythlogserver

and

mythcommflag.log:Dec  1 05:18:52 ***** mythlogserver: 
mythcommflag[21726]: I Logger logging.cpp:487 (launchLogServer) Starting 
mythlogserver
mythcommflag.log:Dec  1 05:19:59 ***** mythlogserver: 
mythcommflag[21726]: I Logger logging.cpp:487 (launchLogServer) Starting 
mythlogserver
mythcommflag.log:Dec  1 05:20:56 ***** mythlogserver: 
mythcommflag[21726]: I Logger logging.cpp:487 (launchLogServer) Starting 
mythlogserver
mythcommflag.log:Dec  1 05:25:47 ***** mythlogserver: 
mythcommflag[21726]: I Logger logging.cpp:487 (launchLogServer) Starting 
mythlogserver
mythcommflag.log:Dec  1 05:27:47 ***** mythlogserver: 
mythcommflag[21726]: I Logger logging.cpp:487 (launchLogServer) Starting 
mythlogserver
mythcommflag.log:Dec  1 05:28:57 ***** mythlogserver: 
mythcommflag[21726]: I Logger logging.cpp:487 (launchLogServer) Starting 
mythlogserver
mythcommflag.log:Dec  1 05:32:57 ***** mythlogserver: 
mythcommflag[21726]: I Logger logging.cpp:487 (launchLogServer) Starting 
mythlogserver

and here

mythbackend.log:Dec  1 04:59:20 ***** mythlogserver: mythbackend[13933]: 
I Logger logging.cpp:487 (launchLogServer) Starting mythlogserver
mythbackend.log:Dec  1 04:59:43 ***** mythlogserver: mythbackend[13933]: 
I Logger logging.cpp:487 (launchLogServer) Starting mythlogserver
mythbackend.log:Dec  1 05:01:37 ***** mythlogserver: mythbackend[13933]: 
I Logger logging.cpp:487 (launchLogServer) Starting mythlogserver

That should not happen, if I understand the wiki entry correctly, right?

Right now, my server is happy, so I can't investigate more, will have to 
wait for mythlogserver instances going crazy again. Will post here!

Cheers,

Matthias