finish_task_switch high in profiles in 2.6.7

Hi, I have a fairly busy mailserver which also has a simple iptables ruleset (blocking some IP's) running 2.6.7 with the deadline i/o scheduler. vmstat was reporting that system time was around 80%. I did the following

readprofile -r ; sleep 240 ; readprofile -n -m /boot/System.map-uname -r | sort -rn -k 1,1 | head -22

48036 total 0.2274
9684 finish_task_switch 80.0331
6992 default_idle 158.9091

  6335 __wake_up                                 87.9861
  5671 remove_wait_queue                         76.6351
  4150 add_wait_queue                            59.2857
  2459 sysenter_past_esp                         21.7611
  1304 find_get_page                             21.0323
  1160 __mod_timer                                4.1281
   938 do_gettimeofday                            5.0430
   756 del_timer_sync                             2.4787
   753 del_timer                                  7.1714
   599 handle_IRQ_event                           5.9900
   570 do_page_fault                              0.4612
   485 __do_softirq                               2.8529
   476 do_sigaction                               0.9136
   469 do_getitimer                               1.7055
   464 do_setitimer                               0.9768
   392 get_offset_tsc                            17.0435
   340 current_kernel_time                        4.9275
   293 in_group_p                                 2.4417
   272 eligible_child                             1.4093

On a 2.6.5 box with a similar workload, the profile is as follows

131202 total 0.3704
42080 fget 667.9365
12868 schedule 8.1084
11231 default_idle 255.2500
9157 fput 436.0476

  6642 remove_wait_queue                         89.7568
  6076 __wake_up                                 93.4769
  5056 page_remove_rmap                          13.4111
  4144 add_wait_queue                            59.2000
  2255 fget_light                                17.4806
  2176 sysenter_past_esp                         19.2566
  1271 kfree                                     11.6606
  1148 kmem_cache_alloc                          14.9091
   934 __kmalloc                                  6.6714
   890 __mod_timer                                3.1673
   768 del_timer_sync                             2.9538
   717 buffered_rmqueue                           1.5621
   715 kmem_cache_free                            8.2184
   613 free_hot_cold_page                         2.4618
   612 del_timer                                  5.8286
   588 __find_get_block                           3.0466
   588 do_page_fault                              0.4757

I am trying to determine where the system time is going and don't have much zen to begin with. Any assistance would be appreciated ?

Is it an SMP system? What sort of workload is it? Does it use threads? Check vmstat to see how much context switching is going on with each kernel.

Thanks.

Yes, It's an SMP (Dual P3-800). Workload is a busy mailserver (get lots of SMTP traffic, validate users against a remote database, reject a truckload of connections). CONFIG_4K_STACKS=y on the 2.6.7 box, e100 driver with NAPI turned off. No threads

The 2.6.7 box shows this wrt context swithes

procs memory swap io system cpu

 r  b   swpd   free   buff  cache   si   so    bi    bo   in    cs us sy wa id
 3  0      0  73096  63000  78100    0    0     0   524 5571 14772 25 73 0  2
 6  0      0  70932  63000  78100    0    0     0   448 5861 11368 34 65 0  1
 7  0      0  72916  63008  78092    0    0     0    12 5838 14956 30 70 0  1
 7  0      0  70852  63016  78084    0    0     0  1008 5551 13951 30 69 0  1
22  0      0  65300  63016  78084    0    0     0     0 5989 16043 34 66 0  1
19  0      0  66516  63020  78148    0    0     0  1252 6100 14653 31 69 0  0
29  1      0  67620  63024  78212    0    0     0   992 6314 14747 31 69 0  0

The 2.6.5 box shows this

procs -----------memory---------- ---swap-- -----io---- --system-- ----cpu----
r b swpd free buff cache si so bi bo in cs us sy id wa
166 0 0 137752 38148 188836 0 0 0 2424 5973 21695 30 70 0 0

34  0      0 135928  38160 189028    0    0     0  2160 5923 22532 32 68 0  0
28  1      0 136928  38184 189344    0    0     0  2904 6393 22098 31 69 0  0
32  1      0 136672  38204 189324    0    0     0  3240 6412 21362 32 68 0  0
33  0      0 135456  38216 189380    0    0     0  1708 6044 24735 28 72 0  0
17  0      0 135372  38264 189536    0    0     0  3044 6305 22326 35 64 0  0

229 0 0 135060 38272 189732 0 0 0 2340 6416 23697 33 67 0 0 32 0 0 134100 38288 189852 0 0 0 3068 6342 24016 33 67 0 0
16 0 0 134292 38300 190044 0 0 0 2408 6451 24727 31 69 0 0

OK

OK. They're both using 100% CPU... is 2.6.5 getting more work done?

So far, it looks like both are doing similar amount of work. am getting more measurements from other boxes

My concern was the high system usage, I had suspected that it might have been due interrupts generated on the NIC. This was not evident in the profile I generated

Regards, Yusuf

OK, keep me CCed on any further developments. In particular if context switches are up or performance is down.

Thanks
Nick

This doesn't look like very intense context switching in either case. 2.6.7 appears to be doing less context switching. I don't see a significant difference in system time, either.

Could you please send me complete profiles?

-- wli

$ awk '{ A[$2] = $1 } END { tot = A["total"]; for (x in A) { if (x != "total") { printf "%4.4f\t%s\n", 100.0*A[x]/tot, x } } }' < /tmp/yusuf-2.6.5 |sort -k 2,2 > /tmp/scaled-2.6.5
$ awk '{ A[$2] = $1 } END { tot = A["total"]; for (x in A) { if (x != "total") { printf "%4.4f\t%s\n", 100.0*A[x]/tot, x } } }' < /tmp/yusuf-2.6.7 |sort -k 2,2 > /tmp/scaled-2.6.7
$ join -1 2 -2 2 -e 0 -a 1 -a 2 /tmp/scaled-2.6.5 /tmp/scaled-2.6.7 | awk 'BEGIN { printf "%%before %%after %%diff func\n" } { A[$1] = $3 ; B[$1] = $2 ; D[$1] = $3 - $2 } END { n = 0; for (x in D) { ++n }; while (n != 0) { z = -1000.0; for (x in D) { if (D[x] > z) { y = x; z = A[x] } }; printf "%8.4f %8.4f %8.4f %s\n", B[y], A[y], D[y], y; delete D[y]; delete A[y]; delete B[y]; --n }; }'
%before %after %diff func
  0.0000  20.1599  20.1599 finish_task_switch
  5.0624  11.8057   6.7433 remove_wait_queue
  3.1585   8.6394   5.4809 add_wait_queue
  4.6310  13.1880   8.5570 __wake_up
  8.5601  14.5557   5.9956 default_idle
  1.6585   5.1191   3.4606 sysenter_past_esp
  0.0000   2.7146   2.7146 find_get_page
  0.6783   2.4149   1.7366 __mod_timer
  0.0000   1.9527   1.9527 do_gettimeofday
  0.0000   1.2470   1.2470 handle_IRQ_event
  0.0000   1.1866   1.1866 do_page_fault
  0.4665   1.5676   1.1011 del_timer
  0.0000   1.0097   1.0097 __do_softirq
  0.0000   0.9909   0.9909 do_sigaction
  0.5854   1.5738   0.9884 del_timer_sync
  0.0000   0.9764   0.9764 do_getitimer
  0.0000   0.9659   0.9659 do_setitimer
  0.0000   0.8161   0.8161 get_offset_tsc
  0.0000   0.7078   0.7078 current_kernel_time
  0.0000   0.6100   0.6100 in_group_p
  9.8078   0.0000  -9.8078 schedule
  3.8536   0.0000  -3.8536 page_remove_rmap
  0.4672   0.0000  -0.4672 free_hot_cold_page
  0.4482   0.0000  -0.4482 __find_get_block
  0.7119   0.0000  -0.7119 __kmalloc
  6.9793   0.0000  -6.9793 fput
 32.0727   0.0000 -32.0727 fget
  0.5465   0.0000  -0.5465 buffered_rmqueue
  0.5450   0.0000  -0.5450 kmem_cache_free
  0.8750   0.0000  -0.8750 kmem_cache_alloc
  0.9687   0.0000  -0.9687 kfree
  1.7187   0.0000  -1.7187 fget_light