Date:	Sat, 29 Jun 2013 23:44:16 +0200
From:	Sedat Dilek <sedat.dilek@...il.com>
To:	Oleg Nesterov <oleg@...hat.com>
Cc:	linux-next@...r.kernel.org, linux-kernel@...r.kernel.org,
	Stephen Rothwell <sfr@...b.auug.org.au>,
	Andrew Morton <akpm@...ux-foundation.org>,
	Tejun Heo <tj@...nel.org>,
	Daniel Vetter <daniel.vetter@...ll.ch>,
	Imre Deak <imre.deak@...el.com>,
	Lukas Czerner <lczerner@...hat.com>,
	Samuel Ortiz <samuel@...tiz.org>,
	Wensong Zhang <wensong@...ux-vs.org>,
	Simon Horman <horms@...ge.net.au>,
	Julian Anastasov <ja@....bg>,
	Ralf Baechle <ralf@...ux-mips.org>
Subject: Re: linux-next: Tree for Jun 28 [ BISECTED: rsyslog/imklog: High CPU
 usage ]

On Fri, Jun 28, 2013 at 9:33 AM, Stephen Rothwell <sfr@...b.auug.org.au> wrote:
> Hi all,
>
> Changes since 20130627:
>
> This tree produces the following warning when built for many (all?)
> configs (it has been fixed in the drm tree):
>
> drivers/video/Kconfig:42:error: recursive dependency detected!
> drivers/video/Kconfig:42:       symbol FB is selected by DRM_KMS_HELPER
> drivers/gpu/drm/Kconfig:29:     symbol DRM_KMS_HELPER is selected by DRM_OMAP
> drivers/gpu/drm/omapdrm/Kconfig:2:      symbol DRM_OMAP depends on FB_OMAP2
> drivers/video/omap2/omapfb/Kconfig:1:   symbol FB_OMAP2 depends on FB
>
> The arm-soc tree gained a conflict against the mfd tree.
>
> I applied a patch to the akpm tree to remove a lot of warnings.
>

[ I kept the CC list of the culprit commit (sorry if I forgot anyone) ]

Hi,

[ SYMPTOM ]

Last Friday I wanted to listen to some music-videos on my
next-20130628 kernel and noticed that my battery got sucked empty very
fast.
I could see with htop that 2 (of 4) rsyslogd processes ran on 100%.

NOTE: next-20130627 (Thursday's Linux-Next) did NOT show these symptoms.

[ "CSI dileks" CHECKS THE LOGS ]

While investigating the logs I saw this:

[ /var/log/syslog ]
Jun 29 15:25:34 fambox rsyslogd: [origin software="rsyslogd"
swVersion="5.8.6" x-pid="900" x-info="http://www.rsyslog.com"] exiting
on signal 15.
Jun 29 15:25:39 fambox kernel: imklog 5.8.6, log source = /proc/kmsg started.
Jun 29 15:25:39 fambox rsyslogd: [origin software="rsyslogd"
swVersion="5.8.6" x-pid="4689" x-info="http://www.rsyslog.com"] start
Jun 29 15:25:39 fambox rsyslogd: rsyslogd's groupid changed to 103
Jun 29 15:25:39 fambox rsyslogd: rsyslogd's userid changed to 101
Jun 29 15:25:39 fambox rsyslogd-2039: Could not open output pipe
'/dev/xconsole' [try http://www.rsyslog.com/e/2039 ]
Jun 29 15:25:39 fambox kernel:
Jun 29 15:26:09 fambox kernel: last message repeated 30176 times
Jun 29 15:27:09 fambox kernel: last message repeated 59603 times
Jun 29 15:28:09 fambox kernel: last message repeated 60081 times
Jun 29 15:29:09 fambox kernel: last message repeated 60148 times

[ 1ST TRYOUT ]

[1] recommends to use a more modern rsyslog-version, so I upgraded
from (5.8.6-1ubuntu8.4) to (7.4.1-0ubuntu1ppa1) from an unofficial
3rd-party software-archive [2] for Ubuntu/precise.
This did not help - still 100% CPU usage observed.

[ 2ND TRYOUT: WORKAROUND ]

Following [1], I temporarily disabled imklog rsyslog-module:

[ /etc/rsyslog.conf ]
...
-$ModLoad imklog   # provides kernel logging support (previously done by rklogd)
+# XXX: Workaround: Do NOT load imklog as it causes 100% CPU workload
by flooding logs. -dileks
+#$ModLoad imklog   # provides kernel logging support (previously done
by rklogd)

Yeah, this resulted in a "normal" system - no high CPU loads anymore
(in idle-mode).

[ CURIOSITY KILLED THE CAT ]

I cannot say if this here is related...

[ /var/log/syslog ]
fambox rsyslogd-2039: Could not open output pipe '/dev/xconsole' [try
http://www.rsyslog.com/e/2039 ]

...it looks like I have to create a '/dev/xconsole' manually.

     root# mknod -m 640 /dev/xconsole p

With the "BROKEN" kernel this IIRC did not help, the good one did not
show xconsole-related stuff in the logs.
But I might remember wrong.

See also:

[ /etc/rsyslog.d/50-default.conf ]
...
# The named pipe /dev/xconsole is for the `xconsole' utility.  To use it,
# you must invoke `xconsole' with the `-file' option:
#
#    $ xconsole -file /dev/xconsole [...]
#
# NOTE: adjust the list below, or you'll go crazy if you have a reasonably
#      busy site..
#
daemon.*;mail.*;\
        news.err;\
        *.=debug;*.=info;\
        *.=notice;*.=warn       |/dev/xconsole
- EOF -

Running manually 'xconsole -file /dev/xconsole' was not successful
(could not open... device) with the bad kernel.
Might be good to comment that xconsole block?

[ GIT-BISECT SESSION ]

As this all did not show me what caused the problem I started a
git-bisect session.

This revealed the following culprit commit:

     commit bb1f30cb7d3ba21098f0ee7e0382160ba2599a43
     "wait: introduce wait_event_common(wq, condition, state, timeout)"

This commit was 1st introduced with Friday's next-20130628!

NOTE: See also git-bisect-log.txt and git-bisect-visualize.txt for the results.

Reverting it successfully with two other related patches results in a
"normal" system again.

See attached patch lists:
      Revert "fix warnings from ?: operator in wait.h"
      Revert "wait: introduce prepare_to_wait_event()"
      Revert "wait: introduce wait_event_common(wq, condition, state, timeout)"

[ GIVEAWAYS ]

For the sake of completeness I have attached my kernel-config.

Oleg, can you look at that?
If you need more inputs lemme know.

Thanks in advance.

Regards,
- Sedat -

[1] http://www.gossamer-threads.com/lists/rsyslog/users/8087
[2] https://launchpad.net/~tmortensen/+archive/rsyslogv7

View attachment "git-bisect-log.txt" of type "text/plain" (2097 bytes)

View attachment "git-bisect-visualize.txt" of type "text/plain" (2138 bytes)

Download attachment "3.10.0-rc7-next20130628-7-iniza-small.patch" of type "application/octet-stream" (17100 bytes)

Download attachment "config-3.10.0-rc7-next20130628-7-iniza-small" of type "application/octet-stream" (114320 bytes)

Powered by blists - more mailing lists