Re: [2.6.18-rc7-mm1] slow boot
From: Tilman Schmidt
Date: Thu Sep 28 2006 - 20:14:17 EST
Am 29.09.2006 01:30 schrieb Randy Dunlap:
> On Fri, 29 Sep 2006 01:20:12 +0200 Tilman Schmidt wrote:
>> Am 28.09.2006 19:12 schrieb Andi Kleen:
>>>
>>> Can you perhaps boot with profile=1 and then send readprofile output after
>>> boot?
>> I'm afraid I'll need instructions for that. I assume "profile=1"
>> is to be appended to the kernel command line; but how do I
>> retrieve that readprofile output you are asking for?
>
> Use 'readprofile'. Usage is described in
> Documentation/basic_profiling.txt in the kernel source tree.
Thanks. Result attached.
--
Tilman Schmidt E-Mail: tilman@xxxxxxx
Bonn, Germany
Diese Nachricht besteht zu 100% aus wiederverwerteten Bits.
Ungeoeffnet mindestens haltbar bis: (siehe Rueckseite)
4 calibrate_delay 0.0020
59946 default_idle 525.8421
4 cpu_idle 0.0351
9 sysenter_past_esp 0.0638
1 error_code 0.0156
3 sched_clock 0.0273
1 page_is_ram 0.0088
1 pgd_alloc 0.0500
5 do_page_fault 0.0043
1 __wake_up 0.0175
2 add_preempt_count 0.0213
24 sub_preempt_count 0.2243
11 __might_sleep 0.0738
2 requeue_task 0.0455
5 task_rq_lock 0.1667
4 try_to_wake_up 0.0153
1 wake_up_process 0.0588
1 free_task 0.0278
8 __put_task_struct 0.0428
2 do_fork 0.0054
2 acquire_console_sem 0.0156
1 release_console_sem 0.0021
28 vprintk 0.0367
2 profile_hit 0.0364
2 delayed_put_task_struct 0.0645
3 do_wait 0.0012
1 sys_gettimeofday 0.0109
1 current_fs_time 0.0106
71 tasklet_action 0.6017
2 __local_bh_disable 0.0163
6212 __do_softirq 35.7011
1 local_bh_enable_ip 0.0047
89 local_bh_enable 0.3309
2 __tasklet_schedule 0.0187
1 register_proc_table 0.0042
2 lock_timer_base 0.0392
74 run_timer_softirq 0.2202
2 __mod_timer 0.0132
2 mod_timer 0.0465
4 del_timer 0.0548
3 do_gettimeofday 0.0124
1 getnstimeofday 0.0047
10 free_uid 0.0877
1 sigprocmask 0.0047
2 run_workqueue 0.0103
1 flush_cpu_workqueue 0.0071
1 worker_thread 0.0036
1 schedule_work 0.0588
6 put_pid 0.1714
1 delayed_put_pid 0.0769
1 alloc_pid 0.0019
29 rcu_start_batch 0.6444
2 rcu_init_percpu_data 0.0238
95 __rcu_process_callbacks 0.2707
17 rcu_process_callbacks 0.4857
1 call_rcu_bh 0.0094
1 sys_clock_gettime 0.0076
1 kthread_should_stop 0.0385
2 __wake_up_bit 0.0408
1 wake_bit_function 0.0149
1 init_waitqueue_head 0.0303
2 remove_wait_queue 0.0351
2 add_wait_queue 0.0377
179 hrtimer_run_queues 0.6047
1 hrtimer_cancel 0.0417
2 sys_nanosleep 0.0235
1 down_write_trylock 0.0200
1 down_read 0.0169
1 debug_mutex_free_waiter 0.0152
1 lockdep_init_map 0.0061
8 debug_check_no_locks_freed 0.0282
23 lock_release 0.0821
996 lock_acquire 9.1376
1 drop_key_refs 0.0227
1 get_futex_key 0.0045
3 do_futex 0.0009
1 sys_futex 0.0041
12 lookup_symbol 0.2353
1 page_waitqueue 0.0222
1 find_get_page 0.0161
1 sys_fadvise64_64 0.0023
2 __free_pages_ok 0.0069
22 get_page_from_freelist 0.0263
1 __alloc_pages 0.0016
3 free_hot_cold_page 0.0098
2 wb_kupdate 0.0096
1 test_clear_page_writeback 0.0056
1 test_set_page_writeback 0.0045
1 generic_writepages 0.0015
1 force_page_cache_readahead 0.0090
1 release_pages 0.0030
1 __pagevec_lru_add 0.0053
1 lru_add_drain 0.0115
1 mark_page_accessed 0.0200
1 put_page 0.0182
1 vma_prio_tree_insert 0.0227
1 vm_normal_page 0.0115
3 unmap_vmas 0.0027
4 do_wp_page 0.0049
1 copy_page_range 0.0014
1 __handle_mm_fault 0.0006
3 find_vma 0.0353
1 __vm_enough_memory 0.0046
1 vma_adjust 0.0013
1 do_munmap 0.0023
2 do_mmap_pgoff 0.0013
1 page_remove_rmap 0.0143
4 __remove_vm_area 0.0769
4 check_irq_on 0.2000
7 kmem_flagcheck 0.1795
1 kmem_cache_name 0.1250
1 dbg_redzone1 0.0357
18 poison_obj 0.4091
401 check_poison_obj 1.1392
28 drain_array 0.1667
1 cache_flusharray 0.0044
74 kfree 0.3834
458 kmem_cache_free 2.5730
2 kmem_rcu_free 0.0500
4 drain_freelist 0.0263
53 cache_reap 0.2409
7 cache_alloc_debugcheck_after 0.0219
44 kmem_cache_alloc 0.2716
35 cache_alloc_refill 0.0233
1 __kmalloc_track_caller 0.0046
3 kmem_cache_zalloc 0.0152
15 __kmalloc 0.0685
4 sys_faccessat 0.0131
2 sys_access 0.1111
1 __dentry_open 0.0019
1 do_sys_open 0.0055
1 sys_write 0.0104
10 file_free_rcu 0.5882
2 get_max_files 0.2000
11 fget_light 0.0663
3 sync_supers 0.0152
1 sys_readlinkat 0.0068
3 generic_fillattr 0.0164
1 vfs_getattr 0.0059
1 vfs_lstat 0.0526
2 pipe_readv 0.0025
4 getname 0.0217
1 permission 0.0051
2 __follow_mount 0.0192
3 do_lookup 0.0097
6 __link_path_walk 0.0018
2 link_path_walk 0.0101
2 do_path_lookup 0.0032
5 __user_walk_fd 0.0769
4 poll_freewait 0.0444
1 __pollwait 0.0055
43 do_select 0.0341
22 core_sys_select 0.0298
10 sys_select 0.0306
11 do_sys_poll 0.0109
3 sys_poll 0.0435
7 d_callback 0.1795
1 _d_rehash 0.0156
1 __d_path 0.0029
5 __d_lookup 0.0187
1 alloc_inode 0.0024
1 file_update_time 0.0076
1 is_bad_inode 0.0455
5 free_fdtable_rcu 0.0198
1 sync_sb_inodes 0.0016
1 unlock_buffer 0.0526
2 alloc_buffer_head 0.0260
4 __find_get_block_slow 0.0145
1 ll_rw_block 0.0055
6 __find_get_block 0.0134
2 __getblk 0.0037
2 __block_write_full_page 0.0026
1 block_write_full_page 0.0048
1 bio_init 0.0094
1 init_once 0.0084
2 do_mpage_readpage 0.0013
1 inotify_d_instantiate 0.0098
1 proc_readfd 0.0019
1 sysfs_get_name 0.0149
1 sysfs_release 0.0066
2 sysfs_lookup 0.0045
1 sysfs_create_link 0.0032
1 reiserfs_discard_all_prealloc 0.0167
1 search_by_entry_key 0.0017
1 reiserfs_lookup 0.0039
2 _get_block_create_0 0.0013
1 reiserfs_read_locked_inode 0.0008
1 reiserfs_commit_page 0.0023
10 reiserfs_readdir 0.0088
2 load_bitmap_info_data 0.0145
2 comp_items 0.0317
1 decrement_counters_in_path 0.0147
25 search_by_key 0.0064
1 flush_commit_list 0.0007
4 do_journal_end 0.0014
2 do_journal_begin_r 0.0031
1 journal_begin 0.0043
1 journal_end_sync 0.0093
1 reiserfs_commit_for_inode 0.0026
1 direntry_create_vi 0.0030
2 reiserfs_permission 0.0556
1 dummy_inode_alloc_security 0.1429
1 dummy_task_free_security 0.2000
2 dummy_vm_enough_memory 0.0625
1 init_request_from_bio 0.0076
3 _atomic_dec_and_lock 0.0625
1 prio_tree_replace 0.0110
2 prio_tree_insert 0.0040
1 radix_tree_preload 0.0071
6 memcmp 0.1429
3 number 0.0059
106 delay_tsc 4.6087
15 read_current_timer 0.5357
1 __delay 0.0909
3 memcpy 0.0698
7 strncpy_from_user 0.0875
1 __copy_from_user_ll 0.0045
3 copy_from_user 0.0278
18 __copy_to_user_ll 0.0811
4 copy_to_user 0.0488
1 irqsafe2A_spin_12 0.0066
1 irqsafe2A_wlock_12 0.0066
1 irqsafe2A_rlock_12 0.0066
1 irqsafe2A_spin_21 0.0066
1 irqsafe2A_wlock_21 0.0066
1 irqsafe2A_rlock_21 0.0066
19 dotest 0.0206
1 irqsafe1_hard_spin_12 0.0067
1 irqsafe1_hard_wlock_12 0.0067
1 irqsafe1_hard_rlock_12 0.0067
1 irqsafe1_hard_wlock_21 0.0067
1 irqsafe1_hard_rlock_21 0.0067
2 irqsafe2B_hard_spin_12 0.0123
1 irqsafe2B_hard_wlock_12 0.0062
1 irqsafe2B_hard_rlock_12 0.0062
1 irqsafe2B_hard_spin_21 0.0062
2 irqsafe2B_hard_wlock_21 0.0123
2 irqsafe2B_hard_rlock_21 0.0123
1 irqsafe3_hard_spin_123 0.0053
1 irqsafe3_hard_wlock_123 0.0053
1 irqsafe3_hard_rlock_123 0.0053
2 irqsafe3_hard_spin_132 0.0105
1 irqsafe3_hard_wlock_132 0.0053
1 irqsafe3_hard_rlock_132 0.0053
1 irqsafe3_hard_wlock_213 0.0053
1 irqsafe3_hard_rlock_213 0.0053
2 irqsafe3_hard_spin_231 0.0105
1 irqsafe3_hard_wlock_231 0.0053
1 irqsafe3_hard_rlock_231 0.0053
1 irqsafe3_hard_spin_312 0.0053
1 irqsafe3_hard_wlock_312 0.0053
1 irqsafe3_hard_rlock_312 0.0053
1 irqsafe3_hard_spin_321 0.0053
1 irqsafe3_hard_wlock_321 0.0053
1 irqsafe3_hard_rlock_321 0.0053
1 irqsafe4_hard_spin_123 0.0050
2 irqsafe4_hard_wlock_123 0.0099
2 irqsafe4_hard_rlock_123 0.0099
2 irqsafe4_hard_spin_132 0.0099
1 irqsafe4_hard_wlock_132 0.0050
1 irqsafe4_hard_rlock_132 0.0050
1 irqsafe4_hard_wlock_213 0.0050
1 irqsafe4_hard_rlock_213 0.0050
1 irqsafe4_hard_spin_231 0.0050
1 irqsafe4_hard_wlock_231 0.0050
1 irqsafe4_hard_rlock_231 0.0050
2 irqsafe4_hard_spin_312 0.0099
1 irqsafe4_hard_wlock_312 0.0050
1 irqsafe4_hard_rlock_312 0.0050
1 irqsafe4_hard_spin_321 0.0050
1 irqsafe4_hard_wlock_321 0.0050
1 irqsafe4_hard_rlock_321 0.0050
1 irq_inversion_hard_spin_123 0.0050
2 irq_inversion_hard_wlock_123 0.0099
2 irq_inversion_hard_rlock_123 0.0099
2 irq_inversion_hard_spin_132 0.0099
1 irq_inversion_hard_wlock_132 0.0050
1 irq_inversion_hard_rlock_132 0.0050
1 irq_inversion_hard_wlock_213 0.0050
1 irq_inversion_hard_rlock_213 0.0050
1 irq_inversion_hard_spin_231 0.0050
1 irq_inversion_hard_wlock_231 0.0050
1 irq_inversion_hard_rlock_231 0.0050
2 irq_inversion_hard_spin_312 0.0099
1 irq_inversion_hard_wlock_312 0.0050
1 irq_inversion_hard_rlock_312 0.0050
1 irq_inversion_hard_spin_321 0.0050
1 irq_inversion_hard_wlock_321 0.0050
1 irq_inversion_hard_rlock_321 0.0050
1 irq_read_recursion_hard_123 0.0050
2 irq_read_recursion_hard_132 0.0099
1 irq_read_recursion_hard_231 0.0050
2 irq_read_recursion_hard_312 0.0099
1 irq_read_recursion_hard_321 0.0050
2 __spin_lock_init 0.0200
5 _raw_spin_unlock 0.0455
1 _raw_read_lock 0.0417
4 _raw_spin_lock 0.0175
3 fb_get_color_depth 0.0517
1 vgacon_save_screen 0.0105
5 cursor_timer_handler 0.1163
14 fb_flashcursor 0.0220
1 fbcon_cursor 0.0016
13 bit_cursor 0.0117
7 bit_putcs 0.0063
20 bitfill_aligned 0.1010
9 cfb_copyarea 0.0042
56 cfb_imageblit 0.0399
1 acpi_os_signal_semaphore 0.0099
1 acpi_ns_lookup 0.0007
2 acpi_tb_sum_table 0.0417
2 acpi_tb_validate_rsdp 0.0189
1 scrup 0.0053
1 con_chars_in_buffer 0.1429
2 do_con_write 0.0004
2 intel_i810_configure 0.0074
12 i810_write_dac 0.2553
62 i810_read_dac 1.3478
26 i810fb_getcolreg 0.0956
3 i810_screen_off 0.0349
4 i810_enable_cursor 0.1333
983 i810fb_cursor 1.4413
4 vortex_timer 0.0049
14 ide_inb 1.2727
2 ide_outb 0.3333
2 ide_driveid_update 0.0051
2 try_to_identify 0.0019
1 probe_hwif 0.0006
1 usb_hcd_poll_rh_status 0.0029
1 rh_timer_func 0.1000
2 usb_hcd_submit_urb 0.0010
13 i8042_interrupt 0.0260
4 i8042_timer_func 0.2500
1 sock_poll 0.0476
1 sock_wfree 0.0172
1 datagram_poll 0.0045
1 udp_poll 0.0055
5 unix_poll 0.0278
1 cache_clean 0.0025
46 schedule 0.0338
3 preempt_schedule 0.0361
2 cond_resched 0.0408
3 schedule_timeout 0.0197
2 __mutex_unlock_slowpath 0.0080
1 mutex_unlock 0.1000
9 __mutex_lock_interruptible_slowpath 0.0143
148 __mutex_lock_slowpath 0.2814
11 mutex_lock_nested 0.0202
6 _spin_lock 0.1200
26 _write_unlock_irq 0.3881
5 _spin_lock_irq 0.0893
2 _spin_lock_irqsave 0.0333
6 _spin_unlock 0.0984
605 _spin_unlock_irqrestore 6.7978
700 _spin_unlock_irq 10.4478
2 _read_unlock_irqrestore 0.0225
19 _read_unlock_irq 0.2836
12 _write_unlock_irqrestore 0.1348
1 unlock_kernel 0.0179
1 __release_kernel_lock 0.0417
46 *unknown*
72643 total 0.0308
Attachment:
signature.asc
Description: OpenPGP digital signature