2004-03-28 20:03:49

by Andreas Hartmann

[permalink] [raw]
Subject: Very poor performance with 2.6.4

Hello!

I tested kernel 2.6.4. While compiling kdelibs and kdebase, I felt, that
kernel 2.6 seems to be slower than 2.4.25.

So I did some tests to compare the performance directly. Therefore I
rebooted for everey test in init 2 (no X).

I locally compiled 2.6.5rc2 3 times under 2.6.4 and under 2.4.25 on a
reiserfs LVM partition, which resides onto a IDE HD (using DMA) and got
the following result:

In the middle, compiling under kernel 2.6.4 tooks 9.3% more real time than
under 2.4.25.
The user-processortime is about the same, but the system-processortime is
under 2.6.4 32.9% higher than under 2.4.25.


Now, I switched off preemption. But the performance isn't much better:
8.8% (9.3% with preemption) more real-time compared to 2.4.25 and 28%
(32.9% with preepmtion) more system-time.



Does anybody know, how to get the same performance under 2.6.4 (or even
better) as under 2.4.25?


My hardware:
AMD Athlon(tm) XP 2000+

00:00.0 Host bridge: VIA Technologies, Inc. VT8366/A/7 [Apollo KT266/A/333]
00:01.0 PCI bridge: VIA Technologies, Inc. VT8366/A/7 [Apollo KT266/A/333 AGP]
00:09.0 Ethernet controller: Silicon Integrated Systems [SiS] SiS900
10/100 Ethernet (rev 02)
00:0c.0 Ethernet controller: Intel Corp. 82557/8/9 [Ethernet Pro 100] (rev 0c)
00:10.0 USB Controller: VIA Technologies, Inc. USB (rev 80)
00:10.1 USB Controller: VIA Technologies, Inc. USB (rev 80)
00:10.2 USB Controller: VIA Technologies, Inc. USB (rev 80)
00:10.3 USB Controller: VIA Technologies, Inc. USB 2.0 (rev 82)
00:11.0 ISA bridge: VIA Technologies, Inc. VT8235 ISA Bridge
00:11.1 IDE interface: VIA Technologies, Inc.
VT82C586A/B/VT82C686/A/B/VT8233/A/C/VT8235 PIPC Bus Master IDE (rev 06)
00:11.5 Multimedia audio controller: VIA Technologies, Inc. VT8233/A/8235
AC97 Audio Controller (rev 50)
01:00.0 VGA compatible controller: ATI Technologies Inc Rage 128 PF/PRO
AGP 4x TMDS


Regards,
Andreas Hartmann


2004-03-28 20:24:45

by Matt Heler

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Have you tried the -mm tree yet ?

If not you should.

Matt

On Sunday 28 March 2004 1:02 pm, Andreas Hartmann wrote:
> Hello!
>
> I tested kernel 2.6.4. While compiling kdelibs and kdebase, I felt, that
> kernel 2.6 seems to be slower than 2.4.25.
>
> So I did some tests to compare the performance directly. Therefore I
> rebooted for everey test in init 2 (no X).
>
> I locally compiled 2.6.5rc2 3 times under 2.6.4 and under 2.4.25 on a
> reiserfs LVM partition, which resides onto a IDE HD (using DMA) and got
> the following result:
>
> In the middle, compiling under kernel 2.6.4 tooks 9.3% more real time than
> under 2.4.25.
> The user-processortime is about the same, but the system-processortime is
> under 2.6.4 32.9% higher than under 2.4.25.
>
>
> Now, I switched off preemption. But the performance isn't much better:
> 8.8% (9.3% with preemption) more real-time compared to 2.4.25 and 28%
> (32.9% with preepmtion) more system-time.
>
>
>
> Does anybody know, how to get the same performance under 2.6.4 (or even
> better) as under 2.4.25?
>
>
> My hardware:
> AMD Athlon(tm) XP 2000+
>
> 00:00.0 Host bridge: VIA Technologies, Inc. VT8366/A/7 [Apollo KT266/A/333]
> 00:01.0 PCI bridge: VIA Technologies, Inc. VT8366/A/7 [Apollo KT266/A/333
> AGP] 00:09.0 Ethernet controller: Silicon Integrated Systems [SiS] SiS900
> 10/100 Ethernet (rev 02)
> 00:0c.0 Ethernet controller: Intel Corp. 82557/8/9 [Ethernet Pro 100] (rev
> 0c) 00:10.0 USB Controller: VIA Technologies, Inc. USB (rev 80)
> 00:10.1 USB Controller: VIA Technologies, Inc. USB (rev 80)
> 00:10.2 USB Controller: VIA Technologies, Inc. USB (rev 80)
> 00:10.3 USB Controller: VIA Technologies, Inc. USB 2.0 (rev 82)
> 00:11.0 ISA bridge: VIA Technologies, Inc. VT8235 ISA Bridge
> 00:11.1 IDE interface: VIA Technologies, Inc.
> VT82C586A/B/VT82C686/A/B/VT8233/A/C/VT8235 PIPC Bus Master IDE (rev 06)
> 00:11.5 Multimedia audio controller: VIA Technologies, Inc. VT8233/A/8235
> AC97 Audio Controller (rev 50)
> 01:00.0 VGA compatible controller: ATI Technologies Inc Rage 128 PF/PRO
> AGP 4x TMDS
>
>
> Regards,
> Andreas Hartmann
>
> -
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/

2004-03-28 21:11:22

by Sasa U

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Hi,

I also have problems with speed under 2.6 ...

However, disk I/O is slower under 2.6 ... comparing to 2.4.

I talked to some people about it .. and they have the same experience ...

Aksed once about that on this mailing list, but didn't get answers ...


Regards
S

2004-03-29 04:07:14

by Andrew Morton

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Andreas Hartmann <[email protected]> wrote:
>
> I tested kernel 2.6.4. While compiling kdelibs and kdebase, I felt, that
> kernel 2.6 seems to be slower than 2.4.25.
>
> So I did some tests to compare the performance directly. Therefore I
> rebooted for everey test in init 2 (no X).
>
> I locally compiled 2.6.5rc2 3 times under 2.6.4 and under 2.4.25 on a
> reiserfs LVM partition, which resides onto a IDE HD (using DMA) and got
> the following result:
>
> In the middle, compiling under kernel 2.6.4 tooks 9.3% more real time than
> under 2.4.25.
> The user-processortime is about the same, but the system-processortime is
> under 2.6.4 32.9% higher than under 2.4.25.

Try mounting your reiserfs filesystems with the `-o nolargeio=1' option.

If that doesn't help, please run a comparative kernel profile. See
Documentation/basic_profiling.txt.

Thanks.

2004-03-29 04:09:47

by Andi Kleen

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Andreas Hartmann <[email protected]> writes:
>
> Now, I switched off preemption. But the performance isn't much better:
> 8.8% (9.3% with preemption) more real-time compared to 2.4.25 and 28%
> (32.9% with preepmtion) more system-time.

Install oprofile and do a profile run on the 2.6 kernel. This should
tell you where the system time is wasted. Post the results on this
list.

-Andi



2004-03-29 06:17:03

by Andreas Hartmann

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Andrew Morton wrote:
> Andreas Hartmann <[email protected]> wrote:
>>
>> I tested kernel 2.6.4. While compiling kdelibs and kdebase, I felt, that
>> kernel 2.6 seems to be slower than 2.4.25.
>>
>> So I did some tests to compare the performance directly. Therefore I
>> rebooted for everey test in init 2 (no X).
>>
>> I locally compiled 2.6.5rc2 3 times under 2.6.4 and under 2.4.25 on a
>> reiserfs LVM partition, which resides onto a IDE HD (using DMA) and got
>> the following result:
>>
>> In the middle, compiling under kernel 2.6.4 tooks 9.3% more real time than
>> under 2.4.25.
>> The user-processortime is about the same, but the system-processortime is
>> under 2.6.4 32.9% higher than under 2.4.25.
>
> Try mounting your reiserfs filesystems with the `-o nolargeio=1' option.

This didn't help.

>
> If that doesn't help, please run a comparative kernel profile. See
> Documentation/basic_profiling.txt.

I'll do this next.


Regards,
Andreas Hartmann

2004-03-29 14:21:58

by Chris Mason

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

On Mon, 2004-03-29 at 01:16, Andreas Hartmann wrote:
> Andrew Morton wrote:
> > Andreas Hartmann <[email protected]> wrote:
> >>
> >> I tested kernel 2.6.4. While compiling kdelibs and kdebase, I felt, that
> >> kernel 2.6 seems to be slower than 2.4.25.
> >>
> >> So I did some tests to compare the performance directly. Therefore I
> >> rebooted for everey test in init 2 (no X).
> >>
> >> I locally compiled 2.6.5rc2 3 times under 2.6.4 and under 2.4.25 on a
> >> reiserfs LVM partition, which resides onto a IDE HD (using DMA) and got
> >> the following result:
> >>
> >> In the middle, compiling under kernel 2.6.4 tooks 9.3% more real time than
> >> under 2.4.25.
> >> The user-processortime is about the same, but the system-processortime is
> >> under 2.6.4 32.9% higher than under 2.4.25.
> >
> > Try mounting your reiserfs filesystems with the `-o nolargeio=1' option.
>
> This didn't help.
>
> >
> > If that doesn't help, please run a comparative kernel profile. See
> > Documentation/basic_profiling.txt.
>
> I'll do this next.

You might also want to try 2.6.5-rc2 which has a set of reiserfs fixes
from 2.4.x. I'm hoping those will clean things up for you.

2.6.5-rc2-mm3 and higher have a number of other reiserfs performance
fixes, but most of those were not in 2.4. Trying them out will
complicate the picture (although I'm still interested in numbers from
-mm).

-chris


2004-03-29 17:42:43

by Andreas Hartmann

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Andrew Morton wrote:
> Andreas Hartmann <[email protected]> wrote:
>>
>> I tested kernel 2.6.4. While compiling kdelibs and kdebase, I felt, that
>> kernel 2.6 seems to be slower than 2.4.25.
>>
>> So I did some tests to compare the performance directly. Therefore I
>> rebooted for everey test in init 2 (no X).
>>
>> I locally compiled 2.6.5rc2 3 times under 2.6.4 and under 2.4.25 on a
>> reiserfs LVM partition, which resides onto a IDE HD (using DMA) and got
>> the following result:
>>
>> In the middle, compiling under kernel 2.6.4 tooks 9.3% more real time than
>> under 2.4.25.
>> The user-processortime is about the same, but the system-processortime is
>> under 2.6.4 32.9% higher than under 2.4.25.

[...]

> If that doesn't help, please run a comparative kernel profile. See
> Documentation/basic_profiling.txt.

Ok. Here it is:

Kernel 2.4.25 / make of kernel 2.6.5.rc2:

5617 default_idle 117.0208
4 __switch_to 0.0179
1 sys_sigreturn 0.0042
1 do_signal 0.0015
28 system_call 0.5000
2 ret_from_sys_call 0.1176
3 ret_from_exception 0.1200
2 error_code 0.0333
14 device_not_available 0.2917
3 math_state_restore 0.0469
1 do_gettimeofday 0.0104
6 old_mmap 0.0221
10 __constant_copy_from_user 0.0645
1 save_init_fpu 0.0156
9 kernel_fpu_begin 0.1406
11 restore_fpu 0.3438
1 do_check_pgt_cache 0.0069
222 do_page_fault 0.1769
19 schedule 0.0233
2 __wake_up 0.0179
1 complete 0.0089
1 remove_wait_queue 0.0156
4 copy_files 0.0058
3 do_fork 0.0016
3 __constant_c_and_count_memset 0.0234
2 dup_mmap 0.0051
7 exit_notify 0.0095
1 sys_wait4 0.0010
71 do_softirq 0.4437
2 tasklet_hi_action 0.0179
3 bh_action 0.0469
3 timer_bh 0.0144
8 run_timer_list 0.0227
1 exit_sighand 0.0104
2 sys_rt_sigprocmask 0.0048
1 do_sigaction 0.0037
2 sys_rt_sigaction 0.0104
1 sys_ni_syscall 0.0625
8 supplemental_group_member 0.1250
1 in_group_p 0.0208
1 sys_newuname 0.0104
2 __constant_copy_to_user 0.0139
10 __free_pte 0.1042
6 clear_page_tables 0.0375
15 copy_page_range 0.0361
9 zap_page_range 0.0375
5 do_wp_page 0.0098
65 do_anonymous_page 0.2708
36 do_no_page 0.0804
42 handle_mm_fault 0.1641
28 pte_alloc 0.1591
33 zap_pte_range 0.1279
6 vm_enough_memory 0.0625
10 find_vma_prepare 0.0893
5 __vma_link 0.0260
5 vma_merge 0.0223
31 do_mmap_pgoff 0.0223
29 get_unmapped_area 0.1007
34 find_vma 0.3542
1 find_vma_prev 0.0057
1 unmap_fixup 0.0030
2 free_pgtables 0.0114
8 do_munmap 0.0125
1 sys_munmap 0.0089
3 exit_mmap 0.0099
11 set_page_dirty 0.0764
1 add_to_page_cache_unique 0.0069
7 unlock_page 0.0547
76 __find_get_page 1.5833
3 __find_lock_page_helper 0.0312
7 generic_file_readahead 0.0182
12 mark_page_accessed 0.2500
25 do_generic_file_read 0.0226
124 file_read_actor 0.7750
1 generic_file_read 0.0024
44 filemap_nopage 0.0833
4 generic_file_mmap 0.0357
1 read_cache_page 0.0063
10 do_generic_file_write 0.0098
1 __read_cache_page 0.0048
1 kmalloc 0.0125
20 kmem_cache_free 0.4167
1 kfree 0.0156
20 __kmem_cache_alloc 0.0833
37 lru_cache_add 0.3304
11 __lru_cache_del 0.0764
22 delta_nr_inactive_pages 0.2750
52 __free_pages_ok 0.0813
152 rmqueue 0.2794
6 _alloc_pages 0.1875
12 __alloc_pages 0.0197
13 __free_pages 0.4062
7 nr_free_pages 0.0875
4 free_page_and_swap_cache 0.0625
1 can_share_swap_page 0.0089
7 fd_install 0.1458
1 filp_open 0.0089
2 dentry_open 0.0045
7 get_unused_fd 0.0190
4 sys_open 0.0250
3 filp_close 0.0234
2 sys_close 0.0208
4 sys_read 0.0132
2 sys_write 0.0066
7 get_empty_filp 0.0243
12 fput 0.0417
3 fget 0.0625
2 file_move 0.0417
2 __constant_c_and_count_memset 0.0156
1 __remove_from_lru_list 0.0104
15 get_hash_table 0.1172
11 getblk 0.1146
1 balance_dirty_state 0.0125
1 __brelse 0.0312
1 create_buffers 0.0045
4 __block_prepare_write 0.0053
1 block_read_full_page 0.0016
6 cp_new_stat64 0.0208
3 sys_stat64 0.0234
6 sys_fstat64 0.0469
3 __constant_c_and_count_memset 0.0208
1 __constant_copy_to_user 0.0063
5 copy_strings 0.0098
1 setup_arg_pages 0.0031
2 kernel_read 0.0156
1 exec_mmap 0.0028
1 flush_old_exec 0.0016
1 prepare_binprm 0.0031
1 __constant_c_and_count_memset 0.0078
1 pipe_read 0.0020
3 getname 0.0144
5 vfs_permission 0.0184
4 permission 0.0625
2 cached_lookup 0.0179
27 link_path_walk 0.0162
1 path_lookup 0.0156
8 path_init 0.0714
2 __user_walk 0.0208
14 open_namei 0.0105
5 page_getlink 0.0312
2 page_follow_link 0.0250
1 walk_init_root 0.0057
1 __vfs_follow_link 0.0049
1 locks_remove_posix 0.0028
2 locks_remove_flock 0.0179
10 dput 0.0298
1 d_alloc 0.0024
64 d_lookup 0.2667
1 alloc_inode 0.0030
1 __mark_inode_dirty 0.0063
2 iget4_locked 0.0083
1 insert_inode_hash 0.0125
1 update_atime 0.0089
2 dnotify_flush 0.0139
1 create_elf_tables 0.0013
3 load_elf_binary 0.0009
1 proc_lookup 0.0048
2 scan_bitmap_block 0.0017
1 scan_bitmap 0.0018
1 determine_search_start 0.0011
5 balance_leaf 0.0004
2 bin_search_in_dir_item 0.0114
2 search_by_entry_key 0.0039
1 linear_search_in_dir_item 0.0014
1 reiserfs_add_entry 0.0008
1 reiserfs_create 0.0024
1 __constant_c_and_count_memset 0.0057
4 _make_cpu_key 0.0192
1 make_cpu_key 0.0104
2 reiserfs_get_block 0.0004
4 update_stat_data 0.0139
3 reiserfs_update_sd 0.0067
1 reiserfs_new_inode 0.0007
1 reiserfs_truncate_file 0.0018
1 reiserfs_prepare_write 0.0078
1 reiserfs_commit_write 0.0027
9 reiserfs_file_release 0.0085
2 create_virtual_node 0.0015
1 check_left 0.0031
1 check_right 0.0031
3 get_num_ver 0.0033
1 set_parameters 0.0069
1 get_lfree 0.0089
1 get_rfree 0.0089
1 ip_check_balance 0.0003
1 get_direct_parent 0.0048
2 get_neighbors 0.0063
2 wait_tb_buffers_until_unlocked 0.0025
2 reiserfs_dirty_inode 0.0156
1 reiserfs_release_objectid 0.0024
2 leaf_copy_items_entirely 0.0030
5 leaf_insert_into_buf 0.0073
7 leaf_paste_in_buffer 0.0084
1 leaf_cut_entries 0.0033
1 leaf_cut_from_buffer 0.0009
1 __constant_c_and_count_memset 0.0063
1 internal_insert_childs 0.0019
1 __constant_memcpy 0.0039
1 decrement_counters_in_path 0.0125
4 is_leaf 0.0083
5 is_tree_node 0.0446
29 search_by_key 0.0084
1 search_for_position_by_key 0.0010
1 comp_items 0.0104
1 prepare_for_delete_or_cut 0.0006
1 calc_deleted_bytes_number 0.0020
1 init_tb_struct 0.0104
1 reiserfs_delete_solid_item 0.0017
1 maybe_indirect_to_direct 0.0015
1 reiserfs_cut_from_item 0.0008
1 B_IS_IN_TREE 0.0312
3 __constant_memcpy 0.0117
1 get_cnode 0.0069
4 reiserfs_in_journal 0.0076
1 flush_commit_list 0.0009
7 kupdate_one_transaction 0.0133
5 do_journal_begin_r 0.0082
1 journal_mark_dirty 0.0013
2 can_dirty 0.0114
2 check_journal_end 0.0033
1 reiserfs_restore_prepared_buffer 0.0312
1 reiserfs_prepare_for_journal 0.0069
1 __constant_c_and_count_memset 0.0069
1 sd_create_vi 0.0625
1 indirect_part_size 0.0625
3 direntry_create_vi 0.0078
1 direntry_part_size 0.0156
1 release_dev 0.0006
1 add_entropy_words 0.0063
1 credit_entropy_store 0.0208
1 generic_unplug_device 0.0156
2 __make_request 0.0011
1 generic_make_request 0.0033
11 ide_inb 0.6875
18 ide_outb 1.1250
3 ide_outl 0.1875
3 ide_execute_command 0.0187
1 ide_start_request 0.0020
1 ide_do_request 0.0025
1 ide_intr 0.0033
5 ide_build_sglist 0.0098
1 __ide_do_rw_disk 0.0006
1 idedisk_end_request 0.0048
1 sock_poll 0.0156
6 __rdtsc_delay 0.1875
6 __generic_copy_to_user 0.0625
5 __generic_copy_from_user 0.0446
8 strncpy_from_user 0.0714
5 clear_user 0.0625
23 strnlen_user 0.3026
37 _mmx_memcpy 0.1101
824 fast_clear_page 10.3000
129 fast_copy_page 0.5759
10 mmx_clear_page 0.3125
5 number 0.0071
1 vsnprintf 0.0009
2 __rb_rotate_left 0.0312
2 rb_insert_color 0.0083
1 rb_erase 0.0035
8729 total 0.0076


Kernel 2.6.4

79186 default_idle 1649,7083
1 cpu_idle 0,0156
2 exit_thread 0,0312
1 release_thread 0,0104
5 copy_thread 0,0082
1 sys_fork 0,0156
1 sys_execve 0,0078
4 restore_sigcontext 0,0125
2 sys_sigreturn 0,0096
4 setup_sigcontext 0,0132
8 setup_frame 0,0161
3 handle_signal 0,0110
3 do_signal 0,0104
1 do_notify_resume 0,0179
1 ret_from_fork 0,0500
87 ret_from_intr 3,1071
4 resume_userspace 0,1667
243 system_call 5,5227
3 syscall_call 0,2727
19 syscall_exit 1,7273
3 restore_all 0,2143
34 error_code 0,6071
161 device_not_available 3,9268
1 device_not_available_emulate 0,0667
76 math_state_restore 0,9500
5 handle_IRQ_event 0,0446
3 release_x86_irqs 0,0312
9 init_new_context 0,0312
2 destroy_context 0,0125
1 sys_pipe 0,0069
3 sys_mmap2 0,0134
166 old_mmap 0,4323
3 init_fpu 0,0208
191 kernel_fpu_begin 2,9844
98 restore_fpu 3,0625
4 convert_fxsr_to_user 0,0114
1 convert_fxsr_from_user 0,0042
3 save_i387 0,0156
1 restore_i387 0,0078
1 sched_clock 0,0069
49 delay_pmtmr 1,5312
2 pte_alloc_one 0,0250
1 pgd_alloc 0,0312
1 pgd_free 0,0312
2112 do_page_fault 1,5976
2 try_to_wake_up 0,0063
4 sched_fork 0,0312
7 wake_up_forked_process 0,0199
15 schedule_tail 0,0852
62 schedule 0,0484
57 __wake_up 1,1875
1 complete 0,0156
1 wait_for_completion 0,0057
363 __might_sleep 2,2687
1 free_task 0,0208
3 __put_task_struct 0,0117
2 add_wait_queue 0,0417
2 remove_wait_queue 0,0312
2 prepare_to_wait 0,0250
1 finish_wait 0,0125
24 dup_task_struct 0,1154
4 mm_init 0,0179
8 mm_alloc 0,1250
2 __mmdrop 0,0250
4 mmput 0,0357
1 mm_release 0,0052
67 copy_mm 0,0598
4 count_open_files 0,0833
10 copy_files 0,0145
3 unshare_files 0,0312
57 copy_process 0,0239
5 do_fork 0,0137
1 release_console_sem 0,0063
42 release_task 0,0972
3 put_files_struct 0,0156
44 exit_notify 0,0235
8 do_exit 0,0091
3 next_thread 0,0938
3 do_group_exit 0,0234
1 sys_exit_group 0,0312
2 eligible_child 0,0083
3 wait_task_zombie 0,0072
7 sys_wait4 0,0118
2 sys_waitpid 0,0465
16 current_kernel_time 0,2500
2 get_jiffies_64 0,0312
3650 do_softirq 22,8125
3 tasklet_action 0,0268
1 parse_table 0,0030
22 __mod_timer 0,1528
2 mod_timer 0,0179
171 run_timer_softirq 0,4647
1 sys_getpid 0,0625
1 sys_getppid 0,0312
3 sys_getegid 0,1875
3 free_uid 0,0375
7 flush_signal_handlers 0,0875
20 get_signal_to_deliver 0,0266
21 sigprocmask 0,1094
11 sys_rt_sigprocmask 0,0286
22 do_sigaction 0,0529
8 sys_rt_sigaction 0,0250
122 groups_search 1,0893
52 in_group_p 0,4062
2 sys_newuname 0,0114
1 sys_getrlimit 0,0069
1 sys_umask 0,0312
6 alloc_pidmap 0,0129
1 call_rcu 0,0208
1 rcu_check_quiescent_state 0,0104
1 rcu_process_callbacks 0,0045
2 kthread_should_stop 0,0625
3 acct_process 0,0517
1 __remove_from_page_cache 0,0089
2 add_to_page_cache 0,0096
12 page_waitqueue 0,2500
23 unlock_page 0,2396
458 find_get_page 9,5417
6 find_lock_page 0,0417
2 find_or_create_page 0,0104
2 find_get_pages 0,0250
90 do_generic_mapping_read 0,0953
49 file_read_actor 0,1914
43 __generic_file_aio_read 0,0896
12 generic_file_read 0,0682
145 filemap_nopage 0,1888
19 generic_file_mmap 0,2969
17 read_cache_page 0,0312
3 remove_suid 0,0268
17 generic_file_aio_write_nolock 0,0067
1 generic_file_write_nolock 0,0063
3 generic_file_write 0,0208
2 generic_write_checks 0,0033
13 mempool_alloc 0,0451
1 mempool_alloc_slab 0,0312
177 bad_range 1,5804
135 prep_new_page 1,4062
605 free_hot_cold_page 2,7009
5 free_hot_page 0,3125
1549 buffered_rmqueue 5,6949
391 __alloc_pages 0,4611
1 __get_free_pages 0,0125
1 __free_pages 0,0125
1 free_pages 0,0156
78 nr_free_pages 0,9750
2 get_zone_counts 0,0156
1 balance_dirty_pages_ratelimited 0,0156
6 __set_page_dirty_nobuffers 0,0417
3 test_clear_page_dirty 0,0375
39 file_ra_state_init 1,2188
19 do_page_cache_readahead 0,0699
65 page_cache_readahead 0,1562
165 kmem_cache_alloc 1,4732
26 __kmalloc 0,1625
114 kmem_cache_free 1,4250
17 kfree 0,1518
11 reap_timer_fnc 0,0286
7 activate_page 0,0547
250 mark_page_accessed 5,2083
1 lru_cache_add 0,0208
100 lru_cache_add_active 2,0833
10 lru_add_drain 0,1562
104 __page_cache_release 0,6500
74 release_pages 0,2721
4 __pagevec_lru_add 0,0250
221 __pagevec_lru_add_active 1,2557
1 truncate_complete_page 0,0078
1 shrink_cache 0,0016
1 blk_queue_bounce 0,0104
101 clear_page_tables 0,5739
222 pte_alloc_map 1,3875
251 copy_page_range 0,3826
827 zap_pte_range 2,1536
14 zap_pmd_range 0,1250
12 unmap_page_range 0,1071
43 unmap_vmas 0,0814
65 do_wp_page 0,0945
624 do_anonymous_page 1,5000
619 do_no_page 0,8793
577 handle_mm_fault 1,8031
40 remove_shared_vm_struct 0,2778
10 sys_brk 0,0347
110 find_vma_prepare 0,9821
4 __vma_link_rb 0,0625
18 __vma_link 0,1125
12 vma_link 0,0750
2 __insert_vm_struct 0,0139
8 can_vma_merge_before 0,1000
14 can_vma_merge_after 0,1750
85 vma_merge 0,1207
378 do_mmap_pgoff 0,2128
79 get_unmapped_area 0,2469
566 find_vma 5,8958
28 find_vma_prev 0,2917
3 expand_stack 0,0208
10 free_pgtables 0,0625
10 unmap_vma 0,0781
3 unmap_vma_list 0,0625
29 unmap_region 0,1295
28 detach_vmas_to_be_unmapped 0,2500
17 split_vma 0,0409
32 do_munmap 0,0909
16 sys_munmap 0,1250
18 do_brk 0,0331
17 exit_mmap 0,0443
2 insert_vm_struct 0,0156
1 get_one_pte_map_nested 0,0069
494 page_add_rmap 3,4306
308 page_remove_rmap 1,1324
215 __pte_chain_free 2,6875
84 pte_chain_alloc 0,8750
66 free_page_and_swap_cache 0,5893
5 can_share_swap_page 0,0446
3 si_swapinfo 0,0375
1 sys_access 0,0030
29 filp_open 0,2589
89 dentry_open 0,2139
58 get_unused_fd 0,1510
25 fd_install 0,5208
21 sys_open 0,1458
29 filp_close 0,2014
43 sys_close 0,4479
2 default_llseek 0,0156
4 sys_llseek 0,0156
69 vfs_read 0,2156
15 vfs_write 0,0469
17 sys_read 0,1518
8 sys_write 0,0714
42 get_empty_filp 0,1641
22 fput 0,6875
52 __fput 0,2031
34 fget 0,7083
37 fget_light 0,3854
20 file_move 0,4167
15 file_kill 0,4688
63 __constant_c_and_count_memset 0,4922
3 __set_page_buffers 0,0469
170 __find_get_block_slow 0,5592
1 mark_buffer_async_write 0,0312
1 inode_has_buffers 0,0312
36 __set_page_dirty_buffers 0,1607
1 invalidate_inode_buffers 0,0125
1 create_buffers 0,0057
1 init_page_buffers 0,0089
1 grow_dev_page 0,0033
1 __getblk_slow 0,0035
3 mark_buffer_dirty 0,0375
65 __brelse 1,0156
56 bh_lru_install 0,2917
408 __find_get_block 1,8214
39 __getblk 0,3482
28 __bread 0,3500
1 set_bh_page 0,0156
3 block_invalidatepage 0,0125
5 create_empty_buffers 0,0391
6 __block_write_full_page 0,0060
27 __block_prepare_write 0,0241
5 __block_commit_write 0,0347
3 block_read_full_page 0,0041
2 block_prepare_write 0,0250
2 block_commit_write 0,0417
1 generic_commit_write 0,0069
11 submit_bh 0,0229
1 ll_rw_block 0,0078
4 drop_buffers 0,0179
3 alloc_buffer_head 0,0469
1 free_buffer_head 0,0156
9 bio_alloc 0,0216
1 bio_clone 0,0063
3 sync_supers 0,0170
2 blkdev_writepage 0,0417
12 nr_blockdev_pages 0,1875
3 chrdev_open 0,0094
1 cdev_get 0,0104
38 generic_fillattr 0,2969
52 vfs_getattr 0,2708
2 vfs_stat 0,0208
14 vfs_fstat 0,1750
59 cp_new_stat64 0,1844
1 sys_stat64 0,0156
25 sys_fstat64 0,3906
7 count 0,1094
101 copy_strings 0,1661
2 copy_strings_kernel 0,0250
8 put_dirty_page 0,0312
8 setup_arg_pages 0,0179
7 open_exec 0,0292
1 kernel_read 0,0104
2 exec_mmap 0,0078
27 flush_old_exec 0,0147
3 prepare_binprm 0,0144
4 compute_creds 0,0156
9 search_binary_handler 0,0201
6 do_execve 0,0096
3 set_binfmt 0,0312
3 pipe_wait 0,0156
7 pipe_readv 0,0091
1 pipe_read 0,0156
15 pipe_writev 0,0162
1 pipe_write 0,0156
1 pipe_read_release 0,0156
1 pipe_new 0,0048
2 get_pipe_inode 0,0104
1 do_pipe 0,0019
46 getname 0,2212
30 vfs_permission 0,1042
14 permission 0,1094
3 deny_write_access 0,0625
4 path_release 0,0625
2 cached_lookup 0,0139
1 real_lookup 0,0037
56 follow_mount 0,3889
48 do_lookup 0,2727
528 link_path_walk 0,2519
75 path_lookup 0,2757
5 __lookup_hash 0,0223
2 lookup_hash 0,0417
6 __user_walk 0,0625
5 vfs_create 0,0184
122 may_open 0,2824
27 open_namei 0,0241
1 vfs_unlink 0,0023
1 sys_unlink 0,0030
1 vfs_rename_other 0,0031
2 vfs_rename 0,0025
1 sys_rename 0,0018
23 page_getlink 0,1106
35 page_follow_link 0,0841
1 expand_files 0,0089
1 locate_fd 0,0035
1 dupfd 0,0089
1 sys_dup 0,0156
1 kill_fasync 0,0156
3 sys_ioctl 0,0048
1 filldir64 0,0031
1 sys_getdents64 0,0059
1 poll_freewait 0,0125
1 __pollwait 0,0048
3 do_select 0,0044
3 sys_select 0,0023
33 locks_remove_posix 0,1719
18 locks_remove_flock 0,1607
1 steal_locks 0,0104
80 dput 0,2273
5 d_alloc 0,0104
7 d_instantiate 0,0729
2 d_lookup 0,0250
620 __d_lookup 2,4219
1 d_rehash 0,0125
1 sys_getcwd 0,0021
7 alloc_inode 0,0175
3 destroy_inode 0,0312
2 inode_init_once 0,0069
1 __iget 0,0104
1 clear_inode 0,0057
1 prune_icache 0,0022
4 find_inode_fast 0,0417
1 get_new_inode_fast 0,0052
2 iget_locked 0,0125
2 __insert_inode_hash 0,0312
1 generic_delete_inode 0,0045
2 generic_forget_inode 0,0074
1 generic_drop_inode 0,0312
25 inode_times_differ 0,3125
55 update_atime 0,2455
1 inode_update_time 0,0048
1 i_waitq_head 0,0312
2 is_bad_inode 0,0625
15 dnotify_flush 0,1042
64 dnotify_parent 0,5000
7 lookup_mnt 0,0729
3 copy_namespace 0,0042
51 __mark_inode_dirty 0,2452
6 __sync_single_inode 0,0125
1 __writeback_single_inode 0,0057
4 sync_sb_inodes 0,0071
3 writeback_inodes 0,0375
2 writeback_acquire 0,0625
24 do_mpage_readpage 0,0211
6 mpage_writepages 0,0087
6 exit_aio 0,0417
6 eventpoll_init_file 0,3750
2 eventpoll_release_file 0,0096
1 padzero 0,0208
16 create_elf_tables 0,0172
7 elf_map 0,0312
8 load_elf_interp 0,0139
33 load_elf_binary 0,0104
1 proc_delete_inode 0,0089
1 proc_read_inode 0,0156
1 proc_destroy_inode 0,0312
1 proc_get_inode 0,0042
1 proc_pid_unhash 0,0104
5 proc_pid_flush 0,1042
2 proc_file_read 0,0030
16 proc_lookup 0,0833
49 get_vmalloc_info 0,3828
3 meminfo_read_proc 0,0060
2 write_profile 0,0312
20 scan_bitmap_block 0,0171
1 scan_bitmap 0,0018
4 _reiserfs_free_block 0,0119
1 reiserfs_free_block 0,0156
1 reiserfs_discard_all_prealloc 0,0156
2 determine_prealloc_size 0,0139
11 reiserfs_allocate_blocknrs 0,0056
2 balance_leaf_when_delete 0,0018
19 balance_leaf 0,0016
1 free_thrown 0,0089
1 get_left_neighbor_position 0,0208
5 do_balance 0,0184
4 do_balance_mark_leaf_dirty 0,0278
6 bin_search_in_dir_item 0,0341
6 search_by_entry_key 0,0121
5 get_third_component 0,0521
1 reiserfs_match 0,0089
5 linear_search_in_dir_item 0,0069
3 reiserfs_find_entry 0,0085
2 reiserfs_lookup 0,0066
8 reiserfs_add_entry 0,0066
1 new_inode_init 0,0089
2 reiserfs_create 0,0048
1 reiserfs_mkdir 0,0015
2 reiserfs_unlink 0,0030
1 entry_points_to_object 0,0063
3 reiserfs_rename 0,0012
33 _make_cpu_key 0,1587
70 make_cpu_key 0,6250
1 file_capable 0,0156
2 _get_block_create_0 0,0011
13 reiserfs_get_block 0,0026
70 inode2sd 0,3646
7 inode2sd_v1 0,0486
38 update_stat_data 0,1397
62 reiserfs_update_sd 0,1435
14 reiserfs_new_inode 0,0097
2 grab_tail_page 0,0050
3 reiserfs_truncate_file 0,0059
1 lock_buffer_for_writepage 0,0063
20 reiserfs_write_full_page 0,0250
3 reiserfs_prepare_write 0,0187
5 reiserfs_commit_write 0,0136
24 i_attrs_to_sd_attrs 0,2143
1 reiserfs_releasepage 0,0089
1 make_le_item_head 0,0045
66 reiserfs_file_release 0,0607
5 reiserfs_allocate_blocks_for_region 0,0010
2 reiserfs_copy_from_user_to_file_region 0,0078
2 reiserfs_check_for_tail_and_convert 0,0048
15 reiserfs_prepare_file_region_for_write 0,0063
3 reiserfs_file_write 0,0018
3 reiserfs_readdir 0,0023
12 create_virtual_node 0,0094
4 check_left 0,0125
2 check_right 0,0063
12 get_num_ver 0,0139
4 set_parameters 0,0278
2 is_leaf_removable 0,0066
2 get_empty_nodes 0,0039
5 get_lfree 0,0446
2 get_rfree 0,0179
1 get_far_parent 0,0014
7 get_parents 0,0168
11 ip_check_balance 0,0038
1 dc_check_balance_leaf 0,0018
1 dc_check_balance 0,0208
5 check_balance 0,0284
3 get_direct_parent 0,0110
2 get_neighbors 0,0057
5 get_virtual_node_size 0,0625
5 get_mem_for_virtual_node 0,0208
11 wait_tb_buffers_until_unlocked 0,0135
14 fix_nodes 0,0139
5 unfix_nodes 0,0130
1 is_reiserfs_jr 0,0125
1 init_once 0,0208
28 reiserfs_dirty_inode 0,2188
4 reiserfs_get_unused_objectid 0,0139
2 leaf_copy_boundary_item 0,0011
1 leaf_copy_items_entirely 0,0013
1 leaf_copy_items 0,0025
3 leaf_define_dest_src_infos 0,0069
3 leaf_move_items 0,0187
2 leaf_delete_items 0,0045
23 leaf_insert_into_buf 0,0271
9 leaf_paste_in_buffer 0,0097
3 leaf_cut_entries 0,0072
8 leaf_cut_from_buffer 0,0065
16 leaf_delete_items_entirely 0,0278
10 leaf_paste_entries 0,0133
8 internal_insert_childs 0,0128
1 internal_delete_pointers_items 0,0021
1 balance_internal_when_delete 0,0017
1 balance_internal 0,0004
19 decrement_counters_in_path 0,2375
1 pathrelse_and_restore 0,0125
25 pathrelse 0,3906
301 is_leaf 0,6487
53 is_internal 0,3312
164 is_tree_node 1,4643
729 search_by_key 0,1906
13 search_for_position_by_key 0,0133
3 comp_items 0,0268
10 prepare_for_delete_or_cut 0,0053
1 calc_deleted_bytes_number 0,0021
4 init_tb_struct 0,0417
1 reiserfs_delete_solid_item 0,0018
2 maybe_indirect_to_direct 0,0030
5 reiserfs_cut_from_item 0,0040
6 reiserfs_do_truncate 0,0045
2 reiserfs_paste_into_item 0,0066
6 reiserfs_insert_item 0,0187
2 B_IS_IN_TREE 0,0625
18 copy_item_head 0,3750
5 decrement_bcount 0,0781
1 keyed_hash 0,0010
2 r5_hash 0,0250
1 unmap_buffers 0,0069
4 indirect2direct 0,0054
20 init_journal_hash 0,6250
4 get_bitmap_node 0,0250
1 set_bit_in_list_bitmap 0,0089
1 cleanup_bitmap_list 0,0048
10 get_cnode 0,0694
3 free_cnode 0,0208
1 clear_prepared_bits 0,0625
1 reiserfs_check_lock_depth 0,0625
1 push_journal_writer 0,0625
1 pop_journal_writer 0,0625
20 reiserfs_in_journal 0,0417
7 flush_commit_list 0,0061
2 find_newer_jl_for_cn 0,0417
1 submit_logged_buffer 0,0104
1 flush_journal_list 0,0010
68 kupdate_one_transaction 0,1288
1 reiserfs_journal_kupdate 0,0057
37 remove_journal_hash 0,1927
8 reiserfs_wait_on_write_block 0,0556
206 do_journal_begin_r 0,3065
23 journal_begin 0,4792
62 journal_mark_dirty 0,0861
13 journal_end 0,2708
3 remove_from_transaction 0,0082
34 can_dirty 0,1932
1 flush_old_commits 0,0022
81 check_journal_end 0,1235
2 journal_mark_freed 0,0036
3 reiserfs_update_inode_transaction 0,0469
8 reiserfs_restore_prepared_buffer 0,2500
39 reiserfs_prepare_for_journal 0,3482
98 do_journal_end 0,0302
1 mark_buffer_journal_new 0,0625
2 sd_bytes_number 0,1250
1 sd_is_left_mergeable 0,0625
1 sd_create_vi 0,0625
5 sd_part_size 0,1562
5 direct_is_left_mergeable 0,0347
2 direct_create_vi 0,1250
3 direct_part_size 0,1875
1 indirect_bytes_number 0,0312
1 indirect_create_vi 0,0625
2 indirect_part_size 0,1250
1 direntry_is_left_mergeable 0,0625
1 direntry_print_item 0,0024
13 direntry_create_vi 0,0325
1 direntry_check_left 0,0069
4 direntry_part_size 0,0625
3 copy_semundo 0,0144
2 exit_sem 0,0060
1 capable 0,0104
84 dummy_vm_enough_memory 0,4773
6 dummy_bprm_secureexec 0,0938
6 dummy_inode_alloc_security 0,3750
2 dummy_inode_create 0,1250
2 dummy_inode_follow_link 0,1250
30 dummy_inode_permission 1,8750
6 dummy_file_permission 0,3750
11 dummy_file_alloc_security 0,6875
5 dummy_file_free_security 0,3125
34 dummy_file_mmap 2,1250
1 dummy_task_wait 0,0625
1 dummy_d_instantiate 0,0625
2 radix_tree_preload 0,0156
2 radix_tree_insert 0,0104
443 radix_tree_lookup 5,5375
1 radix_tree_delete 0,0042
6 __rb_rotate_left 0,0938
2 __rb_rotate_right 0,0312
33 rb_insert_color 0,1375
7 __rb_erase_color 0,0162
18 rb_erase 0,0703
32 number 0,0435
14 vsnprintf 0,0118
1 vsprintf 0,0208
1 __delay 0,0312
1 __const_udelay 0,0278
4 __get_user_4 0,1739
4 bad_get_user 0,1600
34 memcpy 0,3542
382 _mmx_memcpy 1,0852
8292 fast_clear_page 103,6500
900 fast_copy_page 4,0179
69 mmx_clear_page 2,1562
1 mmx_copy_page 0,0208
89 strncpy_from_user 0,7946
65 clear_user 0,6771
150 strnlen_user 1,5625
1 __copy_user_intel 0,0057
2431 __copy_to_user_ll 21,7054
256 __copy_from_user_ll 2,2857
2 init_dev 0,0014
2 release_dev 0,0014
1 tty_ioctl 0,0007
1 n_tty_ioctl 0,0009
3 vt_ioctl 0,0004
1 vc_allocate 0,0022
4 con_open 0,0227
15 blk_rq_map_sg 0,0446
11 generic_unplug_device 0,1146
1 blk_run_queues 0,0078
1 ioc_set_batching 0,0156
7 get_request 0,0125
1 get_request_wait 0,0045
81 __make_request 0,0582
5 generic_make_request 0,0101
1 submit_bio 0,0089
5 as_set_request 0,0347
131 ide_end_request 0,4309
7 start_request 0,0107
75 ide_do_request 0,0901
27 ide_intr 0,0844
111 ide_inb 6,9375
268 ide_outb 16,7500
12 ide_outl 0,7500
2 SELECT_DRIVE 0,0250
2 ide_wait_stat 0,0066
26 ide_execute_command 0,1806
5 ide_dma_intr 0,0260
3 ide_build_sglist 0,0170
5 ide_build_dmatable 0,0125
1 ide_destroy_dmatable 0,0208
1 ide_start_dma 0,0057
3 __ide_dma_write 0,0134
6 __ide_dma_end 0,0375
6 __ide_do_rw_disk 0,0033
2 ide_do_rw_disk 0,0208
23 i8042_interrupt 0,0757
4 i8042_timer_func 0,0833
1 sock_poll 0,0156
120290 total 0,0752


Hope that helps,
regards,
Andreas

2004-03-29 19:35:57

by Andreas Hartmann

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Chris Mason wrote:
> On Mon, 2004-03-29 at 01:16, Andreas Hartmann wrote:
>> Andrew Morton wrote:
>> > Andreas Hartmann <[email protected]> wrote:
>> >>
>> >> I tested kernel 2.6.4. While compiling kdelibs and kdebase, I felt, that
>> >> kernel 2.6 seems to be slower than 2.4.25.
>> >>
>> >> So I did some tests to compare the performance directly. Therefore I
>> >> rebooted for everey test in init 2 (no X).
>> >>
>> >> I locally compiled 2.6.5rc2 3 times under 2.6.4 and under 2.4.25 on a
>> >> reiserfs LVM partition, which resides onto a IDE HD (using DMA) and got
>> >> the following result:
>> >>
>> >> In the middle, compiling under kernel 2.6.4 tooks 9.3% more real time than
>> >> under 2.4.25.
>> >> The user-processortime is about the same, but the system-processortime is
>> >> under 2.6.4 32.9% higher than under 2.4.25.
>> >
>> > Try mounting your reiserfs filesystems with the `-o nolargeio=1' option.
>>
>> This didn't help.
>>
>> >
>> > If that doesn't help, please run a comparative kernel profile. See
>> > Documentation/basic_profiling.txt.
>>
>> I'll do this next.
>
> You might also want to try 2.6.5-rc2 which has a set of reiserfs fixes
> from 2.4.x. I'm hoping those will clean things up for you.

Ok, here is the result for 2.6.5-rc2 (3 times middle, with preemption),
compared to 2.4.25.

The result is, the performancedifference to 2.4.25 is the same as for
2.6.4 as described above.
Nearly means: The real processing time is about 1% faster than under
2.6.4, but 8.3% slower than with 2.4.25. The system-processortime is 1.2%
faster than under 2.6.4 but 31,7% more than under 2.4.25. The times for
the user-processortime is unchanged.

But I'm not shure if these values are really significant, because the
values for the real time meassured each try differ a lot under 2.6.

For example 2.6.5rc2:
between 9.07 min and 8.37 min for real time.
Under 2.4.25, the differences are a lot of smaller: between 8.06 min and
8.15 min for real time.
The values for user and system time are nearly constant with 6.49 min and
36 sec (kernel 2.6) and 6.43 min / 27 sec for 2.4.25.


Regards,
Andreas Hartmann

2004-03-29 19:44:41

by Andreas Hartmann

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Chris Mason wrote:
> On Mon, 2004-03-29 at 01:16, Andreas Hartmann wrote:
>> Andrew Morton wrote:
>> > Andreas Hartmann <[email protected]> wrote:
>> >>
>> >> I tested kernel 2.6.4. While compiling kdelibs and kdebase, I felt, that
>> >> kernel 2.6 seems to be slower than 2.4.25.
>> >>
>> >> So I did some tests to compare the performance directly. Therefore I
>> >> rebooted for everey test in init 2 (no X).
>> >>
>> >> I locally compiled 2.6.5rc2 3 times under 2.6.4 and under 2.4.25 on a
>> >> reiserfs LVM partition, which resides onto a IDE HD (using DMA) and got
>> >> the following result:
>> >>
>> >> In the middle, compiling under kernel 2.6.4 tooks 9.3% more real time than
>> >> under 2.4.25.
>> >> The user-processortime is about the same, but the system-processortime is
>> >> under 2.6.4 32.9% higher than under 2.4.25.
>> >
>> > Try mounting your reiserfs filesystems with the `-o nolargeio=1' option.
>>
>> This didn't help.
>>
>> >
>> > If that doesn't help, please run a comparative kernel profile. See
>> > Documentation/basic_profiling.txt.
>>
>> I'll do this next.
>
> You might also want to try 2.6.5-rc2 which has a set of reiserfs fixes
> from 2.4.x. I'm hoping those will clean things up for you.

Ooops, I forgot the profiling values for 2.6.5-rc2. Here they are (I took
the values for the slowest run):


99300 default_idle 2068.7500
2 exit_thread 0.0312
1 flush_thread 0.0078
3 prepare_to_copy 0.0234
2 copy_thread 0.0033
2 sys_fork 0.0312
1 sys_vfork 0.0156
1 sys_execve 0.0078
3 restore_sigcontext 0.0094
1 sys_sigreturn 0.0045
3 setup_sigcontext 0.0099
5 setup_frame 0.0101
1 handle_signal 0.0033
1 do_signal 0.0035
252 system_call 5.7273
12 syscall_exit 1.0909
31 error_code 0.5536
184 device_not_available 4.3810
16 handle_IRQ_event 0.1429
3 release_x86_irqs 0.0234
1 init_new_context 0.0037
5 destroy_context 0.0260
127 old_mmap 0.3307
218 kernel_fpu_begin 3.4062
1 convert_fxsr_to_user 0.0028
1 convert_fxsr_from_user 0.0042
3 save_i387 0.0110
1 restore_i387_fxsave 0.0069
1 restore_i387 0.0063
2 sched_clock 0.0139
45 delay_pmtmr 1.4062
2 pte_alloc_one 0.0250
1 pgd_alloc 0.0312
2 pgd_free 0.0625
2170 do_page_fault 1.6194
3 sched_fork 0.0187
3 wake_up_forked_process 0.0078
19 schedule_tail 0.0913
84 schedule 0.0590
5 preempt_schedule 0.0625
74 __wake_up 0.7708
1 wait_for_completion 0.0045
1 io_schedule 0.0312
525 __might_sleep 2.5240
1 free_task 0.0208
2 __put_task_struct 0.0078
2 add_wait_queue 0.0208
5 remove_wait_queue 0.0446
4 prepare_to_wait 0.0312
24 dup_task_struct 0.1154
2 mm_init 0.0089
11 mm_alloc 0.1719
2 __mmdrop 0.0250
6 mmput 0.0417
4 mm_release 0.0208
67 copy_mm 0.0574
9 count_open_files 0.1875
13 copy_files 0.0153
5 unshare_files 0.0521
55 copy_process 0.0196
3 do_fork 0.0082
35 release_task 0.0706
3 put_files_struct 0.0156
45 exit_notify 0.0232
11 do_exit 0.0101
4 do_group_exit 0.0227
3 sys_exit_group 0.0938
7 eligible_child 0.0292
4 wait_task_zombie 0.0078
6 sys_wait4 0.0099
2 sys_waitpid 0.0465
1 .text.lock.exit 0.0044
20 current_kernel_time 0.3125
2 get_jiffies_64 0.0312
4190 do_softirq 26.1875
7 tasklet_action 0.0625
27 __mod_timer 0.0734
4 mod_timer 0.0357
5 del_timer 0.0347
178 run_timer_softirq 0.4120
1 sys_getpid 0.0625
1 schedule_timeout 0.0052
5 flush_signal_handlers 0.0625
1 send_group_sig_info 0.0104
10 get_signal_to_deliver 0.0118
35 sigprocmask 0.1823
12 sys_rt_sigprocmask 0.0300
14 do_sigaction 0.0273
5 sys_rt_sigaction 0.0149
127 groups_search 1.1339
61 in_group_p 0.4766
4 sys_newuname 0.0227
3 sys_getrlimit 0.0208
6 alloc_pidmap 0.0121
2 call_rcu 0.0417
3 rcu_start_batch 0.0469
7 rcu_check_quiescent_state 0.0486
1 rcu_process_callbacks 0.0039
6 exit_itimers 0.0469
4 acct_process 0.0286
1 __remove_from_page_cache 0.0089
1 remove_from_page_cache 0.0125
1 add_to_page_cache 0.0042
2 add_to_page_cache_lru 0.0250
12 page_waitqueue 0.2500
33 unlock_page 0.3438
1 end_page_writeback 0.0078
452 find_get_page 4.7083
1 find_lock_page 0.0048
2 find_or_create_page 0.0114
1 find_get_pages 0.0089
102 do_generic_mapping_read 0.1045
46 file_read_actor 0.1797
46 __generic_file_aio_read 0.0846
17 generic_file_read 0.0966
180 filemap_nopage 0.2123
29 generic_file_mmap 0.4531
18 read_cache_page 0.0331
11 generic_file_aio_write_nolock 0.0040
4 generic_file_write_nolock 0.0250
2 generic_file_write 0.0139
1 generic_write_checks 0.0015
20 mempool_alloc 0.0543
1 mempool_alloc_slab 0.0312
189 bad_range 1.6875
152 prep_new_page 1.5833
577 free_hot_cold_page 2.2539
2 free_hot_page 0.1250
1676 buffered_rmqueue 3.7411
318 __alloc_pages 0.3750
1 free_pages 0.0156
111 nr_free_pages 1.3875
1 get_page_state 0.0312
2 get_zone_counts 0.0156
1 get_dirty_limits 0.0048
4 balance_dirty_pages_ratelimited 0.0250
1 do_writepages 0.0156
4 __set_page_dirty_nobuffers 0.0179
3 test_clear_page_dirty 0.0312
52 file_ra_state_init 1.0833
33 do_page_cache_readahead 0.0897
51 page_cache_readahead 0.0996
2 cache_grow 0.0031
161 kmem_cache_alloc 1.4375
2 kmem_ptr_validate 0.0250
26 __kmalloc 0.1625
94 kmem_cache_free 1.1750
17 kfree 0.1518
12 reap_timer_fnc 0.0242
6 activate_page 0.0375
216 mark_page_accessed 4.5000
169 lru_cache_add_active 1.7604
13 lru_add_drain 0.1354
145 __page_cache_release 1.0069
91 release_pages 0.2473
5 __pagevec_lru_add 0.0195
227 __pagevec_lru_add_active 0.8346
1 shrink_list 0.0008
1 refill_inactive_zone 0.0008
3 blk_queue_bounce 0.0312
79 clear_page_tables 0.4489
286 pte_alloc_map 1.4896
238 copy_page_range 0.2755
744 zap_pte_range 1.9375
8 zap_pmd_range 0.0714
26 unmap_page_range 0.2321
46 unmap_vmas 0.0846
48 do_wp_page 0.0577
706 do_anonymous_page 1.3789
695 do_no_page 0.8865
560 handle_mm_fault 1.5217
42 remove_shared_vm_struct 0.2917
12 sys_brk 0.0417
78 find_vma_prepare 0.6964
6 __vma_link_rb 0.0938
21 __vma_link 0.1313
23 vma_link 0.1437
3 __insert_vm_struct 0.0208
12 can_vma_merge_before 0.1500
29 can_vma_merge_after 0.3625
113 vma_merge 0.1471
418 do_mmap_pgoff 0.2354
81 get_unmapped_area 0.2531
500 find_vma 5.2083
36 find_vma_prev 0.3750
2 expand_stack 0.0104
14 free_pgtables 0.0875
11 unmap_vma 0.0859
6 unmap_vma_list 0.1250
18 unmap_region 0.0804
27 detach_vmas_to_be_unmapped 0.2411
16 split_vma 0.0357
25 do_munmap 0.0625
11 sys_munmap 0.0859
11 do_brk 0.0202
14 exit_mmap 0.0350
3 insert_vm_struct 0.0234
1 get_one_pte_map_nested 0.0069
561 page_add_rmap 3.1875
426 page_remove_rmap 1.4013
1 try_to_unmap_one 0.0024
246 __pte_chain_free 2.1964
113 pte_chain_alloc 0.5885
69 free_page_and_swap_cache 0.6161
4 can_share_swap_page 0.0357
2 si_swapinfo 0.0179
2 sys_access 0.0060
1 sys_chmod 0.0039
35 filp_open 0.3125
105 dentry_open 0.1989
76 get_unused_fd 0.1827
4 put_unused_fd 0.0625
30 fd_install 0.4688
34 sys_open 0.2361
31 filp_close 0.2153
31 sys_close 0.1938
5 default_llseek 0.0208
4 sys_llseek 0.0156
60 vfs_read 0.1875
16 vfs_write 0.0500
14 sys_read 0.1250
6 sys_write 0.0536
54 get_empty_filp 0.2109
14 fput 0.4375
56 __fput 0.1842
29 fget 0.4531
38 fget_light 0.2639
43 file_move 0.4479
28 file_kill 0.4375
67 __constant_c_and_count_memset 0.4653
1 __set_page_buffers 0.0156
1 __clear_page_buffers 0.0156
146 __find_get_block_slow 0.4148
1 mark_buffer_async_write 0.0312
1 inode_has_buffers 0.0312
65 __set_page_dirty_buffers 0.2138
3 create_buffers 0.0170
2 grow_dev_page 0.0057
2 __getblk_slow 0.0069
2 mark_buffer_dirty 0.0250
71 __brelse 1.1094
2 __bforget 0.0208
84 bh_lru_install 0.3750
457 __find_get_block 1.7852
46 __getblk 0.4107
37 __bread 0.4625
1 set_bh_page 0.0156
1 block_invalidatepage 0.0042
1 create_empty_buffers 0.0063
7 __block_write_full_page 0.0067
30 __block_prepare_write 0.0268
4 __block_commit_write 0.0278
1 block_read_full_page 0.0013
2 block_prepare_write 0.0250
11 submit_bh 0.0229
2 check_ttfb_buffer 0.0208
2 free_buffer_head 0.0179
3 init_buffer_head 0.0625
19 bio_alloc 0.0457
2 sync_supers 0.0083
17 nr_blockdev_pages 0.1771
2 chrdev_open 0.0038
1 cdev_get 0.0052
30 generic_fillattr 0.1875
35 vfs_getattr 0.1823
6 vfs_stat 0.0625
11 vfs_fstat 0.1375
53 cp_new_stat64 0.1656
3 sys_stat64 0.0469
26 sys_fstat64 0.4062
8 count 0.1250
105 copy_strings 0.1727
3 put_dirty_page 0.0089
10 setup_arg_pages 0.0223
6 open_exec 0.0250
1 kernel_read 0.0104
6 exec_mmap 0.0187
13 flush_old_exec 0.0060
3 prepare_binprm 0.0144
3 compute_creds 0.0104
12 search_binary_handler 0.0170
4 do_execve 0.0064
5 set_binfmt 0.0312
7 pipe_wait 0.0365
13 pipe_readv 0.0169
7 pipe_writev 0.0075
2 pipe_write 0.0312
2 pipe_release 0.0089
1 pipe_read_fasync 0.0069
27 getname 0.1298
23 vfs_permission 0.0799
20 permission 0.1562
3 deny_write_access 0.0375
1 path_release 0.0156
2 cached_lookup 0.0139
4 real_lookup 0.0147
39 follow_mount 0.2708
43 do_lookup 0.2443
534 link_path_walk 0.2181
72 path_lookup 0.2250
1 __lookup_hash 0.0045
1 lookup_hash 0.0208
6 __user_walk 0.0625
1 lock_rename 0.0028
3 unlock_rename 0.0375
2 vfs_create 0.0074
104 may_open 0.2407
49 open_namei 0.0437
1 vfs_unlink 0.0023
1 sys_unlink 0.0030
1 vfs_rename 0.0012
26 page_getlink 0.1250
23 page_follow_link 0.0479
3 locate_fd 0.0104
1 sys_dup2 0.0033
2 do_fcntl 0.0046
1 sys_fcntl64 0.0052
2 kill_fasync 0.0156
6 sys_ioctl 0.0083
1 vfs_readdir 0.0048
1 filldir64 0.0031
1 poll_freewait 0.0125
1 sys_select 0.0008
31 locks_remove_posix 0.1140
34 locks_remove_flock 0.1771
3 steal_locks 0.0144
3 d_callback 0.0469
2 d_free 0.0312
63 dput 0.1193
1 prune_dcache 0.0022
3 d_alloc 0.0059
3 d_instantiate 0.0234
1 d_lookup 0.0125
652 __d_lookup 1.9405
3 d_delete 0.0117
3 d_rehash 0.0268
2 d_move 0.0033
1 sys_getcwd 0.0017
14 alloc_inode 0.0350
1 destroy_inode 0.0104
2 inode_init_once 0.0069
1 prune_icache 0.0020
1 new_inode 0.0078
1 iget_locked 0.0052
4 __insert_inode_hash 0.0417
2 generic_delete_inode 0.0069
2 generic_forget_inode 0.0057
3 iput 0.0234
36 inode_times_differ 0.4500
87 update_atime 0.3884
5 inode_update_time 0.0223
1 wake_up_inode 0.0208
38 dnotify_flush 0.1979
31 dnotify_parent 0.1615
10 lookup_mnt 0.0781
3 copy_namespace 0.0039
56 __mark_inode_dirty 0.2500
2 write_inode 0.0250
10 __sync_single_inode 0.0184
11 sync_sb_inodes 0.0181
2 writeback_inodes 0.0125
2 writeback_acquire 0.0625
1 writeback_in_progress 0.0625
2 writeback_release 0.0435
32 do_mpage_readpage 0.0274
14 mpage_writepages 0.0190
7 exit_aio 0.0486
1 eventpoll_init_file 0.0312
1 set_brk 0.0104
7 create_elf_tables 0.0075
1 elf_map 0.0045
3 load_elf_interp 0.0052
36 load_elf_binary 0.0114
2 de_put 0.0089
1 proc_read_inode 0.0156
2 proc_alloc_inode 0.0156
1 proc_destroy_inode 0.0312
2 proc_get_inode 0.0066
2 proc_root_lookup 0.0156
3 proc_pid_unhash 0.0234
2 proc_file_read 0.0030
17 proc_lookup 0.0590
1 proc_calc_metrics 0.0104
40 get_vmalloc_info 0.2273
2 meminfo_read_proc 0.0040
2 write_profile 0.0312
12 scan_bitmap_block 0.0103
6 scan_bitmap 0.0107
2 _reiserfs_free_block 0.0060
1 reiserfs_discard_all_prealloc 0.0156
1 use_preallocated_list_if_available 0.0089
17 reiserfs_allocate_blocknrs 0.0086
5 balance_leaf_when_delete 0.0045
26 balance_leaf 0.0021
1 store_thrown 0.0104
2 free_thrown 0.0179
1 replace_key 0.0045
5 do_balance 0.0184
2 do_balance_mark_leaf_dirty 0.0139
5 bin_search_in_dir_item 0.0284
5 search_by_entry_key 0.0101
3 get_third_component 0.0312
1 reiserfs_match 0.0089
11 linear_search_in_dir_item 0.0153
3 reiserfs_find_entry 0.0085
3 reiserfs_lookup 0.0078
5 reiserfs_add_entry 0.0041
1 new_inode_init 0.0089
2 reiserfs_create 0.0045
1 de_still_valid 0.0045
1 set_ino_in_dir_entry 0.0156
3 reiserfs_rename 0.0011
2 reiserfs_delete_inode 0.0066
37 _make_cpu_key 0.1779
92 make_cpu_key 0.8214
2 file_capable 0.0312
1 _get_block_create_0 0.0005
10 reiserfs_get_block 0.0019
77 inode2sd 0.4010
2 inode2sd_v1 0.0139
52 update_stat_data 0.1912
62 reiserfs_update_sd 0.1384
14 reiserfs_new_inode 0.0097
3 grab_tail_page 0.0075
1 reiserfs_truncate_file 0.0017
2 lock_buffer_for_writepage 0.0125
40 reiserfs_write_full_page 0.0500
1 reiserfs_writepage 0.0156
3 reiserfs_prepare_write 0.0170
5 reiserfs_commit_write 0.0101
34 i_attrs_to_sd_attrs 0.3036
3 make_le_item_head 0.0136
51 reiserfs_file_release 0.0431
5 reiserfs_allocate_blocks_for_region 0.0009
1 reiserfs_copy_from_user_to_file_region 0.0039
2 reiserfs_check_for_tail_and_convert 0.0036
10 reiserfs_prepare_file_region_for_write 0.0040
5 reiserfs_file_write 0.0025
2 reiserfs_readdir 0.0015
23 create_virtual_node 0.0180
6 check_left 0.0187
2 check_right 0.0063
9 get_num_ver 0.0104
5 set_parameters 0.0347
2 is_leaf_removable 0.0066
3 are_leaves_removable 0.0082
3 get_empty_nodes 0.0059
5 get_rfree 0.0446
1 get_far_parent 0.0014
2 get_parents 0.0048
18 ip_check_balance 0.0062
1 dc_check_balance_internal 0.0007
3 dc_check_balance_leaf 0.0055
3 check_balance 0.0170
7 get_direct_parent 0.0257
5 get_neighbors 0.0142
4 get_virtual_node_size 0.0500
3 get_mem_for_virtual_node 0.0125
11 wait_tb_buffers_until_unlocked 0.0135
13 fix_nodes 0.0129
10 unfix_nodes 0.0260
1 is_reiserfs_jr 0.0125
1 reiserfs_write_super 0.0069
3 add_save_link 0.0055
3 reiserfs_alloc_inode 0.0625
44 reiserfs_dirty_inode 0.2292
3 reiserfs_get_unused_objectid 0.0104
3 reiserfs_release_objectid 0.0055
2 leaf_copy_boundary_item 0.0011
4 leaf_copy_items_entirely 0.0052
1 leaf_copy_items 0.0025
4 leaf_delete_items 0.0089
15 leaf_insert_into_buf 0.0177
10 leaf_paste_in_buffer 0.0108
1 leaf_cut_entries 0.0024
8 leaf_cut_from_buffer 0.0065
14 leaf_delete_items_entirely 0.0243
13 leaf_paste_entries 0.0173
10 internal_insert_childs 0.0160
2 balance_internal 0.0008
20 decrement_counters_in_path 0.2500
5 pathrelse_and_restore 0.0625
26 pathrelse 0.4062
267 is_leaf 0.5754
30 is_internal 0.1875
158 is_tree_node 1.4107
795 search_by_key 0.2062
10 search_for_position_by_key 0.0102
2 comp_items 0.0208
14 prepare_for_delete_or_cut 0.0072
1 calc_deleted_bytes_number 0.0021
4 init_tb_struct 0.0417
1 reiserfs_delete_object 0.0089
1 maybe_indirect_to_direct 0.0015
4 reiserfs_cut_from_item 0.0032
10 reiserfs_do_truncate 0.0075
2 reiserfs_insert_item 0.0063
1 B_IS_IN_TREE 0.0312
18 copy_item_head 0.3750
3 decrement_bcount 0.0469
3 r5_hash 0.0375
1 reiserfs_unmap_buffer 0.0052
1 unmap_buffers 0.0078
1 indirect2direct 0.0014
22 init_journal_hash 0.6875
1 get_bitmap_node 0.0063
1 set_bit_in_list_bitmap 0.0089
5 get_cnode 0.0347
1 push_journal_writer 0.0625
15 reiserfs_in_journal 0.0312
9 flush_commit_list 0.0078
3 find_newer_jl_for_cn 0.0625
1 remove_all_from_journal_list 0.0057
1 _update_journal_header_block 0.0037
1 flush_older_journal_lists 0.0063
1 submit_logged_buffer 0.0104
41 kupdate_one_transaction 0.0777
28 remove_journal_hash 0.1458
2 journal_transaction_should_end 0.0179
8 reiserfs_wait_on_write_block 0.0556
171 do_journal_begin_r 0.2545
8 journal_begin 0.1667
56 journal_mark_dirty 0.0778
15 journal_end 0.3125
36 can_dirty 0.2045
2 flush_old_commits 0.0043
90 check_journal_end 0.1372
3 journal_mark_freed 0.0054
7 reiserfs_restore_prepared_buffer 0.2188
44 reiserfs_prepare_for_journal 0.3929
90 do_journal_end 0.0277
2 sd_bytes_number 0.1250
2 sd_is_left_mergeable 0.1250
4 sd_create_vi 0.2500
7 sd_part_size 0.2188
5 direct_is_left_mergeable 0.0347
3 direct_create_vi 0.1875
1 indirect_is_left_mergeable 0.0089
2 indirect_create_vi 0.1250
1 indirect_part_size 0.0625
1 direntry_is_left_mergeable 0.0625
13 direntry_create_vi 0.0325
3 direntry_check_left 0.0208
3 direntry_part_size 0.0469
4 copy_semundo 0.0192
3 exit_sem 0.0089
1 sysvipc_sem_read_proc 0.0027
4 dummy_capable 0.0833
117 dummy_vm_enough_memory 0.6648
3 dummy_bprm_alloc_security 0.1875
2 dummy_bprm_secureexec 0.0312
6 dummy_inode_alloc_security 0.3750
1 dummy_inode_create 0.0625
1 dummy_inode_mkdir 0.0625
4 dummy_inode_follow_link 0.2500
30 dummy_inode_permission 1.8750
2 dummy_inode_getattr 0.1250
3 dummy_file_permission 0.1875
21 dummy_file_alloc_security 1.3125
1 dummy_file_free_security 0.0625
38 dummy_file_mmap 2.3750
1 dummy_file_fcntl 0.0625
1 dummy_task_create 0.0625
1 dummy_task_free_security 0.0625
2 dummy_d_instantiate 0.1250
3 radix_tree_insert 0.0156
474 radix_tree_lookup 5.9250
2 radix_tree_gang_lookup 0.0139
2 radix_tree_delete 0.0083
6 __rb_rotate_left 0.0938
6 __rb_rotate_right 0.0938
41 rb_insert_color 0.1708
5 __rb_erase_color 0.0116
30 rb_erase 0.1172
2 skip_atoi 0.0312
21 number 0.0285
12 vsnprintf 0.0101
1 sprintf 0.0208
109 atomic_dec_and_lock 1.3625
4 __const_udelay 0.1111
5 __get_user_4 0.2174
7 bad_get_user 0.7778
56 memcpy 0.5833
368 _mmx_memcpy 1.0000
8390 fast_clear_page 87.3958
852 fast_copy_page 3.3281
82 mmx_clear_page 2.5625
6 mmx_copy_page 0.1250
79 strncpy_from_user 0.7054
51 clear_user 0.5312
184 strnlen_user 1.9167
2 __copy_user_intel 0.0114
2436 __copy_to_user_ll 21.7500
279 __copy_from_user_ll 1.7437
1 init_dev 0.0007
7 release_dev 0.0045
1 tty_open 0.0012
1 tty_release 0.0104
2 tty_ioctl 0.0015
2 n_tty_ioctl 0.0017
1 vt_ioctl 0.0001
1 vc_allocate 0.0022
2 con_close 0.0208
1 elv_set_request 0.0156
1 blk_recount_segments 0.0018
30 blk_rq_map_sg 0.0893
10 generic_unplug_device 0.0893
2 blk_run_queues 0.0114
9 get_request 0.0134
1 blk_congestion_wait 0.0063
112 __make_request 0.0778
7 generic_make_request 0.0141
2 submit_bio 0.0179
2 put_io_context 0.0208
4 get_io_context 0.0312
2 as_work_handler 0.0179
9 as_set_request 0.0625
1 default_end_request 0.0625
145 ide_end_request 0.4315
8 start_request 0.0125
97 ide_do_request 0.1102
40 ide_intr 0.1000
150 ide_inb 9.3750
297 ide_outb 18.5625
28 ide_outl 1.7500
3 SELECT_DRIVE 0.0375
2 ide_wait_stat 0.0066
36 ide_execute_command 0.1875
3 ide_dma_intr 0.0156
2 ide_build_sglist 0.0114
3 ide_build_dmatable 0.0075
1 ide_destroy_dmatable 0.0208
6 ide_start_dma 0.0341
5 __ide_dma_write 0.0223
1 __ide_dma_begin 0.0125
2 __ide_dma_end 0.0125
5 __ide_do_rw_disk 0.0027
19 i8042_interrupt 0.0540
6 i8042_timer_func 0.1250
1 datagram_poll 0.0039
1 rt_check_expire 0.0037
1 tcp_poll 0.0028
142289 total 0.0819


Regards,
Andreas Hartmann

2004-04-02 08:23:08

by Andreas Hartmann

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Chris Mason wrote:
> On Mon, 2004-03-29 at 01:16, Andreas Hartmann wrote:
>> Andrew Morton wrote:
>> > Andreas Hartmann <[email protected]> wrote:
>> >>
>> >> I tested kernel 2.6.4. While compiling kdelibs and kdebase, I felt, that
>> >> kernel 2.6 seems to be slower than 2.4.25.
>> >>
>> >> So I did some tests to compare the performance directly. Therefore I
>> >> rebooted for everey test in init 2 (no X).
>> >>
>> >> I locally compiled 2.6.5rc2 3 times under 2.6.4 and under 2.4.25 on a
>> >> reiserfs LVM partition, which resides onto a IDE HD (using DMA) and got
>> >> the following result:
>> >>
>> >> In the middle, compiling under kernel 2.6.4 tooks 9.3% more real time than
>> >> under 2.4.25.
>> >> The user-processortime is about the same, but the system-processortime is
>> >> under 2.6.4 32.9% higher than under 2.4.25.
>> >
>> > Try mounting your reiserfs filesystems with the `-o nolargeio=1' option.
>>
>> This didn't help.
>>
>> >
>> > If that doesn't help, please run a comparative kernel profile. See
>> > Documentation/basic_profiling.txt.
>>
>> I'll do this next.
>
> You might also want to try 2.6.5-rc2 which has a set of reiserfs fixes
> from 2.4.x. I'm hoping those will clean things up for you.
>
> 2.6.5-rc2-mm3 and higher have a number of other reiserfs performance
> fixes, but most of those were not in 2.4. Trying them out will
> complicate the picture (although I'm still interested in numbers from
> -mm).

Now, I tested 2.6.5-rc3-mm4. Same procedure.
The good news first:
2.6.5-rc3-mm4 is nearly as fast as 2.4.25 - it is about 2% slower than
2.4.25 (with preemption turned on).

Now the bad news:
The system-processor-time is unchanged abnormal high: it is 34% (!) higher
than in 2.4.25 (and about 1% more than in 2.4.6).


Btw: Did the other profile outputs help to find the problem?

These are the profile-values for an example run (make of kernel 2.6.5rc2)
with 2.6.5rc3mm4:

48344 default_idle 1007.1667
2 cpu_idle 0.0312
1 exit_thread 0.0156
2 flush_thread 0.0156
2 release_thread 0.0250
2 prepare_to_copy 0.0156
2 sys_fork 0.0312
1 sys_vfork 0.0156
4 sys_execve 0.0312
1 __down 0.0035
3 sys_sigreturn 0.0134
1 setup_sigcontext 0.0033
7 setup_frame 0.0141
2 handle_signal 0.0078
3 do_signal 0.0099
10 handle_IRQ_event 0.0893
4 release_x86_irqs 0.0312
7 init_new_context 0.0199
1 destroy_context 0.0125
3 do_gettimeofday 0.0170
143 old_mmap 0.3724
213 kernel_fpu_begin 3.3281
2 convert_fxsr_to_user 0.0048
2 convert_fxsr_from_user 0.0060
3 save_i387 0.0110
3 sched_clock 0.0208
36 delay_pmtmr 1.1250
10 get_offset_pmtmr 0.0046
3 pte_alloc_one 0.0375
2 pgd_alloc 0.0625
2 pgd_free 0.0312
2289 do_page_fault 1.7211
1 try_to_wake_up 0.0052
6 wake_up_forked_process 0.0163
85 finish_task_switch 0.5903
18 schedule 0.0163
1 preempt_schedule 0.0125
16 __wake_up 0.1667
1 __wake_up_sync 0.0078
2 wait_for_completion 0.0078
1 io_schedule 0.0312
529 __might_sleep 2.5433
5 __put_task_struct 0.0195
3 add_wait_queue 0.0312
1 remove_wait_queue 0.0069
1 prepare_to_wait 0.0078
28 dup_task_struct 0.1167
4 mm_init 0.0179
7 mm_alloc 0.1094
2 __mmdrop 0.0250
4 mmput 0.0227
4 mm_release 0.0208
48 copy_mm 0.0411
8 count_open_files 0.1667
23 copy_files 0.0271
4 unshare_files 0.0417
37 copy_process 0.0129
8 do_fork 0.0220
49 release_task 0.0988
11 put_files_struct 0.0573
51 exit_notify 0.0270
13 do_exit 0.0119
1 next_thread 0.0312
5 do_group_exit 0.0284
1 sys_exit_group 0.0312
4 eligible_child 0.0167
8 wait_task_zombie 0.0156
9 sys_wait4 0.0148
1 sys_waitpid 0.0233
1 .text.lock.exit 0.0047
25 current_kernel_time 0.3906
1 get_jiffies_64 0.0208
3912 __do_softirq 30.5625
7 tasklet_action 0.0625
23 __mod_timer 0.0553
1 del_timer 0.0057
198 run_timer_softirq 0.4267
1 sys_getpid 0.0625
1 sys_getppid 0.0312
1 sys_getgid 0.0625
1 sys_getegid 0.0625
2 free_uid 0.0125
3 flush_signal_handlers 0.0375
20 get_signal_to_deliver 0.0223
30 sigprocmask 0.1562
17 sys_rt_sigprocmask 0.0425
14 do_sigaction 0.0273
7 sys_rt_sigaction 0.0208
129 groups_search 1.1518
69 in_group_p 0.5391
4 sys_newuname 0.0227
1 getrusage 0.0015
1 sys_getrusage 0.0156
1 __queue_work 0.0069
6 alloc_pidmap 0.0117
2 rcu_do_batch 0.0208
1 rcu_start_batch 0.0156
5 rcu_check_quiescent_state 0.0347
7 rcu_process_callbacks 0.0273
1 kthread_should_stop 0.0312
2 acct_process 0.0143
6 remove_from_page_cache 0.0750
1 filemap_fdatawrite 0.0312
13 add_to_page_cache 0.0580
2 add_to_page_cache_lru 0.0250
22 page_waitqueue 0.4583
1 wait_on_page_bit 0.0052
76 unlock_page 0.7917
7 end_page_writeback 0.0625
874 find_get_page 9.1042
7 find_lock_page 0.0312
2 find_or_create_page 0.0104
2 find_get_pages 0.0179
108 find_get_pages_tag 0.7500
85 do_generic_mapping_read 0.0871
47 file_read_actor 0.1836
70 __generic_file_aio_read 0.1287
30 generic_file_read 0.1705
162 filemap_nopage 0.1841
21 generic_file_mmap 0.3281
13 read_cache_page 0.0232
1 remove_suid 0.0078
10 generic_write_checks 0.0149
28 mempool_alloc 0.0761
1 mempool_alloc_slab 0.0312
93 bad_range 0.8304
74 prep_new_page 0.7708
465 free_hot_cold_page 1.8164
4 free_hot_page 0.2500
1657 buffered_rmqueue 3.5711
356 __alloc_pages 0.4363
1 __free_pages 0.0125
2 free_pages 0.0417
73 nr_free_pages 0.9125
1 get_zone_counts 0.0078
2 balance_dirty_pages_ratelimited 0.0125
2 wb_kupdate 0.0069
3 do_writepages 0.0375
53 __set_page_dirty_nobuffers 0.2760
1 test_clear_page_dirty 0.0057
27 clear_page_dirty_for_io 0.4219
38 test_clear_page_writeback 0.2159
29 test_set_page_writeback 0.1295
2 mapping_tagged 0.0179
77 file_ra_state_init 1.6042
90 do_page_cache_readahead 0.2250
84 page_cache_readahead 0.1694
2 cache_grow 0.0032
161 kmem_cache_alloc 1.4375
20 __kmalloc 0.1250
95 kmem_cache_free 1.1875
18 kfree 0.1607
10 reap_timer_fnc 0.0189
4 activate_page 0.0192
241 mark_page_accessed 5.0208
2 lru_cache_add 0.0208
128 lru_cache_add_active 1.3333
19 lru_add_drain 0.1979
356 __page_cache_release 1.8542
76 release_pages 0.1827
3 __pagevec_lru_add 0.0117
205 __pagevec_lru_add_active 0.7537
1 pagevec_lookup_tag 0.0125
1 truncate_inode_pages 0.0014
5 shrink_list 0.0039
1 blk_queue_bounce 0.0089
88 clear_page_tables 0.4583
265 pte_alloc_map 1.3802
221 copy_page_range 0.2558
667 zap_pte_range 1.7370
13 zap_pmd_range 0.1161
15 unmap_page_range 0.1339
36 unmap_vmas 0.0662
64 do_wp_page 0.0800
692 do_anonymous_page 1.4417
684 do_no_page 0.8906
663 handle_mm_fault 1.4799
54 remove_shared_vm_struct 0.3750
12 sys_brk 0.0417
109 find_vma_prepare 0.9732
14 __vma_link_rb 0.2188
23 __vma_link 0.1437
16 vma_link 0.1000
4 __insert_vm_struct 0.0278
8 can_vma_merge_before 0.1000
46 can_vma_merge_after 0.5750
119 vma_merge 0.1730
311 do_mmap_pgoff 0.1735
66 get_unmapped_area 0.2062
548 find_vma 5.7083
36 find_vma_prev 0.3750
1 expand_stack 0.0052
22 free_pgtables 0.1375
10 unmap_vma 0.0781
3 unmap_vma_list 0.0625
22 unmap_region 0.0982
20 detach_vmas_to_be_unmapped 0.1786
16 split_vma 0.0357
23 do_munmap 0.0575
16 sys_munmap 0.1250
20 do_brk 0.0368
23 exit_mmap 0.0575
473 page_add_rmap 2.6875
304 page_remove_rmap 1.0000
295 __pte_chain_free 2.6339
109 pte_chain_alloc 0.5677
72 free_page_and_swap_cache 0.6429
10 can_share_swap_page 0.0893
4 si_swapinfo 0.0357
3 sys_access 0.0089
34 filp_open 0.3036
51 dentry_open 0.0966
59 get_unused_fd 0.1418
20 fd_install 0.3125
29 sys_open 0.2014
32 filp_close 0.2222
41 sys_close 0.2562
5 default_llseek 0.0208
2 sys_llseek 0.0078
52 vfs_read 0.1625
9 vfs_write 0.0281
14 sys_read 0.1250
4 sys_write 0.0357
46 get_empty_filp 0.1797
22 fput 0.6875
67 __fput 0.2204
23 fget 0.3594
42 fget_light 0.3281
19 file_move 0.1979
26 file_kill 0.4062
57 __constant_c_and_count_memset 0.3958
5 bh_waitq_head 0.1562
47 wake_up_buffer 0.9792
19 unlock_buffer 0.2375
3 __wait_on_buffer 0.0125
3 __set_page_buffers 0.0469
159 __find_get_block_slow 0.4141
4 inode_has_buffers 0.1250
41 __set_page_dirty_buffers 0.1424
2 invalidate_inode_buffers 0.0179
2 create_buffers 0.0114
1 __getblk_slow 0.0035
43 __brelse 0.6719
76 bh_lru_install 0.3393
473 __find_get_block 1.8477
30 __getblk 0.2679
29 __bread 0.3625
3 create_empty_buffers 0.0187
14 __block_write_full_page 0.0139
3 __block_prepare_write 0.0027
2 block_prepare_write 0.0250
2 block_write_full_page 0.0078
5 submit_bh 0.0104
1 check_ttfb_buffer 0.0104
1 drop_buffers 0.0045
1 try_to_free_buffers 0.0048
2 alloc_buffer_head 0.0208
3 init_buffer_head 0.0625
19 bio_alloc 0.0457
11 bio_clone 0.0688
2 sync_supers 0.0083
23 nr_blockdev_pages 0.2396
2 chrdev_open 0.0038
1 cdev_get 0.0052
77 generic_fillattr 0.4813
46 vfs_getattr 0.2396
31 vfs_fstat 0.3875
43 cp_new_stat64 0.1344
1 sys_stat64 0.0156
20 sys_fstat64 0.3125
2 count 0.0312
90 copy_strings 0.1480
2 copy_strings_kernel 0.0250
1 put_dirty_page 0.0030
9 setup_arg_pages 0.0176
9 open_exec 0.0375
2 kernel_read 0.0208
3 exec_mmap 0.0110
15 flush_old_exec 0.0066
2 prepare_binprm 0.0096
7 compute_creds 0.0243
9 search_binary_handler 0.0128
4 do_execve 0.0063
1 set_binfmt 0.0063
5 pipe_wait 0.0260
15 pipe_readv 0.0195
1 pipe_read 0.0156
9 pipe_writev 0.0097
3 pipe_write 0.0469
2 pipe_release 0.0089
1 pipe_write_fasync 0.0069
1 pipe_write_release 0.0156
1 get_pipe_inode 0.0052
53 getname 0.2548
30 vfs_permission 0.1042
28 permission 0.2188
1 get_write_access 0.0125
2 deny_write_access 0.0250
1 path_release 0.0156
1 cached_lookup 0.0069
5 real_lookup 0.0184
25 follow_mount 0.1736
22 do_lookup 0.1250
453 link_path_walk 0.1827
84 path_lookup 0.2625
2 __lookup_hash 0.0089
1 lookup_hash 0.0208
5 __user_walk 0.0521
1 unlock_rename 0.0125
4 vfs_create 0.0147
128 may_open 0.2963
33 open_namei 0.0290
1 vfs_mkdir 0.0039
1 vfs_unlink 0.0023
1 sys_unlink 0.0030
1 vfs_rename_other 0.0031
1 sys_rename 0.0018
25 page_getlink 0.1302
23 page_follow_link 0.0464
1 set_close_on_exec 0.0156
2 expand_files 0.0179
2 locate_fd 0.0069
1 sys_dup2 0.0033
2 generic_file_fcntl 0.0046
1 fasync_helper 0.0042
3 sys_ioctl 0.0042
3 filldir64 0.0094
1 max_select_fd 0.0045
2 do_select 0.0028
39 locks_remove_posix 0.1434
37 locks_remove_flock 0.1927
6 steal_locks 0.0288
1 d_callback 0.0156
1 d_free 0.0156
67 dput 0.1074
8 d_alloc 0.0156
3 d_instantiate 0.0234
644 __d_lookup 1.9167
6 d_rehash 0.0536
9 alloc_inode 0.0216
1 inode_init_once 0.0039
4 clear_inode 0.0227
1 prune_icache 0.0018
5 new_inode 0.0312
3 get_new_inode_fast 0.0110
1 iget_locked 0.0052
6 __insert_inode_hash 0.0625
4 generic_delete_inode 0.0132
8 iput 0.0625
33 inode_times_differ 0.4125
69 update_atime 0.3080
6 inode_update_time 0.0268
1 i_waitq_head 0.0312
2 wake_up_inode 0.0417
2 is_bad_inode 0.0250
35 dnotify_flush 0.1823
44 dnotify_parent 0.2292
5 lookup_mnt 0.0391
3 copy_namespace 0.0039
53 __mark_inode_dirty 0.1840
10 __sync_single_inode 0.0216
1 __writeback_single_inode 0.0052
12 sync_sb_inodes 0.0179
1 writeback_acquire 0.0312
4 writeback_in_progress 0.2500
3 writeback_release 0.0652
22 do_mpage_readpage 0.0188
1 mpage_readpages 0.0024
41 mpage_writepages 0.0483
4 exit_aio 0.0278
4 eventpoll_init_file 0.1250
5 set_brk 0.0521
24 create_elf_tables 0.0259
9 elf_map 0.0402
12 load_elf_interp 0.0192
35 load_elf_binary 0.0104
2 de_put 0.0089
1 proc_delete_inode 0.0069
3 proc_get_inode 0.0094
3 proc_pid_unhash 0.0234
1 proc_file_read 0.0015
20 proc_lookup 0.0694
41 get_vmalloc_info 0.2330
2 meminfo_read_proc 0.0040
3 write_profile 0.0469
44 scan_bitmap_block 0.0377
9 scan_bitmap 0.0165
2 _reiserfs_free_block 0.0060
2 reiserfs_free_block 0.0312
1 reiserfs_discard_all_prealloc 0.0156
2 determine_prealloc_size 0.0139
15 reiserfs_allocate_blocknrs 0.0076
1 reiserfs_claim_blocks_to_be_allocated 0.0208
1 reiserfs_release_claimed_blocks 0.0208
3 reiserfs_can_fit_pages 0.0312
3 balance_leaf_when_delete 0.0027
21 balance_leaf 0.0017
3 free_thrown 0.0268
1 reiserfs_invalidate_buffer 0.0208
4 do_balance 0.0147
4 bin_search_in_dir_item 0.0227
9 search_by_entry_key 0.0181
5 get_third_component 0.0521
3 linear_search_in_dir_item 0.0042
4 reiserfs_find_entry 0.0114
1 reiserfs_lookup 0.0026
10 reiserfs_add_entry 0.0082
2 new_inode_init 0.0179
4 reiserfs_create 0.0089
4 reiserfs_unlink 0.0050
1 reiserfs_rename 0.0004
1 reiserfs_delete_inode 0.0037
33 _make_cpu_key 0.1587
88 make_cpu_key 0.7857
1 file_capable 0.0156
1 reiserfs_get_block 0.0002
72 inode2sd 0.3750
4 inode2sd_v1 0.0278
28 update_stat_data 0.1029
59 reiserfs_update_sd 0.1272
14 reiserfs_new_inode 0.0097
1 grab_tail_page 0.0025
10 reiserfs_truncate_file 0.0179
73 reiserfs_write_full_page 0.0830
4 reiserfs_writepage 0.0625
10 i_attrs_to_sd_attrs 0.0893
1 invalidatepage_can_drop 0.0069
3 reiserfs_invalidatepage 0.0134
3 make_le_item_head 0.0136
50 reiserfs_file_release 0.0434
29 reiserfs_allocate_blocks_for_region 0.0055
4 reiserfs_copy_from_user_to_file_region 0.0167
7 reiserfs_commit_page 0.0273
9 reiserfs_submit_file_region_for_write 0.0117
5 reiserfs_check_for_tail_and_convert 0.0089
49 reiserfs_prepare_file_region_for_write 0.0199
30 reiserfs_file_write 0.0151
1 reiserfs_readdir 0.0007
15 create_virtual_node 0.0117
4 check_left 0.0125
1 check_right 0.0031
15 get_num_ver 0.0174
5 set_parameters 0.0347
1 are_leaves_removable 0.0027
4 get_rfree 0.0357
1 is_left_neighbor_in_cache 0.0063
3 get_parents 0.0072
18 ip_check_balance 0.0062
1 dc_check_balance_internal 0.0007
5 dc_check_balance_leaf 0.0092
2 dc_check_balance 0.0417
4 check_balance 0.0227
3 get_direct_parent 0.0110
7 get_neighbors 0.0199
1 get_virtual_node_size 0.0125
2 get_mem_for_virtual_node 0.0083
6 wait_tb_buffers_until_unlocked 0.0074
18 fix_nodes 0.0184
6 unfix_nodes 0.0170
1 is_reiserfs_jr 0.0125
3 add_save_link 0.0055
1 remove_save_link 0.0045
1 reiserfs_alloc_inode 0.0208
62 reiserfs_dirty_inode 0.3229
1 reiserfs_get_unused_objectid 0.0035
1 leaf_copy_boundary_item 0.0005
3 leaf_copy_items_entirely 0.0039
1 leaf_copy_items 0.0025
4 leaf_define_dest_src_infos 0.0093
1 leaf_shift_left 0.0052
2 leaf_delete_items 0.0045
22 leaf_insert_into_buf 0.0259
9 leaf_paste_in_buffer 0.0097
3 leaf_cut_entries 0.0072
12 leaf_cut_from_buffer 0.0097
7 leaf_delete_items_entirely 0.0122
13 leaf_paste_entries 0.0173
7 internal_insert_childs 0.0112
1 internal_delete_pointers_items 0.0021
1 internal_insert_key 0.0030
1 balance_internal_when_delete 0.0018
2 balance_internal 0.0008
29 decrement_counters_in_path 0.3625
1 pathrelse_and_restore 0.0125
21 pathrelse 0.3281
274 is_leaf 0.5905
29 is_internal 0.1812
167 is_tree_node 1.4911
716 search_by_key 0.1857
14 search_for_position_by_key 0.0143
1 comp_items 0.0104
5 prepare_for_delete_or_cut 0.0026
2 calc_deleted_bytes_number 0.0042
9 init_tb_struct 0.0938
1 padd_item 0.0312
2 maybe_indirect_to_direct 0.0030
6 reiserfs_cut_from_item 0.0048
8 reiserfs_do_truncate 0.0060
2 reiserfs_paste_into_item 0.0066
1 reiserfs_insert_item 0.0031
3 B_IS_IN_TREE 0.0938
10 copy_item_head 0.2083
3 decrement_bcount 0.0469
3 r5_hash 0.0375
3 indirect2direct 0.0038
22 init_journal_hash 0.6875
5 get_cnode 0.0312
2 free_cnode 0.0139
1 reiserfs_check_lock_depth 0.0625
89 reiserfs_in_journal 0.1794
2 submit_ordered_buffer 0.0312
1 write_ordered_chunk 0.0125
1 reiserfs_free_jh 0.0089
5 reiserfs_add_ordered_list 0.0260
16 write_ordered_buffers 0.0263
47 reiserfs_async_progress_wait 0.3264
11 flush_commit_list 0.0107
2 find_newer_jl_for_cn 0.0417
2 flush_journal_list 0.0013
7 dirty_one_transaction 0.0547
33 remove_journal_hash 0.1719
1 alloc_journal_list 0.0069
20 reiserfs_wait_on_write_block 0.1389
15 wake_queued_writers 0.2344
106 do_journal_begin_r 0.1656
36 journal_begin 0.1731
59 journal_mark_dirty 0.0899
40 journal_end 0.2083
1 remove_from_transaction 0.0028
30 can_dirty 0.1705
65 check_journal_end 0.1016
1 journal_mark_freed 0.0020
8 reiserfs_restore_prepared_buffer 0.0417
40 reiserfs_prepare_for_journal 0.3125
133 do_journal_end 0.0452
1 sd_bytes_number 0.0625
1 sd_is_left_mergeable 0.0625
1 sd_create_vi 0.0625
2 sd_part_size 0.0625
2 direct_is_left_mergeable 0.0139
1 direct_create_vi 0.0625
3 direct_part_size 0.1875
1 indirect_bytes_number 0.0312
3 indirect_part_size 0.1875
6 direntry_is_left_mergeable 0.3750
8 direntry_create_vi 0.0200
1 direntry_check_left 0.0069
1 direntry_part_size 0.0156
3 copy_semundo 0.0144
1 exit_sem 0.0030
1 capable 0.0104
4 dummy_capable 0.0833
110 dummy_vm_enough_memory 0.6250
1 dummy_bprm_alloc_security 0.0625
1 dummy_bprm_set_security 0.0625
1 dummy_bprm_secureexec 0.0156
5 dummy_inode_alloc_security 0.3125
2 dummy_inode_unlink 0.1250
6 dummy_inode_follow_link 0.3750
20 dummy_inode_permission 1.2500
1 dummy_inode_getattr 0.0625
6 dummy_file_permission 0.3750
18 dummy_file_alloc_security 1.1250
3 dummy_file_free_security 0.1875
2 dummy_file_ioctl 0.1250
32 dummy_file_mmap 2.0000
4 dummy_task_wait 0.2500
1 dummy_d_instantiate 0.0625
2 kobject_get 0.0250
2 kobject_put 0.0625
2 radix_tree_preload 0.0125
13 __rb_rotate_left 0.2031
10 __rb_rotate_right 0.1562
58 rb_insert_color 0.2417
6 __rb_erase_color 0.0139
29 rb_erase 0.1133
3 skip_atoi 0.0469
21 number 0.0285
17 vsnprintf 0.0144
2 vsprintf 0.0417
2 sprintf 0.0417
76 atomic_dec_and_lock 0.9500
1 __delay 0.0312
4 __get_user_4 0.1739
3 bad_get_user 0.3333
38 memcpy 0.3958
355 _mmx_memcpy 0.9647
8365 fast_clear_page 87.1354
827 fast_copy_page 3.2305
83 mmx_clear_page 2.5938
1 mmx_copy_page 0.0208
77 direct_strncpy_from_user 0.6875
55 direct_clear_user 0.5729
149 direct_strnlen_user 1.5521
2 __copy_user_intel 0.0114
2408 __copy_to_user_ll 21.5000
247 __copy_from_user_ll 1.5437
1 write_null 0.0625
3 init_dev 0.0019
4 release_dev 0.0026
3 tty_open 0.0035
1 tty_fasync 0.0035
2 tty_ioctl 0.0015
2 vt_ioctl 0.0002
1 con_open 0.0057
1 con_close 0.0063
21 blk_rq_map_sg 0.0656
4 generic_unplug_device 0.0357
6 get_request 0.0089
73 __make_request 0.0507
12 generic_make_request 0.0242
3 submit_bio 0.0117
1 put_io_context 0.0104
1 get_io_context 0.0078
1 blk_backing_dev_unplug 0.0208
3 as_work_handler 0.0268
3 as_set_request 0.0208
1 mii_link_ok 0.0125
181 ide_end_request 0.5387
4 start_request 0.0068
60 ide_do_request 0.0682
28 ide_intr 0.0700
92 ide_inb 5.7500
162 ide_outb 10.1250
9 ide_outl 0.5625
1 SELECT_DRIVE 0.0125
4 ide_wait_stat 0.0132
23 ide_execute_command 0.1198
5 ide_dma_intr 0.0260
5 ide_build_sglist 0.0284
11 ide_build_dmatable 0.0275
1 ide_start_dma 0.0057
4 __ide_dma_write 0.0167
1 __ide_dma_end 0.0063
2 __ide_do_rw_disk 0.0011
2 ide_do_rw_disk 0.0208
19 i8042_interrupt 0.0540
2 i8042_timer_func 0.0417
3 sock_poll 0.0469
1 fn_hash_lookup 0.0037
8 ret_from_intr 0.2963
261 system_call 5.9318
2 syscall_call 0.1818
15 syscall_exit 1.3636
33 error_code 0.5893
174 device_not_available 4.1429
90826 total 0.0533


Regards,
Andreas Hartmann

2004-04-02 10:25:14

by Andrew Morton

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Andreas Hartmann <[email protected]> wrote:
>
> Now, I tested 2.6.5-rc3-mm4. Same procedure.
> The good news first:
> 2.6.5-rc3-mm4 is nearly as fast as 2.4.25 - it is about 2% slower than
> 2.4.25 (with preemption turned on).
>
> Now the bad news:
> The system-processor-time is unchanged abnormal high: it is 34% (!) higher
> than in 2.4.25 (and about 1% more than in 2.4.6).
>
>
> Btw: Did the other profile outputs help to find the problem?
>
> These are the profile-values for an example run (make of kernel 2.6.5rc2)
> with 2.6.5rc3mm4:

Spending a lot of time on do_softirq() while compiling stuff is peculiar.

What device drivers are running at the time? disk/network/usb/etc?

2004-04-02 20:55:25

by Andreas Hartmann

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Andrew Morton wrote:
> Andreas Hartmann <[email protected]> wrote:
>>
>> Now, I tested 2.6.5-rc3-mm4. Same procedure.
>> The good news first:
>> 2.6.5-rc3-mm4 is nearly as fast as 2.4.25 - it is about 2% slower than
>> 2.4.25 (with preemption turned on).
>>
>> Now the bad news:
>> The system-processor-time is unchanged abnormal high: it is 34% (!) higher
>> than in 2.4.25 (and about 1% more than in 2.4.6).
>>
>>
>> Btw: Did the other profile outputs help to find the problem?
>>
>> These are the profile-values for an example run (make of kernel 2.6.5rc2)
>> with 2.6.5rc3mm4:
>
> Spending a lot of time on do_softirq() while compiling stuff is peculiar.
>
> What device drivers are running at the time? disk/network/usb/etc?

Module Size Used by Not tainted
eepro100 19828 1 (autoclean)
mii 2480 0 (autoclean) [eepro100]
sis900 13036 1 (autoclean)
crc32 2880 0 (autoclean) [sis900]
usb-storage 26416 0 (unused)
scsi_mod 87488 0 [usb-storage]
uhci 25436 0 (unused)
usbcore 62316 0 [usb-storage uhci]
lvm-mod 44416 12 (autoclean)
unix 15308 13 (autoclean)

These are all modules (drivers), which are running - in both cases (2.4.25
and 2.6.x).


Regards,
Andreas Hartmann

2004-04-02 21:11:01

by Andrew Morton

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Andreas Hartmann <[email protected]> wrote:
>
> > What device drivers are running at the time? disk/network/usb/etc?
>
> Module Size Used by Not tainted
> eepro100 19828 1 (autoclean)
> mii 2480 0 (autoclean) [eepro100]
> sis900 13036 1 (autoclean)
> crc32 2880 0 (autoclean) [sis900]
> usb-storage 26416 0 (unused)
> scsi_mod 87488 0 [usb-storage]
> uhci 25436 0 (unused)
> usbcore 62316 0 [usb-storage uhci]
> lvm-mod 44416 12 (autoclean)
> unix 15308 13 (autoclean)

No. I mean which drivers were actually doing significant amounts of work
during the test?

(you appear to not have any disks)

2004-04-03 00:23:44

by Andreas Hartmann

[permalink] [raw]
Subject: Re: Very poor performance with 2.6.4

Andrew Morton wrote:
> Andreas Hartmann <[email protected]> wrote:
>>
>> > What device drivers are running at the time? disk/network/usb/etc?
[..]
> No. I mean which drivers were actually doing significant amounts of work
> during the test?
>
> (you appear to not have any disks)

Surely do I have disks - I forgot them :-). I've got two IDE-HD's,
/dev/hda and /dev/hdb. /dev/hdb is switched off during boot with hdparm.
On /dev/hda, the whole work is done.
There is a cdrom and a cd-writer on /dev/hdd and /dev/hdc. They have been
not used during the tests.

I think it is best, if I post the whole boot-entries from messages:


Apr 2 08:14:56 athlon kernel: PI: PCI Interrupt Routing Table
[\_SB_.PCI0._PRT]
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [LNKA] (IRQs 1 3 4
5 6 7 10 *11 12 14 15)
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [LNKB] (IRQs 1 3 4
5 6 7 *10 11 12 14 15)
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [LNKC] (IRQs 1 3 4
*5 6 7 10 11 12 14 15)
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [LNKD] (IRQs 1 3 4
5 6 7 10 *11 12 14 15)
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [ALKA] (IRQs 20)
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [ALKB] (IRQs 21)
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [ALKC] (IRQs 22)
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [ALKD] (IRQs 23)
Apr 2 08:14:56 athlon kernel: IOAPIC[0]: Set PCI routing entry (2-16 ->
0xa9 -> IRQ 16 Mode:1 Active:1)
Apr 2 08:14:56 athlon kernel: 00:00:08[A] -> 2-16 -> IRQ 16
Apr 2 08:14:56 athlon kernel: IOAPIC[0]: Set PCI routing entry (2-17 ->
0xb1 -> IRQ 17 Mode:1 Active:1)
Apr 2 08:14:56 athlon kernel: 00:00:08[B] -> 2-17 -> IRQ 17
Apr 2 08:14:56 athlon kernel: IOAPIC[0]: Set PCI routing entry (2-18 ->
0xb9 -> IRQ 18 Mode:1 Active:1)
Apr 2 08:14:56 athlon kernel: 00:00:08[C] -> 2-18 -> IRQ 18
Apr 2 08:14:56 athlon kernel: IOAPIC[0]: Set PCI routing entry (2-19 ->
0xc1 -> IRQ 19 Mode:1 Active:1)
Apr 2 08:14:56 athlon kernel: 00:00:08[D] -> 2-19 -> IRQ 19
Apr 2 08:14:56 athlon kernel: _CRS returns NULL! Using IRQ 21 fordevice
(PCI Interrupt Link [ALKB]).
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [ALKB] enabled at
IRQ 21
Apr 2 08:14:56 athlon kernel: IOAPIC[0]: Set PCI routing entry (2-21 ->
0xc9 -> IRQ 21 Mode:1 Active:1)
Apr 2 08:14:56 athlon kernel: 00:00:10[A] -> 2-21 -> IRQ 21
Apr 2 08:14:56 athlon kernel: _CRS returns NULL! Using IRQ 20 fordevice
(PCI Interrupt Link [ALKA]).
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [ALKA] enabled at
IRQ 20
Apr 2 08:14:56 athlon kernel: IOAPIC[0]: Set PCI routing entry (2-20 ->
0xd1 -> IRQ 20 Mode:1 Active:1)
Apr 2 08:14:56 athlon kernel: 00:00:11[A] -> 2-20 -> IRQ 20
Apr 2 08:14:56 athlon kernel: _CRS returns NULL! Using IRQ 22 fordevice
(PCI Interrupt Link [ALKC]).
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [ALKC] enabled at
IRQ 22
Apr 2 08:14:56 athlon kernel: IOAPIC[0]: Set PCI routing entry (2-22 ->
0xd9 -> IRQ 22 Mode:1 Active:1)
Apr 2 08:14:56 athlon kernel: 00:00:11[C] -> 2-22 -> IRQ 22
Apr 2 08:14:56 athlon kernel: _CRS returns NULL! Using IRQ 23 fordevice
(PCI Interrupt Link [ALKD]).
Apr 2 08:14:56 athlon kernel: ACPI: PCI Interrupt Link [ALKD] enabled at
IRQ 23
Apr 2 08:14:56 athlon kernel: IOAPIC[0]: Set PCI routing entry (2-23 ->
0xe1 -> IRQ 23 Mode:1 Active:1)
Apr 2 08:14:56 athlon kernel: 00:00:11[D] -> 2-23 -> IRQ 23
Apr 2 08:14:56 athlon kernel: number of MP IRQ sources: 15.
Apr 2 08:14:56 athlon kernel: number of IO-APIC #2 registers: 24.
Apr 2 08:14:56 athlon kernel: testing the IO APIC.......................
Apr 2 08:14:56 athlon kernel: IO APIC #2......
Apr 2 08:14:56 athlon kernel: .... register #00: 02000000
Apr 2 08:14:56 athlon kernel: ....... : physical APIC id: 02
Apr 2 08:14:56 athlon kernel: ....... : Delivery Type: 0
Apr 2 08:14:56 athlon kernel: ....... : LTS : 0
Apr 2 08:14:56 athlon kernel: .... register #01: 00178003
Apr 2 08:14:56 athlon kernel: ....... : max redirection entries: 0017
Apr 2 08:14:56 athlon kernel: ....... : PRQ implemented: 1
Apr 2 08:14:56 athlon kernel: ....... : IO APIC version: 0003
Apr 2 08:14:56 athlon kernel: .... IRQ redirection table:
Apr 2 08:14:56 athlon kernel: NR Log Phy Mask Trig IRR Pol Stat Dest
Deli Vect:
Apr 2 08:14:56 athlon kernel: 00 000 00 1 0 0 0 0 0 0 00
Apr 2 08:14:56 athlon kernel: 01 001 01 0 0 0 0 0 1 1 39
Apr 2 08:14:56 athlon kernel: 02 001 01 0 0 0 0 0 1 1 31
Apr 2 08:14:56 athlon kernel: 03 001 01 0 0 0 0 0 1 1 41
Apr 2 08:14:56 athlon kernel: 04 001 01 0 0 0 0 0 1 1 49
Apr 2 08:14:56 athlon kernel: 05 001 01 0 0 0 0 0 1 1 51
Apr 2 08:14:56 athlon kernel: 06 001 01 0 0 0 0 0 1 1 59
Apr 2 08:14:56 athlon kernel: 07 001 01 0 0 0 0 0 1 1 61
Apr 2 08:14:56 athlon kernel: 08 001 01 0 0 0 0 0 1 1 69
Apr 2 08:14:56 athlon kernel: 09 001 01 0 1 0 1 0 1 1 71
Apr 2 08:14:56 athlon kernel: 0a 001 01 0 0 0 0 0 1 1 79
Apr 2 08:14:56 athlon kernel: 0b 001 01 0 0 0 0 0 1 1 81
Apr 2 08:14:56 athlon kernel: 0c 001 01 0 0 0 0 0 1 1 89
Apr 2 08:14:56 athlon kernel: 0d 001 01 0 0 0 0 0 1 1 91
Apr 2 08:14:56 athlon kernel: 0e 001 01 0 0 0 0 0 1 1 99
Apr 2 08:14:56 athlon kernel: 0f 001 01 0 0 0 0 0 1 1 A1
Apr 2 08:14:56 athlon kernel: 10 001 01 1 1 0 1 0 1 1 A9
Apr 2 08:14:56 athlon kernel: 11 001 01 1 1 0 1 0 1 1 B1
Apr 2 08:14:56 athlon kernel: 12 001 01 1 1 0 1 0 1 1 B9
Apr 2 08:14:56 athlon kernel: 13 001 01 1 1 0 1 0 1 1 C1
Apr 2 08:14:56 athlon kernel: 14 001 01 1 1 0 1 0 1 1 D1
Apr 2 08:14:56 athlon kernel: 15 001 01 1 1 0 1 0 1 1 C9
Apr 2 08:14:56 athlon kernel: 16 001 01 1 1 0 1 0 1 1 D9
Apr 2 08:14:56 athlon kernel: 17 001 01 1 1 0 1 0 1 1 E1
Apr 2 08:14:56 athlon kernel: IRQ to pin mappings:
Apr 2 08:14:56 athlon kernel: IRQ0 -> 0:2
Apr 2 08:14:56 athlon kernel: IRQ1 -> 0:1
Apr 2 08:14:56 athlon kernel: IRQ3 -> 0:3
Apr 2 08:14:56 athlon kernel: IRQ4 -> 0:4
Apr 2 08:14:56 athlon kernel: IRQ5 -> 0:5
Apr 2 08:14:56 athlon kernel: IRQ6 -> 0:6
Apr 2 08:14:56 athlon kernel: IRQ7 -> 0:7
Apr 2 08:14:56 athlon kernel: IRQ8 -> 0:8
Apr 2 08:14:56 athlon kernel: IRQ9 -> 0:9
Apr 2 08:14:56 athlon kernel: IRQ10 -> 0:10
Apr 2 08:14:56 athlon kernel: IRQ11 -> 0:11
Apr 2 08:14:56 athlon kernel: IRQ12 -> 0:12
Apr 2 08:14:56 athlon kernel: IRQ13 -> 0:13
Apr 2 08:14:56 athlon kernel: IRQ14 -> 0:14
Apr 2 08:14:56 athlon kernel: IRQ15 -> 0:15
Apr 2 08:14:56 athlon kernel: IRQ16 -> 0:16
Apr 2 08:14:56 athlon kernel: IRQ17 -> 0:17
Apr 2 08:14:56 athlon kernel: IRQ18 -> 0:18
Apr 2 08:14:56 athlon kernel: IRQ19 -> 0:19
Apr 2 08:14:56 athlon kernel: IRQ20 -> 0:20
Apr 2 08:14:56 athlon kernel: IRQ21 -> 0:21
Apr 2 08:14:56 athlon kernel: IRQ22 -> 0:22
Apr 2 08:14:56 athlon kernel: IRQ23 -> 0:23
Apr 2 08:14:56 athlon kernel: .................................... done.
Apr 2 08:14:56 athlon kernel: PCI: Using ACPI for IRQ routing
Apr 2 08:14:56 athlon kernel: PCI: if you experience problems, try using
option 'pci=noacpi' or even 'acpi=off'
Apr 2 08:14:56 athlon kernel: Initializing Cryptographic API
Apr 2 08:14:56 athlon kernel: PCI: Via IRQ fixup for 0000:00:10.0, from
11 to 5
Apr 2 08:14:56 athlon kernel: PCI: Via IRQ fixup for 0000:00:10.1, from
10 to 5
Apr 2 08:14:56 athlon kernel: Uniform Multi-Platform E-IDE driver
Revision: 7.00alpha2
Apr 2 08:14:56 athlon kernel: ide: Assuming 33MHz system bus speed for
PIO modes; override with idebus=xx
Apr 2 08:14:56 athlon kernel: VP_IDE: IDE controller at PCI slot 0000:00:11.1
Apr 2 08:14:56 athlon kernel: VP_IDE: chipset revision 6
Apr 2 08:14:56 athlon kernel: VP_IDE: not 100% native mode: will probe
irqs later
Apr 2 08:14:56 athlon kernel: VP_IDE: VIA vt8235 (rev 00) IDE UDMA133
controller on pci0000:00:11.1
Apr 2 08:14:56 athlon kernel: ide0: BM-DMA at 0xe400-0xe407, BIOS
settings: hda:DMA, hdb:DMA
Apr 2 08:14:56 athlon kernel: ide1: BM-DMA at 0xe408-0xe40f, BIOS
settings: hdc:DMA, hdd:DMA
Apr 2 08:14:56 athlon kernel: hda: WDC WD205AA, ATA DISK drive
Apr 2 08:14:56 athlon kernel: hdb: WDC WD450AA-00BAA0, ATA DISK drive
Apr 2 08:14:56 athlon kernel: Using anticipatory io scheduler
Apr 2 08:14:56 athlon kernel: ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Apr 2 08:14:56 athlon kernel: hdc: PLEXTOR CD-R PX-W1610A, ATAPI
CD/DVD-ROM drive
Apr 2 08:14:56 athlon kernel: hdd: ATAPI CDROM 48X, ATAPI CD/DVD-ROM drive
Apr 2 08:14:56 athlon kernel: ide1 at 0x170-0x177,0x376 on irq 15
Apr 2 08:14:56 athlon kernel: hda: max request size: 128KiB
Apr 2 08:14:56 athlon kernel: hda: 40079088 sectors (20520 MB) w/2048KiB
Cache, CHS=39761/16/63, UDMA(66)
Apr 2 08:14:56 athlon kernel: hda: hda1 hda2 hda3 hda4 < hda5 hda6 hda7
hda8 hda9 hda10 >
Apr 2 08:14:56 athlon kernel: hdb: max request size: 128KiB
Apr 2 08:14:56 athlon kernel: hdb: 87930864 sectors (45020 MB) w/2048KiB
Cache, CHS=65535/16/63, UDMA(66)
Apr 2 08:14:56 athlon kernel: hdb: hdb1 hdb2 < hdb5 hdb6 hdb7 hdb8 hdb9
hdb10 hdb11 hdb12 hdb13 hdb14 hdb15 >
Apr 2 08:14:56 athlon kernel: ieee1394: raw1394: /dev/raw1394 device
initialized
Apr 2 08:14:56 athlon kernel: mice: PS/2 mouse device common for all mice
Apr 2 08:14:56 athlon kernel: serio: i8042 AUX port at 0x60,0x64 irq 12
Apr 2 08:14:56 athlon kernel: input: PS/2 Logitech Mouse on isa0060/serio1
Apr 2 08:14:56 athlon kernel: serio: i8042 KBD port at 0x60,0x64 irq 1
Apr 2 08:14:56 athlon kernel: input: AT Translated Set 2 keyboard on
isa0060/serio0
Apr 2 08:14:56 athlon kernel: NET: Registered protocol family 2
Apr 2 08:14:56 athlon kernel: IP: routing cache hash table of 4096
buckets, 32Kbytes
Apr 2 08:14:56 athlon kernel: TCP: Hash tables configured (established
32768 bind 65536)
Apr 2 08:14:56 athlon kernel: ip_conntrack version 2.1 (4095 buckets,
32760 max) - 296 bytes per conntrack
Apr 2 08:14:56 athlon kernel: ip_tables: (C) 2000-2002 Netfilter core team
Apr 2 08:14:56 athlon kernel: ipt_recent v0.3.1: Stephen Frost
<[email protected]>. http://snowman.net/projects/ipt_recent/
Apr 2 08:14:56 athlon kernel: arp_tables: (C) 2002 David S. Miller
Apr 2 08:14:56 athlon kernel: ACPI: (supports S0 S1 S4 S5)
Apr 2 08:14:56 athlon kernel: found reiserfs format "3.5" with standard
journal
Apr 2 08:14:56 athlon kernel: reiserfs: using ordered data mode
Apr 2 08:14:56 athlon kernel: Reiserfs journal params: device hda1, size
8192, journal first block 18, max trans len 1024, max batch 900, max
commit age 30, max trans age 30
Apr 2 08:14:56 athlon kernel: reiserfs: checking transaction log (hda1)
for (hda1)
Apr 2 08:14:56 athlon kernel: Using tea hash to sort names
Apr 2 08:14:56 athlon kernel: VFS: Mounted root (reiserfs filesystem).
Apr 2 08:14:56 athlon kernel: Freeing unused kernel memory: 144k freed
Apr 2 08:14:56 athlon kernel: NET: Registered protocol family 1
Apr 2 08:14:56 athlon kernel: Adding 514040k swap on /dev/hda9.
Priority:-1 extents:1
Apr 2 08:14:56 athlon kernel: device-mapper: 4.1.0-ioctl (2003-12-10)
initialised: [email protected]
Apr 2 08:14:56 athlon kernel: hdc: ATAPI 40X CD-ROM CD-R/RW drive, 2048kB
Cache, DMA
Apr 2 08:14:56 athlon kernel: Uniform CD-ROM driver Revision: 3.20
Apr 2 08:14:56 athlon kernel: hdd: ATAPI CD-ROM drive, 128kB Cache, UDMA(33)
Apr 2 08:14:56 athlon kernel: found reiserfs format "3.6" with standard
journal
Apr 2 08:14:56 athlon kernel: reiserfs: using ordered data mode
Apr 2 08:14:56 athlon kernel: Reiserfs journal params: device hda8, size
8192, journal first block 18, max trans len 1024, max batch 900, max
commit age 30, max trans age 30
Apr 2 08:14:56 athlon kernel: reiserfs: checking transaction log (hda8)
for (hda8)
Apr 2 08:14:56 athlon kernel: Using r5 hash to sort names
Apr 2 08:14:56 athlon kernel: found reiserfs format "3.6" with standard
journal
Apr 2 08:14:56 athlon kernel: reiserfs: using ordered data mode
Apr 2 08:14:56 athlon kernel: Reiserfs journal params: device dm-13, size
8192, journal first block 18, max trans len 1024, max batch 900, max
commit age 30, max trans age 30
Apr 2 08:14:56 athlon kernel: reiserfs: checking transaction log (dm-13)
for (dm-13)
Apr 2 08:14:56 athlon kernel: Using r5 hash to sort names
Apr 2 08:14:56 athlon kernel: found reiserfs format "3.6" with standard
journal
Apr 2 08:14:56 athlon kernel: reiserfs: using ordered data mode
Apr 2 08:14:56 athlon kernel: Reiserfs journal params: device hda7, size
8192, journal first block 18, max trans len 1024, max batch 900, max
commit age 30, max trans age 30
Apr 2 08:14:56 athlon kernel: reiserfs: checking transaction log (hda7)
for (hda7)
Apr 2 08:14:56 athlon kernel: Using r5 hash to sort names
Apr 2 08:14:56 athlon kernel: found reiserfs format "3.6" with standard
journal
Apr 2 08:14:56 athlon kernel: reiserfs: using ordered data mode
Apr 2 08:14:56 athlon kernel: Reiserfs journal params: device dm-8, size
8192, journal first block 18, max trans len 1024, max batch 900, max
commit age 30, max trans age 30
Apr 2 08:14:56 athlon kernel: reiserfs: checking transaction log (dm-8)
for (dm-8)
Apr 2 08:14:56 athlon kernel: Using r5 hash to sort names
Apr 2 08:14:56 athlon kernel: found reiserfs format "3.6" with standard
journal
Apr 2 08:14:56 athlon kernel: reiserfs: using ordered data mode
Apr 2 08:14:56 athlon kernel: Reiserfs journal params: device dm-11, size
8192, journal first block 18, max trans len 1024, max batch 900, max
commit age 30, max trans age 30
Apr 2 08:14:56 athlon kernel: reiserfs: checking transaction log (dm-11)
for (dm-11)
Apr 2 08:14:56 athlon kernel: Using r5 hash to sort names
Apr 2 08:14:56 athlon kernel: found reiserfs format "3.6" with standard
journal
Apr 2 08:14:56 athlon kernel: reiserfs: using ordered data mode
Apr 2 08:14:56 athlon kernel: Reiserfs journal params: device dm-10, size
8192, journal first block 18, max trans len 1024, max batch 900, max
commit age 30, max trans age 30
Apr 2 08:14:56 athlon kernel: reiserfs: checking transaction log (dm-10)
for (dm-10)
Apr 2 08:14:56 athlon kernel: Using r5 hash to sort names
Apr 2 08:14:56 athlon kernel: found reiserfs format "3.6" with standard
journal
Apr 2 08:14:56 athlon kernel: reiserfs: using ordered data mode
Apr 2 08:14:56 athlon kernel: Reiserfs journal params: device dm-9, size
8192, journal first block 18, max trans len 1024, max batch 900, max
commit age 30, max trans age 30
Apr 2 08:14:56 athlon kernel: reiserfs: checking transaction log (dm-9)
for (dm-9)
Apr 2 08:14:56 athlon kernel: Using r5 hash to sort names
Apr 2 08:14:56 athlon kernel: found reiserfs format "3.6" with standard
journal
Apr 2 08:14:56 athlon kernel: reiserfs: using ordered data mode
Apr 2 08:14:56 athlon kernel: Reiserfs journal params: device hda5, size
8192, journal first block 18, max trans len 1024, max batch 900, max
commit age 30, max trans age 30
Apr 2 08:14:56 athlon kernel: reiserfs: checking transaction log (hda5)
for (hda5)
Apr 2 08:14:56 athlon kernel: Using r5 hash to sort names
Apr 2 08:14:56 athlon kernel: blk: queue dfd55c00, I/O limit 4095Mb (mask
0xffffffff)
Apr 2 08:14:56 athlon kernel: blk: queue dfd55800, I/O limit 4095Mb (mask
0xffffffff)
Apr 2 08:14:56 athlon kernel: parport0: PC-style at 0x378 (0x778), irq 7
[PCSPP(,...)]
Apr 2 08:14:56 athlon kernel: lp0: using parport0 (interrupt-driven).
Apr 2 08:14:56 athlon kernel: usbcore: registered new driver usbfs
Apr 2 08:14:56 athlon kernel: usbcore: registered new driver hub
Apr 2 08:14:56 athlon kernel: USB Universal Host Controller Interface
driver v2.2
Apr 2 08:14:56 athlon kernel: uhci_hcd 0000:00:10.0: VIA Technologies,
Inc. USB
Apr 2 08:14:56 athlon kernel: uhci_hcd 0000:00:10.0: irq 21, io base 0000d800
Apr 2 08:14:56 athlon kernel: uhci_hcd 0000:00:10.0: new USB bus
registered, assigned bus number 1
Apr 2 08:14:56 athlon kernel: hub 1-0:1.0: USB hub found
Apr 2 08:14:56 athlon kernel: hub 1-0:1.0: 2 ports detected
Apr 2 08:14:56 athlon kernel: uhci_hcd 0000:00:10.1: VIA Technologies,
Inc. USB (#2)
Apr 2 08:14:56 athlon kernel: uhci_hcd 0000:00:10.1: irq 21, io base 0000dc00
Apr 2 08:14:56 athlon kernel: uhci_hcd 0000:00:10.1: new USB bus
registered, assigned bus number 2
Apr 2 08:14:56 athlon kernel: hub 2-0:1.0: USB hub found
Apr 2 08:14:56 athlon kernel: hub 2-0:1.0: 2 ports detected
Apr 2 08:14:56 athlon kernel: uhci_hcd 0000:00:10.2: VIA Technologies,
Inc. USB (#3)
Apr 2 08:14:56 athlon kernel: uhci_hcd 0000:00:10.2: irq 21, io base 0000e000
Apr 2 08:14:56 athlon kernel: uhci_hcd 0000:00:10.2: new USB bus
registered, assigned bus number 3
Apr 2 08:14:56 athlon kernel: hub 3-0:1.0: USB hub found
Apr 2 08:14:56 athlon kernel: hub 3-0:1.0: 2 ports detected
Apr 2 08:14:56 athlon kernel: SCSI subsystem initialized
Apr 2 08:14:56 athlon kernel: Initializing USB Mass Storage driver...
Apr 2 08:14:56 athlon kernel: usbcore: registered new driver usb-storage
Apr 2 08:14:56 athlon kernel: USB Mass Storage support registered.
Apr 2 08:14:56 athlon kernel: Serial: 8250/16550 driver $Revision: 1.90 $
8 ports, IRQ sharing disabled
Apr 2 08:14:56 athlon kernel: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
Apr 2 08:14:56 athlon kernel: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
Apr 2 08:14:56 athlon kernel: sis900.c: v1.08.07 11/02/2003
Apr 2 08:14:56 athlon kernel: eth0: SiS 900 Internal MII PHY transceiver
found at address 1.
Apr 2 08:14:56 athlon kernel: eth0: Using transceiver found at address 1
as default
Apr 2 08:14:56 athlon kernel: eth0: SiS 900 PCI Fast Ethernet at 0xd000,
IRQ 17, 00:40:33:e2:43:71.
Apr 2 08:14:56 athlon kernel: eth0: Media Link Off
Apr 2 08:14:56 athlon kernel: eepro100.c:v1.09j-t 9/29/99 Donald Becker
http://www.scyld.com/network/eepro100.html
Apr 2 08:14:56 athlon kernel: eepro100.c: $Revision: 1.36 $ 2000/11/17
Modified by Andrey V. Savochkin <[email protected]> and others
Apr 2 08:14:56 athlon kernel: eth1: 0000:00:0c.0, 00:02:B3:8F:F9:11, IRQ 18.
Apr 2 08:14:56 athlon kernel: Board assembly 751767-004, Physical
connectors present: RJ45
Apr 2 08:14:56 athlon kernel: Primary interface chip i82555 PHY #1.
Apr 2 08:14:56 athlon kernel: Secondary interface chip i82555.
Apr 2 08:14:56 athlon kernel: General self-test: passed.
Apr 2 08:14:56 athlon kernel: Serial sub-system self-test: passed.
Apr 2 08:14:56 athlon kernel: Internal registers self-test: passed.
Apr 2 08:14:56 athlon kernel: ROM checksum self-test: passed (0x3258698e).


Regards,
Andreas Hartmann