Re: X much slower in 2.0.24 than in 1.2.13

Nuno Grilo (l38486@alfa.ist.utl.pt)
Sat, 2 Nov 1996 21:18:01 +0000 (WET)


On Sat, 2 Nov 1996, Linus Torvalds wrote:

>
> Ok, anybody want to profile their kernel? It's really pretty simple:
>
> - boot the kernel with the "profile=2" kernel command line (you can use
> a line like
> append = "profile=2"
> in your lilo.conf if you use LILO).
>
> - make sure you have the System.map file that corresponds to your kernel
> in your root directory (this should be done automatically for you if you
> use "make zlilo" to create the kernel)
>
> - do a "echo > /proc/profile" as root before starting x11perf to clear
> out any old profiling information
>
> - run x11perf and afterwards parse the profile information with the supplied
> program. The output is very easy to decipher..
>
> I'd be interested to hear what the results are, and the anomaly _should_
> show up pretty clearly.
>
> Linus

I had to make the following change to the program:

--- profile.c.orig Sat Nov 2 21:11:16 1996
+++ profile.c Sat Nov 2 21:11:37 1996
@@ -104,7 +104,7 @@
fscanf(kmap, "%x %*s %s\n", &next_symbol_value, next_symbol);
continue;
}
- lseek (fp , sizeof(unsigned int)+current_symbol_value-0xc0100000 , SEEK_SET);
+ lseek (fp , sizeof(unsigned int)+current_symbol_value-0x00100000 , SEEK_SET);
has_read = read (fp , buffer , sizeof(buffer) );
for ( j = 0 ; j < has_read/sizeof(unsigned int) ; j++) {
if (!strcmp(func, current_symbol))

With kernel 2.0.23 I had the following results:

1 0.10% 001104e0 do_page_fault
1 0.10% 0011a110 partial_clear
1 0.10% 0011a5c0 handle_mm_fault
1 0.10% 00124920 grow_files
1 0.10% 0012e930 file_ioctl
1 0.10% 0012eea0 free_wait
1 0.10% 0012f240 _set_fd_set
1 0.10% 001382a0 sock_release
1 0.10% 0013a440 sock_rmalloc
1 0.10% 0013db10 unix_copyrights
1 0.10% 0013dd90 unix_attach_fds
1 0.10% 00153b80 ext2_new_inode
1 0.10% 00162e60 read_core
2 0.21% 0013a170 sock_getsockopt
2 0.21% 0013a4a0 sock_rspace
2 0.21% 0013a530 sock_wfree
2 0.21% 0013b210 skb_copy_datagram_iovec
2 0.21% 0013b230 datagram_select
2 0.21% 0013ce20 unix_destroy_socket
2 0.21% 0013cf30 unix_fcntl
2 0.21% 0013dcb0 unix_detach_fds
3 0.32% 00110bb0 sys_pause
3 0.32% 00116fb0 sys_sysinfo
3 0.32% 00120380 _free_page
3 0.32% 0012f1d0 _get_fd_set
3 0.32% 0013a580 sock_alloc_send_skb
3 0.32% 0017d760 release_dev
3 0.32% 0017dc40 tty_open
4 0.43% 0010fb10 timer_interrupt
4 0.43% 00138510 sock_select
4 0.43% 0013a4f0 sock_wspace
4 0.43% 0013a770 show_net_buffers
4 0.43% 001509a0 inet_getname
5 0.53% 0011e830 kmalloc_init
5 0.53% 00120460 free_pages
5 0.53% 0013a6e0 _release_sock
6 0.64% 00122e30 sys_llseek
6 0.64% 00123100 sys_write
7 0.75% 001107f0 wake_up_process
7 0.75% 001381d0 sock_alloc
7 0.75% 0013a8f0 alloc_skb
7 0.75% 00144eb0 ip_getsockopt
7 0.75% 00180480 read_chan
7 0.75% 00180be0 write_chan
8 0.86% 00110bd0 wake_up
8 0.86% 0013a7e0 kfree_skb
8 0.86% 0013b1d0 skb_copy_datagram
9 0.97% 00123250 sock_readv_writev
9 0.97% 0012f270 sys_select
10 1.07% 001202c0 ll_rw_page
11 1.18% 0010a7b0 lcall7
11 1.18% 0013b180 skb_free_datagram
12 1.29% 00123330 do_readv_writev
13 1.40% 0011e8a0 kmalloc
14 1.51% 00138350 sock_read
15 1.61% 00120570 _get_free_pages
16 1.72% 0011e550 sys_mremap
17 1.83% 0012ed10 filldir
17 1.83% 00145280 tcp_err
18 1.94% 0010f430 get_cpuinfo
20 2.15% 00110e80 interruptible_sleep_on
20 2.15% 0012eef0 check
21 2.26% 0012edc0 sys_getdents
24 2.58% 0012ef80 do_select
26 2.80% 0013b000 skb_recv_datagram
28 3.02% 0010a500 do_signal
33 3.55% 0013ddf0 unix_sendmsg
38 4.09% 00119cc0 do_wp_page
48 5.17% 00110900 schedule
105 11.32% 0013adc0 verify_iovec
229 24.70% 0013e260 unix_recvmsg
927 100.00% 00000000 total

and with 2.0.24:

1 0.01% 001104e0 do_page_fault
1 0.01% 00123100 sys_write
1 0.01% 00130d20 create_elf_tables
1 0.01% 00138670 sock_wake_async
1 0.01% 0013a6e0 _release_sock
1 0.01% 0013d060 def_callback3
1 0.01% 00145150 tcp_find_established
1 0.01% 001455c0 tcp_select
1 0.01% 00151390 ext2_permission
1 0.01% 00163140 write_profile
2 0.03% 00125ca0 refile_buffer
2 0.03% 00138420 sock_write
2 0.03% 00150c60 inet_select
2 0.03% 00163040 read_profile
3 0.05% 00110fe0 del_timer
3 0.05% 00145520 tcp_listen_select
4 0.07% 00110cd0 wake_up_interruptible
4 0.07% 00138350 sock_read
5 0.08% 00110fa0 add_timer
5 0.08% 0013a8f0 alloc_skb
7 0.12% 00123050 sys_read
7 0.12% 00180d90 normal_select
8 0.14% 00110900 schedule
8 0.14% 0017de20 tty_select
10 0.17% 0010f6d0 do_gettimeofday
10 0.17% 0011eac0 kfree
10 0.17% 0013a7e0 kfree_skb
11 0.19% 0011e8a0 kmalloc
23 0.41% 0013dc70 unix_fd_free
54 0.96% 0013af80 memcpy_fromiovec
72 1.28% 0012f240 _set_fd_set
93 1.66% 0010fc80 old_select
98 1.75% 0013a3e0 sock_wmalloc
108 1.92% 0013e760 unix_select
111 1.98% 00138510 sock_select
119 2.12% 0012eef0 check
137 2.44% 0013e260 unix_recvmsg
142 2.53% 001235c0 sys_writev
149 2.66% 0012eea0 free_wait
151 2.69% 0012f1d0 _get_fd_set
159 2.83% 00123250 sock_readv_writev
172 3.07% 0013a580 sock_alloc_send_skb
234 4.17% 00123330 do_readv_writev
254 4.53% 00120570 _get_free_pages
277 4.94% 0010a8c0 ret_from_sys_call
286 5.10% 00120460 free_pages
301 5.37% 0013ddf0 unix_sendmsg
354 6.32% 0012f270 sys_select
357 6.37% 0010a840 system_call
423 7.55% 0013b230 datagram_select
654 11.67% 0012ef80 do_select
759 13.55% 00119f50 verify_area
5600 100.00% 00000000 total

I hope it helps