Opened 8 years ago

Closed 7 years ago

#11230 closed Bug Report - General (Won't Fix)

mythlogserver high cpu usage

Reported by: cleanrock@… Owned by: beirdo
Priority: minor Milestone: 0.27
Component: MythTV - Mythlogserver Version: 0.26
Severity: low Keywords:
Cc: Ticket locked: no


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 8 years ago by Ronald Frazier <ron@…>

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.

comment:2 Changed 8 years ago by Johan Rehnberg <cleanrock@…>

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 8 years ago by basti@…

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 8 years ago by emp2008@…

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 8 years ago by david_farmer@…

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 8 years ago by jeremy.thornhill@…

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 8 years ago by Andrew Armstrong <androidarmstrong@…>

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/
#1  0x00007fc237732be8 in ?? () from /usr/lib/
#2  0x00007fc23770e06a in ?? () from /usr/lib/
#3  0x00007fc243840fff in _dl_fini () from /lib64/
#4  0x00007fc2412c2e51 in __run_exit_handlers () from /usr/lib/
#5  0x00007fc2412c2ed5 in exit () from /usr/lib/
#6  0x00007fc2412aca1c in __libc_start_main () from /usr/lib/
#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 Changed 8 years ago by basti@…

I have ages old ATI 3850, so this is not limited to Nvidia drivers.

comment:9 in reply to:  8 Changed 8 years ago by Andrew Armstrong <androidarmstrong@…>

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 8 years ago by androidarmstrong@…

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 8 years ago by antony.gelberg@…

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 8 years ago by jeremyenos@…

I've also seen this occur. No activity on this for awhile. Any update?

comment:13 Changed 8 years ago by barth@…


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 8 years ago by barth@…

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 8 years ago by stuartm

"I can´t understand why such a big issue is not getting fixed."

Very few people have 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?

Last edited 8 years ago by stuartm (previous) (diff)

comment:16 Changed 8 years ago by stuartm

Milestone: unknown0.27
Priority: minorcritical

comment:17 Changed 8 years ago by JYA

Priority: criticalminor

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 7 years ago by Ville Aakko <ville.aakko@…>


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 7 years ago by sphery

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 7 years ago by Ville Aakko <ville.aakko@…>

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 7 years ago by sphery

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 7 years ago by JYA

Resolution: Won't Fix
Status: newclosed

compile mythtv with --disable-mythlogserver

Note: See TracTickets for help on using tickets.