Strange performance change 59 -> 61/62

Strange performance change 59 -> 61/62

[Martin J. Bligh]

I'm comparing 59-mjb6 to 61-mjb1 and notice some strange performance
differences that I can't explain ... not a big drop, but odd.
Only changes in -mjb during that switchover were to drop the merged stuff
and add:

+ sighand_locking
+ percpu_loadavg 
+ irq_affinity
+ kirq_clustered_fix

However, all but percpu_loadavg are just bugfixes, and I tested 
percpu_loadavg seperately (see below). Moreover, the profile differences
don't seem related.

Kernbench-2: (make -j N vmlinux, where N = 2 x num_cpus)
                                   Elapsed        User      System         CPU
                   2.5.59-mjb6       45.55      564.83      110.03     1481.00
           2.5.59-mjb6-cpuload       45.72      563.63      110.80     1474.67
                   2.5.61-mjb1       45.55      563.99      112.96     1485.50
                   2.5.62-mjb1       45.81      564.41      112.76     1478.00

Kernbench-16: (make -j N vmlinux, where N = 16 x num_cpus)
                                   Elapsed        User      System         CPU
                   2.5.59-mjb6       46.59      568.81      131.97     1503.67
           2.5.59-mjb6-cpuload       46.60      567.42      132.19     1502.67
                   2.5.61-mjb1       46.91      568.71      138.26     1506.33
                   2.5.62-mjb1       47.21      569.17      139.55     1500.67

Note the increase in systime. Diffprofile shows:

Most of the changes kind of look dcache releated, but I have the same
exact dcache patches in both trees (with sunrpc fixes) ... is anyone
familiar with the pattern below, and might be able to see what's 
causing this?

Thanks,

M.

2.5.59-mjb6 -> 2.5.61-mjb1 (+ worse in 61, - better)

1562 .text.lock.file_table
583 dentry_open
551 get_empty_filp
479 __mark_inode_dirty
274 __down
162 atomic_dec_and_lock
162 __fput
159 page_remove_rmap
148 page_add_rmap
122 vma_merge
97 current_kernel_time
93 file_move
92 do_no_page
81 do_schedule
72 find_get_page
68 dput
62 can_vma_merge_after
54 __copy_to_user_ll
...
-58 sys_brk
-69 fd_install
-70 __copy_from_user_ll
-86 do_lookup
-205 do_generic_mapping_read
-219 do_anonymous_page
-248 file_ra_state_init
-256 vfs_read
-308 path_lookup
-309 d_lookup
-506 vm_enough_memory
-1796 total
-4472 default_idle

Re: Strange performance change 59 -> 61/62

[Andrew Morton]

"Martin J. Bligh" <mbligh@aracnet.com> wrote:
>
> I'm comparing 59-mjb6 to 61-mjb1 and notice some strange performance
> differences that I can't explain ... not a big drop, but odd.
>...
> 
> 1562 .text.lock.file_table
> 583 dentry_open
> 551 get_empty_filp

The first one here is fget().  That's causing problems on ppc64 as well - the
machine is spending as long in fget as it is in copy_foo_user() in dbench
runs.

One possibility is that we're calling fget() more often than previously,
although that would be rather odd.  Can you add the below patch, and monitor
/proc/meminfo:nr_fgets?

If not that, then maybe some funny cacheline aliasing thing?


 file_table.c       |    2 ++
 linux/page-flags.h |    1 +
 page_alloc.c       |    1 +
 3 files changed, 4 insertions(+)

diff -puN include/linux/page-flags.h~fget-counter include/linux/page-flags.h
--- 25/include/linux/page-flags.h~fget-counter	2003-02-19 10:14:54.000000000 -0800
+++ 25-akpm/include/linux/page-flags.h	2003-02-19 10:15:26.000000000 -0800
@@ -87,6 +87,7 @@ struct page_state {
 	unsigned long nr_reverse_maps;	/* includes PageDirect */
 	unsigned long nr_mapped;	/* mapped into pagetables */
 	unsigned long nr_slab;		/* In slab */
+	unsigned long nr_fgets;
 #define GET_PAGE_STATE_LAST nr_slab
 
 	/*
diff -puN mm/page_alloc.c~fget-counter mm/page_alloc.c
--- 25/mm/page_alloc.c~fget-counter	2003-02-19 10:15:20.000000000 -0800
+++ 25-akpm/mm/page_alloc.c	2003-02-19 10:15:48.000000000 -0800
@@ -1439,6 +1439,7 @@ static char *vmstat_text[] = {
 	"nr_reverse_maps",
 	"nr_mapped",
 	"nr_slab",
+	"nr_fgets",
 
 	"pgpgin",
 	"pgpgout",
diff -puN fs/file_table.c~fget-counter fs/file_table.c
--- 25/fs/file_table.c~fget-counter	2003-02-19 10:15:55.000000000 -0800
+++ 25-akpm/fs/file_table.c	2003-02-19 10:16:21.000000000 -0800
@@ -12,6 +12,7 @@
 #include <linux/module.h>
 #include <linux/smp_lock.h>
 #include <linux/fs.h>
+#include <linux/mm.h>
 #include <linux/security.h>
 #include <linux/eventpoll.h>
 #include <linux/mount.h>
@@ -156,6 +157,7 @@ struct file * fget(unsigned int fd)
 	struct file * file;
 	struct files_struct *files = current->files;
 
+	inc_page_state(nr_fgets);
 	read_lock(&files->file_lock);
 	file = fcheck(fd);
 	if (file)

_

Re: Strange performance change 59 -> 61/62

[Martin J. Bligh]

>> I'm comparing 59-mjb6 to 61-mjb1 and notice some strange performance
>> differences that I can't explain ... not a big drop, but odd.
>> ...
>> 
>> 1562 .text.lock.file_table
>> 583 dentry_open
>> 551 get_empty_filp
> 
> The first one here is fget().  That's causing problems on ppc64 as well - the
> machine is spending as long in fget as it is in copy_foo_user() in dbench
> runs.
> 
> One possibility is that we're calling fget() more often than previously,
> although that would be rather odd.  Can you add the below patch, and monitor
> /proc/meminfo:nr_fgets?

Thanks for the patch, sorry it took me so long to get the testing done.

59: 4742165
61: 4743166

Pretty damned close ;-)

> If not that, then maybe some funny cacheline aliasing thing?

Mmm... you mean like something sharing the cacheline with the file lock?

M.

Re: Strange performance change 59 -> 61/62

[Martin J. Bligh]

>>> I'm comparing 59-mjb6 to 61-mjb1 and notice some strange performance
>>> differences that I can't explain ... not a big drop, but odd.
>>> ...
>>> 
>>> 1562 .text.lock.file_table
>>> 583 dentry_open
>>> 551 get_empty_filp
>> 
>> The first one here is fget().  That's causing problems on ppc64 as well - the
>> machine is spending as long in fget as it is in copy_foo_user() in dbench
>> runs.
>> 
>> One possibility is that we're calling fget() more often than previously,
>> although that would be rather odd.  Can you add the below patch, and monitor
>> /proc/meminfo:nr_fgets?

Some more stats ... which look rather suspicious. 600% increase for
dentry_open and __mark_inode_dirty? Hmmmmm.

      5198    35.9% .text.lock.file_table
      4562     2.6% total
       736    19.5% get_empty_filp
       568   617.4% dentry_open
       510   607.1% __mark_inode_dirty
       285    11.3% atomic_dec_and_lock
       272    11.9% __fput
       230    23.0% dput
       167     8.9% file_move
       159     1.0% page_remove_rmap
       128    67.7% vma_merge
       118    17.1% current_kernel_time
        66     1.0% page_add_rmap
        62     0.0% can_vma_merge_after
        50     2.3% do_schedule
...
       -56   -16.0% do_brk
       -67    -8.5% sys_brk
       -73    -0.5% do_anonymous_page
       -83   -45.6% do_lookup
      -109   -11.3% fd_install
      -114    -3.9% __copy_from_user_ll
      -133   -10.9% do_generic_mapping_read
      -282   -18.4% vfs_read
      -314   -34.4% file_ra_state_init
      -373    -7.7% vm_enough_memory
      -445    -5.5% d_lookup
     -1693    -3.8% default_idle

Re: Strange performance change 59 -> 61/62

[Andrew Morton]

"Martin J. Bligh" <mbligh@aracnet.com> wrote:
>
> Some more stats ... which look rather suspicious. 600% increase for
> dentry_open and __mark_inode_dirty? Hmmmmm.

__mark_inode_dirty() just got itself an smp_mb().  Would be instructive to
disable that.

dentry_open(): don't know - fs/open.c hasn't changed at all.  Perhaps
dcache_rcu has caused additional pingpong?

Re: Strange performance change 59 -> 61/62

[Martin J. Bligh]

>> Some more stats ... which look rather suspicious. 600% increase for
>> dentry_open and __mark_inode_dirty? Hmmmmm.
> 
> __mark_inode_dirty() just got itself an smp_mb().  Would be instructive to
> disable that.
> 
> dentry_open(): don't know - fs/open.c hasn't changed at all.  Perhaps
> dcache_rcu has caused additional pingpong?

2.5.59-mjb6             84 __mark_inode_dirty
2.5.61-mjb1            594 __mark_inode_dirty
2.5.61-mjb1-no_mb       74 __mark_inode_dirty

Yup, that fixed that one ... but presumably it was put there for a reason,
so I can't just rip it out ;-) Thanks, I'll go take a closer look at the
others.

M

Re: Strange performance change 59 -> 61/62

[Andrew Morton]

"Martin J. Bligh" <mbligh@aracnet.com> wrote:
>
> >> Some more stats ... which look rather suspicious. 600% increase for
> >> dentry_open and __mark_inode_dirty? Hmmmmm.
> > 
> > __mark_inode_dirty() just got itself an smp_mb().  Would be instructive to
> > disable that.
> > 
> > dentry_open(): don't know - fs/open.c hasn't changed at all.  Perhaps
> > dcache_rcu has caused additional pingpong?
> 
> 2.5.59-mjb6             84 __mark_inode_dirty
> 2.5.61-mjb1            594 __mark_inode_dirty
> 2.5.61-mjb1-no_mb       74 __mark_inode_dirty
> 
> Yup, that fixed that one ... but presumably it was put there for a reason,
> so I can't just rip it out ;-) Thanks, I'll go take a closer look at the
> others.

mark_inode_dirty() tends to be called _very_ frequently.  Too frequently.

Could you try remounting all filesystems noatime with

	mount /mnt/point -o remount,noatime

and the below patch will prevent us calling the barrier-happy
current_kernel_time() for noatime mounts.


diff -puN fs/inode.c~update_atime-speedup fs/inode.c
--- 25/fs/inode.c~update_atime-speedup	Fri Feb 21 12:17:00 2003
+++ 25-akpm/fs/inode.c	Fri Feb 21 12:17:33 2003
@@ -1091,17 +1091,20 @@ sector_t bmap(struct inode * inode, sect
  
 void update_atime(struct inode *inode)
 {
-	struct timespec now = CURRENT_TIME; 
+	struct timespec now;
 
-	/* Can later do this more lazily with a per superblock interval */
-	if (timespec_equal(&inode->i_atime, &now))
-		return;
 	if (IS_NOATIME(inode))
 		return;
 	if (IS_NODIRATIME(inode) && S_ISDIR(inode->i_mode))
 		return;
 	if (IS_RDONLY(inode))
 		return;
+
+	now = CURRENT_TIME;
+
+	/* Can later do this more lazily with a per superblock interval */
+	if (timespec_equal(&inode->i_atime, &now))
+		return;
 	inode->i_atime = now;
 	mark_inode_dirty_sync(inode);
 }

_

Re: Strange performance change 59 -> 61/62

[Martin J. Bligh]

> mark_inode_dirty() tends to be called _very_ frequently.  Too frequently.
> 
> Could you try remounting all filesystems noatime with
> 
> 	mount /mnt/point -o remount,noatime
> 
> and the below patch will prevent us calling the barrier-happy
> current_kernel_time() for noatime mounts.

Cool, that works nicely - thanks.

2.5.59-mjb6:             84 __mark_inode_dirty
2.5.61-mjb1:            594 __mark_inode_dirty
2.5.61-mjb1-no_mb:       74 __mark_inode_dirty
2.5.61-mjb1-noatime:     65 __mark_inode_dirty

M.

Re: Strange performance change 59 -> 61/62

[Andrew Morton]

"Martin J. Bligh" <mbligh@aracnet.com> wrote:
>
> > mark_inode_dirty() tends to be called _very_ frequently.  Too frequently.
> > 
> > Could you try remounting all filesystems noatime with
> > 
> > 	mount /mnt/point -o remount,noatime
> > 
> > and the below patch will prevent us calling the barrier-happy
> > current_kernel_time() for noatime mounts.
> 
> Cool, that works nicely - thanks.
> 
> 2.5.59-mjb6:             84 __mark_inode_dirty
> 2.5.61-mjb1:            594 __mark_inode_dirty
> 2.5.61-mjb1-no_mb:       74 __mark_inode_dirty
> 2.5.61-mjb1-noatime:     65 __mark_inode_dirty
> 

OK.  We used to only run mark_inode_dirty() for atime updates just when it
had actually changed.  ie: once per second.  But for reasons which remain
obscure that was taken out.

This probably explains your ext3 woes.  Poor old ext3 has to do a ton of work
in ext3_mark_inode_dirty(), yet on 99% of the calls, nothing has even
changed.  Which is why I suggested that you retest ext3 with noatime.

I shall fix it up.

Re: Strange performance change 59 -> 61/62

[Martin J. Bligh]

> OK.  We used to only run mark_inode_dirty() for atime updates just when it
> had actually changed.  ie: once per second.  But for reasons which remain
> obscure that was taken out.
> 
> This probably explains your ext3 woes.  Poor old ext3 has to do a ton of work
> in ext3_mark_inode_dirty(), yet on 99% of the calls, nothing has even
> changed.  Which is why I suggested that you retest ext3 with noatime.

Shall do - tommorow ;-)
 
> I shall fix it up.

Sounds great - thank you,

M.

Strange performance change 59 -> 61/62

[Martin J. Bligh]

I'm comparing 59-mjb6 to 61-mjb1 and notice some strange performance
differences that I can't explain ... not a big drop, but odd.
Only changes in -mjb during that switchover were to drop the merged stuff
and add:

+ sighand_locking
+ percpu_loadavg 
+ irq_affinity
+ kirq_clustered_fix

However, all but percpu_loadavg are just bugfixes, and I tested 
percpu_loadavg seperately (see below). Moreover, the profile differences
don't seem related.

Kernbench-2: (make -j N vmlinux, where N = 2 x num_cpus)
                                   Elapsed        User      System         CPU
                   2.5.59-mjb6       45.55      564.83      110.03     1481.00
           2.5.59-mjb6-cpuload       45.72      563.63      110.80     1474.67
                   2.5.61-mjb1       45.55      563.99      112.96     1485.50
                   2.5.62-mjb1       45.81      564.41      112.76     1478.00

Kernbench-16: (make -j N vmlinux, where N = 16 x num_cpus)
                                   Elapsed        User      System         CPU
                   2.5.59-mjb6       46.59      568.81      131.97     1503.67
           2.5.59-mjb6-cpuload       46.60      567.42      132.19     1502.67
                   2.5.61-mjb1       46.91      568.71      138.26     1506.33
                   2.5.62-mjb1       47.21      569.17      139.55     1500.67

Note the increase in systime. Diffprofile shows:

Most of the changes kind of look dcache releated, but I have the same
exact dcache patches in both trees (with sunrpc fixes) ... is anyone
familiar with the pattern below, and might be able to see what's 
causing this?

Thanks,

M.

2.5.59-mjb6 -> 2.5.61-mjb1 (+ worse in 61, - better)

1562 .text.lock.file_table
583 dentry_open
551 get_empty_filp
479 __mark_inode_dirty
274 __down
162 atomic_dec_and_lock
162 __fput
159 page_remove_rmap
148 page_add_rmap
122 vma_merge
97 current_kernel_time
93 file_move
92 do_no_page
81 do_schedule
72 find_get_page
68 dput
62 can_vma_merge_after
54 __copy_to_user_ll
...
-58 sys_brk
-69 fd_install
-70 __copy_from_user_ll
-86 do_lookup
-205 do_generic_mapping_read
-219 do_anonymous_page
-248 file_ra_state_init
-256 vfs_read
-308 path_lookup
-309 d_lookup
-506 vm_enough_memory
-1796 total
-4472 default_idle