Modify
Warning Please read the Ticket HowTo before creating or commenting on a ticket. Failure to do so may cause your ticket to be rejected or result in a slower response.

Opened 18 months ago

Last modified 15 hours ago

#11230 new Bug Report - General

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

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.

Attachments (0)

Change History (19)

comment:1 Changed 18 months 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 18 months 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 17 months 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 14 months 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 14 months 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 14 months 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 14 months 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/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: Changed 14 months ago by basti@…

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

comment:9 in reply to: ↑ 8 Changed 14 months 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 13 months 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 11 months 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 9 months ago by jeremyenos@…

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

comment:13 Changed 8 months ago by barth@…

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 8 months 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 months 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 months ago by stuartm (previous) (diff)

comment:16 Changed 8 months ago by stuartm

  • Milestone changed from unknown to 0.27
  • Priority changed from minor to critical

comment:17 Changed 8 months ago by jyavenard

  • Priority changed from critical to 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 22 hours ago by Ville Aakko <ville.aakko@…>

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 15 hours ago by mdean

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.

Add Comment

Modify Ticket

Action
as new .
Author


E-mail address and user name can be saved in the Preferences.

 
Note: See TracTickets for help on using tickets.