Opened 11 years ago
Closed 10 years ago
#11230 closed Bug Report - General (Won't Fix)
mythlogserver high cpu usage
| Reported by: | Owned by: | beirdo | |
|---|---|---|---|
| Priority: | minor | Milestone: | 0.27 |
| Component: | MythTV - Mythlogserver | Version: | 0.26 |
| Severity: | low | Keywords: | |
| Cc: | Ticket locked: | no |
Description
As topic says, mythtvlogserver consumes a lot of cpu time. Even when mythbackend is idle and not recording it will use cpu time, it ends up as one of my highest cpu time consumers.
Also it use a lot of memory but i guess that is because of qt usage.
Change History (22)
comment:1 Changed 11 years ago by
comment:2 Changed 11 years ago by
In my case its not that i have two mythlogserver running, mine uses about 1% of my rather strong cpu, but that is way too much, i look at cpu time, not cpu percentage at some point in time. I am on archlinux.
comment:3 Changed 11 years ago by
Google "mythtv 0.26 mytlogserver cpu time" - seems to affect a lot of people. On my system I can trigger this by starving the filesystem IO by e.g. unpacking a large rar. This results in mythlogserver hogging 100% of CPU tie every time.
comment:4 Changed 11 years ago by
from my kernel logs:
Feb 21 12:57:09 Lexington-19 kernel: [ 293.938761] mythlogserver[2703]: segfault at 38 ip 00000038 sp ae32fbcc error 14 in mythlogserver[8048000+3000]
comment:5 Changed 11 years ago by
I'm getting this all the time too. Here is the worst case I have seen so far.
$ top
top - 20:29:08 up 2 days, 5:46, 1 user, load average: 31.48, 31.25, 31.28
Tasks: 174 total, 14 running, 159 sleeping, 0 stopped, 1 zombie
%Cpu(s): 99.0 us, 0.7 sy, 0.3 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem: 2052400 total, 1819040 used, 233360 free, 71184 buffers
KiB Swap: 2002640 total, 134912 used, 1867728 free, 311672 cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
14227 david 20 0 742m 20m 4744 R 18.3 1.0 46:32.42 mythlogserver
14391 david 20 0 870m 20m 4744 R 18.3 1.0 46:03.86 mythlogserver
14569 david 20 0 806m 20m 4764 R 14.6 1.0 46:20.97 mythlogserver
14628 david 20 0 806m 20m 4760 R 14.6 1.0 46:15.34 mythlogserver
14646 david 20 0 806m 20m 4764 R 14.6 1.0 46:27.65 mythlogserver
14394 david 20 0 806m 20m 4760 R 14.3 1.0 46:30.62 mythlogserver
14560 david 20 0 806m 20m 4764 R 14.3 1.0 46:12.28 mythlogserver
14580 david 20 0 806m 20m 4764 R 14.3 1.0 46:26.56 mythlogserver
14855 david 20 0 742m 20m 4744 R 14.3 1.0 45:56.76 mythlogserver
14871 david 20 0 742m 20m 4744 R 13.9 1.0 45:56.64 mythlogserver
14638 david 20 0 806m 20m 4760 R 13.6 1.0 46:27.30 mythlogserver
14738 david 20 0 870m 20m 4760 R 13.6 1.0 46:15.30 mythlogserver
489 root 20 0 183m 75m 6612 S 9.3 3.8 7:52.07 X
14858 david 20 0 870m 20m 4784 R 7.0 1.0 23:02.56 mythlogserver
18625 david 20 0 1287m 22m 1392 S 1.0 1.1 15:32.41 mythlogserver
86 root 20 0 0 0 0 S 0.3 0.0 0:00.05 kworker/u:5
398 mysql 20 0 1300m 102m 3852 S 0.3 5.1 9:12.40 mysqld
734 david 20 0 189m 3900 1888 S 0.3 0.2 1:56.37 panel-7-datetim
779 david 20 0 13520 1556 1060 R 0.3 0.1 0:00.01 top
843 david 20 0 925m 13m 5900 S 0.3 0.7 0:05.76 nemo
981 root 20 0 0 0 0 S 0.3 0.0 0:41.63 kdvb-ad-1-fe-0
2333 david 20 0 28676 980 588 S 0.3 0.0 5:21.54 scdaemon
12220 david 39 19 1486m 325m 2644 S 0.3 16.2 10:59.00 HandBrakeCLI
12483 david 39 19 1250m 207m 2604 S 0.3 10.4 10:48.12 HandBrakeCLI
1 root 20 0 32816 2276 844 S 0.0 0.1 0:48.22 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:00.01 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 0:01.48 ksoftirqd/0
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
7 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/u:0H
8 root rt 0 0 0 0 S 0.0 0.0 0:01.11 migration/0
9 root 20 0 0 0 0 S 0.0 0.0 1:00.30 rcu_preempt
10 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_bh
11 root 20 0 0 0 0 S 0.0 0.0 0:00.00 rcu_sched
12 root rt 0 0 0 0 S 0.0 0.0 0:00.67 watchdog/0
13 root rt 0 0 0 0 S 0.0 0.0 0:00.59 watchdog/1
14 root 20 0 0 0 0 S 0.0 0.0 0:01.18 ksoftirqd/1
15 root rt 0 0 0 0 S 0.0 0.0 0:00.64 migration/1
17 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/1:0H
18 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 cpuset
19 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 khelper
20 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kdevtmpfsdavid
Usually it is only about 4 copies of mythlogserver, and CPU usage is 99% for each core.
comment:6 Changed 11 years ago by
I've observed this as well. When mythlogserver goes rogue, a bunch of processes spawn and consume 100% CPU, grinding the system to a halt and causing playback issues. I have no reliable way to reproduce this state but it seems to happen a couple of times a week.
For now I've simply chmod -x the mythlogserver binary as a workaround. MythTV seems to function fine without it (well, with the exception of logging).
Ideally there would be a way to completely disable mythlogserver and simply use the old stdout / stderr functionality instead. I have no desire nor need for advanced logging capabilities in my PVR software, most especially when such capabilities are presently coming at the expense of it being able to actually perform as PVR software :)
comment:7 Changed 11 years ago by
I've had this problem ever since upgrading from MythTV 0.25 to 0.26 on my ARCH Linux system.
mythlogserver processes seem to be looping in the nvidia display driver, so to experience it you must have an nvidia graphics card.
An easy way to reproduce the problem (for me) is to start a gdb debug session with the original mythlogserver (non-looping) process:
gdb mythlogserver nnnn
...where nnnn is the PID of the mythlogserver process that is not using a lot of CPU.
Almost immediately, more mythlogserver instances will be started (every 30 seconds or so) and will eat CPU. Exit from gdb. No new instances should start. Now start a gdb session with one of the looping mythlogserver instances and issue a backtrace command:
(gdb) bt #0 0x00007fc23399bd18 in _nv012tls () from /usr/lib/libnvidia-tls.so.313.26 #1 0x00007fc237732be8 in ?? () from /usr/lib/libGL.so.1 #2 0x00007fc23770e06a in ?? () from /usr/lib/libGL.so.1 #3 0x00007fc243840fff in _dl_fini () from /lib64/ld-linux-x86-64.so.2 #4 0x00007fc2412c2e51 in __run_exit_handlers () from /usr/lib/libc.so.6 #5 0x00007fc2412c2ed5 in exit () from /usr/lib/libc.so.6 #6 0x00007fc2412aca1c in __libc_start_main () from /usr/lib/libc.so.6 #7 0x0000000000401e49 in ?? ()
...this tells me that the loop is in /usr/lib/libnvidia-tls. Dissassembling shows the looping code:
(gdb) disassemble 0x00007fc23399bd18 Dump of assembler code for function _nv012tls: 0x00007fc23399bcf0 <+0>: mov 0x201ab1(%rip),%rax # 0x7fc233b9d7a8 0x00007fc23399bcf7 <+7>: push %rbx 0x00007fc23399bcf8 <+8>: mov 0x10(%rax),%rax 0x00007fc23399bcfc <+12>: mov %fs:(%rax),%rbx 0x00007fc23399bd00 <+16>: callq 0x7fc23399ba30 <_nv008tls> 0x00007fc23399bd05 <+21>: test %rax,%rax 0x00007fc23399bd08 <+24>: mov %rax,%rdx 0x00007fc23399bd0b <+27>: je 0x7fc23399bd24 <_nv012tls+52> 0x00007fc23399bd0d <+29>: nopl (%rax) 0x00007fc23399bd10 <+32>: cmp %rbx,%rdx 0x00007fc23399bd13 <+35>: je 0x7fc23399bd1c <_nv012tls+44> 0x00007fc23399bd15 <+37>: mov 0x8(%rdx),%eax => 0x00007fc23399bd18 <+40>: test %eax,%eax 0x00007fc23399bd1a <+42>: jne 0x7fc23399bd15 <_nv012tls+37> 0x00007fc23399bd1c <+44>: mov (%rdx),%rdx 0x00007fc23399bd1f <+47>: test %rdx,%rdx 0x00007fc23399bd22 <+50>: jne 0x7fc23399bd10 <_nv012tls+32> 0x00007fc23399bd24 <+52>: pop %rbx 0x00007fc23399bd25 <+53>: retq End of assembler dump.
FWIW I suspect that the loop is between the jne and mov instructions:
0x00007fc23399bd15 <+37>: mov 0x8(%rdx),%eax => 0x00007fc23399bd18 <+40>: test %eax,%eax 0x00007fc23399bd1a <+42>: jne 0x7fc23399bd15 <_nv012tls+37>
Google shows that in an earlier version of the nvidia driver the loop was even tighter (simply a jump to the same jump instruction).
So my guess is that the immediate cause of the high CPU utilisation is an nvidia driver error. Somehow, the nvidia driver is being called as an exit handler when mythlogserver tries to exit (because an instance is already running perhaps). But I do wonder why a graphics card driver is being invoked for a program such as mythlogserver which runs as a daemon.
The nvidia driver versions that I have seen with this problem since I moved to MythTV 0.26 are:
[2012-11-21 18:37] upgraded nvidia (302.17-4 -> 310.19-2) [2013-03-03 19:10] upgraded nvidia (310.19-2 -> 313.18-3) [2013-03-07 00:19] upgraded nvidia (313.18-3 -> 313.26-1)
...302.17-4 was with MythTV 0.25, so it is unknown whether that exhibited the problem as there was no mythlogserver program in 0.25.
My nvidia card details are:
[myth@myth ~]$ nvidia-smi
Sun Mar 10 22:58:09 2013
+------------------------------------------------------+
| NVIDIA-SMI 4.313.26 Driver Version: 313.26 |
|-------------------------------+----------------------+----------------------+
| GPU Name | Bus-Id Disp. | Volatile Uncorr. ECC |
| Fan Temp Perf Pwr:Usage/Cap| Memory-Usage | GPU-Util Compute M. |
|===============================+======================+======================|
| 0 GeForce GT 240 | 0000:01:00.0 N/A | N/A |
| 10% 40C N/A N/A / N/A | 3% 30MB / 1023MB | N/A Default |
+-------------------------------+----------------------+----------------------+
+-----------------------------------------------------------------------------+
| Compute processes: GPU Memory |
| GPU PID Process name Usage |
|=============================================================================|
| 0 Not Supported |
+-----------------------------------------------------------------------------+
comment:8 follow-up: 9 Changed 11 years ago by
I have ages old ATI 3850, so this is not limited to Nvidia drivers.
comment:9 Changed 11 years ago by
Replying to basti@…:
I have ages old ATI 3850, so this is not limited to Nvidia drivers.
Interesting. Nevertheless I've reported the problem to NVidia. Hopefully they'll be able to give a hint.
comment:10 Changed 11 years ago by
I just upgraded mythtv from 1:0.26.0-7 -> 1:0.26.0-8 and the problem is still there, so I just made mythlogserver non-executable:
sudo chmod a-x /usr/bin/mythlogserver
Problem gone. I can do without logging.
comment:11 Changed 11 years ago by
We are seeing this too in 0.26-fixes. Is anyone working on it or able to inform us how to give more useful debug info in order that someone will be able to work it?
comment:12 Changed 11 years ago by
I've also seen this occur. No activity on this for awhile. Any update?
comment:13 Changed 11 years ago by
Hi,
I have had this issue ever since upgrading to 0.26 - there are several new instances of mythlogserver started, sometimes many per minute, all of them consuming as much cpu time as they get - so I added a cron script which just kills all of them every minute, but my HTPC still runs hot with that and gets loud.
It´s no joy any more to run mythtv, and I can´t understand why such a big issue is not getting fixed.
What for is mythlogserver anyway? Can´t I switch it off completely and go back to the old behaviour?
comment:14 Changed 11 years ago by
This is my process list, filtered, about 8 minutes after the last kill:
1722 ? Rsl 1:40 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 1754 ? Rsl 1:33 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 1776 ? Rsl 0:55 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 1814 ? Rsl 1:25 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 1914 ? SNsl 1:02 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 1925 ? Rsl 1:18 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --syslog local7 1947 ? RNsl 0:38 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 1962 ? Rsl 1:07 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --syslog local7 1973 ? Rsl 1:04 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 2062 ? Rsl 1:01 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --syslog local7 2072 ? Rsl 0:42 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 2085 ? RNsl 0:44 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 2103 ? Rsl 0:44 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 2114 ? RNsl 0:29 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 2125 ? Ssl 0:20 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --syslog local7 2135 ? Ssl 0:08 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 2174 ? Ssl 0:12 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 2207 ? Rsl 0:09 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 2220 ? Rsl 0:07 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --syslog local7 2231 ? Rsl 0:06 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog 2248 ? Rsl 0:02 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --syslog local7 2283 ? Rsl 0:00 /usr/bin/mythlogserver --daemon --verbose general --loglevel info --nodblog
comment:15 Changed 11 years ago by
"I can´t understand why such a big issue is not getting fixed."
No-one else has reported experiencing this issue, so while it is understandably a big issue for you, it's not come to our attention before now. Your issue is different to the one first reported in this ticket, could you please open a new ticket?
comment:16 Changed 11 years ago by
| Milestone: | unknown → 0.27 |
|---|---|
| Priority: | minor → critical |
comment:17 Changed 11 years ago by
| Priority: | critical → minor |
|---|
there are two options to bypass the problem.
1-Compile mythtv using configure --disable-mythlogserver ; this will use an alternative logging server local to each application. or 2-Run any myth application with --nologserver
option 1 has the advantage that you can still benefit from logging to syslog, a file or the database option 2 will only log to the console
comment:18 Changed 10 years ago by
Hi,
I don't know how common this issue is, but just reporting that I've had id as an annoyance during the last year, for as much that during the time I've been using other software. However, I've now re-tried version 0.27_p20140321 (on Gentoo) and still got hit by this issue. This is very annoying and makes mythtv totally unusable for me.
However, I will try the workarounds provided here. In case there's anything I can too to provide information for fixing this, please ask.
comment:19 Changed 10 years ago by
Having multiple instances of mythlogserver running is almost definitely due to misconfiguration, such that different MythTV processes are run as different users, some of which do not have appropriate permissions for the specified logging. There was no code written to handle the situation where MythTV applications are told to log in one way, but the system refuses to allow it, so a mythlogserver process is spawned and spins while it's trying to start, but it never finishes starting, so can't be contacted by other MythTV applications so they assume there's no mythlogserver running and start their own. Configure your system properly and specify an appropriate logging method and it won't do this.
comment:20 Changed 10 years ago by
Hi mdean,
Thanks for your comment. I've found out the discussion in the mailing list and know the suspected culprit.
However on my system 1) mythtv logging seems to be working without problems AFAICT (into /var/log/mythtv, which is writeable by 'mythtv', and the logs do appear there) and 2) the problems surfaces every now and them, sporadically, without any intervention from the user, 1-7 times in a week (if I'm lucky, it will work for a week, and if I'm not, it will re-occur in 24hours after a restart). This makes it difficult to debug for sure, since I have no idea what triggers it.
I'm using Gentoo with the distributions initscripts. Mythbackend and all related processes should be running as user 'mythtv' specifically made for the purpose (I just checked, and they are according to 'htop'). Only the frontend is run as a different user (on the same machine in my case, 99% of the time), and even sometimes I don't use the mythfrontend but XBMC.
However, for the time being, I have disabled the mythlogserver altogether. I will see if I have time, and I will double check the permission problems described here. Also, given that I'm using the distribution provided ebuilds, I wouldn't rule out a downstream problem in my case - but I presume others with this problem are using some other distributions.
Finally, I have to add that in the case this appears to be a permission problem after all (or some other misconfiguration), I disagree that it's OK for a software to spawn more processes each eating the CPU IMHO. There should be sanity checks for (write) permissions and a sane way to handle the error, since a permission error is not that rare thing to occur - and will occur, eventually, on someones setup. OK, you can't do sanity checks for all kinds of misconfigurations, but file permissions should be handled. But this is just my opinion.
comment:21 Changed 10 years ago by
Because mythlogserver exits after a period of inactivity and because the mythlogserver process is started, again, by whichever process has new log messages to write when there is no process already running, mythfrontend--and any other MythTV process, including mythpreviewgen, mythtranscode, mythjobqueue, mythcommflag, mythmetadatalookup, ...--can (and will, eventually, depending on timing) start mythlogserver. Therefore, the fact that you're running mythfrontend as a different user means this is most likely what's causing the problem. The problem may also be exacerbated by different processes being started with different logging instructions (sometimes direct writing, sometimes syslog, as is shown in comment:14, above, by barth).
Solutions: 1) Don't use mythlogserver 2) Use syslog logging (for every MythTV application, every single time it's executed) rather than direct logging so that a different process (which is always run as the same user--whichever user runs your syslog daemon) does the actual writing 3) Run mythfrontend as the same user as every other MythTV application on the host and ensure permissions are correct for the direct-logging destination
And, yes, we could have code to check for problems so that mythlogserver fails gracefully. All it requires is for someone to take the time to write such code. You may call it a bug that MythTV's mythlogserver fails (spectacularly) when the system is misconfigured, but some may call mythlogserver's inability to detect and recover from system misconfiguration a missing feature (mythlogserver, itself, was never finished due to lack of motivation caused by mass complaints against it). Note, also, that there are many other misconfigurations (of mythbackend, mythfrontend, ...) that cause catastrophic failures and we lack code to handle them, too. If I had unlimited time, I'd write code to handle all the possible failures, misconfigurations, ... Since I don't, I have to hope that someone else who feels mythlogserver's lack of graceful recovery from system misconfiguration (even in light of the future of mythlogserver) warrants their spending their own time to write code to handle it more gracefully.
As it is, the rest of the development team has taken the view that throwing out mythlogserver is the approach to take, so there's no use writing new code for it. (And, FWIW, if I were fixing things, I would rip out mythlogserver's "exit on inactivity" functionality (that was included so users wouldn't complain about an "unnecessary" extra process taking up resources when there's nothing to log) and make it a normal, always-running daemon process so it could be started once as a specified user and just work.)
comment:22 Changed 10 years ago by
| Resolution: | → Won't Fix |
|---|---|
| Status: | new → closed |
compile mythtv with --disable-mythlogserver
I too noticed this problem today. Mythlog server was running at 100% cpu utilization with only 1 tuner watching livetv. What I did notice was that there were actually 2 copies of mythlogserver running. One was at 100% and the other at 1% utilization. I tailed the backened log and watch while I killed the process running at 100%. There appeared to be no interruption to the logging. I assume there is no reason for 2 copies of this to be running, and perhaps the high utilization is related to the fact that there are 2 copies running.