2.6.19-rc5 breaks klogd 1.4.1

All of lore.kernel.org
 help / color / mirror / Atom feed

* 2.6.19-rc5 breaks klogd 1.4.1
@ 2006-11-09  5:23 John Wendel
  2006-11-09  6:41 ` Andrew Morton
  0 siblings, 1 reply; 6+ messages in thread
From: John Wendel @ 2006-11-09  5:23 UTC (permalink / raw)
  To: Linux Kernel

Just installed -rc5, system very slow, noticed klogd in a tight loop 
doing a "read". -rc4 is OK.

Sorry, I have printk configured off, so I don't have any logs.

Thanks,

John

^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: 2.6.19-rc5 breaks klogd 1.4.1
  2006-11-09  5:23 2.6.19-rc5 breaks klogd 1.4.1 John Wendel
@ 2006-11-09  6:41 ` Andrew Morton
       [not found]   ` <4552D4B4.5020505@comcast.net>
  0 siblings, 1 reply; 6+ messages in thread
From: Andrew Morton @ 2006-11-09  6:41 UTC (permalink / raw)
  To: John Wendel; +Cc: Linux Kernel

On Wed, 08 Nov 2006 21:23:33 -0800
John Wendel <jwendel10@comcast.net> wrote:

> Just installed -rc5, system very slow, noticed klogd in a tight loop 
> doing a "read". -rc4 is OK.
> 
> Sorry, I have printk configured off, so I don't have any logs.
> 

Please run

	strace -p $(pidof klogd)


^ permalink raw reply	[flat|nested] 6+ messages in thread

[parent not found: <4552D4B4.5020505@comcast.net>]

* Re: 2.6.19-rc5 breaks klogd 1.4.1
       [not found]   ` <4552D4B4.5020505@comcast.net>
@ 2006-11-09  7:35     ` Andrew Morton
  2006-11-09 10:11       ` Mike Galbraith
  0 siblings, 1 reply; 6+ messages in thread
From: Andrew Morton @ 2006-11-09  7:35 UTC (permalink / raw)
  To: John Wendel; +Cc: linux-kernel


You removed the mailing list from cc.  Please don't.

On Wed, 08 Nov 2006 23:11:48 -0800
John Wendel <jwendel10@comcast.net> wrote:

> Andrew Morton wrote:
> > On Wed, 08 Nov 2006 21:23:33 -0800
> > John Wendel <jwendel10@comcast.net> wrote:
> >
> >   
> >> Just installed -rc5, system very slow, noticed klogd in a tight loop 
> >> doing a "read". -rc4 is OK.
> >>
> >> Sorry, I have printk configured off, so I don't have any logs.
> >>
> >>     
> >
> > Please run
> >
> > 	strace -p $(pidof klogd)
> >
> >
> >   
> Strace attached.
> 
>
> execve("/sbin/klogd", ["klogd", "-n"], [/* 27 vars */]) = 0
> uname({sys="Linux", node="Godzilla.localdomain", ...}) = 0
> brk(0)                                  = 0x80007000
> access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
> open("/etc/ld.so.cache", O_RDONLY)      = 3
> fstat64(3, {st_mode=S_IFREG|0644, st_size=138777, ...}) = 0
> old_mmap(NULL, 138777, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7f9c000
> close(3)                                = 0
> open("/lib/tls/libc.so.6", O_RDONLY)    = 3
> read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\20O\1\000"..., 512) = 512
> fstat64(3, {st_mode=S_IFREG|0755, st_size=1521816, ...}) = 0
> old_mmap(NULL, 1223868, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb7e71000
> mprotect(0xb7f95000, 27836, PROT_NONE)  = 0
> old_mmap(0xb7f96000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x124000) = 0xb7f96000
> old_mmap(0xb7f9a000, 7356, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7f9a000
> close(3)                                = 0
> old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7e70000
> mprotect(0xb7f96000, 8192, PROT_READ)   = 0
> mprotect(0xb7fd5000, 4096, PROT_READ)   = 0
> set_thread_area({entry_number:-1 -> 6, base_addr:0xb7e70aa0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
> munmap(0xb7f9c000, 138777)              = 0
> chdir("/")                              = 0
> brk(0)                                  = 0x80007000
> brk(0x80028000)                         = 0x80028000
> open("/var/run/klogd.pid", O_RDONLY)    = -1 ENOENT (No such file or directory)
> open("/var/run/klogd.pid", O_RDWR|O_CREAT, 0644) = 3
> fcntl64(3, F_GETFL)                     = 0x2 (flags O_RDWR)
> fstat64(3, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
> mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fbd000
> _llseek(3, 0, [0], SEEK_CUR)            = 0
> flock(3, LOCK_EX|LOCK_NB)               = 0
> getpid()                                = 4702
> write(3, "4702\n", 5)                   = 5
> flock(3, LOCK_UN)                       = 0
> close(3)                                = 0
> rt_sigaction(SIGHUP, {SIG_IGN}, {SIG_DFL}, 8) = 0
> rt_sigaction(SIGINT, {SIG_IGN}, {SIG_DFL}, 8) = 0
> rt_sigaction(SIGQUIT, {SIG_IGN}, {SIG_DFL}, 8) = 0
> 
> [removed a bunch of these]
> 
> rt_sigaction(SIGRT_29, {SIG_IGN}, {SIG_DFL}, 8) = 0
> rt_sigaction(SIGRT_30, {SIG_IGN}, {SIG_DFL}, 8) = 0
> rt_sigaction(SIGRT_31, {SIG_IGN}, {SIG_DFL}, 8) = 0
> rt_sigaction(SIGRT_32, {SIG_IGN}, {SIG_DFL}, 8) = 0
> rt_sigaction(SIGINT, {0x8000186b, [INT], SA_RESTART}, {SIG_IGN}, 8) = 0
> rt_sigaction(SIGKILL, {0x8000186b, [KILL], SA_RESTART}, {SIG_IGN}, 8) = -1 EINVAL (Invalid argument)
> rt_sigaction(SIGTERM, {0x8000186b, [TERM], SA_RESTART}, {SIG_IGN}, 8) = 0
> rt_sigaction(SIGHUP, {0x8000186b, [HUP], SA_RESTART}, {SIG_IGN}, 8) = 0
> rt_sigaction(SIGTSTP, {0x80001492, [TSTP], SA_RESTART}, {SIG_IGN}, 8) = 0
> rt_sigaction(SIGCONT, {0x80001450, [CONT], SA_RESTART}, {SIG_IGN}, 8) = 0
> rt_sigaction(SIGUSR1, {0x800014d4, [USR1], SA_RESTART}, {SIG_IGN}, 8) = 0
> rt_sigaction(SIGUSR2, {0x800014d4, [USR2], SA_RESTART}, {SIG_IGN}, 8) = 0
> syslog(0x8, 0, 0x6)                     = 0
> stat64("/proc/kmsg", {st_mode=S_IFREG|0400, st_size=0, ...}) = 0
> open("/proc/kmsg", O_RDONLY)            = 3

So /proc/kmsg is fd 3.

> socket(PF_FILE, SOCK_DGRAM, 0)          = 4
> connect(4, {sa_family=AF_FILE, path="/dev/log"}, 10) = 0
> time([1163055813])                      = 1163055813
> open("/etc/localtime", O_RDONLY)        = 5
> fstat64(5, {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
> fstat64(5, {st_mode=S_IFREG|0644, st_size=1017, ...}) = 0
> mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fbc000
> read(5, "TZif\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\4\0"..., 4096) = 1017
> close(5)                                = 0
> munmap(0xb7fbc000, 4096)                = 0
> write(4, "<6>Nov  8 23:03:33 kernel: klogd"..., 73) = 73
> uname({sys="Linux", node="Godzilla.localdomain", ...}) = 0
> open("/boot/System.map-2.6.19-rc5", O_RDONLY) = 5
> open("/boot/System.map-2.6.19-rc5", O_RDONLY) = 6
> time([1163055813])                      = 1163055813
> write(4, "<6>Nov  8 23:03:33 kernel: Inspe"..., 66) = 66
> fstat64(6, {st_mode=S_IFREG|0644, st_size=571337, ...}) = 0
> mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fbc000
> read(6, "00000400 A __kernel_vsyscall\n000"..., 4096) = 4096
> read(6, "re\nc0104500 T math_emulate\nc0104"..., 4096) = 4096
> read(6, "c010a980 t generic_set_mtrr\nc010"..., 4096) = 4096
> 
> [removed a bunch of these]
> 
> read(6, "c010f7f0 T account_steal_time\nc0"..., 4096) = 4096
> read(6, "hash_entries\nc02f86f0 T tcp_init"..., 4096) = 4096
> read(6, "cpi_skip_timer_override\nc02fd840"..., 4096) = 4096
> read(6, "tup_parse_reservetop\nc0300b48 t "..., 4096) = 4096
> read(6, "0300f18 t __initcall_pcibios_ass"..., 4096) = 4096
> read(6, "t cubictcp_unregister\nc03034c0 t"..., 4096) = 4096
> uname({sys="Linux", node="Godzilla.localdomain", ...}) = 0
> close(6)                                = 0
> munmap(0xb7fbc000, 4096)                = 0
> close(5)                                = 0
> open("/boot/System.map-2.6.19-rc5", O_RDONLY) = 5
> fstat64(5, {st_mode=S_IFREG|0644, st_size=571337, ...}) = 0
> mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fbc000
> read(5, "00000400 A __kernel_vsyscall\n000"..., 4096) = 4096
> read(5, "re\nc0104500 T math_emulate\nc0104"..., 4096) = 4096
> read(5, "c010a980 t generic_set_mtrr\nc010"..., 4096) = 4096
> read(5, "c010f7f0 T account_steal_time\nc0"..., 4096) = 4096
> read(5, "s_waitpid\nc0115ee0 t itimer_get_"..., 4096) = 4096
> read(5, "ut\nc011b4e0 T sys_gettid\nc011b4f"..., 4096) = 4096
> read(5, "e\nc0120a70 T sys_sethostname\nc01"..., 4096) = 4096
> 
> [removed a bunch of these]
> 
> read(5, "p\nc0124d80 T sys_clock_nanosleep"..., 4096) = 4096
> read(5, "_latency_notifier\nc0128a30 T unr"..., 4096) = 4096
> read(5, "cpi_skip_timer_override\nc02fd840"..., 4096) = 4096
> read(5, "tup_parse_reservetop\nc0300b48 t "..., 4096) = 4096
> read(5, "0300f18 t __initcall_pcibios_ass"..., 4096) = 4096
> read(5, "t cubictcp_unregister\nc03034c0 t"..., 4096) = 4096
> uname({sys="Linux", node="Godzilla.localdomain", ...}) = 0
> read(5, "c030a008 B pmd_cache\nc030a00c B "..., 4096) = 4096
> read(5, "ck\nc030d980 b pkmap_count\nc030e9"..., 4096) = 4096
> read(5, "_workqueue\nc031400c b per_cpu__b"..., 4096) = 4096
> read(5, " acpi_gbl_root_node_struct\nc0314"..., 4096) = 4096
> read(5, "settings\nc0319cdc b cdrom_sysctl"..., 4096) = 4096
> read(5, "family_ht\nc031b620 b rover.1\nc03"..., 4096) = 1993
> read(5, "", 4096)                       = 0
> time([1163055813])                      = 1163055813
> write(4, "<6>Nov  8 23:03:33 kernel: Loade"..., 82) = 82
> time([1163055813])                      = 1163055813
> write(4, "<6>Nov  8 23:03:33 kernel: Symbo"..., 64) = 64
> close(5)                                = 0
> munmap(0xb7fbc000, 4096)                = 0
> get_kernel_syms(0)                      = -1 ENOSYS (Function not implemented)
> time([1163055813])                      = 1163055813
> write(4, "<6>Nov  8 23:03:33 kernel: No mo"..., 83) = 83
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> read(3, "", 4095)                       = 0
> 
> [repeats until I kill it]
> 

And, predictably, reads from /proc/kmsg aren't blocking.

I can't see what might have caused that.  Are you sure that 2.6.19-rc4 was
OK?  And are you sure that nothing else has changed on that system?


^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: 2.6.19-rc5 breaks klogd 1.4.1
  2006-11-09  7:35     ` Andrew Morton
@ 2006-11-09 10:11       ` Mike Galbraith
  2006-11-09 15:25         ` Mike Galbraith
  0 siblings, 1 reply; 6+ messages in thread
From: Mike Galbraith @ 2006-11-09 10:11 UTC (permalink / raw)
  To: Andrew Morton; +Cc: John Wendel, linux-kernel

On Wed, 2006-11-08 at 23:35 -0800, Andrew Morton wrote:

> And, predictably, reads from /proc/kmsg aren't blocking.
> 
> I can't see what might have caused that.  Are you sure that 2.6.19-rc4 was
> OK?  And are you sure that nothing else has changed on that system?

Here, both rc4 and rc5 do the same if printk is configured out.

Why do we have a /proc/ksmg when nothing can get to it?

	-Mike


^ permalink raw reply	[flat|nested] 6+ messages in thread

* Re: 2.6.19-rc5 breaks klogd 1.4.1
  2006-11-09 10:11       ` Mike Galbraith
@ 2006-11-09 15:25         ` Mike Galbraith
  2006-11-11  6:44           ` [patch] [trivial] " Mike Galbraith
  0 siblings, 1 reply; 6+ messages in thread
From: Mike Galbraith @ 2006-11-09 15:25 UTC (permalink / raw)
  To: Andrew Morton; +Cc: John Wendel, linux-kernel

On Thu, 2006-11-09 at 11:11 +0100, Mike Galbraith wrote:
> On Wed, 2006-11-08 at 23:35 -0800, Andrew Morton wrote:
> 
> > And, predictably, reads from /proc/kmsg aren't blocking.
> > 
> > I can't see what might have caused that.  Are you sure that 2.6.19-rc4 was
> > OK?  And are you sure that nothing else has changed on that system?
> 
> Here, both rc4 and rc5 do the same if printk is configured out.

Well duh, of course it does.  Testing and _then_ looking at the source
was not the correct order in this case :)

> Why do we have a /proc/ksmg when nothing can get to it?

The sensible thing seemed to be to whack it, but when I did that, klogd
just switched interfaces, and proceeded to eat 100% cpu doing
syslog(0x2, 0xb7fc0008, 0x1ffff) instead.  Leaving it in place, but
making it block to simulate an empty buffer works fine, but seems kinda
cheezy.

Whacking /proc/kmsg, and making sys_syslog() block on read to simulate
the empty buffer seemed much better, but SuSE's boot scripts hang when
they try to create /var/log/boot.msg ala /sbin/klogd -s -o -n
-f /var/log/boot.msg.  That seems to work now only because there is
always something there to grab.

The correct answer seems to be "fix klogd, or don't disable printk".

	-Mike


^ permalink raw reply	[flat|nested] 6+ messages in thread

* [patch] [trivial] Re: 2.6.19-rc5 breaks klogd 1.4.1
  2006-11-09 15:25         ` Mike Galbraith
@ 2006-11-11  6:44           ` Mike Galbraith
  0 siblings, 0 replies; 6+ messages in thread
From: Mike Galbraith @ 2006-11-11  6:44 UTC (permalink / raw)
  To: Andrew Morton; +Cc: John Wendel, linux-kernel

On Thu, 2006-11-09 at 16:25 +0100, Mike Galbraith wrote:

> The correct answer seems to be "fix klogd, or don't disable printk".

I don't like that answer one bit.  I think it's much better to remove
the syslog interface when printk is disabled rather than leave it in
place for userland to trip over.

Signed-off-by: Mike Galbraith <efault@gmx.de>

--- linux-2.6.19-rc5/fs/proc/Makefile.org	2006-11-09 13:08:17.000000000 +0100
+++ linux-2.6.19-rc5/fs/proc/Makefile	2006-11-09 13:09:06.000000000 +0100
@@ -8,8 +8,9 @@ proc-y			:= nommu.o task_nommu.o
 proc-$(CONFIG_MMU)	:= mmu.o task_mmu.o
 
 proc-y       += inode.o root.o base.o generic.o array.o \
-		kmsg.o proc_tty.o proc_misc.o
+		proc_tty.o proc_misc.o
 
 proc-$(CONFIG_PROC_KCORE)	+= kcore.o
 proc-$(CONFIG_PROC_VMCORE)	+= vmcore.o
 proc-$(CONFIG_PROC_DEVICETREE)	+= proc_devtree.o
+proc-$(CONFIG_PRINTK)	+= kmsg.o
--- linux-2.6.19-rc5/fs/proc/proc_misc.c.org	2006-11-09 13:04:50.000000000 +0100
+++ linux-2.6.19-rc5/fs/proc/proc_misc.c	2006-11-09 13:06:29.000000000 +0100
@@ -696,9 +696,11 @@ void __init proc_misc_init(void)
 	proc_symlink("mounts", NULL, "self/mounts");
 
 	/* And now for trickier ones */
+#ifdef CONFIG_PRINTK
 	entry = create_proc_entry("kmsg", S_IRUSR, &proc_root);
 	if (entry)
 		entry->proc_fops = &proc_kmsg_operations;
+#endif
 	create_seq_entry("devices", 0, &proc_devinfo_operations);
 	create_seq_entry("cpuinfo", 0, &proc_cpuinfo_operations);
 #ifdef CONFIG_BLOCK
--- linux-2.6.19-rc5/kernel/printk.c.org	2006-11-08 07:44:27.000000000 +0100
+++ linux-2.6.19-rc5/kernel/printk.c	2006-11-11 06:44:59.000000000 +0100
@@ -631,12 +631,7 @@ EXPORT_SYMBOL(vprintk);
 
 asmlinkage long sys_syslog(int type, char __user *buf, int len)
 {
-	return 0;
-}
-
-int do_syslog(int type, char __user *buf, int len)
-{
-	return 0;
+	return -ENOSYS;
 }
 
 static void call_console_drivers(unsigned long start, unsigned long end)



^ permalink raw reply	[flat|nested] 6+ messages in thread

end of thread, other threads:[~2006-11-11  6:43 UTC | newest]

Thread overview: 6+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2006-11-09  5:23 2.6.19-rc5 breaks klogd 1.4.1 John Wendel
2006-11-09  6:41 ` Andrew Morton
     [not found]   ` <4552D4B4.5020505@comcast.net>
2006-11-09  7:35     ` Andrew Morton
2006-11-09 10:11       ` Mike Galbraith
2006-11-09 15:25         ` Mike Galbraith
2006-11-11  6:44           ` [patch] [trivial] " Mike Galbraith

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.