unusual scheduling performance

On 16x, 2.5.47 kernel compiles take about 26s when the machine is otherwise idle.

On 32x, 2.5.47 kernel compiles take about 48s when the machine is otherwise idle.

When a single-threaded task consumes an entire cpu, kernel compiles take 36s on 32s when the machine is idle aside from the task consuming that cpu and the kernel compile itself.

I suspect the scheduler, because cpu reporting in top(1) shows that a two or more cpu-intensive tasks are concentrated on the same cpu, and some long-lived tasks appear to be "bouncing" across cpus. If someone with knowledge and/or expertise with respect to scheduling semantics could look into this, I would be much obliged. Resolving this would likely address many SMP and/or NUMA scheduling performance issues.

Thanks,
Bill

1. make -j <what?>

2. profiles?

3. Can you try the latest set of NUMA sched patches posted by Eric Focht?

M.

(1) make -j64 bzImage
(2) doesn't sound useful for load balancing
(3) sure

Bill

I'm seeing the same thing. In my pagecache warmup test, I do 20 greps to pull in a 10-gig fileset. Each grep works on 1/20th of the files.

For a long, long time, one the file set was warmed up, the time to do the test took ~14 secdonds:

Average Real: 14.0824
Average User: 0.94055
Average Sys:  5.20875

Full profile here:
http://www.sr71.net/prof/grep/run-grep-warm-2.5.47-11-15-2002-15.21.31/

As of 2.5.47, it looks like this:
Average Real: 18.9168
Average User: 1.0073
Average Sys: 4.9918
Full profile here: http://www.sr71.net/prof/grep/run-grep-warm-2.5.47-11-15-2002-15.58.02/

                               readprofile ticks
                               ------------------
                               fast   slow   diff
       page_cache_readahead:     93     82    -11
    __generic_file_aio_read:     73     83     10
                  file_move:     52     86     34
                dget_locked:     57     87     30
              proc_pid_stat:    149     88    -61
       ep_notify_file_close:     59     89     30
               get_pid_list:     21     91     70
               update_atime:    100     93     -7
              get_unused_fd:     23    105     82
                       fget:    120    113     -7
                       dput:    100    120     20
             get_empty_filp:    105    121     16
                system_call:    113    129     16
    rwsem_down_write_failed:           133    133
            vfs_follow_link:    116    164     48
            file_read_actor:    198    227     29
                     __fput:    178    241     63
          radix_tree_lookup:    324    293    -31
        atomic_dec_and_lock:    229    307     78
    .text.lock.dec_and_lock:    111    331    220
             try_to_wake_up:           374    374
                kmap_atomic:    346    398     52
              kunmap_atomic:    379    409     30
                   vfs_read:    440    431     -9
           .text.lock.namei:    149    482    333
                 __d_lookup:    456    518     62
             link_path_walk:    533    710    177
                   schedule:      1   1060   1059
    do_generic_mapping_read:   1880   1846    -34
                  poll_idle:   2059  33416  31357
             __copy_to_user:  94208  87678  -6530
                      total: 104173 132206  28033

So, schedule() is being called a _lot_ more. But, for some reason, the slower one wasn't caught doing __copy_to_user() as much.

Bill, does this look like what you're seeing?

Dave Hansen
[email protected]

Possible culprit.

Please stick a dump_stack() in rwsem_down_write_failed(), and add the below. Suggest you stick with 2.5.47 to diagnose this. The loss of kksymoops is a pain.

 fs/eventpoll.c |    2 ++
 1 files changed, 2 insertions(+)

@@ -328,6 +328,8 @@ void eventpoll_release(struct file *file
 	if (list_empty(lsthead))
 		return;
 
+	printk("hey!\n");
+
 	/*
 	 * We don't want to get "file->f_ep_lock" because it is not
 	 * necessary. It is not necessary because we're in the "struct file"

_

Yup. That was a random stab based on recently-added down_write() calls.

However the down_write isn't there in 2.5.47 so that's a false lead. We'll need that dump_stack() output.

Here's Dave's profile. ep_notify_file_close() makes a small appearance. The change you made to 2.5.48 will wipe that out. Neat.

  0.058%       78 locks_remove_flock
  0.062%       82 page_cache_readahead
  0.062%       83 __generic_file_aio_read
  0.065%       86 file_move
  0.065%       87 dget_locked
  0.066%       88 proc_pid_stat
  0.067%       89 ep_notify_file_close
  0.068%       91 get_pid_list
  0.070%       93 update_atime
  0.079%      105 get_unused_fd
  0.085%      113 fget
  0.090%      120 dput
  0.091%      121 get_empty_filp
  0.097%      129 system_call
  0.100%      133 rwsem_down_write_failed
  0.124%      164 vfs_follow_link
  0.171%      227 file_read_actor
  0.182%      241 __fput
  0.221%      293 radix_tree_lookup
  0.232%      307 atomic_dec_and_lock
  0.250%      331 .text.lock.dec_and_lock
  0.282%      374 try_to_wake_up
  0.301%      398 kmap_atomic
  0.309%      409 kunmap_atomic
  0.326%      431 vfs_read
  0.364%      482 .text.lock.namei
  0.391%      518 __d_lookup
  0.537%      710 link_path_walk

0.801% 1060 schedule
1.396% 1846 do_generic_mapping_read
25.275% 33416 poll_idle
66.319% 87678 __copy_to_user
100.000% 132206 total

It was per-Linus suggestion actually :)

- Davide

That little tidbit isn't even in .47. Is that patch against one of the 2.5.47-mm's?

Dave Hansen
[email protected]

No Andrew took it from 2.5.48 ...

- Davide

[...]

No, I'm seeing strange load balancing behavior. But you seem to have tripped over a somewhat more severe anomaly.

Bill

As Andrew suggested, I put a dump_stack() in rwsem_down_write_failed().

This was actually in a 2.5.47 bk snapshot, so it has eventpoll in it. kksymoops is broken, so:
dmesg | tail -20 | sort | uniq | ksymoops -m /boot/System.map

Trace; c01c5757 <rwsem_down_write_failed+27/170>
Trace; c01220c6 <update_wall_time+16/50>
Trace; c01223ee <do_timer+2e/c0>
Trace; c0166bd3 <.text.lock.eventpoll+6/f3>
Trace; c0146568 <__fput+18/c0>
Trace; c010ae9a <handle_IRQ_event+2a/60>
Trace; c0144a05 <filp_close+85/b0>
Trace; c0144a8d <sys_close+5d/70>
Trace; c0108fab <syscall_call+7/b>

Trace; c01c5757 <rwsem_down_write_failed+27/170>
Trace; c0166bd3 <.text.lock.eventpoll+6/f3>
Trace; c0146568 <__fput+18/c0>
Trace; c011e90b <do_softirq+6b/d0>
Trace; c0144a05 <filp_close+85/b0>
Trace; c0144a8d <sys_close+5d/70>
Trace; c0108fab <syscall_call+7/b>

Trace; c01c5757 <rwsem_down_write_failed+27/170>
Trace; c0166bd3 <.text.lock.eventpoll+6/f3>
Trace; c0146568 <__fput+18/c0>
Trace; c0144c2d <generic_file_llseek+2d/e0>
Trace; c0144a05 <filp_close+85/b0>
Trace; c0144a8d <sys_close+5d/70>
Trace; c0108fab <syscall_call+7/b>

Trace; c01c5757 <rwsem_down_write_failed+27/170>
Trace; c0166bd3 <.text.lock.eventpoll+6/f3>
Trace; c0146568 <__fput+18/c0>
Trace; c01553fa <sys_getdents64+4a/98>
Trace; c0144a05 <filp_close+85/b0>
Trace; c0144a8d <sys_close+5d/70>
Trace; c0108fab <syscall_call+7/b>

Mystery solved?

Dave Hansen
[email protected]

So printk("hey!\n") would have worked. Looks like it would have talked to you, too...

So it would appear that eventpoll_release() is the problem. How odd. You're not actually _using_ epoll there, are you?

Could you pls use 2.5.48 ...
This is wierd, the code is straight forward.

- Davide

Not unless grep uses epoll.

Dave Hansen
[email protected]

I'd be surprised if it would :)

- Davide

Could you pls put this in eventpoll_release() :

        if (list_empty(lsthead))
                return;

	printk("[%p] head=%p prev=%p next=%p\n", current, lsthead,
		lsthead->prev, lsthead->next);

- Davide

one thing to note is that the kernel's compilation is not something that parallelizes well to above 8 CPUs. Our make architecture creates many link points which serialize 'threads of compilation'.

i'd try two things:

1) try Erich Focht's NUMA enhancements to the load balancer.

2) remove the -pipe flag from arch/i386/Makefile

the later thing will reduce the number of processes and makes compilation more localized to a single CPU - which might (or might not) help NUMA architectures.

Ingo

Well, I was only -j64. Thats 2 processes per-cpu... something unusual seems to happen with low process/cpu density. Some fiddling around with prior kernels seemed to show that both -j64 and -j256 were previously near-equivalent sweet spots for 32x.

The unusual bit that neither of those can really address was that eating a single cpu with something completely unrelated sped the whole process up from 48s to 36s on 32x (this is all nicely repeatable). No good explanations for this have surfaced yet. I'll have to get a good way of logging what processes are chewing how much cpu and what cpus they're running on before I can send comprehensible traces of this.

OTOH Focht's fork() and/or exec() -time load balancing should significantly help the low process/cpu density case by creating an opportunity for load balancing before the lifetime of short-lived processes expires, with the added bonus of keeping things within nodes most of the time.

Thanks,
Bill