lkml.org 
[lkml]   [2006]   [Dec]   [14]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: Temporary random kernel hang
On Mon, 11 Dec 2006 10:46:25 -0800 (PST)
seven <horia.muntean@gmail.com> wrote:

>
>
>
> > A kernel profile will tell us were the kernel is burning CPU. Something
> > like this (run as root):
> >
> > #!/bin/sh
> > while true
> > do
> > opcontrol --stop
> > opcontrol --shutdown
> > rm -rf /var/lib/oprofile
> > opcontrol --vmlinux=/boot/vmlinux-$(uname -r)
> > opcontrol --start-daemon
> > opcontrol --start
> > date
> > sleep 5
> > opcontrol --stop
> > opcontrol --shutdown
> > opreport -l /boot/vmlinux-$(uname -r) | head -50
> > done | tee /tmp/oprofile-output
> >
> > Then locate the output record which correlates with one of these episodes.
> > -
> > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at http://vger.kernel.org/majordomo-info.html
> > Please read the FAQ at http://www.tux.org/lkml/
> >
> >
>
>
> Hello Andrew,

No, I wasn't ignoring you for four days. Please, always do reply-to-all.

> First, thank you for the pointers. I did what you suggested ( installed
> oprofile and run the script ). In the same time, I added a timestamp column
> to vmstat recording.
>
> I can see dramatic changes in the output of opreport during the freeze
> period, but I do not know what it means.
>
> ..
>
> CPU: P4 / Xeon, speed 3000.18 MHz (estimated)
> Counted GLOBAL_POWER_EVENTS events (time during which processor is not
> stopped) with a unit mask of 0x01 (mandatory) count 100000
> samples % symbol name
> 741 4.3771 ia32_sysenter_target
> 682 4.0286 sysenter_do_call
> 622 3.6742 find_vma
> 523 3.0894 copy_user_generic
> 515 3.0421 schedule
> 495 2.9240 do_futex
> 419 2.4750 __find_get_block
> 373 2.2033 do_gettimeofday
> 372 2.1974 tcp_sendmsg
> 325 1.9198 main_timer_handler
> 312 1.8430 try_to_wake_up
> 298 1.7603 __switch_to
> 260 1.5358 fget
> 239 1.4118 gs_change
> 227 1.3409 ia32_syscall
> 222 1.3114 __down_read
> 219 1.2936 page_fault
> 193 1.1401 find_lock_page
> 189 1.1164 __up_read
> 180 1.0633 fget_light
> 178 1.0515 clear_page
> 178 1.0515 tcp_ack
> 175 1.0337 ll_rw_block
> 167 0.9865 math_state_restore
> 156 0.9215 thread_return
> 154 0.9097 lock_sock
> 151 0.8920 fput
> 138 0.8152 recalc_task_prio
> 135 0.7974 tcp_v4_rcv
> 129 0.7620 kfree
> 128 0.7561 IRQ0xa9_interrupt
> 124 0.7325 release_sock
> 123 0.7266 device_not_available
> 120 0.7088 __tcp_push_pending_frames
> 114 0.6734 __kmalloc
> 111 0.6557 unlock_buffer
> 110 0.6498 inet_sendmsg
> 108 0.6380 __brelse
> 105 0.6202 do_gettimeoffset_tsc
> 100 0.5907 rw_verify_area
> 95 0.5612 tcp_init_tso_segs
> 94 0.5553 kmem_cache_free
> 94 0.5553 radix_tree_lookup
> 92 0.5434 ip_output
> 89 0.5257 file_update_time
> 86 0.5080 dnotify_parent
> 86 0.5080 kmem_cache_alloc

versus

> Using default event: GLOBAL_POWER_EVENTS:100000:1:1:1
> Daemon started.
> Profiler running.
> Mon Dec 11 18:30:09 GMT 2006
> Stopping profiling.
> Stopping profiling.
> Killing daemon.
> CPU: P4 / Xeon, speed 3000.18 MHz (estimated)
> Counted GLOBAL_POWER_EVENTS events (time during which processor is not
> stopped) with a unit mask of 0x01 (mandatory) count 100000
> samples % symbol name
> 196048 9.3307 page_fault
> 184945 8.8023 force_sig_info
> 153475 7.3045 do_signal
> 120071 5.7146 get_signal_to_deliver
> 116196 5.5302 ia32_setup_sigcontext
> 89368 4.2534 ia32_syscall
> 82987 3.9497 __down_read_trylock
> 82396 3.9215 save_i387_ia32
> 79436 3.7807 copy_user_generic
> 77587 3.6927 __sigqueue_alloc
> 74439 3.5428 sys32_rt_sigreturn
> 69484 3.3070 recalc_sigpending_tsk
> 65733 3.1285 do_page_fault
> 49694 2.3651 retint_restore_args
> 45756 2.1777 ia32_setup_rt_frame
> 45717 2.1759 try_to_wake_up
> 45658 2.1730 restore_i387_ia32
> 31626 1.5052 __up_read
> 30286 1.4414 __dequeue_signal
> 29849 1.4206 memcpy
> 27139 1.2917 sys32_sigaltstack
> 25838 1.2297 ia32_restore_sigcontext
> 25126 1.1958 kmem_cache_free
> 24757 1.1783 do_sigaltstack
> 22884 1.0891 __sigqueue_free
> 22818 1.0860 error_sti
> 22007 1.0474 signal_wake_up
> 19816 0.9431 kmem_cache_alloc
> 17810 0.8476 retint_signal
> 17208 0.8190 is_prefetch
> 16315 0.7765 _atomic_dec_and_lock

It's certainly different. It is hard to work out what might be going
on in there, but there's no obvious sign of misbehaviour. It could be that
the application has simply gone berzerk and is doing a larger number or
expensive system calls.

The next step would be to try to catch one of these eposides with strace.
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

\
 
 \ /
  Last update: 2006-12-14 23:13    [W:0.041 / U:0.296 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site