[mythtv-users] Many instances of mythlogserver running and taking up 98% of CPU
Matthias.myth
mythtv at thyroff.net
Sun Dec 2 12:32:08 UTC 2012
Hello Bill,
thanks for your reply. I had read the entry in the wiki, but I did not
really get much out of it.
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)
But I have many lines in /var/log/mythtv/mythbackend.log, see at the end
of this message.
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
To be honest, I do not know why the backend also logs to
/var/log/mythbackend.log, and why that much. Is the mythbackend.conf the
only place where logging can be configured? Nothing in /etc/default,
where I looked, and nothing in /etc/mythtv, as far as I can tell. Where
can I configure the parameters that are listed in the ps output further
below? (--daemon --verbose general --loglevel info --syslog local 7 ...
sounds heavy! Also interesting that there are two different sets of
parameters.)
About how I was finding the multiple copies: I have been looking at top:
root@*****:/home/mth# top
top - 11:54:57 up 7 days, 15:53, 4 users, load average: 2.24, 2.18, 2.15
Tasks: 263 total, 3 running, 259 sleeping, 0 stopped, 1 zombie
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
Mem: 2061460k total, 1950672k used, 110788k free, 56524k buffers
Swap: 8191996k total, 694260k used, 7497736k free, 804696k cached
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
7240 root 20 0 8260 1980 1720 S 10 0.1 0:11.87 http
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
15831 myth 20 0 136m 7284 4568 S 1 0.4 0:27.02 update-notifier
27342 mythtv 20 0 326m 2500 1756 S 1 0.1 13:24.32 mythlogserver
5546 mth 20 0 4388 2028 1288 S 0 0.1 0:00.33 imapd
6659 root 20 0 4772 2176 1580 S 0 0.1 0:00.06 couriertls
6660 gnr 20 0 3932 1528 1292 S 0 0.1 0:00.02 imapd
6716 root 20 0 0 0 0 S 0 0.0 0:01.21 cx88[2] dvb
6723 root 20 0 0 0 0 S 0 0.0 0:00.85 cx88[1] dvb
7445 root 20 0 2856 1224 864 R 0 0.1 0:00.22 top
27846 root 20 0 0 0 0 S 0 0.0 3:53.01 kdvb-ad-2-fe-0
1 root 20 0 3796 1476 760 S 0 0.1 0:05.06 init
2 root 20 0 0 0 0 S 0 0.0 0:00.24 kthreadd
3 root 20 0 0 0 0 S 0 0.0 0:14.14 ksoftirqd/0
6 root RT 0 0 0 0 S 0 0.0 0:00.89 migration/0
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%.... -> ?
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
but ps axH will give me 16.
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.
Does this information help?
Thanks for looking at it!
Matthias
________________________________________________________________
Excerpt from mythbackend.log:
...
Dec 2 11:02:28 ***** mythlogserver: mythbackend[27816]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 1.0 GB w/freq: 15 min
Dec 2 11:03:52 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2128 (HandleReschedule) Reschedule requested for MATCH 0 0
0 - EITScanner
Dec 2 11:03:55 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2241 (HandleReschedule) Scheduled 260 items in 2.9 = 0.85
match + 1.45 check + 0.62 place
Dec 2 11:04:40 ***** mythlogserver: mythbackend[27816]: I HouseKeeping
housekeeper.cpp:221 (RunHouseKeeping) Running housekeeping thread
Dec 2 11:07:06 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2128 (HandleReschedule) Reschedule requested for MATCH 0 0
0 - EITScanner
Dec 2 11:07:09 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2241 (HandleReschedule) Scheduled 260 items in 3.1 = 1.05
match + 1.40 check + 0.63 place
Dec 2 11:09:41 ***** mythlogserver: mythbackend[27816]: I HouseKeeping
housekeeper.cpp:221 (RunHouseKeeping) Running housekeeping thread
Dec 2 11:11:11 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2128 (HandleReschedule) Reschedule requested for MATCH 0 0
0 - EITScanner
Dec 2 11:11:14 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2241 (HandleReschedule) Scheduled 260 items in 3.3 = 0.96
match + 1.65 check + 0.73 place
Dec 2 11:14:43 ***** mythlogserver: mythbackend[27816]: I HouseKeeping
housekeeper.cpp:221 (RunHouseKeeping) Running housekeeping thread
Dec 2 11:15:00 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2128 (HandleReschedule) Reschedule requested for MATCH 0 0
0 - EITScanner
Dec 2 11:15:03 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2241 (HandleReschedule) Scheduled 260 items in 3.1 = 1.02
match + 1.49 check + 0.55 place
Dec 2 11:17:28 ***** mythlogserver: mythbackend[27816]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 1.0 GB w/freq: 15 min
Dec 2 11:18:02 ***** mythlogserver: mythbackend[27816]: I SSDP
mythdbcon.cpp:409 (PurgeIdleConnections) New DB connection, total: 16
Dec 2 11:18:02 ***** mythlogserver: mythbackend[27816]: I CoreContext
mythdbcon.cpp:409 (PurgeIdleConnections) New DB connection, total: 16
Dec 2 11:19:44 ***** mythlogserver: mythbackend[27816]: I HouseKeeping
housekeeper.cpp:221 (RunHouseKeeping) Running housekeeping thread
Dec 2 11:20:42 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2128 (HandleReschedule) Reschedule requested for MATCH 0 0
0 - EITScanner
Dec 2 11:20:45 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2241 (HandleReschedule) Scheduled 260 items in 3.0 = 0.95
match + 1.40 check + 0.60 place
Dec 2 11:24:44 ***** mythlogserver: mythbackend[27816]: I HouseKeeping
housekeeper.cpp:221 (RunHouseKeeping) Running housekeeping thread
Dec 2 11:29:47 ***** mythlogserver: mythbackend[27816]: I HouseKeeping
housekeeper.cpp:221 (RunHouseKeeping) Running housekeeping thread
Dec 2 11:31:16 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2128 (HandleReschedule) Reschedule requested for MATCH 0 0
0 - EITScanner
Dec 2 11:31:19 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2241 (HandleReschedule) Scheduled 260 items in 2.9 = 0.91
match + 1.37 check + 0.66 place
Dec 2 11:32:28 ***** mythlogserver: mythbackend[27816]: N Expire
autoexpire.cpp:264 (CalcParams) AutoExpire: CalcParams(): Max required
Free Space: 1.0 GB w/freq: 15 min
Dec 2 11:34:49 ***** mythlogserver: mythbackend[27816]: I HouseKeeping
housekeeper.cpp:221 (RunHouseKeeping) Running housekeeping thread
Dec 2 11:36:04 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2128 (HandleReschedule) Reschedule requested for MATCH 0 0
0 - EITScanner
Dec 2 11:36:07 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2241 (HandleReschedule) Scheduled 260 items in 2.8 = 0.87
match + 1.43 check + 0.49 place
Dec 2 11:39:56 ***** mythlogserver: mythbackend[27816]: I HouseKeeping
housekeeper.cpp:221 (RunHouseKeeping) Running housekeeping thread
Dec 2 11:40:09 ***** mythlogserver: mythbackend[27816]: E DVBRead
dtvsignalmonitor.cpp:321 (HandlePAT)
DTVSM(/dev/dvb/adapter103/frontend0): Program #8211 not found in
PAT!#012Program Association Section#012 PSIP tableID(0x0) length(69)
extension(0x430)#012 version(7) current(1) section(0)
last_section(0)#012 tsid(1072) programCount(15)#012 program number
0 has PID 0x0010#012 program number 8201 has PID 0x0500#012
program number 8210 has PID 0x0509#012 program number 8228 has PID
0x051b#012 program number 8298 has PID 0x04fe#012 program number
8221 has PID 0x0514#012 program number 8205 has PID 0x0504#012
program number 8299 has PID 0x04ff#012 program number 8209 has PID
0x0508#012 program number 8208 has PID 0x0507#012 program number
8207 has PID 0x0506#012 program number 8206 has PID 0x0505#012
program number 8204 has PID 0x0503#012 program number 8203 has PID
0x0502#012 program number 8202 has PID 0x0501
Dec 2 11:40:10 ***** mythlogserver: mythbackend[27816]: E DVBRead
mpeg/mpegstreamdata.cpp:817 (ProcessPAT) ProcessPAT: Program not found
in PAT. Rescan your transports.
Dec 2 11:40:10 ***** mythlogserver: mythbackend[27816]: E DVBRead
mpeg/mpegstreamdata.cpp:423 (CreatePATSingleProgram) Desired program
#8211 not found in PAT.#012#011#011#011Cannot create single program PAT.
Dec 2 11:42:15 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2128 (HandleReschedule) Reschedule requested for MATCH 0 0
0 - EITScanner
Dec 2 11:42:18 ***** mythlogserver: mythbackend[27816]: I Scheduler
scheduler.cpp:2241 (HandleReschedule) Scheduled 260 items in 2.9 = 0.85
match + 1.41 check + 0.65 place
More information about the mythtv-users
mailing list