* new latency report
@ 2000-07-07 1:49 Roger Larsson
2000-07-07 3:21 ` Andrew Morton
2000-07-09 17:44 ` Alan Cox
0 siblings, 2 replies; 6+ messages in thread
From: Roger Larsson @ 2000-07-07 1:49 UTC (permalink / raw)
To: linux-kernel, linux-mm, linux-audio-dev
[-- Attachment #1: Type: text/plain, Size: 573 bytes --]
Hi,
The attached output shows that when we hit swap - there are
code lines with latency problems :-(
[the actual code tested is test3-pre2 with my latency modifications
(improvement and profiling) but has one modification relative
test3-pre4
kswapd in the tested version always sleeps => problems accounted
to the process causing it]
see the 293ms in generic_make_request...
and the 704ms used to busy loop in modprobe...
(SB16 non PnP)
These are worse then the previously found aux_write_dev :-(
/RogerL
--
Home page:
http://www.norran.net/nra02596/
[-- Attachment #2: warn-2.4.0-test3-2-vmscan.latency.6-wcrrmr --]
[-- Type: text/plain, Size: 43590 bytes --]
Jul 5 23:17:45 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:17:45 dox kernel: Trace:
Jul 5 23:17:46 dox kernel: isapnp: Scanning for Pnp cards...
Jul 5 23:17:46 dox kernel: isapnp: No Plug & Play device found
Jul 5 23:17:46 dox kernel: Latency 704ms PID 230 % modprobe
Jul 5 23:17:46 dox kernel: Trace: [__rdtsc_delay+14/24] [__rdtsc_delay+14/24] [__rdtsc_delay+14/24] [__rdtsc_delay+16/24] [__rdtsc_delay+14/24] [__rdtsc_delay+14/24] [__rdtsc_delay+14/24] [__rdtsc_delay+14/24] [__rdtsc_delay+16/24] [__rdtsc_delay+16/24]
Jul 5 23:17:46 dox insmod: /lib/modules/2.4.0-test3/sound/sb.o: post-install sb failed
Jul 5 23:17:46 dox insmod: /lib/modules/2.4.0-test3/sound/sb.o: insmod char-major-14 failed
Jul 5 23:17:57 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:17:57 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:18:00 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:18:00 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:18:05 dox kernel: Latency 9ms PID 193 % nscd
Jul 5 23:18:05 dox kernel: Trace: [try_to_free_buffers+44/344]
Jul 5 23:18:05 dox kernel: Latency 8ms PID 233 % head
Jul 5 23:18:05 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:18:05 dox kernel: Latency 5ms PID 2 % kswapd
Jul 5 23:18:05 dox kernel: Trace: [kmem_slab_destroy+246/500]
Jul 5 23:18:06 dox kernel: Latency 10ms PID 233 % head
Jul 5 23:18:06 dox kernel: Trace: [try_to_free_buffers+22/344]
Jul 5 23:18:06 dox kernel: Latency 12ms PID 233 % head
Jul 5 23:18:06 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500]
Jul 5 23:18:07 dox kernel: Latency 9ms PID 233 % head
Jul 5 23:18:07 dox kernel: Trace:
Jul 5 23:18:07 dox kernel: Latency 9ms PID 2 % kswapd
Jul 5 23:18:07 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:18:08 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:18:08 dox kernel: Trace:
Jul 5 23:18:11 dox kernel: Latency 12ms PID 233 % head
Jul 5 23:18:11 dox kernel: Trace: [kmem_slab_destroy+234/500]
Jul 5 23:18:14 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:18:14 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:18:14 dox kernel: Latency 13ms PID 233 % head
Jul 5 23:18:14 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:18:18 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:18:18 dox kernel: Trace:
Jul 5 23:18:18 dox kernel: Latency 7ms PID 233 % head
Jul 5 23:18:18 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:18:18 dox kernel: Latency 5ms PID 233 % head
Jul 5 23:18:18 dox kernel: Trace: [shrink_mmap+368/524]
Jul 5 23:18:18 dox kernel: Latency 11ms PID 233 % head
Jul 5 23:18:18 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:18:18 dox kernel: Latency 6ms PID 233 % head
Jul 5 23:18:18 dox kernel: Trace:
Jul 5 23:18:18 dox kernel: Latency 9ms PID 2 % kswapd
Jul 5 23:18:18 dox kernel: Trace: [kmem_slab_destroy+265/500]
Jul 5 23:18:19 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:18:19 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:18:23 dox kernel: Latency 6ms PID 2 % kswapd
Jul 5 23:18:23 dox kernel: Trace: [generic_make_request+102/1880]
Jul 5 23:18:23 dox kernel: Latency 6ms PID 233 % head
Jul 5 23:18:23 dox kernel: Trace:
Jul 5 23:18:32 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:18:32 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:18:34 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:18:34 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:18:38 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:18:38 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:18:43 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:18:43 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:18:45 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:18:45 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:18:47 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:18:47 dox kernel: Trace:
Jul 5 23:18:48 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:18:48 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:18:49 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:18:49 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:18:49 dox kernel: Latency 6ms PID 235 % cp
Jul 5 23:18:49 dox kernel: Trace:
Jul 5 23:18:52 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:18:52 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:18:56 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:18:56 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:19:00 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:19:00 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:19:05 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:19:05 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:19:06 dox kernel: Latency 6ms PID 2 % kswapd
Jul 5 23:19:06 dox kernel: Trace: [shrink_mmap+75/524]
Jul 5 23:19:06 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:19:06 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:19:07 dox kernel: Latency 7ms PID 235 % cp
Jul 5 23:19:07 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:19:13 dox kernel: Latency 6ms PID 235 % cp
Jul 5 23:19:13 dox kernel: Trace:
Jul 5 23:19:13 dox kernel: Latency 7ms PID 2 % kswapd
Jul 5 23:19:13 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:19:17 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:19:17 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:19:26 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:19:26 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:19:27 dox kernel: Latency 9ms PID 2 % kswapd
Jul 5 23:19:27 dox kernel: Trace: [shrink_mmap+95/524]
Jul 5 23:19:29 dox kernel: Latency 24ms PID 2 % kswapd
Jul 5 23:19:29 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500]
Jul 5 23:19:31 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:19:31 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:19:33 dox kernel: Latency 6ms PID 235 % cp
Jul 5 23:19:33 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:19:39 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:19:39 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:19:42 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:19:42 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:19:45 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:19:45 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:19:46 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:19:46 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:19:49 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:19:49 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:19:50 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:19:50 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:19:52 dox kernel: Latency 5ms PID 235 % cp
Jul 5 23:19:52 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:19:54 dox kernel: Latency 5ms PID 235 % cp
Jul 5 23:19:54 dox kernel: Trace:
Jul 5 23:19:55 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:19:55 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:19:58 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:19:58 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:19:59 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:19:59 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:20:01 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:20:01 dox kernel: Trace:
Jul 5 23:20:03 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:20:03 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:20:09 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:20:09 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:20:13 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:20:13 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:20:14 dox kernel: Latency 5ms PID 235 % cp
Jul 5 23:20:14 dox kernel: Trace:
Jul 5 23:20:16 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:20:16 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:20:17 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:20:17 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:20:19 dox kernel: Latency 9ms PID 235 % cp
Jul 5 23:20:19 dox kernel: Trace: [try_to_free_buffers+22/344]
Jul 5 23:20:20 dox kernel: Latency 6ms PID 235 % cp
Jul 5 23:20:20 dox kernel: Trace:
Jul 5 23:20:21 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:20:21 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:20:31 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:20:31 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:20:33 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:20:33 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:20:36 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:20:36 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:20:38 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:20:38 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:20:41 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:20:41 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:20:43 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:20:43 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:20:45 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:20:45 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:20:48 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:20:48 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:20:51 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:20:51 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:20:54 dox kernel: Latency 5ms PID 2 % kswapd
Jul 5 23:20:54 dox kernel: Trace:
Jul 5 23:20:56 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:20:56 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:21:02 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:21:02 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:21:06 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:06 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:21:12 dox kernel: Latency 8ms PID 237 % cat
Jul 5 23:21:12 dox kernel: Trace:
Jul 5 23:21:19 dox kernel: Latency 9ms PID 237 % cat
Jul 5 23:21:19 dox kernel: Trace: [try_to_free_buffers+52/344]
Jul 5 23:21:21 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:21 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:21:22 dox kernel: Latency 5ms PID 237 % cat
Jul 5 23:21:22 dox kernel: Trace: [__alloc_pages+27/400]
Jul 5 23:21:23 dox kernel: Latency 5ms PID 237 % cat
Jul 5 23:21:23 dox kernel: Trace:
Jul 5 23:21:26 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:21:26 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:21:27 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:27 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:21:28 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:28 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:21:30 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:30 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:21:31 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:31 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:21:34 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:21:34 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:21:42 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:42 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:21:45 dox kernel: Latency 12ms PID 227 % vmstat
Jul 5 23:21:45 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:21:47 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:47 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:21:48 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:48 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:21:51 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:51 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:21:52 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:52 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:21:52 dox kernel: Latency 6ms PID 237 % cat
Jul 5 23:21:52 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:21:53 dox kernel: Latency 13ms PID 2 % kswapd
Jul 5 23:21:53 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500]
Jul 5 23:21:55 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:55 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:21:58 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:21:58 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:21:59 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:21:59 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:22:03 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:22:03 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:22:05 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:22:05 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:22:06 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:22:06 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:22:08 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:22:08 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:22:10 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:22:10 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:22:16 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:22:16 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:22:17 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:22:17 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:22:25 dox kernel: Latency 5ms PID 239 % cat
Jul 5 23:22:25 dox kernel: Trace:
Jul 5 23:22:28 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:22:28 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:22:29 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:22:29 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:22:30 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:22:30 dox kernel: Trace:
Jul 5 23:22:35 dox kernel: Latency 5ms PID 239 % cat
Jul 5 23:22:35 dox kernel: Trace: [shrink_mmap+75/524]
Jul 5 23:22:35 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:22:35 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:22:39 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:22:39 dox kernel: Trace: [try_to_free_buffers+49/344]
Jul 5 23:22:39 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:22:39 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:22:43 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:22:43 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:22:52 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:22:52 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:22:54 dox kernel: Latency 5ms PID 239 % cat
Jul 5 23:22:54 dox kernel: Trace:
Jul 5 23:22:57 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:22:57 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:00 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:00 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:23:01 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:01 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:04 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:04 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:05 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:05 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:23:08 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:08 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:23:11 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:11 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:23:12 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:12 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:23:16 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:16 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:23:16 dox kernel: Latency 5ms PID 239 % cat
Jul 5 23:23:16 dox kernel: Trace:
Jul 5 23:23:22 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:22 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:23:25 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:25 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:28 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:28 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:23:30 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:30 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:23:32 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:32 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:23:33 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:33 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:35 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:35 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:37 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:37 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:23:38 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:38 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:23:40 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:40 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:23:42 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:42 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:43 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:43 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:23:45 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:45 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:48 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:48 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:49 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:49 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:23:51 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:51 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:52 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:52 dox kernel: Trace:
Jul 5 23:23:55 dox kernel: Latency 7ms PID 240 % mmap002
Jul 5 23:23:55 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:23:55 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:23:55 dox kernel: Trace:
Jul 5 23:23:55 dox kernel: Latency 7ms PID 240 % mmap002
Jul 5 23:23:55 dox kernel: Trace: [ext2_get_block+978/1196]
Jul 5 23:23:57 dox kernel: Latency 6ms PID 240 % mmap002
Jul 5 23:23:57 dox kernel: Trace: [__wake_up+497/512]
Jul 5 23:23:57 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:23:57 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:23:58 dox kernel: Latency 15ms PID 2 % kswapd
Jul 5 23:23:58 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500]
Jul 5 23:23:59 dox kernel: Latency 7ms PID 240 % mmap002
Jul 5 23:23:59 dox kernel: Trace:
Jul 5 23:24:00 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:24:00 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:24:00 dox kernel: Latency 22ms PID 240 % mmap002
Jul 5 23:24:00 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+187/500] [kmem_slab_destroy+177/500]
Jul 5 23:24:01 dox kernel: Latency 9ms PID 240 % mmap002
Jul 5 23:24:01 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:24:02 dox kernel: Latency 6ms PID 240 % mmap002
Jul 5 23:24:02 dox kernel: Trace: [kmem_cache_alloc+121/452]
Jul 5 23:24:02 dox kernel: Latency 12ms PID 240 % mmap002
Jul 5 23:24:02 dox kernel: Trace: [__wake_up+23/512]
Jul 5 23:24:04 dox kernel: Latency 5ms PID 240 % mmap002
Jul 5 23:24:04 dox kernel: Trace:
Jul 5 23:24:04 dox kernel: Latency 8ms PID 2 % kswapd
Jul 5 23:24:04 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:24:06 dox kernel: Latency 30ms PID 240 % mmap002
Jul 5 23:24:06 dox kernel: Trace: [nr_free_buffer_pages+1/52] [block_getblk+799/844] [ext2_get_block+1071/1196]
Jul 5 23:24:06 dox kernel: Latency 72ms PID 240 % mmap002
Jul 5 23:24:06 dox kernel: Trace: [__mark_buffer_dirty+11/56] [block_getblk+113/844] [kmem_cache_alloc+121/452] [ext2_new_block+214/2056] [block_getblk+676/844] [kmem_cache_alloc+121/452] [get_unused_buffer_head+63/192]
Jul 5 23:24:06 dox kernel: Latency 24ms PID 240 % mmap002
Jul 5 23:24:06 dox kernel: Trace: [get_unused_buffer_head+61/192] [filemap_sync+500/904]
Jul 5 23:24:06 dox kernel: Latency 8ms PID 240 % mmap002
Jul 5 23:24:06 dox kernel: Trace: [kmem_cache_alloc+121/452]
Jul 5 23:24:06 dox kernel: Latency 5ms PID 240 % mmap002
Jul 5 23:24:06 dox kernel: Trace:
Jul 5 23:24:07 dox kernel: Latency 7ms PID 240 % mmap002
Jul 5 23:24:07 dox kernel: Trace: [__insert_into_lru_list+68/96]
Jul 5 23:24:07 dox kernel: Latency 18ms PID 240 % mmap002
Jul 5 23:24:07 dox kernel: Trace: [kmem_cache_grow+725/1136]
Jul 5 23:24:07 dox kernel: Latency 25ms PID 240 % mmap002
Jul 5 23:24:07 dox kernel: Trace: [kmem_cache_grow+898/1136] [__wake_up+497/512]
Jul 5 23:24:07 dox kernel: Latency 10ms PID 240 % mmap002
Jul 5 23:24:07 dox kernel: Trace: [generic_make_request+1848/1880] [__wake_up+497/512]
Jul 5 23:24:07 dox kernel: Latency 31ms PID 240 % mmap002
Jul 5 23:24:07 dox kernel: Trace: [__wake_up+497/512] [__wake_up+497/512] [try_to_swap_out+76/636]
Jul 5 23:24:07 dox kernel: Latency 23ms PID 240 % mmap002
Jul 5 23:24:07 dox kernel: Trace: [__wake_up+23/512] [try_to_swap_out+76/636]
Jul 5 23:24:08 dox kernel: Latency 13ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [__refile_buffer+52/84]
Jul 5 23:24:08 dox kernel: Latency 19ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [kmem_cache_alloc+131/452] [kmem_cache_alloc+153/452]
Jul 5 23:24:08 dox kernel: Latency 19ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [try_to_swap_out+6/636] [__wake_up+497/512]
Jul 5 23:24:08 dox kernel: Latency 18ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [generic_make_request+1848/1880] [generic_make_request+1848/1880]
Jul 5 23:24:08 dox kernel: Latency 27ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [generic_make_request+1848/1880] [__wake_up+497/512] [try_to_swap_out+604/636]
Jul 5 23:24:08 dox kernel: Latency 12ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [ide_build_sglist+115/208] [generic_make_request+1848/1880]
Jul 5 23:24:08 dox kernel: Latency 18ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [generic_make_request+1848/1880] [<c6868873>]
Jul 5 23:24:08 dox kernel: Latency 26ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [generic_make_request+1848/1880] [blk_get_queue+60/64] [generic_make_request+1848/1880]
Jul 5 23:24:08 dox kernel: Latency 8ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace:
Jul 5 23:24:08 dox kernel: Latency 17ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [__wake_up+23/512] [try_to_swap_out+7/636]
Jul 5 23:24:08 dox kernel: Latency 54ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [generic_make_request+1848/1880] [generic_make_request+1848/1880] [generic_make_request+1848/1880] [generic_make_request+1848/1880] [generic_make_request+1848/1880]
Jul 5 23:24:08 dox kernel: Latency 13ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [generic_make_request+1848/1880]
Jul 5 23:24:08 dox kernel: Latency 21ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [generic_make_request+1871/1880] [generic_make_request+1848/1880]
Jul 5 23:24:08 dox kernel: Latency 20ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [generic_make_request+1848/1880] [generic_make_request+1848/1880]
Jul 5 23:24:08 dox kernel: Latency 5ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [generic_make_request+1848/1880]
Jul 5 23:24:08 dox kernel: Latency 14ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [try_to_swap_out+76/636]
Jul 5 23:24:08 dox kernel: Latency 10ms PID 240 % mmap002
Jul 5 23:24:08 dox kernel: Trace: [inode_getblk+4/884]
Jul 5 23:24:12 dox kernel: Latency 75ms PID 240 % mmap002
Jul 5 23:24:12 dox kernel: Trace: [kmem_cache_alloc+121/452] [ext2_get_block+26/1196] [<c6868873>] [__brelse+8/32] [set_bh_page+7/100] [kmem_cache_grow+725/1136] [<c68780b6>] [set_bh_page+18/100]
Jul 5 23:24:12 dox kernel: Latency 13ms PID 240 % mmap002
Jul 5 23:24:12 dox kernel: Trace: [kmem_cache_alloc+121/452]
Jul 5 23:24:12 dox kernel: Latency 23ms PID 240 % mmap002
Jul 5 23:24:12 dox kernel: Trace: [get_hash_table+109/148] [__mark_buffer_dirty+54/56] [__insert_into_lru_list+50/96]
Jul 5 23:24:12 dox kernel: Latency 12ms PID 240 % mmap002
Jul 5 23:24:12 dox kernel: Trace: [set_bh_page+2/100]
Jul 5 23:24:13 dox kernel: Latency 75ms PID 240 % mmap002
Jul 5 23:24:13 dox kernel: Trace: [__refile_buffer+1/84] [ext2_new_block+292/2056] [get_hash_table+98/148] [block_getblk+650/844] [get_unused_buffer_head+63/192] [ext2_alloc_block+142/144] [get_unused_buffer_head+65/192] [kmem_cache_alloc+121/452]
Jul 5 23:24:15 dox kernel: Latency 29ms PID 240 % mmap002
Jul 5 23:24:15 dox kernel: Trace: [ext2_get_block+1150/1196] [kmem_cache_grow+486/1136] [<c6868873>]
Jul 5 23:24:15 dox kernel: Latency 7ms PID 240 % mmap002
Jul 5 23:24:15 dox kernel: Trace: [wake_up_process+213/220]
Jul 5 23:24:16 dox kernel: Latency 6ms PID 240 % mmap002
Jul 5 23:24:16 dox kernel: Trace: [wakeup_bdflush+76/516]
Jul 5 23:24:16 dox kernel: Latency 13ms PID 240 % mmap002
Jul 5 23:24:16 dox kernel: Trace: [kmem_cache_grow+898/1136]
Jul 5 23:24:16 dox kernel: Latency 5ms PID 240 % mmap002
Jul 5 23:24:16 dox kernel: Trace: [get_unused_buffer_head+65/192]
Jul 5 23:24:16 dox kernel: Latency 13ms PID 240 % mmap002
Jul 5 23:24:16 dox kernel: Trace: [ext2_new_block+1756/2056] [get_hash_table+68/148]
Jul 5 23:24:17 dox kernel: Latency 12ms PID 240 % mmap002
Jul 5 23:24:17 dox kernel: Trace: [<c68780b6>]
Jul 5 23:24:17 dox kernel: Latency 23ms PID 240 % mmap002
Jul 5 23:24:17 dox kernel: Trace: [__mark_buffer_dirty+11/56] [wakeup_bdflush+76/516] [__refile_buffer+72/84]
Jul 5 23:24:17 dox kernel: Latency 10ms PID 240 % mmap002
Jul 5 23:24:17 dox kernel: Trace: [filemap_sync+500/904]
Jul 5 23:24:18 dox kernel: Latency 15ms PID 240 % mmap002
Jul 5 23:24:18 dox kernel: Trace: [ext2_get_block+912/1196]
Jul 5 23:24:19 dox kernel: Latency 11ms PID 240 % mmap002
Jul 5 23:24:19 dox kernel: Trace: [get_hash_table+95/148]
Jul 5 23:24:19 dox kernel: Latency 28ms PID 240 % mmap002
Jul 5 23:24:19 dox kernel: Trace: [__wake_up+497/512] [try_to_swap_out+231/636]
Jul 5 23:24:19 dox kernel: Latency 17ms PID 240 % mmap002
Jul 5 23:24:19 dox kernel: Trace: [generic_make_request+1848/1880]
Jul 5 23:24:19 dox kernel: Latency 30ms PID 240 % mmap002
Jul 5 23:24:19 dox kernel: Trace: [kmem_cache_alloc+121/452] [__insert_into_lru_list+83/96] [ext2_new_block+1323/2056]
Jul 5 23:24:21 dox kernel: Latency 154ms PID 240 % mmap002
Jul 5 23:24:21 dox kernel: Trace: [do_buffer_fdatasync+31/132] [writeout_one_page+23/76] [writeout_one_page+23/76] [__refile_buffer+1/84] [writeout_one_page+16/76] [__remove_from_lru_list+9/108] [__insert_into_lru_list+74/96] [generic_make_request+1848/1880] [__ll_rw_block+110/440] [generic_make_request+1848/1880]
Jul 5 23:24:23 dox kernel: Latency 43ms PID 240 % mmap002
Jul 5 23:24:23 dox kernel: Trace: [__wake_up+0/512] [waitfor_one_page+23/64] [__wake_up+497/512] [waitfor_one_page+23/64]
Jul 5 23:24:27 dox kernel: Latency 11ms PID 240 % mmap002
Jul 5 23:24:27 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:24:28 dox kernel: Latency 11ms PID 240 % mmap002
Jul 5 23:24:28 dox kernel: Trace: [try_to_swap_out+18/636]
Jul 5 23:24:28 dox kernel: Latency 8ms PID 240 % mmap002
Jul 5 23:24:28 dox kernel: Trace: [__wake_up+497/512]
Jul 5 23:24:28 dox kernel: Latency 38ms PID 240 % mmap002
Jul 5 23:24:28 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+246/500] [kmem_slab_destroy+179/500]
Jul 5 23:24:28 dox kernel: Latency 5ms PID 240 % mmap002
Jul 5 23:24:28 dox kernel: Trace:
Jul 5 23:24:29 dox kernel: Latency 27ms PID 240 % mmap002
Jul 5 23:24:29 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500]
Jul 5 23:24:29 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:24:29 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:24:30 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:24:30 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:24:31 dox kernel: Latency 10ms PID 240 % mmap002
Jul 5 23:24:31 dox kernel: Trace: [try_to_swap_out+76/636]
Jul 5 23:24:31 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:24:31 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:24:32 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:24:32 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:24:33 dox kernel: Latency 12ms PID 240 % mmap002
Jul 5 23:24:33 dox kernel: Trace: [swap_out_vma+319/464]
Jul 5 23:24:36 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:24:36 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:24:40 dox kernel: Latency 9ms PID 240 % mmap002
Jul 5 23:24:40 dox kernel: Trace: [swap_out_vma+343/464]
Jul 5 23:24:41 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:24:41 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:24:45 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:24:45 dox kernel: Trace:
Jul 5 23:24:46 dox kernel: Latency 14ms PID 240 % mmap002
Jul 5 23:24:46 dox kernel: Trace: [try_to_swap_out+206/636] [try_to_swap_out+76/636]
Jul 5 23:24:47 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:24:47 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:24:51 dox kernel: Latency 10ms PID 240 % mmap002
Jul 5 23:24:51 dox kernel: Trace: [try_to_swap_out+227/636]
Jul 5 23:24:51 dox kernel: Latency 6ms PID 240 % mmap002
Jul 5 23:24:51 dox kernel: Trace: [try_to_swap_out+604/636]
Jul 5 23:24:51 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:24:51 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:24:57 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:24:57 dox kernel: Trace:
Jul 5 23:24:59 dox kernel: Latency 10ms PID 240 % mmap002
Jul 5 23:25:00 dox kernel: Trace: [ide_do_request+660/736]
Jul 5 23:25:00 dox kernel: Latency 6ms PID 242 % cron
Jul 5 23:25:00 dox kernel: Trace: [swap_out+95/272]
Jul 5 23:25:03 dox kernel: Latency 11ms PID 240 % mmap002
Jul 5 23:25:03 dox kernel: Trace: [__wake_up+26/512]
Jul 5 23:25:04 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:25:04 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:25:05 dox kernel: Latency 17ms PID 240 % mmap002
Jul 5 23:25:05 dox kernel: Trace: [swap_out_vma+319/464] [__wake_up+497/512]
Jul 5 23:25:07 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:25:07 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:25:10 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:25:10 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:25:13 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:25:13 dox kernel: Trace:
Jul 5 23:25:15 dox kernel: Latency 10ms PID 240 % mmap002
Jul 5 23:25:15 dox kernel: Trace: [__wake_up+7/512]
Jul 5 23:25:16 dox kernel: Latency 27ms PID 228 % tee
Jul 5 23:25:16 dox kernel: Trace: [swap_out_vma+365/464] [<c6868873>]
Jul 5 23:25:16 dox kernel: Latency 7ms PID 227 % vmstat
Jul 5 23:25:16 dox kernel: Trace: [try_to_swap_out+0/636]
Jul 5 23:25:18 dox kernel: Latency 9ms PID 227 % vmstat
Jul 5 23:25:18 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:25:23 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:25:23 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:25:40 dox kernel: Latency 10ms PID 240 % mmap002
Jul 5 23:25:40 dox kernel: Trace: [try_to_swap_out+0/636]
Jul 5 23:25:40 dox kernel: Latency 7ms PID 240 % mmap002
Jul 5 23:25:40 dox kernel: Trace: [try_to_swap_out+18/636]
Jul 5 23:25:41 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:25:41 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:25:46 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:25:46 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:25:47 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:25:47 dox kernel: Trace:
Jul 5 23:25:50 dox kernel: Latency 8ms PID 240 % mmap002
Jul 5 23:25:50 dox kernel: Trace: [try_to_swap_out+76/636]
Jul 5 23:25:50 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:25:50 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:25:50 dox kernel: Latency 6ms PID 240 % mmap002
Jul 5 23:25:50 dox kernel: Trace: [swap_out_vma+319/464]
Jul 5 23:25:57 dox kernel: Latency 23ms PID 240 % mmap002
Jul 5 23:25:57 dox kernel: Trace: [try_to_swap_out+227/636] [try_to_swap_out+206/636]
Jul 5 23:25:58 dox kernel: Latency 5ms PID 240 % mmap002
Jul 5 23:25:58 dox kernel: Trace: [filemap_sync+440/904]
Jul 5 23:25:58 dox kernel: Latency 9ms PID 240 % mmap002
Jul 5 23:25:58 dox kernel: Trace: [set_bh_page+96/100]
Jul 5 23:25:58 dox kernel: Latency 21ms PID 240 % mmap002
Jul 5 23:25:58 dox kernel: Trace: [kmem_cache_grow+898/1136] [kmem_cache_grow+725/1136]
Jul 5 23:25:58 dox kernel: Latency 55ms PID 240 % mmap002
Jul 5 23:25:58 dox kernel: Trace: [kmem_cache_grow+725/1136] [kmem_cache_grow+725/1136] [block_getblk+103/844] [kmem_cache_grow+959/1136] [__brelse+0/32] [block_getblk+121/844]
Jul 5 23:25:58 dox kernel: Latency 41ms PID 240 % mmap002
Jul 5 23:25:58 dox kernel: Trace: [balance_dirty_state+15/72] [block_getblk+666/844] [block_getblk+148/844] [kmem_cache_alloc+20/452] [mark_buffer_dirty+0/24]
Jul 5 23:25:58 dox kernel: Latency 35ms PID 240 % mmap002
Jul 5 23:25:58 dox kernel: Trace: [kmem_cache_alloc+121/452] [filemap_sync+503/904] [getblk+4/152]
Jul 5 23:26:01 dox kernel: Latency 59ms PID 240 % mmap002
Jul 5 23:26:01 dox kernel: Trace: [ext2_get_block+1027/1196] [block_getblk+419/844] [wakeup_bdflush+91/516] [__brelse+8/32] [get_hash_table+98/148] [wake_up_process+206/220]
Jul 5 23:26:01 dox kernel: Latency 293ms PID 240 % mmap002
Jul 5 23:26:01 dox kernel: Trace: [<c68780b6>] [generic_make_request+95/1880] [generic_make_request+1848/1880] [generic_make_request+1848/1880] [lock_page+25/36] [generic_make_request+1871/1880] [generic_make_request+1848/1880] [generic_make_request+1848/1880] [generic_make_request+1848/1880] [generic_make_request+1848/1880]
Jul 5 23:26:05 dox kernel: Latency 18ms PID 240 % mmap002
Jul 5 23:26:05 dox kernel: Trace: [waitfor_one_page+51/64]
Jul 5 23:26:05 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:05 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:26:05 dox kernel: Latency 100ms PID 240 % mmap002
Jul 5 23:26:05 dox kernel: Trace: [zap_page_range+308/500] [try_to_free_buffers+87/344] [truncate_inode_pages+270/612] [kmem_cache_free+212/644] [block_flushpage+64/144] [truncate_inode_pages+173/612] [kmem_cache_free+55/644] [__wake_up+7/512] [kmem_cache_free+637/644] [kmem_cache_free+212/644]
Jul 5 23:26:06 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:26:06 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:26:07 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:26:07 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:26:07 dox kernel: Latency 77ms PID 2 % kswapd
Jul 5 23:26:07 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500]
Jul 5 23:26:11 dox kernel: Latency 48ms PID 240 % mmap002
Jul 5 23:26:11 dox kernel: Trace: [trunc_indirect+384/568] [zap_page_range+380/500] [free_page_and_swap_cache+123/128] [__free_pages_ok+675/700]
Jul 5 23:26:12 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:26:12 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:26:13 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:13 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:26:15 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:15 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:26:17 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:26:17 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:26:18 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:18 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:26:20 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:20 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:26:22 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:26:22 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:26:23 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:23 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:26:25 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:25 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:26:27 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:26:27 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:26:28 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:28 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:26:30 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:30 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:26:32 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:26:32 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:26:33 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:33 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:26:36 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:36 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:26:39 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:39 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:26:41 dox kernel: Latency 6ms PID 0 % swapper
Jul 5 23:26:41 dox kernel: Trace:
Jul 5 23:26:43 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:26:43 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:26:46 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:46 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:26:48 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:26:48 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:26:54 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:26:54 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:26:56 dox kernel: Latency 7ms PID 244 % cat
Jul 5 23:26:56 dox kernel: Trace:
Jul 5 23:26:58 dox kernel: Latency 7ms PID 2 % kswapd
Jul 5 23:26:58 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:27:00 dox kernel: Latency 11ms PID 244 % cat
Jul 5 23:27:00 dox kernel: Trace: [kmem_cache_free+212/644]
Jul 5 23:27:00 dox kernel: Latency 9ms PID 244 % cat
Jul 5 23:27:00 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:27:00 dox kernel: Latency 20ms PID 227 % vmstat
Jul 5 23:27:00 dox kernel: Trace: [kmem_cache_free+212/644] [kmem_cache_free+4/644]
Jul 5 23:27:01 dox kernel: Latency 19ms PID 244 % cat
Jul 5 23:27:01 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500]
Jul 5 23:27:01 dox kernel: Latency 6ms PID 244 % cat
Jul 5 23:27:01 dox kernel: Trace:
Jul 5 23:27:01 dox kernel: Latency 9ms PID 244 % cat
Jul 5 23:27:01 dox kernel: Trace: [kmem_cache_free+59/644]
Jul 5 23:27:01 dox kernel: Latency 14ms PID 244 % cat
Jul 5 23:27:01 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500]
Jul 5 23:27:01 dox kernel: Latency 19ms PID 244 % cat
Jul 5 23:27:01 dox kernel: Trace: [kmem_cache_free+212/644] [kmem_cache_free+212/644]
Jul 5 23:27:01 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:01 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:27:01 dox kernel: Latency 20ms PID 2 % kswapd
Jul 5 23:27:01 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500]
Jul 5 23:27:02 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:02 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:27:05 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:05 dox kernel: Trace:
Jul 5 23:27:06 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:06 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:27:07 dox kernel: Latency 6ms PID 244 % cat
Jul 5 23:27:07 dox kernel: Trace: [try_to_free_buffers+52/344]
Jul 5 23:27:07 dox kernel: Latency 26ms PID 244 % cat
Jul 5 23:27:07 dox kernel: Trace: [kmem_slab_destroy+177/500] [kmem_slab_destroy+177/500]
Jul 5 23:27:08 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:27:08 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:27:11 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:27:11 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:27:12 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:12 dox kernel: Trace:
Jul 5 23:27:17 dox kernel: Latency 5ms PID 244 % cat
Jul 5 23:27:17 dox kernel: Trace:
Jul 5 23:27:17 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:27:17 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:27:18 dox kernel: Latency 6ms PID 244 % cat
Jul 5 23:27:18 dox kernel: Trace:
Jul 5 23:27:18 dox kernel: Latency 9ms PID 244 % cat
Jul 5 23:27:18 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:27:21 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:21 dox kernel: Trace:
Jul 5 23:27:23 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:23 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:27:23 dox kernel: Latency 7ms PID 244 % cat
Jul 5 23:27:23 dox kernel: Trace:
Jul 5 23:27:24 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:24 dox kernel: Trace: [si_swapinfo+72/136]
Jul 5 23:27:26 dox kernel: Latency 9ms PID 244 % cat
Jul 5 23:27:26 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:27:28 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:27:28 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:27:31 dox kernel: Latency 7ms PID 2 % kswapd
Jul 5 23:27:31 dox kernel: Trace:
Jul 5 23:27:33 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:33 dox kernel: Trace:
Jul 5 23:27:33 dox kernel: Latency 10ms PID 244 % cat
Jul 5 23:27:33 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:27:35 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:27:35 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:27:38 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:27:38 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:27:42 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:27:42 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:27:43 dox kernel: Latency 8ms PID 244 % cat
Jul 5 23:27:43 dox kernel: Trace: [shrink_mmap+374/524]
Jul 5 23:27:43 dox kernel: Latency 8ms PID 244 % cat
Jul 5 23:27:43 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:27:45 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:27:45 dox kernel: Trace: [si_swapinfo+88/136]
Jul 5 23:27:46 dox kernel: Latency 9ms PID 2 % kswapd
Jul 5 23:27:46 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:27:47 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:47 dox kernel: Trace: [si_swapinfo+93/136]
Jul 5 23:27:49 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:27:49 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:27:51 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:51 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:27:57 dox kernel: Latency 5ms PID 227 % vmstat
Jul 5 23:27:57 dox kernel: Trace: [si_swapinfo+75/136]
Jul 5 23:28:00 dox kernel: Latency 6ms PID 227 % vmstat
Jul 5 23:28:00 dox kernel: Trace: [si_swapinfo+98/136]
Jul 5 23:28:18 dox kernel: Latency 5ms PID 2 % kswapd
Jul 5 23:28:18 dox kernel: Trace:
Jul 5 23:28:19 dox kernel: Latency 17ms PID 2 % kswapd
Jul 5 23:28:19 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:28:43 dox kernel: Latency 11ms PID 2 % kswapd
Jul 5 23:28:43 dox kernel: Trace: [kmem_slab_destroy+177/500]
Jul 5 23:30:32 dox kernel: Latency 5ms PID 268 % cat
Jul 5 23:30:32 dox kernel: Trace:
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: new latency report
2000-07-07 1:49 new latency report Roger Larsson
@ 2000-07-07 3:21 ` Andrew Morton
2000-07-07 14:38 ` Oliver Xymoron
2000-07-09 17:44 ` Alan Cox
1 sibling, 1 reply; 6+ messages in thread
From: Andrew Morton @ 2000-07-07 3:21 UTC (permalink / raw)
To: Roger Larsson; +Cc: linux-kernel, linux-mm, linux-audio-dev
[-- Attachment #1: Type: text/plain, Size: 747 bytes --]
Roger Larsson wrote:
>
> Hi,
>
> The attached output shows that when we hit swap - there are
> code lines with latency problems :-(
> [the actual code tested is test3-pre2 with my latency modifications
> (improvement and profiling) but has one modification relative
> test3-pre4
> kswapd in the tested version always sleeps => problems accounted
> to the process causing it]
I'm losing sleep over kswapd.
> see the 293ms in generic_make_request...
Try adding the attached patch to your existing tree. It fixes a lot of stuff. sys_close() and sys_exit() still need attention.
> and the 704ms used to busy loop in modprobe...
> (SB16 non PnP)
Don't worry about it.
> These are worse then the previously found aux_write_dev :-(
Or this.
[-- Attachment #2: low-latency.patch --]
[-- Type: text/plain, Size: 1427 bytes --]
--- linux-2.4.0-test3-pre4/mm/filemap.c Thu Jul 6 20:23:47 2000
+++ linux-akpm/mm/filemap.c Fri Jul 7 01:39:02 2000
@@ -160,6 +160,8 @@
start = (lstart + PAGE_CACHE_SIZE - 1) >> PAGE_CACHE_SHIFT;
repeat:
+ if (current->need_resched)
+ schedule(); /* LOWLATENCY sys_unlink() */
head = &mapping->pages;
spin_lock(&pagecache_lock);
curr = head->next;
@@ -450,6 +452,10 @@
page_cache_get(page);
spin_unlock(&pagecache_lock);
+
+ if (current->need_resched)
+ schedule(); /* LOWLATENCY sys_sync() */
+
lock_page(page);
/* The buffers could have been free'd while we waited for the page lock */
@@ -1081,6 +1087,9 @@
* "pos" here (the actor routine has to update the user buffer
* pointers and the remaining count).
*/
+ if (current->need_resched)
+ schedule(); /* LOWLATENCY sys_read() */
+
nr = actor(desc, page, offset, nr);
offset += nr;
index += offset >> PAGE_CACHE_SHIFT;
@@ -1533,6 +1542,8 @@
* vma/file is guaranteed to exist in the unmap/sync cases because
* mmap_sem is held.
*/
+ if (current->need_resched)
+ schedule(); /* LOWLATENCY sys_msync() */
return page->mapping->a_ops->writepage(file, page);
}
@@ -2486,6 +2497,9 @@
while (count) {
unsigned long bytes, index, offset;
char *kaddr;
+
+ if (current->need_resched)
+ schedule(); /* LOWLATENCY sys_write() */
/*
* Try to find the page in the cache. If it isn't there,
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: new latency report
2000-07-07 3:21 ` Andrew Morton
@ 2000-07-07 14:38 ` Oliver Xymoron
0 siblings, 0 replies; 6+ messages in thread
From: Oliver Xymoron @ 2000-07-07 14:38 UTC (permalink / raw)
To: Andrew Morton; +Cc: Roger Larsson, linux-kernel, linux-mm, linux-audio-dev
On Fri, 7 Jul 2000, Andrew Morton wrote:
> Try adding the attached patch to your existing tree. It fixes a lot
> of stuff. sys_close() and sys_exit() still need attention.
Consider making a macro UGLYSCHEDULINGPOINT for these additions so that we
can find these easily and maybe easily switch between normal and
lowlatency for benchmarking. The 'UGLY' is to do dissuade people from
overuse.
--
"Love the dolphins," she advised him. "Write by W.A.S.T.E.."
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org. For more info on Linux MM,
see: http://www.linux.eu.org/Linux-MM/
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: new latency report
2000-07-07 1:49 new latency report Roger Larsson
2000-07-07 3:21 ` Andrew Morton
@ 2000-07-09 17:44 ` Alan Cox
2000-07-09 18:13 ` [linux-audio-dev] " Benno Senoner
1 sibling, 1 reply; 6+ messages in thread
From: Alan Cox @ 2000-07-09 17:44 UTC (permalink / raw)
To: Roger Larsson; +Cc: linux-kernel, linux-mm, linux-audio-dev
> and the 704ms used to busy loop in modprobe...
> (SB16 non PnP)
I take patches for the sb16 if it bugs you enough to fix it.
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org. For more info on Linux MM,
see: http://www.linux.eu.org/Linux-MM/
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [linux-audio-dev] Re: new latency report
2000-07-09 17:44 ` Alan Cox
@ 2000-07-09 18:13 ` Benno Senoner
2000-07-10 21:30 ` Jörn Nettingsmeier
0 siblings, 1 reply; 6+ messages in thread
From: Benno Senoner @ 2000-07-09 18:13 UTC (permalink / raw)
To: Alan Cox, Roger Larsson; +Cc: linux-kernel, linux-mm, linux-audio-dev
On Sun, 09 Jul 2000, Alan Cox wrote:
> > and the 704ms used to busy loop in modprobe...
> > (SB16 non PnP)
>
> I take patches for the sb16 if it bugs you enough to fix it.
The point is that modprobe will be a general problem:
many modules will freeze your box for dozen if not hundreds of msecs.
( eg aic7xxx )
We can live with this if we require that the user insmods all the modules
at boottime.
The problem could be the audiomatic module loading / cleaning
(kmod).
For example how do we know in advance that the user wants to use
pppd ? (ppp.o , slhc.o )
If he is offline while doing low-latency audio , and suddenly needs
something from the net, as soon as he fires up pppd, a latency-peak
may occur.
So a way to avoid latency peaks would be to inform the user, that
if (during his audio recording sessions) he wants to do some stuff which
requires module loading , he has to preload the modules at boottime,
and disable automatic module cleanup.
Anyone better ideas ?
Benno.
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org. For more info on Linux MM,
see: http://www.linux.eu.org/Linux-MM/
^ permalink raw reply [flat|nested] 6+ messages in thread
* Re: [linux-audio-dev] Re: new latency report
2000-07-09 18:13 ` [linux-audio-dev] " Benno Senoner
@ 2000-07-10 21:30 ` Jörn Nettingsmeier
0 siblings, 0 replies; 6+ messages in thread
From: Jörn Nettingsmeier @ 2000-07-10 21:30 UTC (permalink / raw)
To: Benno Senoner
Cc: Alan Cox, Roger Larsson, linux-kernel, linux-mm, linux-audio-dev
Benno Senoner wrote:
> So a way to avoid latency peaks would be to inform the user, that
> if (during his audio recording sessions) he wants to do some stuff which
> requires module loading , he has to preload the modules at boottime,
> and disable automatic module cleanup.
>
> Anyone better ideas ?
>
> Benno.
i think it's a bad approach to add some warning kludge to modprobe.
keep these tools lean and mean - besides, we wouldn't stand a chance
fiddling with modutils on lkml :)
it's no big deal telling the users to have all modules loaded on
startup and no autoclean.
low-latency users will be willing to take this small effort, and
audio boxen tend to have lots of memory, so dynamic unloading will
not be necessary.
just my....
jorn
--
Jorn Nettingsmeier
Kurfurstenstr. 49
45138 Essen, Germany
http://www.folkwang.uni-essen.de/~nettings/
--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org. For more info on Linux MM,
see: http://www.linux.eu.org/Linux-MM/
^ permalink raw reply [flat|nested] 6+ messages in thread
end of thread, other threads:[~2000-07-10 21:30 UTC | newest]
Thread overview: 6+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2000-07-07 1:49 new latency report Roger Larsson
2000-07-07 3:21 ` Andrew Morton
2000-07-07 14:38 ` Oliver Xymoron
2000-07-09 17:44 ` Alan Cox
2000-07-09 18:13 ` [linux-audio-dev] " Benno Senoner
2000-07-10 21:30 ` Jörn Nettingsmeier
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox