From: Miklos S. <mi...@sz...> - 2007-11-28 12:47:31
|
When writing a big file to a ubd disk, everything in uml slows down to a crawl, even though CPU usage is minimal. So I wanted to try the latency tracer from -rt, but it doesn't compile with UML: CC arch/um/kernel/asm-offsets.s In file included from arch/um/include/sysdep/kernel-offsets.h:2, from arch/um/kernel/asm-offsets.c:1: include/linux/sched.h: In function ‘set_tsk_need_resched_delayed’: include/linux/sched.h:2105: error: ‘TIF_NEED_RESCHED_DELAYED’ undeclared (first use in this function) include/linux/sched.h:2105: error: (Each undeclared identifier is reported only once include/linux/sched.h:2105: error: for each function it appears in.) include/linux/sched.h: In function ‘clear_tsk_need_resched_delayed’: include/linux/sched.h:2110: error: ‘TIF_NEED_RESCHED_DELAYED’ undeclared (first use in this function) include/linux/sched.h: In function ‘need_resched_delayed’: include/linux/sched.h:2115: error: ‘TIF_NEED_RESCHED_DELAYED’ undeclared (first use in this function) make[1]: *** [arch/um/kernel/asm-offsets.s] Error 1 make: *** [prepare0] Error 2 Ingo, do you think this route is worthwhile pursuing, or is it too difficult to make -rt work for UML? Thanks, Miklos |
From: Ingo M. <mi...@el...> - 2007-11-28 12:50:46
|
* Miklos Szeredi <mi...@sz...> wrote: > When writing a big file to a ubd disk, everything in uml slows down to > a crawl, even though CPU usage is minimal. > > So I wanted to try the latency tracer from -rt, but it doesn't compile > with UML: note that there are standalone patches as well: http://people.redhat.com/mingo/latency-tracing-patches/ so there's no forced need to use -rt. > Ingo, do you think this route is worthwhile pursuing, or is it too > difficult to make -rt work for UML? -rt should work for UML as well - but it needs porting (as every architecture). Ingo |
From: Miklos S. <mi...@sz...> - 2007-11-28 13:09:58
|
> * Miklos Szeredi <mi...@sz...> wrote: > > > When writing a big file to a ubd disk, everything in uml slows down to > > a crawl, even though CPU usage is minimal. > > > > So I wanted to try the latency tracer from -rt, but it doesn't compile > > with UML: > > note that there are standalone patches as well: > > http://people.redhat.com/mingo/latency-tracing-patches/ > > so there's no forced need to use -rt. Ah, forgotten about that. Unfortunately the latency tracer patch doesn't compile either: CC kernel/latency_trace.o kernel/latency_trace.c:28:21: error: asm/rtc.h: No such file or directory kernel/latency_trace.c:63:3: error: #error Implement cycles_to_usecs. kernel/latency_trace.c: In function ‘____trace’: kernel/latency_trace.c:658: error: implicit declaration of function ‘irqs_disabled_flags’ make[1]: *** [kernel/latency_trace.o] Error 1 Miklos |
From: Jeff D. <jd...@ad...> - 2007-11-28 15:08:53
|
On Wed, Nov 28, 2007 at 02:09:45PM +0100, Miklos Szeredi wrote: > kernel/latency_trace.c:28:21: error: asm/rtc.h: No such file or directory For things like this, look at the host's asm/foo.h and see if it's usable in UML (and contains things that you need). If it is, just make a asm-um/foo.h which just includes "asm/arch/foo.h". Jeff -- Work email - jdike at linux dot intel dot com |
From: Ingo M. <mi...@el...> - 2007-11-28 13:15:39
|
* Miklos Szeredi <mi...@sz...> wrote: > > so there's no forced need to use -rt. > > Ah, forgotten about that. > > Unfortunately the latency tracer patch doesn't compile either: > > CC kernel/latency_trace.o > kernel/latency_trace.c:28:21: error: asm/rtc.h: No such file or directory > kernel/latency_trace.c:63:3: error: #error Implement cycles_to_usecs. > kernel/latency_trace.c: In function ???____trace???: > kernel/latency_trace.c:658: error: implicit declaration of function ???irqs_disabled_flags??? > make[1]: *** [kernel/latency_trace.o] Error 1 hm, just fill those functions in - should be fairly trivial and we can carry those patches in -rt. (I'd suggest to create an empty asm-um/rtc.h stub as well, for consistency.) Ingo |
From: Ingo M. <mi...@el...> - 2007-11-28 13:15:58
|
* Ingo Molnar <mi...@el...> wrote: > > CC kernel/latency_trace.o > > kernel/latency_trace.c:28:21: error: asm/rtc.h: No such file or directory > > kernel/latency_trace.c:63:3: error: #error Implement cycles_to_usecs. > > kernel/latency_trace.c: In function ???____trace???: > > kernel/latency_trace.c:658: error: implicit declaration of function ???irqs_disabled_flags??? > > make[1]: *** [kernel/latency_trace.o] Error 1 > > hm, just fill those functions in - should be fairly trivial and we can > carry those patches in -rt. (I'd suggest to create an empty > asm-um/rtc.h stub as well, for consistency.) trivial == 'far easier than porting -rt to UML' :-) Ingo |
From: Miklos S. <mi...@sz...> - 2007-11-28 13:25:10
|
> > > CC kernel/latency_trace.o > > > kernel/latency_trace.c:28:21: error: asm/rtc.h: No such file or directory > > > kernel/latency_trace.c:63:3: error: #error Implement cycles_to_usecs. > > > kernel/latency_trace.c: In function ???____trace???: > > > kernel/latency_trace.c:658: error: implicit declaration of function ???irqs_disabled_flags??? > > > make[1]: *** [kernel/latency_trace.o] Error 1 > > > > hm, just fill those functions in - should be fairly trivial and we can > > carry those patches in -rt. (I'd suggest to create an empty > > asm-um/rtc.h stub as well, for consistency.) > > trivial == 'far easier than porting -rt to UML' :-) OK :) If I get stuck, I'll leave it to Jeff... Thanks, Miklos |
From: Jeff D. <jd...@ad...> - 2007-11-28 15:07:00
|
On Wed, Nov 28, 2007 at 01:47:20PM +0100, Miklos Szeredi wrote: > When writing a big file to a ubd disk, everything in uml slows down to > a crawl, even though CPU usage is minimal. What exactly is your test case? I have some patches which theoretically should help I/O performance which I've been sitting on because I can't find a case where they help. Jeff -- Work email - jdike at linux dot intel dot com |
From: Miklos S. <mi...@sz...> - 2007-11-28 15:35:33
|
> > When writing a big file to a ubd disk, everything in uml slows down to > > a crawl, even though CPU usage is minimal. > > What exactly is your test case? Something like: dd if=/host/tmp/bigfile of=/tmp/bigfile bs=1048576 count=100 and run 'top' or 'watch something' in another terminal, which sometimes completely stops updating during the write. > I have some patches which theoretically should help I/O performance > which I've been sitting on because I can't find a case where they > help. It's not I/O performance I'm worried about, but scheduling latencies. CPU use inside and outside the UML is minimal, so I can't see where this slowdown comes from. Miklos |
From: Miklos S. <mi...@sz...> - 2007-11-28 15:38:51
|
> On Wed, Nov 28, 2007 at 02:09:45PM +0100, Miklos Szeredi wrote: > > kernel/latency_trace.c:28:21: error: asm/rtc.h: No such file or directory > > For things like this, look at the host's asm/foo.h and see if it's > usable in UML (and contains things that you need). If it is, just > make a asm-um/foo.h which just includes "asm/arch/foo.h". Yeah, I know that trick :) It doesn't help in this case. I've gotten as far as realizing that the latency tracer needs the irqflags tracing (Documentation/irqflags-tracing.tx) and that UML doesn't yet support that. Miklos |
From: Ingo M. <mi...@el...> - 2007-11-28 15:42:10
|
* Miklos Szeredi <mi...@sz...> wrote: > > On Wed, Nov 28, 2007 at 02:09:45PM +0100, Miklos Szeredi wrote: > > > kernel/latency_trace.c:28:21: error: asm/rtc.h: No such file or directory > > > > For things like this, look at the host's asm/foo.h and see if it's > > usable in UML (and contains things that you need). If it is, just > > make a asm-um/foo.h which just includes "asm/arch/foo.h". > > Yeah, I know that trick :) > > It doesn't help in this case. I've gotten as far as realizing that > the latency tracer needs the irqflags tracing > (Documentation/irqflags-tracing.tx) and that UML doesn't yet support > that. it doesnt need it - turn IRQOFF_TRACING off. You want FUNCTION_TRACING to work (and perhaps WAKEUP_TIMING) so that you can take a look at what's going on, right? Ingo |
From: Jeff D. <jd...@ad...> - 2007-11-28 17:38:56
|
On Wed, Nov 28, 2007 at 04:38:39PM +0100, Miklos Szeredi wrote: > It doesn't help in this case. I've gotten as far as realizing that > the latency tracer needs the irqflags tracing > (Documentation/irqflags-tracing.tx) and that UML doesn't yet support > that. Try the patch below - no guarantees, however, it boots here and printks stuff. -- Work email - jdike at linux dot intel dot com Index: linux-2.6.22/arch/um/Kconfig =================================================================== --- linux-2.6.22.orig/arch/um/Kconfig 2007-11-28 10:57:24.000000000 -0500 +++ linux-2.6.22/arch/um/Kconfig 2007-11-28 12:36:39.000000000 -0500 @@ -33,18 +33,13 @@ config PCI config PCMCIA bool -# Yet to do! -config TRACE_IRQFLAGS_SUPPORT - bool - default n - config LOCKDEP_SUPPORT bool default y config STACKTRACE_SUPPORT bool - default n + default y config GENERIC_CALIBRATE_DELAY bool Index: linux-2.6.22/arch/um/Kconfig.debug =================================================================== --- linux-2.6.22.orig/arch/um/Kconfig.debug 2007-11-28 10:57:22.000000000 -0500 +++ linux-2.6.22/arch/um/Kconfig.debug 2007-11-28 11:34:19.000000000 -0500 @@ -2,6 +2,10 @@ menu "Kernel hacking" source "lib/Kconfig.debug" +config TRACE_IRQFLAGS_SUPPORT + bool + default y + config GPROF bool "Enable gprof support" depends on DEBUG_INFO && FRAME_POINTER Index: linux-2.6.22/arch/um/include/sysdep-i386/tls.h =================================================================== --- linux-2.6.22.orig/arch/um/include/sysdep-i386/tls.h 2007-11-28 12:36:28.000000000 -0500 +++ linux-2.6.22/arch/um/include/sysdep-i386/tls.h 2007-11-28 12:36:39.000000000 -0500 @@ -1,8 +1,6 @@ #ifndef _SYSDEP_TLS_H #define _SYSDEP_TLS_H -# ifndef __KERNEL__ - /* Change name to avoid conflicts with the original one from <asm/ldt.h>, which * may be named user_desc (but in 2.4 and in header matching its API was named * modify_ldt_ldt_s). */ @@ -19,13 +17,6 @@ typedef struct um_dup_user_desc { unsigned int useable:1; } user_desc_t; -# else /* __KERNEL__ */ - -# include <asm/ldt.h> -typedef struct user_desc user_desc_t; - -# endif /* __KERNEL__ */ - #define GDT_ENTRY_TLS_MIN_I386 6 #define GDT_ENTRY_TLS_MIN_X86_64 12 Index: linux-2.6.22/arch/um/include/sysdep-x86_64/tls.h =================================================================== --- linux-2.6.22.orig/arch/um/include/sysdep-x86_64/tls.h 2007-11-28 12:36:28.000000000 -0500 +++ linux-2.6.22/arch/um/include/sysdep-x86_64/tls.h 2007-11-28 12:36:39.000000000 -0500 @@ -1,8 +1,6 @@ #ifndef _SYSDEP_TLS_H #define _SYSDEP_TLS_H -# ifndef __KERNEL__ - /* Change name to avoid conflicts with the original one from <asm/ldt.h>, which * may be named user_desc (but in 2.4 and in header matching its API was named * modify_ldt_ldt_s). */ @@ -20,10 +18,4 @@ typedef struct um_dup_user_desc { unsigned int lm:1; } user_desc_t; -# else /* __KERNEL__ */ - -# include <asm/ldt.h> -typedef struct user_desc user_desc_t; - -# endif /* __KERNEL__ */ #endif /* _SYSDEP_TLS_H */ Index: linux-2.6.22/arch/um/kernel/sysrq.c =================================================================== --- linux-2.6.22.orig/arch/um/kernel/sysrq.c 2007-11-28 10:57:22.000000000 -0500 +++ linux-2.6.22/arch/um/kernel/sysrq.c 2007-11-28 12:36:39.000000000 -0500 @@ -7,6 +7,7 @@ #include "linux/kernel.h" #include "linux/module.h" #include "linux/kallsyms.h" +#include "linux/stacktrace.h" #include "asm/page.h" #include "asm/processor.h" #include "sysrq.h" @@ -78,3 +79,4 @@ void show_stack(struct task_struct *task printk("Call Trace: \n"); show_trace(task, esp); } + Index: linux-2.6.22/arch/um/sys-i386/tls.c =================================================================== --- linux-2.6.22.orig/arch/um/sys-i386/tls.c 2007-11-28 12:36:28.000000000 -0500 +++ linux-2.6.22/arch/um/sys-i386/tls.c 2007-11-28 12:36:39.000000000 -0500 @@ -24,7 +24,8 @@ int do_set_thread_area(struct user_desc u32 cpu; cpu = get_cpu(); - ret = os_set_thread_area(info, userspace_pid[cpu]); + ret = os_set_thread_area((struct um_dup_user_desc *) info, + userspace_pid[cpu]); put_cpu(); if (ret) @@ -40,7 +41,8 @@ int do_get_thread_area(struct user_desc u32 cpu; cpu = get_cpu(); - ret = os_get_thread_area(info, userspace_pid[cpu]); + ret = os_get_thread_area((struct um_dup_user_desc *) info, + userspace_pid[cpu]); put_cpu(); if (ret) Index: linux-2.6.22/include/asm-um/irqflags.h =================================================================== --- linux-2.6.22.orig/include/asm-um/irqflags.h 2007-11-28 10:57:22.000000000 -0500 +++ linux-2.6.22/include/asm-um/irqflags.h 2007-11-28 11:34:19.000000000 -0500 @@ -1,6 +1,31 @@ #ifndef __UM_IRQFLAGS_H #define __UM_IRQFLAGS_H -/* Empty for now */ +#include "os.h" + +static inline int raw_irqs_disabled_flags(unsigned long flags) +{ + return flags == 0; +} + +static inline void raw_local_irq_disable(void) +{ + block_signals(); +} + +static inline void raw_local_irq_enable(void) +{ + unblock_signals(); +} + +static inline void raw_local_irq_restore(unsigned long flags) +{ + set_signals(flags); +} + +#define raw_local_irq_save(flags) do { typecheck(unsigned long, flags); \ + (flags) = get_signals(); \ + block_signals(); } while(0) + #endif Index: linux-2.6.22/arch/um/include/os.h =================================================================== --- linux-2.6.22.orig/arch/um/include/os.h 2007-11-28 12:36:28.000000000 -0500 +++ linux-2.6.22/arch/um/include/os.h 2007-11-28 12:36:39.000000000 -0500 @@ -213,8 +213,8 @@ extern int helper_wait(int pid); /* tls.c */ -extern int os_set_thread_area(user_desc_t *info, int pid); -extern int os_get_thread_area(user_desc_t *info, int pid); +extern int os_set_thread_area(struct um_dup_user_desc *info, int pid); +extern int os_get_thread_area(struct um_dup_user_desc *info, int pid); /* umid.c */ extern int umid_file_name(char *name, char *buf, int len); Index: linux-2.6.22/arch/um/kernel/Makefile =================================================================== --- linux-2.6.22.orig/arch/um/kernel/Makefile 2007-11-28 12:36:28.000000000 -0500 +++ linux-2.6.22/arch/um/kernel/Makefile 2007-11-28 12:36:39.000000000 -0500 @@ -15,6 +15,8 @@ obj-$(CONFIG_BLK_DEV_INITRD) += initrd.o obj-$(CONFIG_GPROF) += gprof_syms.o obj-$(CONFIG_GCOV) += gmon_syms.o +subarch-obj-$(CONFIG_STACKTRACE) += kernel/stacktrace.o + USER_OBJS := config.o include arch/um/scripts/Makefile.rules Index: linux-2.6.22/arch/um/sys-i386/sysrq.c =================================================================== --- linux-2.6.22.orig/arch/um/sys-i386/sysrq.c 2007-11-28 12:36:28.000000000 -0500 +++ linux-2.6.22/arch/um/sys-i386/sysrq.c 2007-11-28 12:36:39.000000000 -0500 @@ -7,6 +7,7 @@ #include "linux/smp.h" #include "linux/sched.h" #include "linux/kallsyms.h" +#include <asm/stacktrace.h> #include "asm/ptrace.h" #include "sysrq.h" @@ -44,33 +45,97 @@ static inline int valid_stack_ptr(struct } /* Adapted from i386 (we also print the address we read from). */ -static inline unsigned long print_context_stack(struct thread_info *tinfo, - unsigned long *stack, unsigned long ebp) +static unsigned long print_context_stack(struct thread_info *tinfo, + unsigned long *stack, unsigned long ebp, + const struct stacktrace_ops *ops, + void *data) { unsigned long addr; #ifdef CONFIG_FRAME_POINTER while (valid_stack_ptr(tinfo, (void *)ebp)) { addr = *(unsigned long *)(ebp + 4); - printk("%08lx: [<%08lx>]", ebp + 4, addr); - print_symbol(" %s", addr); - printk("\n"); + ops->address(data, addr); ebp = *(unsigned long *)ebp; } #else while (valid_stack_ptr(tinfo, stack)) { addr = *stack; - if (__kernel_text_address(addr)) { - printk("%08lx: [<%08lx>]", (unsigned long) stack, addr); - print_symbol(" %s", addr); - printk("\n"); - } + if (__kernel_text_address(addr)) + ops->address(data, addr); stack++; } #endif return ebp; } +void dump_trace(struct task_struct *task, struct pt_regs *regs, + unsigned long *stack, const struct stacktrace_ops *ops, + void *data) +{ + struct thread_info *context; + unsigned long ebp = 0; + + if (!task) + task = current; + + if (!stack) { + unsigned long dummy; + stack = &dummy; + if (task != current) + stack = (unsigned long *) KSTK_ESP(task); + } + +#ifdef CONFIG_FRAME_POINTER + if (!ebp) { + if (task == current) { + /* Grab ebp right from our regs */ + asm ("movl %%ebp, %0" : "=r" (ebp) : ); + } else { + ebp = KSTK_EBP(task); + } + } +#endif + + context = (struct thread_info *) + ((unsigned long)stack & (~(THREAD_SIZE - 1))); + ebp = print_context_stack(context, stack, ebp, ops, data); +} + +static void show_trace_warning_symbol(void *data, char *msg, + unsigned long symbol) +{ + printk(data); + print_symbol(msg, symbol); + printk("\n"); +} + +static void show_trace_warning(void *data, char *msg) +{ + printk("%s%s\n", (char *) data, msg); +} + +static int show_trace_stack(void *data, char *name) +{ + return 0; +} + +/* + * Print one address/symbol entries per line. + */ +static void show_trace_address(void *data, unsigned long addr) +{ + printk("%s [<%08lx>] ", (char *) data, addr); + print_symbol("%s\n", addr); +} + +static const struct stacktrace_ops show_trace_ops = { + .warning = show_trace_warning, + .warning_symbol = show_trace_warning_symbol, + .stack = show_trace_stack, + .address = show_trace_address, +}; + void show_trace(struct task_struct* task, unsigned long * stack) { unsigned long ebp; @@ -79,7 +144,8 @@ void show_trace(struct task_struct* task /* Turn this into BUG_ON if possible. */ if (!stack) { stack = (unsigned long*) &stack; - printk("show_trace: got NULL stack, implicit assumption task == current"); + printk("show_trace: got NULL stack, implicit assumption " + "task == current"); WARN_ON(1); } @@ -94,7 +160,7 @@ void show_trace(struct task_struct* task context = (struct thread_info *) ((unsigned long)stack & (~(THREAD_SIZE - 1))); - print_context_stack(context, stack, ebp); + print_context_stack(context, stack, ebp, &show_trace_ops, ""); printk("\n"); } Index: linux-2.6.22/include/asm-um/stacktrace.h =================================================================== --- /dev/null 1970-01-01 00:00:00.000000000 +0000 +++ linux-2.6.22/include/asm-um/stacktrace.h 2007-11-28 12:36:39.000000000 -0500 @@ -0,0 +1,6 @@ +#ifndef __UM_STACKTRACE_H +#define __UM_STACKTRACE_H + +#include "asm/arch/stacktrace.h" + +#endif |
From: Miklos S. <mi...@sz...> - 2007-11-28 16:00:20
|
> > > On Wed, Nov 28, 2007 at 02:09:45PM +0100, Miklos Szeredi wrote: > > > > kernel/latency_trace.c:28:21: error: asm/rtc.h: No such file or directory > > > > > > For things like this, look at the host's asm/foo.h and see if it's > > > usable in UML (and contains things that you need). If it is, just > > > make a asm-um/foo.h which just includes "asm/arch/foo.h". > > > > Yeah, I know that trick :) > > > > It doesn't help in this case. I've gotten as far as realizing that > > the latency tracer needs the irqflags tracing > > (Documentation/irqflags-tracing.tx) and that UML doesn't yet support > > that. > > it doesnt need it - turn IRQOFF_TRACING off. # CONFIG_CRITICAL_IRQSOFF_TIMING is not set This seems to be off. But latency_trace.c uses irqs_disabled_flags(), which is defined in <linux/irqflags.h> only if CONFIG_TRACE_IRQFLAGS_SUPPORT is set. So perhaps latency_trace.c should be using raw_irqs_disabled_flags() instead. But UML doesn't define that either and I have no idea how to do that, so this is still not solved yet. Miklos # # Automatically generated make config: don't edit # Linux kernel version: 2.6.24-rc3 # Wed Nov 28 16:43:30 2007 # CONFIG_DEFCONFIG_LIST="arch/$ARCH/defconfig" CONFIG_GENERIC_HARDIRQS=y CONFIG_UML=y CONFIG_MMU=y CONFIG_NO_IOMEM=y # CONFIG_TRACE_IRQFLAGS_SUPPORT is not set CONFIG_LOCKDEP_SUPPORT=y # CONFIG_STACKTRACE_SUPPORT is not set CONFIG_GENERIC_CALIBRATE_DELAY=y CONFIG_GENERIC_BUG=y CONFIG_GENERIC_TIME=y CONFIG_GENERIC_CLOCKEVENTS=y CONFIG_IRQ_RELEASE_METHOD=y # # UML-specific options # # CONFIG_STATIC_LINK is not set # # Host processor type and features # # CONFIG_M386 is not set # CONFIG_M486 is not set # CONFIG_M586 is not set # CONFIG_M586TSC is not set # CONFIG_M586MMX is not set # CONFIG_M686 is not set # CONFIG_MPENTIUMII is not set # CONFIG_MPENTIUMIII is not set # CONFIG_MPENTIUMM is not set CONFIG_MPENTIUM4=y # CONFIG_MK6 is not set # CONFIG_MK7 is not set # CONFIG_MK8 is not set # CONFIG_MCRUSOE is not set # CONFIG_MEFFICEON is not set # CONFIG_MWINCHIPC6 is not set # CONFIG_MWINCHIP2 is not set # CONFIG_MWINCHIP3D is not set # CONFIG_MGEODEGX1 is not set # CONFIG_MGEODE_LX is not set # CONFIG_MCYRIXIII is not set # CONFIG_MVIAC3_2 is not set # CONFIG_MVIAC7 is not set # CONFIG_MPSC is not set # CONFIG_MCORE2 is not set # CONFIG_GENERIC_CPU is not set # CONFIG_X86_GENERIC is not set CONFIG_X86_CMPXCHG=y CONFIG_X86_L1_CACHE_SHIFT=7 CONFIG_X86_XADD=y CONFIG_X86_WP_WORKS_OK=y CONFIG_X86_INVLPG=y CONFIG_X86_BSWAP=y CONFIG_X86_POPAD_OK=y CONFIG_X86_GOOD_APIC=y CONFIG_X86_INTEL_USERCOPY=y CONFIG_X86_USE_PPRO_CHECKSUM=y CONFIG_X86_TSC=y CONFIG_X86_CMOV=y CONFIG_X86_MINIMUM_CPU_FAMILY=4 CONFIG_UML_X86=y CONFIG_X86_32=y CONFIG_RWSEM_XCHGADD_ALGORITHM=y # CONFIG_64BIT is not set CONFIG_SEMAPHORE_SLEEPERS=y CONFIG_HOST_VMSPLIT_3G=y # CONFIG_HOST_VMSPLIT_3G_OPT is not set # CONFIG_HOST_VMSPLIT_2G is not set # CONFIG_HOST_VMSPLIT_1G is not set CONFIG_TOP_ADDR=0xC0000000 # CONFIG_3_LEVEL_PGTABLES is not set CONFIG_ARCH_HAS_SC_SIGNALS=y CONFIG_ARCH_REUSE_HOST_VSYSCALL_AREA=y CONFIG_GENERIC_HWEIGHT=y CONFIG_SELECT_MEMORY_MODEL=y CONFIG_FLATMEM_MANUAL=y # CONFIG_DISCONTIGMEM_MANUAL is not set # CONFIG_SPARSEMEM_MANUAL is not set CONFIG_FLATMEM=y CONFIG_FLAT_NODE_MEM_MAP=y # CONFIG_SPARSEMEM_STATIC is not set # CONFIG_SPARSEMEM_VMEMMAP_ENABLE is not set CONFIG_SPLIT_PTLOCK_CPUS=4 # CONFIG_RESOURCES_64BIT is not set CONFIG_ZONE_DMA_FLAG=0 CONFIG_VIRT_TO_BUS=y # CONFIG_TICK_ONESHOT is not set # CONFIG_NO_HZ is not set # CONFIG_HIGH_RES_TIMERS is not set CONFIG_GENERIC_CLOCKEVENTS_BUILD=y CONFIG_LD_SCRIPT_DYN=y CONFIG_NET=y CONFIG_BINFMT_ELF=y # CONFIG_BINFMT_AOUT is not set # CONFIG_BINFMT_MISC is not set CONFIG_HOSTFS=y # CONFIG_HPPFS is not set CONFIG_MCONSOLE=y CONFIG_MAGIC_SYSRQ=y # CONFIG_SMP is not set CONFIG_NEST_LEVEL=0 # CONFIG_HIGHMEM is not set CONFIG_KERNEL_STACK_ORDER=3 # # General setup # CONFIG_EXPERIMENTAL=y CONFIG_BROKEN_ON_SMP=y CONFIG_INIT_ENV_ARG_LIMIT=128 CONFIG_LOCALVERSION="" # CONFIG_LOCALVERSION_AUTO is not set CONFIG_SWAP=y # CONFIG_SYSVIPC is not set # CONFIG_POSIX_MQUEUE is not set # CONFIG_BSD_PROCESS_ACCT is not set # CONFIG_TASKSTATS is not set # CONFIG_USER_NS is not set # CONFIG_PID_NS is not set # CONFIG_AUDIT is not set # CONFIG_IKCONFIG is not set CONFIG_LOG_BUF_SHIFT=14 # CONFIG_CGROUPS is not set CONFIG_FAIR_GROUP_SCHED=y CONFIG_FAIR_USER_SCHED=y # CONFIG_FAIR_CGROUP_SCHED is not set CONFIG_SYSFS_DEPRECATED=y # CONFIG_RELAY is not set # CONFIG_BLK_DEV_INITRD is not set # CONFIG_CC_OPTIMIZE_FOR_SIZE is not set CONFIG_SYSCTL=y # CONFIG_EMBEDDED is not set CONFIG_UID16=y CONFIG_SYSCTL_SYSCALL=y CONFIG_KALLSYMS=y # CONFIG_KALLSYMS_ALL is not set # CONFIG_KALLSYMS_EXTRA_PASS is not set CONFIG_HOTPLUG=y CONFIG_PRINTK=y CONFIG_BUG=y CONFIG_ELF_CORE=y CONFIG_BASE_FULL=y CONFIG_FUTEX=y CONFIG_ANON_INODES=y CONFIG_EPOLL=y CONFIG_SIGNALFD=y CONFIG_EVENTFD=y CONFIG_SHMEM=y CONFIG_VM_EVENT_COUNTERS=y CONFIG_SLAB=y # CONFIG_SLUB is not set # CONFIG_SLOB is not set CONFIG_RT_MUTEXES=y # CONFIG_TINY_SHMEM is not set CONFIG_BASE_SMALL=0 CONFIG_MODULES=y CONFIG_MODULE_UNLOAD=y CONFIG_MODULE_FORCE_UNLOAD=y # CONFIG_MODVERSIONS is not set # CONFIG_MODULE_SRCVERSION_ALL is not set # CONFIG_KMOD is not set CONFIG_BLOCK=y # CONFIG_LBD is not set # CONFIG_BLK_DEV_IO_TRACE is not set # CONFIG_LSF is not set # CONFIG_BLK_DEV_BSG is not set # # IO Schedulers # CONFIG_IOSCHED_NOOP=y # CONFIG_IOSCHED_AS is not set # CONFIG_IOSCHED_DEADLINE is not set # CONFIG_IOSCHED_CFQ is not set # CONFIG_DEFAULT_AS is not set # CONFIG_DEFAULT_DEADLINE is not set # CONFIG_DEFAULT_CFQ is not set CONFIG_DEFAULT_NOOP=y CONFIG_DEFAULT_IOSCHED="noop" CONFIG_BLK_DEV=y CONFIG_BLK_DEV_UBD=y # CONFIG_BLK_DEV_UBD_SYNC is not set CONFIG_BLK_DEV_COW_COMMON=y CONFIG_BLK_DEV_LOOP=y # CONFIG_BLK_DEV_CRYPTOLOOP is not set # CONFIG_BLK_DEV_NBD is not set # CONFIG_BLK_DEV_RAM is not set # CONFIG_ATA_OVER_ETH is not set # # Character Devices # CONFIG_STDERR_CONSOLE=y CONFIG_STDIO_CONSOLE=y # CONFIG_SSL is not set # CONFIG_NULL_CHAN is not set # CONFIG_PORT_CHAN is not set # CONFIG_PTY_CHAN is not set # CONFIG_TTY_CHAN is not set CONFIG_XTERM_CHAN=y CONFIG_NOCONFIG_CHAN=y CONFIG_CON_ZERO_CHAN="fd:0,fd:1" CONFIG_CON_CHAN="xterm" CONFIG_SSL_CHAN="pty" CONFIG_UNIX98_PTYS=y # CONFIG_LEGACY_PTYS is not set # CONFIG_RAW_DRIVER is not set # CONFIG_WATCHDOG is not set # CONFIG_UML_SOUND is not set # CONFIG_SOUND is not set # CONFIG_HOSTAUDIO is not set # CONFIG_HW_RANDOM is not set # CONFIG_UML_RANDOM is not set # CONFIG_MMAPPER is not set # # Generic Driver Options # CONFIG_UEVENT_HELPER_PATH="/sbin/hotplug" CONFIG_STANDALONE=y CONFIG_PREVENT_FIRMWARE_BUILD=y # CONFIG_FW_LOADER is not set # CONFIG_DEBUG_DRIVER is not set # CONFIG_DEBUG_DEVRES is not set # CONFIG_SYS_HYPERVISOR is not set # # Networking # # # Networking options # # CONFIG_PACKET is not set CONFIG_UNIX=y CONFIG_XFRM=y # CONFIG_XFRM_USER is not set # CONFIG_XFRM_SUB_POLICY is not set # CONFIG_XFRM_MIGRATE is not set # CONFIG_NET_KEY is not set CONFIG_INET=y # CONFIG_IP_MULTICAST is not set # CONFIG_IP_ADVANCED_ROUTER is not set CONFIG_IP_FIB_HASH=y # CONFIG_IP_PNP is not set # CONFIG_NET_IPIP is not set # CONFIG_NET_IPGRE is not set # CONFIG_ARPD is not set # CONFIG_SYN_COOKIES is not set # CONFIG_INET_AH is not set # CONFIG_INET_ESP is not set # CONFIG_INET_IPCOMP is not set # CONFIG_INET_XFRM_TUNNEL is not set # CONFIG_INET_TUNNEL is not set CONFIG_INET_XFRM_MODE_TRANSPORT=y CONFIG_INET_XFRM_MODE_TUNNEL=y CONFIG_INET_XFRM_MODE_BEET=y # CONFIG_INET_LRO is not set CONFIG_INET_DIAG=y CONFIG_INET_TCP_DIAG=y # CONFIG_TCP_CONG_ADVANCED is not set CONFIG_TCP_CONG_CUBIC=y CONFIG_DEFAULT_TCP_CONG="cubic" # CONFIG_TCP_MD5SIG is not set # CONFIG_IPV6 is not set # CONFIG_INET6_XFRM_TUNNEL is not set # CONFIG_INET6_TUNNEL is not set # CONFIG_NETWORK_SECMARK is not set # CONFIG_NETFILTER is not set # CONFIG_IP_DCCP is not set # CONFIG_IP_SCTP is not set # CONFIG_TIPC is not set # CONFIG_ATM is not set # CONFIG_BRIDGE is not set # CONFIG_VLAN_8021Q is not set # CONFIG_DECNET is not set # CONFIG_LLC2 is not set # CONFIG_IPX is not set # CONFIG_ATALK is not set # CONFIG_X25 is not set # CONFIG_LAPB is not set # CONFIG_ECONET is not set # CONFIG_WAN_ROUTER is not set # CONFIG_NET_SCHED is not set # # Network testing # # CONFIG_NET_PKTGEN is not set # CONFIG_HAMRADIO is not set # CONFIG_IRDA is not set # CONFIG_BT is not set # CONFIG_AF_RXRPC is not set # # Wireless # # CONFIG_CFG80211 is not set # CONFIG_WIRELESS_EXT is not set # CONFIG_MAC80211 is not set # CONFIG_IEEE80211 is not set # CONFIG_RFKILL is not set # CONFIG_NET_9P is not set # # UML Network Devices # CONFIG_UML_NET=y # CONFIG_UML_NET_ETHERTAP is not set CONFIG_UML_NET_TUNTAP=y # CONFIG_UML_NET_SLIP is not set # CONFIG_UML_NET_DAEMON is not set # CONFIG_UML_NET_VDE is not set # CONFIG_UML_NET_MCAST is not set # CONFIG_UML_NET_PCAP is not set # CONFIG_UML_NET_SLIRP is not set # CONFIG_NETDEVICES is not set # CONFIG_CONNECTOR is not set # # File systems # CONFIG_EXT2_FS=y CONFIG_EXT2_FS_XATTR=y CONFIG_EXT2_FS_POSIX_ACL=y CONFIG_EXT2_FS_SECURITY=y CONFIG_EXT2_FS_XIP=y CONFIG_FS_XIP=y CONFIG_EXT3_FS=y CONFIG_EXT3_FS_XATTR=y CONFIG_EXT3_FS_POSIX_ACL=y CONFIG_EXT3_FS_SECURITY=y # CONFIG_EXT4DEV_FS is not set CONFIG_JBD=y CONFIG_FS_MBCACHE=y # CONFIG_REISERFS_FS is not set # CONFIG_JFS_FS is not set CONFIG_FS_POSIX_ACL=y # CONFIG_XFS_FS is not set # CONFIG_GFS2_FS is not set # CONFIG_OCFS2_FS is not set # CONFIG_MINIX_FS is not set # CONFIG_ROMFS_FS is not set CONFIG_INOTIFY=y CONFIG_INOTIFY_USER=y # CONFIG_QUOTA is not set CONFIG_DNOTIFY=y # CONFIG_AUTOFS_FS is not set # CONFIG_AUTOFS4_FS is not set CONFIG_FUSE_FS=y # # CD-ROM/DVD Filesystems # # CONFIG_ISO9660_FS is not set # CONFIG_UDF_FS is not set # # DOS/FAT/NT Filesystems # # CONFIG_MSDOS_FS is not set # CONFIG_VFAT_FS is not set # CONFIG_NTFS_FS is not set # # Pseudo filesystems # CONFIG_PROC_FS=y CONFIG_PROC_KCORE=y CONFIG_PROC_SYSCTL=y CONFIG_SYSFS=y CONFIG_TMPFS=y # CONFIG_TMPFS_POSIX_ACL is not set # CONFIG_HUGETLB_PAGE is not set # CONFIG_CONFIGFS_FS is not set # # Miscellaneous filesystems # # CONFIG_ADFS_FS is not set # CONFIG_AFFS_FS is not set # CONFIG_HFS_FS is not set # CONFIG_HFSPLUS_FS is not set # CONFIG_BEFS_FS is not set # CONFIG_BFS_FS is not set # CONFIG_EFS_FS is not set # CONFIG_CRAMFS is not set # CONFIG_VXFS_FS is not set # CONFIG_HPFS_FS is not set # CONFIG_QNX4FS_FS is not set # CONFIG_SYSV_FS is not set # CONFIG_UFS_FS is not set CONFIG_NETWORK_FILESYSTEMS=y # CONFIG_NFS_FS is not set # CONFIG_NFSD is not set # CONFIG_SMB_FS is not set # CONFIG_CIFS is not set # CONFIG_NCP_FS is not set # CONFIG_CODA_FS is not set # CONFIG_AFS_FS is not set # # Partition Types # # CONFIG_PARTITION_ADVANCED is not set CONFIG_MSDOS_PARTITION=y # CONFIG_NLS is not set # CONFIG_DLM is not set # # Security options # # CONFIG_KEYS is not set # CONFIG_SECURITY is not set # CONFIG_SECURITY_FILE_CAPABILITIES is not set # CONFIG_CRYPTO is not set # # Library routines # # CONFIG_CRC_CCITT is not set # CONFIG_CRC16 is not set # CONFIG_CRC_ITU_T is not set # CONFIG_CRC32 is not set # CONFIG_CRC7 is not set # CONFIG_LIBCRC32C is not set CONFIG_PLIST=y CONFIG_HAS_DMA=y # # SCSI device support # # CONFIG_RAID_ATTRS is not set # CONFIG_SCSI is not set # CONFIG_SCSI_DMA is not set # CONFIG_SCSI_NETLINK is not set # CONFIG_MD is not set # CONFIG_INPUT is not set CONFIG_INSTRUMENTATION=y # CONFIG_PROFILING is not set # CONFIG_MARKERS is not set # # Kernel hacking # CONFIG_PRINTK_TIME=y # CONFIG_ENABLE_WARN_DEPRECATED is not set # CONFIG_ENABLE_MUST_CHECK is not set # CONFIG_UNUSED_SYMBOLS is not set # CONFIG_DEBUG_FS is not set CONFIG_DEBUG_KERNEL=y # CONFIG_DEBUG_SHIRQ is not set # CONFIG_DETECT_SOFTLOCKUP is not set # CONFIG_SCHED_DEBUG is not set # CONFIG_SCHEDSTATS is not set # CONFIG_TIMER_STATS is not set # CONFIG_DEBUG_SLAB is not set # CONFIG_DEBUG_RT_MUTEXES is not set # CONFIG_RT_MUTEX_TESTER is not set CONFIG_DEBUG_SPINLOCK=y CONFIG_DEBUG_MUTEXES=y CONFIG_DEBUG_SPINLOCK_SLEEP=y # CONFIG_DEBUG_LOCKING_API_SELFTESTS is not set CONFIG_STACKTRACE=y CONFIG_EVENT_TRACE=y CONFIG_FUNCTION_TRACE=y # CONFIG_WAKEUP_TIMING is not set # CONFIG_CRITICAL_IRQSOFF_TIMING is not set CONFIG_MCOUNT=y # CONFIG_DEBUG_KOBJECT is not set CONFIG_DEBUG_BUGVERBOSE=y CONFIG_DEBUG_INFO=y # CONFIG_DEBUG_VM is not set CONFIG_DEBUG_LIST=y # CONFIG_DEBUG_SG is not set CONFIG_FRAME_POINTER=y CONFIG_FORCED_INLINING=y # CONFIG_BOOT_PRINTK_DELAY is not set # CONFIG_RCU_TORTURE_TEST is not set # CONFIG_FAULT_INJECTION is not set # CONFIG_SAMPLES is not set # CONFIG_GPROF is not set # CONFIG_GCOV is not set # CONFIG_DEBUG_STACK_USAGE is not set |
From: Ingo M. <mi...@el...> - 2007-11-28 16:05:17
|
* Miklos Szeredi <mi...@sz...> wrote: > > it doesnt need it - turn IRQOFF_TRACING off. > > # CONFIG_CRITICAL_IRQSOFF_TIMING is not set > > This seems to be off. > > But latency_trace.c uses irqs_disabled_flags(), which is defined in > <linux/irqflags.h> only if CONFIG_TRACE_IRQFLAGS_SUPPORT is set. > > So perhaps latency_trace.c should be using raw_irqs_disabled_flags() > instead. But UML doesn't define that either and I have no idea how to > do that, so this is still not solved yet. irqs_disabled_flags() gives us a nonessential bit of the trace output: _------=> CPU# / _-----=> irqs-off | / _----=> need-resched || / _---=> hardirq/softirq ||| / _--=> preempt-depth |||| / ||||| delay cmd pid ||||| time | caller \ / ||||| \ | / privoxy-12926 1.Ns1 0us : ktime_get_ts (ktime_get) privoxy-12926 1.Ns1 0us : getnstimeofday (ktime_get_ts) privoxy-12926 1.Ns1 1us : set_normalized_timespec (ktime_get_ts) privoxy-12926 1.Ns1 1us : rb_first (htb_dequeue) it's the 'irqs-off' flag, which is 'd', 'D' or '.'. so you can define irqs_off_flags to always-0 and you should be able to get pretty good traces still. It should have no functional impact. Ingo |
From: Miklos S. <mi...@sz...> - 2007-11-28 16:58:10
|
> so you can define irqs_off_flags to always-0 and you should be able to > get pretty good traces still. It should have no functional impact. OK, managed to make it compile, but then something goes wrong in tracer_alloc_bootmem(). Jeff? (attaching patch, which goes on top of latency-tracer-v2.6.24-rc2-git5-combo.patch, which goes on top of 2.6.24-rc3) Miklos #0 0xffffe410 in __kernel_vsyscall () #1 0xf7e498f5 in raise () from /lib/libc.so.6 #2 0xf7e4b1e1 in abort () from /lib/libc.so.6 #3 0x0806ba54 in os_dump_core () at arch/um/os-Linux/util.c:147 #4 0x0805d009 in panic_exit (self=0x8239594, unused1=0, unused2=0x8250360) at arch/um/kernel/um_arch.c:370 #5 0x080927d7 in notifier_call_chain (nl=0x824032c, val=0, v=0x8250360, nr_to_call=-1, nr_calls=0x0) at kernel/notifier.c:69 #6 0x080928b8 in __atomic_notifier_call_chain (nh=0x824031c, val=0, v=0x8250360, nr_to_call=-1, nr_calls=0x0) at kernel/notifier.c:158 #7 0x080928ee in atomic_notifier_call_chain (nh=0x824031c, val=0, v=0x8250360) at kernel/notifier.c:167 #8 0x08077e17 in panic (fmt=0x81f82b6 "Out of memory") at kernel/panic.c:101 #9 0x0804f6d0 in __alloc_bootmem (size=33554432, align=128, goal=4294967295) at mm/bootmem.c:442 #10 0x0804ea0d in tracer_alloc_bootmem (size=33554432) at kernel/latency_trace.c:2690 #11 0x0804ea78 in init_tracer () at kernel/latency_trace.c:2718 #12 0x08049668 in start_kernel () at init/main.c:590 #13 0x0804b00b in start_kernel_proc (unused=0x0) at arch/um/kernel/skas/process.c:40 #14 0x08069672 in run_kernel_thread (fn=0x804afda <start_kernel_proc>, arg=0x0, jmp_ptr=0x823922c) at arch/um/os-Linux/process.c:264 #15 0x0805a22d in new_thread_handler () at arch/um/kernel/process.c:153 #16 0x00000000 in ?? () ---------------- Index: linux/include/asm-um/rtc.h =================================================================== --- /dev/null 1970-01-01 00:00:00.000000000 +0000 +++ linux/include/asm-um/rtc.h 2007-11-28 17:41:42.000000000 +0100 @@ -0,0 +1 @@ +/* stub for the latency tracer */ Index: linux/include/asm-um/irqflags.h =================================================================== --- linux.orig/include/asm-um/irqflags.h 2007-11-28 17:36:21.000000000 +0100 +++ linux/include/asm-um/irqflags.h 2007-11-28 17:41:42.000000000 +0100 @@ -1,6 +1,9 @@ #ifndef __UM_IRQFLAGS_H #define __UM_IRQFLAGS_H -/* Empty for now */ +static inline int raw_irqs_disabled_flags(unsigned long flags) +{ + return 0; +} #endif Index: linux/kernel/latency_trace.c =================================================================== --- linux.orig/kernel/latency_trace.c 2007-11-28 17:41:35.000000000 +0100 +++ linux/kernel/latency_trace.c 2007-11-28 17:55:20.000000000 +0100 @@ -26,6 +26,7 @@ #include <asm/unistd.h> #include <asm/asm-offsets.h> #include <asm/rtc.h> +#include <asm/irqflags.h> #include <linux/stacktrace.h> #ifndef DEFINE_RAW_SPINLOCK @@ -59,6 +60,8 @@ static unsigned long notrace cycles_to_u delta = mulhwu(tb_to_us, delta); #elif defined(CONFIG_ARM) delta = mach_cycles_to_usecs(delta); +#elif defined(CONFIG_UML) + /* Dunno */ #else #error Implement cycles_to_usecs. #endif @@ -655,7 +658,7 @@ again: entry->cpu = cpu; #endif entry->flags = (irqs_off() ? TRACE_FLAG_IRQS_OFF : 0) | - (irqs_disabled_flags(flags) ? TRACE_FLAG_IRQS_HARD_OFF : 0)| + (raw_irqs_disabled_flags(flags) ? TRACE_FLAG_IRQS_HARD_OFF : 0)| ((pc & HARDIRQ_MASK) ? TRACE_FLAG_HARDIRQ : 0) | ((pc & SOFTIRQ_MASK) ? TRACE_FLAG_SOFTIRQ : 0) | (need_resched() ? TRACE_FLAG_NEED_RESCHED : 0) | @@ -786,6 +789,7 @@ void notrace trace_special_sym(void) if (!trace_enabled || !stackframe_tracing) return; +#ifndef CONFIG_UML trace.entries = entries; trace.skip = 3; trace.max_entries = STACK_ENTRIES; @@ -802,6 +806,7 @@ void notrace trace_special_sym(void) entries[1], entries[2], entries[3]); ___trace(TRACE_SPECIAL_SYM, entries[4], 0, entries[5], entries[6], entries[7]); +#endif } EXPORT_SYMBOL(trace_special_sym); |
From: Ingo M. <mi...@el...> - 2007-11-28 17:02:22
|
* Miklos Szeredi <mi...@sz...> wrote: > > so you can define irqs_off_flags to always-0 and you should be able > > to get pretty good traces still. It should have no functional > > impact. > > OK, managed to make it compile, but then something goes wrong in > tracer_alloc_bootmem(). try with a lower MAX_TRACE first - 1 million entries (default) uses up like 32 MB of RAM per CPU, that might be quite a bit and your UML image might not be able to take that. also, you can do a s/trace_alloc_bootmem/alloc_bootmem - the alloc-bootmem wrapping was only done to get the tracer boot with really ridiculously high MAX_TRACE. Ingo |
From: Miklos S. <mi...@sz...> - 2007-11-28 17:03:10
|
> OK, managed to make it compile, but then something goes wrong in > tracer_alloc_bootmem(). It needs 32M, and uml has that much by default. Doh. But something is still wrong: > /store/quilt/linux/linux mem=64 Core dump limits : soft - 0 hard - NONE Checking that ptrace can change system call numbers...OK Checking syscall emulation patch for ptrace...missing Checking for tmpfs mount on /dev/shm...nothing mounted on /dev/shm Checking PROT_EXEC mmap in /tmp/...OK Checking for the skas3 patch in the host: - /proc/mm...not found: No such file or directory - PTRACE_FAULTINFO...not found: Invalid argument - PTRACE_LDT...not found: Invalid argument UML running in SKAS0 mode setup_physmem - mapping -8093632 bytes of memory at 0x0x8800000 failed - errno = -12 Miklos |
From: Ingo M. <mi...@el...> - 2007-11-28 17:24:53
|
* Miklos Szeredi <mi...@sz...> wrote: > > OK, managed to make it compile, but then something goes wrong in > > tracer_alloc_bootmem(). > > It needs 32M, and uml has that much by default. Doh. reduce MAX_TRACE to something like 1024 to make sure allocation is not an issue. Do you still see problems? Ingo |
From: Miklos S. <mi...@sz...> - 2007-11-28 17:25:22
|
> > OK, managed to make it compile, but then something goes wrong in > > tracer_alloc_bootmem(). > > It needs 32M, and uml has that much by default. Doh. > > But something is still wrong: > > > /store/quilt/linux/linux mem=64 I'm an idiot, sorry. It should have been mem=64M. No wonder it didn't manage to start with 64 bytes of memory ;) So now with s/trace_alloc_bootmem/alloc_bootmem and MAX_TRACE set to 4096UL*16UL it boots fine. Miklos |
From: Jeff D. <jd...@ad...> - 2007-11-28 18:29:56
|
On Wed, Nov 28, 2007 at 04:35:12PM +0100, Miklos Szeredi wrote: > Something like: > > dd if=/host/tmp/bigfile of=/tmp/bigfile bs=1048576 count=100 > > and run 'top' or 'watch something' in another terminal, which > sometimes completely stops updating during the write. Are you talking about missing updates for a few seconds, or for longer? With the common above, with top -delay 1, and with 600M of data, I'm seeing occasional 2-3 pauses, with one missing 5 seconds. Jeff -- Work email - jdike at linux dot intel dot com |
From: Ingo M. <mi...@el...> - 2007-11-28 18:37:18
|
* Jeff Dike <jd...@ad...> wrote: > On Wed, Nov 28, 2007 at 04:35:12PM +0100, Miklos Szeredi wrote: > > Something like: > > > > dd if=/host/tmp/bigfile of=/tmp/bigfile bs=1048576 count=100 > > > > and run 'top' or 'watch something' in another terminal, which > > sometimes completely stops updating during the write. > > Are you talking about missing updates for a few seconds, or for > longer? With the common above, with top -delay 1, and with 600M of > data, I'm seeing occasional 2-3 pauses, with one missing 5 seconds. even sub-second delays are a huge issue if the system is otherwise idle - it signals some sort of missed event condition. scheduling must be instantenous. Ingo |
From: Miklos S. <mi...@sz...> - 2007-11-28 18:46:24
|
> > Something like: > > > > dd if=/host/tmp/bigfile of=/tmp/bigfile bs=1048576 count=100 > > > > and run 'top' or 'watch something' in another terminal, which > > sometimes completely stops updating during the write. > > Are you talking about missing updates for a few seconds, or for > longer? With the common above, with top -delay 1, and with 600M of > data, I'm seeing occasional 2-3 pauses, with one missing 5 seconds. Yes, that sort of thing. Sometimes it pauses soon after starting the dd, and never recovers till it's finished, but that is not easily reproducible. Miklos |
From: Miklos S. <mi...@sz...> - 2007-11-29 10:19:57
|
I can't say I'm understading these traces very well, but here's a snippet that looks a bit strange. I'm running 'while true; do date; done' in parallel with the dd. For some time it is doing 100% CPU as expected, then it goes into a second or so of mosty idle (afaics), and then returns to the normal pattern again. Any thoughts? date-7119 0.... 15636591us!: schedule <bash-502> (0 0) bash-502 0.... 15643908us!: schedule <date-7119> (0 0) bash-502 0.... 15646250us!: schedule <date-7120> (0 0) date-7120 0.... 15647023us!: schedule <bash-502> (0 0) dd-6444 0.... 15654505us+: schedule <date-7120> (0 0) bash-502 0.... 15654602us!: schedule <dd-6444> (0 0) bash-502 0.... 15656809us!: schedule <date-7121> (0 0) date-7121 0.... 15657585us!: schedule <bash-502> (0 0) dd-6444 0.... 15664962us+: schedule <date-7121> (0 0) bash-502 0.... 15665056us!: schedule <dd-6444> (0 0) bash-502 0.... 15667246us!: schedule <date-7122> (0 0) date-7122 0.... 15668015us!: schedule <bash-502> (0 0) dd-6444 0.... 15675447us+: schedule <date-7122> (0 0) bash-502 0.... 15675539us!: schedule <dd-6444> (0 0) bash-502 0.... 15677726us!: schedule <date-7123> (0 0) date-7123 0.... 15678496us!: schedule <bash-502> (0 0) bash-502 0.... 15685867us!: schedule <date-7123> (0 0) bash-502 0.... 15688117us!: schedule <date-7124> (0 0) date-7124 0.... 15688896us!: schedule <bash-502> (0 0) bash-502 0.... 15696317us!: schedule <date-7124> (0 0) bash-502 0.... 15698604us!: schedule <date-7125> (0 0) date-7125 0.... 15699374us!: schedule <bash-502> (0 0) bash-502 0.... 15706800us!: schedule <date-7125> (0 0) bash-502 0.... 15709065us!: schedule <date-7126> (0 0) date-7126 0.... 15709838us!: schedule <bash-502> (0 0) bash-502 0.... 15717247us!: schedule <date-7126> (0 0) bash-502 0.... 15719626us!: schedule <date-7127> (0 0) date-7127 0.... 15720405us+: schedule <bash-502> (0 0) date-7127 0.Ns. 15720466us+: __trace_start_sched_wakeup <ksoftirq-3> (115 -1) ksoftirq-3 0.... 15720471us+: schedule <date-7127> (0 -5) date-7127 0.... 15720481us!: schedule <ksoftirq-3> (-5 0) dd-6444 0.... 15723423us!: schedule <date-7127> (0 0) dd-6444 0.... 15727689us!: __trace_start_sched_wakeup <kswapd0-33> (115 -1) kswapd0-33 0.... 15736528us+: schedule <dd-6444> (0 -5) dd-6444 0.... 15736537us!: schedule <kswapd0-33> (-5 0) date-7127 0.... 15740399us!: schedule <dd-6444> (0 0) bash-502 0.... 15745240us!: schedule <date-7127> (0 0) bash-502 0.... 15747667us!: schedule <date-7128> (0 0) date-7128 0.... 15748462us!: schedule <bash-502> (0 0) date-7128 0.... 15749685us!: __trace_start_sched_wakeup <kswapd0-33> (115 -1) kswapd0-33 0.... 15755989us+: schedule <date-7128> (0 -5) bash-502 0.... 15756000us!: schedule <kswapd0-33> (-5 0) bash-502 0.Ns. 15756427us+: __trace_start_sched_wakeup <kblockd/-14> (115 -1) kblockd/-14 0.... 15756436us+: schedule <bash-502> (0 -5) bash-502 0.... 15756480us!: schedule <kblockd/-14> (-5 0) bash-502 0.... 15758372us!: schedule <date-7129> (0 0) date-7129 0.... 15759148us!: schedule <bash-502> (0 0) bash-502 0.... 15766505us!: schedule <date-7129> (0 0) bash-502 0.... 15768896us!: schedule <date-7130> (0 0) date-7130 0.... 15769677us!: schedule <bash-502> (0 0) date-7130 0..h. 15773773us!: __trace_start_sched_wakeup <kswapd0-33> (115 -1) kswapd0-33 0.... 15777168us+: schedule <date-7130> (0 -5) dd-6444 0.... 15777180us+: schedule <kswapd0-33> (-5 0) bash-502 0.... 15777274us!: schedule <dd-6444> (0 0) bash-502 0.... 15779535us!: schedule <date-7131> (0 0) date-7131 0.... 15780307us!: schedule <bash-502> (0 0) bash-502 0.... 15787778us!: schedule <date-7131> (0 0) bash-502 0.... 15790057us!: schedule <date-7132> (0 0) date-7132 0.... 15790829us!: schedule <bash-502> (0 0) bash-502 0.... 15798234us!: schedule <date-7132> (0 0) bash-502 0.... 15800525us!: schedule <date-7133> (0 0) date-7133 0.... 15801298us!: schedule <bash-502> (0 0) <idle>-0 0.... 15802726us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 15854372us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 15854375us+: __trace_start_sched_wakeup <dd-6444> (120 -1) <idle>-0 0.Nh. 15854378us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) dd-6444 0.... 15854392us+: schedule <<idle>-0> (20 0) kswapd0-33 0.... 15854400us+: schedule <dd-6444> (0 -5) date-7133 0.... 15854407us+: schedule <kswapd0-33> (-5 0) <idle>-0 0.... 15854412us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 15904812us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 15904815us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) <idle>-0 0.Nh. 15904818us+: __trace_start_sched_wakeup <dd-6444> (120 -1) kswapd0-33 0.... 15904833us+: schedule <<idle>-0> (20 -5) dd-6444 0.... 15904843us+: schedule <kswapd0-33> (-5 0) date-7133 0.... 15904852us+: schedule <dd-6444> (0 0) <idle>-0 0.... 15904858us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 15945062us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 15945065us+: __trace_start_sched_wakeup <dd-6444> (120 -1) <idle>-0 0.Nh. 15945067us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) dd-6444 0.... 15945083us+: schedule <<idle>-0> (20 0) kswapd0-33 0.... 15945091us+: schedule <dd-6444> (0 -5) date-7133 0.... 15945099us+: schedule <kswapd0-33> (-5 0) <idle>-0 0.... 15945106us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 15975282us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 15975285us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) <idle>-0 0.Nh. 15975289us+: __trace_start_sched_wakeup <dd-6444> (120 -1) kswapd0-33 0.... 15975307us+: schedule <<idle>-0> (20 -5) dd-6444 0.... 15975319us+: schedule <kswapd0-33> (-5 0) date-7133 0.... 15975329us+: schedule <dd-6444> (0 0) <idle>-0 0.... 15975337us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 16025774us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16025777us+: __trace_start_sched_wakeup <dd-6444> (120 -1) <idle>-0 0.Nh. 16025781us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) dd-6444 0.... 16025801us+: schedule <<idle>-0> (20 0) kswapd0-33 0.... 16025812us+: schedule <dd-6444> (0 -5) date-7133 0.... 16025844us+: schedule <kswapd0-33> (-5 0) <idle>-0 0.... 16025852us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 16035765us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16035768us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) <idle>-0 0.Nh. 16035772us+: __trace_start_sched_wakeup <dd-6444> (120 -1) <idle>-0 0.Nh. 16035780us+: __trace_start_sched_wakeup <kjournal-68> (115 -1) kswapd0-33 0.... 16035802us+: schedule <<idle>-0> (20 -5) dd-6444 0.... 16035814us+: schedule <kswapd0-33> (-5 0) kjournal-68 0.... 16035824us!: schedule <dd-6444> (0 -5) date-7133 0.... 16036451us+: schedule <kjournal-68> (-5 0) <idle>-0 0.... 16036459us!: schedule <date-7133> (0 20) <idle>-0 0.Ns. 16044503us+: __trace_start_sched_wakeup <events/0-4> (115 -1) events/0-4 0.... 16044512us+: schedule <<idle>-0> (20 -5) <idle>-0 0.... 16044564us!: schedule <events/0-4> (-5 20) <idle>-0 0.Nh. 16076072us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16076075us+: __trace_start_sched_wakeup <dd-6444> (120 -1) <idle>-0 0.Nh. 16076078us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) dd-6444 0.... 16076104us+: schedule <<idle>-0> (20 0) kswapd0-33 0.... 16076114us+: schedule <dd-6444> (0 -5) date-7133 0.... 16076124us+: schedule <kswapd0-33> (-5 0) <idle>-0 0.... 16076132us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 16237235us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16237239us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) <idle>-0 0.Nh. 16237242us+: __trace_start_sched_wakeup <dd-6444> (120 -1) kswapd0-33 0.... 16237266us+: schedule <<idle>-0> (20 -5) dd-6444 0.... 16237280us+: schedule <kswapd0-33> (-5 0) date-7133 0.... 16237291us+: schedule <dd-6444> (0 0) <idle>-0 0.... 16237299us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 16338000us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16338003us+: __trace_start_sched_wakeup <dd-6444> (120 -1) <idle>-0 0.Nh. 16338007us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) dd-6444 0.... 16338034us+: schedule <<idle>-0> (20 0) kswapd0-33 0.... 16338045us+: schedule <dd-6444> (0 -5) date-7133 0.... 16338056us+: schedule <kswapd0-33> (-5 0) <idle>-0 0.... 16338063us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 16347973us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16347976us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) <idle>-0 0.Nh. 16347979us+: __trace_start_sched_wakeup <dd-6444> (120 -1) kswapd0-33 0.... 16348002us+: schedule <<idle>-0> (20 -5) dd-6444 0.... 16348014us+: schedule <kswapd0-33> (-5 0) date-7133 0.... 16348024us+: schedule <dd-6444> (0 0) <idle>-0 0.... 16348032us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 16438814us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16438818us+: __trace_start_sched_wakeup <dd-6444> (120 -1) <idle>-0 0.Nh. 16438821us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) dd-6444 0.... 16438843us+: schedule <<idle>-0> (20 0) kswapd0-33 0.... 16438855us+: schedule <dd-6444> (0 -5) date-7133 0.... 16438865us+: schedule <kswapd0-33> (-5 0) <idle>-0 0.... 16438873us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 16519442us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16519445us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) <idle>-0 0.Nh. 16519448us+: __trace_start_sched_wakeup <dd-6444> (120 -1) kswapd0-33 0.... 16519466us+: schedule <<idle>-0> (20 -5) dd-6444 0.... 16519478us+: schedule <kswapd0-33> (-5 0) date-7133 0.... 16519488us+: schedule <dd-6444> (0 0) <idle>-0 0.... 16519496us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 16579941us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16579944us+: __trace_start_sched_wakeup <dd-6444> (120 -1) <idle>-0 0.Nh. 16579947us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) dd-6444 0.... 16579968us+: schedule <<idle>-0> (20 0) kswapd0-33 0.... 16579978us+: schedule <dd-6444> (0 -5) date-7133 0.... 16579988us+: schedule <kswapd0-33> (-5 0) <idle>-0 0.... 16579996us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 16589889us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16589892us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) <idle>-0 0.Nh. 16589895us+: __trace_start_sched_wakeup <dd-6444> (120 -1) kswapd0-33 0.... 16589913us+: schedule <<idle>-0> (20 -5) dd-6444 0.... 16589924us+: schedule <kswapd0-33> (-5 0) date-7133 0.... 16589935us+: schedule <dd-6444> (0 0) <idle>-0 0.... 16589942us!: schedule <date-7133> (0 20) <idle>-0 0.Nh. 16610104us+: __trace_start_sched_wakeup <date-7133> (120 -1) <idle>-0 0.Nh. 16610107us+: __trace_start_sched_wakeup <dd-6444> (120 -1) <idle>-0 0.Nh. 16610110us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) dd-6444 0.... 16610130us+: schedule <<idle>-0> (20 0) kswapd0-33 0.... 16610140us!: schedule <dd-6444> (0 -5) date-7133 0.... 16610487us!: schedule <kswapd0-33> (-5 0) bash-502 0.... 16622148us!: schedule <date-7133> (0 0) bash-502 0.... 16626384us!: schedule <date-7134> (0 0) date-7134 0.... 16627783us!: schedule <bash-502> (0 0) bash-502 0.... 16641348us!: schedule <date-7134> (0 0) bash-502 0.... 16645627us!: schedule <date-7135> (0 0) date-7135 0.... 16647022us!: schedule <bash-502> (0 0) bash-502 0.... 16658816us!: schedule <date-7135> (0 0) date-7136 0..h. 16660498us!: __trace_start_sched_wakeup <kswapd0-33> (115 -1) kswapd0-33 0.... 16661220us+: schedule <date-7136> (0 -5) dd-6444 0.... 16661230us+: schedule <kswapd0-33> (-5 0) bash-502 0.... 16661238us!: schedule <dd-6444> (0 0) date-7136 0.... 16662012us!: schedule <bash-502> (0 0) bash-502 0.... 16669457us!: schedule <date-7136> (0 0) bash-502 0.... 16671791us!: schedule <date-7137> (0 0) date-7137 0.... 16672512us!: schedule <bash-502> (0 0) bash-502 0.... 16679839us!: schedule <date-7137> (0 0) bash-502 0.... 16682313us!: schedule <date-7138> (0 0) date-7138 0.... 16683096us!: schedule <bash-502> (0 0) bash-502 0.... 16691274us!: schedule <date-7138> (0 0) bash-502 0.... 16694598us!: schedule <date-7139> (0 0) date-7139 0.... 16695374us!: schedule <bash-502> (0 0) bash-502 0.... 16702798us!: schedule <date-7139> (0 0) bash-502 0.... 16705100us!: schedule <date-7140> (0 0) date-7140 0.... 16705881us!: schedule <bash-502> (0 0) dd-6444 0.... 16713383us+: schedule <date-7140> (0 0) bash-502 0.... 16713486us!: schedule <dd-6444> (0 0) bash-502 0.... 16715698us!: schedule <date-7141> (0 0) date-7141 0.... 16716479us!: schedule <bash-502> (0 0) bash-502 0.... 16723865us!: schedule <date-7141> (0 0) bash-502 0.... 16726163us!: schedule <date-7142> (0 0) date-7142 0.... 16726929us!: schedule <bash-502> (0 0) bash-502 0.... 16734434us!: schedule <date-7142> (0 0) bash-502 0.... 16736736us!: schedule <date-7143> (0 0) date-7143 0.... 16737509us!: schedule <bash-502> (0 0) bash-502 0.... 16744911us!: schedule <date-7143> (0 0) bash-502 0.... 16747186us!: schedule <date-7144> (0 0) date-7144 0.... 16747955us!: schedule <bash-502> (0 0) bash-502 0.... 16755349us!: schedule <date-7144> (0 0) bash-502 0.... 16757672us!: schedule <date-7145> (0 0) date-7145 0.... 16758447us!: schedule <bash-502> (0 0) dd-6444 0.... 16765879us+: schedule <date-7145> (0 0) bash-502 0.... 16765982us!: schedule <dd-6444> (0 0) bash-502 0.... 16768170us!: schedule <date-7146> (0 0) date-7146 0.... 16768954us!: schedule <bash-502> (0 0) bash-502 0.... 16776368us!: schedule <date-7146> (0 0) bash-502 0.... 16778667us!: schedule <date-7147> (0 0) date-7147 0.... 16779439us!: schedule <bash-502> (0 0) bash-502 0.... 16786847us!: schedule <date-7147> (0 0) bash-502 0.... 16789129us!: schedule <date-7148> (0 0) date-7148 0.... 16789906us!: schedule <bash-502> (0 0) bash-502 0.... 16797281us!: schedule <date-7148> (0 0) bash-502 0.... 16799726us!: schedule <date-7149> (0 0) date-7149 0.... 16800504us!: schedule <bash-502> (0 0) bash-502 0.... 16807922us!: schedule <date-7149> (0 0) bash-502 0.... 16810202us!: schedule <date-7150> (0 0) date-7150 0.... 16810969us!: schedule <bash-502> (0 0) bash-502 0.... 16818372us!: schedule <date-7150> (0 0) bash-502 0.... 16820666us!: schedule <date-7151> (0 0) date-7151 0.... 16821440us!: schedule <bash-502> (0 0) dd-6444 0.... 16829023us+: schedule <date-7151> (0 0) bash-502 0.... 16829125us!: schedule <dd-6444> (0 0) bash-502 0.... 16831302us!: schedule <date-7152> (0 0) date-7152 0.... 16832074us!: schedule <bash-502> (0 0) bash-502 0.... 16839389us!: schedule <date-7152> (0 0) bash-502 0.... 16841702us!: schedule <date-7153> (0 0) bash-502 0.N.. 16842322us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) kswapd0-33 0.... 16842352us!: schedule <bash-502> (0 -5) bash-502 0.... 16842568us!: schedule <kswapd0-33> (-5 0) date-7153 0.... 16842745us!: schedule <bash-502> (0 0) bash-502 0.... 16850087us!: schedule <date-7153> (0 0) bash-502 0.... 16852366us!: schedule <date-7154> (0 0) date-7154 0.... 16853151us!: schedule <bash-502> (0 0) bash-502 0.... 16860617us!: schedule <date-7154> (0 0) bash-502 0.... 16862940us!: schedule <date-7155> (0 0) date-7155 0.... 16863715us!: schedule <bash-502> (0 0) bash-502 0.... 16871092us!: schedule <date-7155> (0 0) date-7156 0..h. 16872536us!: __trace_start_sched_wakeup <kswapd0-33> (115 -1) kswapd0-33 0.... 16873519us+: schedule <date-7156> (0 -5) dd-6444 0.... 16873527us+: schedule <kswapd0-33> (-5 0) bash-502 0.... 16873535us!: schedule <dd-6444> (0 0) date-7156 0.... 16874310us!: schedule <bash-502> (0 0) bash-502 0.... 16881743us!: schedule <date-7156> (0 0) bash-502 0.... 16884041us!: schedule <date-7157> (0 0) date-7157 0.... 16884824us!: schedule <bash-502> (0 0) bash-502 0.... 16892154us!: schedule <date-7157> (0 0) bash-502 0.... 16894569us!: schedule <date-7158> (0 0) date-7158 0.... 16895343us!: schedule <bash-502> (0 0) bash-502 0.... 16902783us!: schedule <date-7158> (0 0) bash-502 0.... 16905369us!: schedule <date-7159> (0 0) date-7159 0.... 16906191us!: schedule <bash-502> (0 0) bash-502 0.... 16913569us!: schedule <date-7159> (0 0) bash-502 0.... 16915927us!: schedule <date-7160> (0 0) date-7160 0.... 16916760us!: schedule <bash-502> (0 0) bash-502 0.... 16924096us!: schedule <date-7160> (0 0) bash-502 0.... 16926448us!: schedule <date-7161> (0 0) date-7161 0.... 16927257us!: schedule <bash-502> (0 0) bash-502 0.... 16934587us!: schedule <date-7161> (0 0) bash-502 0.... 16936905us!: schedule <date-7162> (0 0) date-7162 0.... 16937720us!: schedule <bash-502> (0 0) bash-502 0.... 16945142us!: schedule <date-7162> (0 0) bash-502 0.... 16947452us!: schedule <date-7163> (0 0) date-7163 0.... 16948262us!: schedule <bash-502> (0 0) bash-502 0.... 16955611us!: schedule <date-7163> (0 0) dd-6444 0.... 16956304us!: schedule <bash-502> (0 0) dd-6444 0.... 16958669us!: __trace_start_sched_wakeup <kswapd0-33> (115 -1) kswapd0-33 0.... 16958806us+: schedule <dd-6444> (0 -5) bash-502 0.... 16958900us!: schedule <kswapd0-33> (-5 0) bash-502 0.... 16960857us!: schedule <date-7164> (0 0) date-7164 0.... 16961712us!: schedule <bash-502> (0 0) date-7164 0.Ns. 16968470us+: __trace_start_sched_wakeup <ksoftirq-3> (115 -1) ksoftirq-3 0.... 16968479us+: schedule <date-7164> (0 -5) date-7164 0.... 16968578us!: schedule <ksoftirq-3> (-5 0) bash-502 0.... 16969310us!: schedule <date-7164> (0 0) bash-502 0.... 16971659us!: schedule <date-7165> (0 0) date-7165 0.... 16972487us!: schedule <bash-502> (0 0) bash-502 0.... 16979969us!: schedule <date-7165> (0 0) bash-502 0.... 16982280us!: schedule <date-7166> (0 0) date-7166 0.... 16983107us!: schedule <bash-502> (0 0) bash-502 0.... 16990504us!: schedule <date-7166> (0 0) bash-502 0.... 16992802us!: schedule <date-7167> (0 0) date-7167 0.... 16993618us!: schedule <bash-502> (0 0) bash-502 0.... 17001059us!: schedule <date-7167> (0 0) bash-502 0.... 17003350us!: schedule <date-7168> (0 0) date-7168 0.... 17004162us!: schedule <bash-502> (0 0) date-7168 0..h. 17006553us!: __trace_start_sched_wakeup <kswapd0-33> (115 -1) kswapd0-33 0.... 17011682us+: schedule <date-7168> (0 -5) bash-502 0.... 17011692us!: schedule <kswapd0-33> (-5 0) bash-502 0.... 17014005us!: schedule <date-7169> (0 0) date-7169 0.... 17014814us!: schedule <bash-502> (0 0) bash-502 0.... 17022217us!: schedule <date-7169> (0 0) bash-502 0.... 17024519us!: schedule <date-7170> (0 0) date-7170 0.... 17025334us!: schedule <bash-502> (0 0) bash-502 0.... 17032788us!: schedule <date-7170> (0 0) bash-502 0.... 17035069us!: schedule <date-7171> (0 0) date-7171 0.... 17035878us!: schedule <bash-502> (0 0) bash-502 0.... 17043372us!: schedule <date-7171> (0 0) bash-502 0.... 17045678us!: schedule <date-7172> (0 0) date-7172 0.... 17046486us!: schedule <bash-502> (0 0) bash-502 0.... 17053866us!: schedule <date-7172> (0 0) bash-502 0.... 17056168us!: schedule <date-7173> (0 0) date-7173 0.... 17056999us!: schedule <bash-502> (0 0) bash-502 0.... 17064367us!: schedule <date-7173> (0 0) bash-502 0.... 17066673us!: schedule <date-7174> (0 0) date-7174 0.... 17067523us!: schedule <bash-502> (0 0) bash-502 0.... 17074961us!: schedule <date-7174> (0 0) bash-502 0.... 17077271us!: schedule <date-7175> (0 0) date-7175 0.... 17078082us!: schedule <bash-502> (0 0) bash-502 0.... 17085411us!: schedule <date-7175> (0 0) bash-502 0.... 17087738us!: schedule <date-7176> (0 0) date-7176 0.... 17088561us!: schedule <bash-502> (0 0) bash-502 0.... 17095920us!: schedule <date-7176> (0 0) bash-502 0.... 17098194us!: schedule <date-7177> (0 0) date-7177 0.... 17098958us!: schedule <bash-502> (0 0) bash-502 0.... 17106376us!: schedule <date-7177> (0 0) bash-502 0.... 17108848us!: schedule <date-7178> (0 0) date-7178 0.... 17109639us!: schedule <bash-502> (0 0) bash-502 0.... 17117073us!: schedule <date-7178> (0 0) bash-502 0.... 17119410us!: schedule <date-7179> (0 0) date-7179 0.... 17120214us!: schedule <bash-502> (0 0) bash-502 0.... 17127600us!: schedule <date-7179> (0 0) |
From: Ingo M. <mi...@el...> - 2007-11-29 10:58:01
|
* Miklos Szeredi <mi...@sz...> wrote: > I can't say I'm understading these traces very well, but here's a > snippet that looks a bit strange. I'm running 'while true; do date; > done' in parallel with the dd. > > For some time it is doing 100% CPU as expected, then it goes into a > second or so of mosty idle (afaics), and then returns to the normal > pattern again. try: echo 1 > /proc/sys/kernel/stackframe_tracing to get symbolic stack backdumps for the wakeup points, and add trace_special_sym() calls to generate extra stackdump entries at arbitrary places. schedule() does not have it right now - it might make sense to add it. also, enabling mcount: echo 1 > /proc/sys/kernel/mcount_enabled will give you a _lot_ more verbose trace. Likewise: echo 1 > /proc/sys/kernel/syscall_tracing (but for that you'd have to add the sys_call()/sys_ret() instrumentation that x86 has in entry_32.S) but even this highlevel trace shows something weird: > events/0-4 0.... 16044512us+: schedule <<idle>-0> (20 -5) > <idle>-0 0.... 16044564us!: schedule <events/0-4> (-5 20) > <idle>-0 0.Nh. 16076072us+: __trace_start_sched_wakeup <date-7133> (120 -1) > <idle>-0 0.Nh. 16076075us+: __trace_start_sched_wakeup <dd-6444> (120 -1) > <idle>-0 0.Nh. 16076078us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) > dd-6444 0.... 16076104us+: schedule <<idle>-0> (20 0) how come UML idled for 30 msecs here, while the workload was supposed to be CPU-bound? It's not IO bound anywhere, right? No SMP artifacts either, right? Ingo |
From: Miklos S. <mi...@sz...> - 2007-11-29 11:36:25
|
> > I can't say I'm understading these traces very well, but here's a > > snippet that looks a bit strange. I'm running 'while true; do date; > > done' in parallel with the dd. > > > > For some time it is doing 100% CPU as expected, then it goes into a > > second or so of mosty idle (afaics), and then returns to the normal > > pattern again. > > try: > > echo 1 > /proc/sys/kernel/stackframe_tracing > > to get symbolic stack backdumps for the wakeup points, and add > trace_special_sym() calls to generate extra stackdump entries at > arbitrary places. schedule() does not have it right now - it might make > sense to add it. Umm, trace_special_sym() is ifdefed out, because UML doesn't have save_stack_trace(). > also, enabling mcount: > > echo 1 > /proc/sys/kernel/mcount_enabled > > will give you a _lot_ more verbose trace. Likewise: > > echo 1 > /proc/sys/kernel/syscall_tracing > > (but for that you'd have to add the sys_call()/sys_ret() instrumentation > that x86 has in entry_32.S) I'll have a look. > but even this highlevel trace shows something weird: > > events/0-4 0.... 16044512us+: schedule <<idle>-0> (20 -5) > > <idle>-0 0.... 16044564us!: schedule <events/0-4> (-5 20) > > <idle>-0 0.Nh. 16076072us+: __trace_start_sched_wakeup <date-7133> (120 -1) > > <idle>-0 0.Nh. 16076075us+: __trace_start_sched_wakeup <dd-6444> (120 -1) > > <idle>-0 0.Nh. 16076078us+: __trace_start_sched_wakeup <kswapd0-33> (115 -1) > > dd-6444 0.... 16076104us+: schedule <<idle>-0> (20 0) > > how come UML idled for 30 msecs here, while the workload was supposed to > be CPU-bound? It's not IO bound anywhere, right? No SMP artifacts > either, right? Yes. The UML kernel is UP, and I don't think 'date' or 'bash' want to do any disk I/O. Could disk I/O be blocking the tty? I think UML uses separate threads for these, but I don't know the details. Miklos |